Details
-
Bug
-
Resolution: Fixed
-
Major - P3
-
3.5.9
-
None
-
Fully Compatible
-
ALL
-
Platforms 2017-08-21
Description
Guys Im not really sure if title is the exactly case. But to me its seems that someone from wild send message to our (authenticated) mongo and service has been restarted. Afterwards golang services connected to the mongo instance start failing with message `EOF `.
Take a look on this logs:
2017-08-02T07:55:43.624+0000 I NETWORK [listener] connection accepted from 139.162.253.137:38676 #484 (0 connections now open)
|
2017-08-02T07:55:44.378+0000 I NETWORK [listener] connection accepted from 45.79.183.235:60838 #485 (0 connections now open)
|
2017-08-02T07:55:44.383+0000 I NETWORK [conn485] received client metadata from 45.79.183.235:60838 conn: { driver: { name: "nodejs", version: "2.2.29" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "4.9.15-x86_64-linode81" }, platform: "Node.js v4.4.3, LE, mongodb-core: 2.1.13" }
|
2017-08-02T07:55:44.550+0000 I NETWORK [listener] connection accepted from 45.79.183.235:60908 #486 (0 connections now open)
|
2017-08-02T07:55:44.629+0000 I NETWORK [listener] connection accepted from 45.79.183.235:60910 #487 (0 connections now open)
|
2017-08-02T07:55:44.630+0000 I ACCESS [conn487] Unauthorized: not authorized on admin to execute command { listDatabases: 1, $db: "admin" }
|
2017-08-02T07:55:44.711+0000 I NETWORK [conn486] end connection 45.79.183.235:60908 (4 connections now open)
|
2017-08-02T07:55:44.711+0000 I NETWORK [conn487] end connection 45.79.183.235:60910 (4 connections now open)
|
2017-08-02T07:55:44.712+0000 I NETWORK [conn485] end connection 45.79.183.235:60838 (3 connections now open)
|
2017-08-02T07:55:45.122+0000 I NETWORK [conn484] end connection 139.162.253.137:38676 (2 connections now open)
|
2017-08-02T07:55:45.137+0000 I NETWORK [listener] connection accepted from 139.162.253.137:38986 #488 (0 connections now open)
|
2017-08-02T07:55:46.639+0000 I NETWORK [conn488] end connection 139.162.253.137:38986 (2 connections now open)
|
2017-08-02T07:55:46.649+0000 I NETWORK [listener] connection accepted from 139.162.253.137:39276 #489 (0 connections now open)
|
2017-08-02T07:55:46.649+0000 I ACCESS [conn489] Unauthorized: not authorized on test to execute command { serverStatus: 1.0, $db: "test" }
|
2017-08-02T07:55:48.162+0000 I NETWORK [conn489] end connection 139.162.253.137:39276 (2 connections now open)
|
2017-08-02T07:55:48.244+0000 I NETWORK [listener] connection accepted from 139.162.253.137:39630 #490 (0 connections now open)
|
2017-08-02T07:55:49.746+0000 I NETWORK [conn490] end connection 139.162.253.137:39630 (2 connections now open)
|
2017-08-02T07:55:49.758+0000 I NETWORK [listener] connection accepted from 139.162.253.137:39808 #491 (0 connections now open)
|
2017-08-02T07:55:51.260+0000 I NETWORK [conn491] end connection 139.162.253.137:39808 (2 connections now open)
|
2017-08-02T07:55:51.271+0000 I NETWORK [listener] connection accepted from 139.162.253.137:40076 #492 (0 connections now open)
|
2017-08-02T07:55:52.772+0000 I NETWORK [conn492] end connection 139.162.253.137:40076 (2 connections now open)
|
2017-08-02T07:55:52.784+0000 I NETWORK [listener] connection accepted from 139.162.253.137:40402 #493 (0 connections now open)
|
2017-08-02T07:55:52.784+0000 I NETWORK [conn493] Error receiving request from client: SSLHandshakeFailed: SSLHandshakeFailed. Ending connection from 139.162.253.137:40402 (connection id: 493)
|
2017-08-02T07:55:52.784+0000 I NETWORK [conn493] end connection 139.162.253.137:40402 (2 connections now open)
|
2017-08-02T07:55:52.807+0000 I NETWORK [listener] connection accepted from 139.162.253.137:40408 #494 (0 connections now open)
|
2017-08-02T07:55:52.807+0000 I NETWORK [conn494] Error receiving request from client: SSLHandshakeFailed: SSLHandshakeFailed. Ending connection from 139.162.253.137:40408 (connection id: 494)
|
2017-08-02T07:55:52.807+0000 I NETWORK [conn494] end connection 139.162.253.137:40408 (2 connections now open)
|
2017-08-02T07:55:52.832+0000 I NETWORK [listener] connection accepted from 139.162.253.137:40412 #495 (0 connections now open)
|
2017-08-02T07:55:52.832+0000 I NETWORK [conn495] Error receiving request from client: SSLHandshakeFailed: SSLHandshakeFailed. Ending connection from 139.162.253.137:40412 (connection id: 495)
|
2017-08-02T07:55:52.832+0000 I NETWORK [conn495] end connection 139.162.253.137:40412 (2 connections now open)
|
2017-08-02T07:55:52.858+0000 I NETWORK [listener] connection accepted from 139.162.253.137:40418 #496 (0 connections now open)
|
2017-08-02T07:55:52.858+0000 I NETWORK [conn496] recv(): message msgLen 671088768 is invalid. Min 16 Max: 48000000
|
2017-08-02T07:55:52.858+0000 F - [conn496] Invariant failure !_inMessage.empty() src/mongo/transport/service_state_machine.cpp 162
|
2017-08-02T07:55:52.858+0000 F - [conn496]
|
***aborting after invariant() failure
|
2017-08-02T07:55:52.890+0000 F - [conn496] Got signal: 6 (Aborted).
|
0x55c62aed9491 0x55c62aed86a9 0x55c62aed8b8d 0x7f8003cd6890 0x7f8003951067 0x7f8003952448 0x55c62982cff2 0x55c629ac64e8 0x55c629ac4714 0x55c629ac3a88 0x55c62ad670e4 0x7f8003ccf064 0x7f8003a0462d
|
----- BEGIN BACKTRACE -----
|
mongod(_ZN5mongo15printStackTraceERSo+0x41) [0x55c62aed9491]
|
mongod(+0x1F116A9) [0x55c62aed86a9]
|
mongod(+0x1F11B8D) [0x55c62aed8b8d]
|
libpthread.so.0(+0xF890) [0x7f8003cd6890]
|
libc.so.6(gsignal+0x37) [0x7f8003951067]
|
libc.so.6(abort+0x148) [0x7f8003952448]
|
mongod(_ZN5mongo17invariantOKFailedEPKcRKNS_6StatusES1_j+0x0) [0x55c62982cff2]
|
mongod(_ZN5mongo19ServiceStateMachine14processMessageEv+0x988) [0x55c629ac64e8]
|
mongod(_ZN5mongo19ServiceStateMachine7runNextEv+0x254) [0x55c629ac4714]
|
mongod(+0xAFCA88) [0x55c629ac3a88]
|
mongod(+0x1DA00E4) [0x55c62ad670e4]
|
libpthread.so.0(+0x8064) [0x7f8003ccf064]
|
libc.so.6(clone+0x6D) [0x7f8003a0462d]
|
----- END BACKTRACE -----
|
2017-08-02T07:55:55.070+0000 I CONTROL [initandlisten] MongoDB starting : pid=1 port=27017 dbpath=/data/db 64-bit host=87ddc89b0e06
|
2017-08-02T07:55:55.071+0000 I CONTROL [initandlisten] db version v3.5.9
|
2017-08-02T07:55:55.071+0000 I CONTROL [initandlisten] git version: d5e9b4994557285017795d9ed9129341314da202
|
2017-08-02T07:55:55.072+0000 I CONTROL [initandlisten] OpenSSL version: OpenSSL 1.0.1t 3 May 2016
|
2017-08-02T07:55:55.072+0000 I CONTROL [initandlisten] allocator: tcmalloc
|
2017-08-02T07:55:55.072+0000 I CONTROL [initandlisten] modules: none
|
2017-08-02T07:55:55.072+0000 I CONTROL [initandlisten] build environment:
|
2017-08-02T07:55:55.072+0000 I CONTROL [initandlisten] distmod: debian81
|
2017-08-02T07:55:55.072+0000 I CONTROL [initandlisten] distarch: x86_64
|
2017-08-02T07:55:55.072+0000 I CONTROL [initandlisten] target_arch: x86_64
|
2017-08-02T07:55:55.072+0000 I CONTROL [initandlisten] options: { net: { bindIpAll: true }, security: { authorization: "enabled" }, storage: { engine: "wiredTiger" } }
|
2017-08-02T07:55:55.072+0000 W - [initandlisten] Detected unclean shutdown - /data/db/mongod.lock is not empty.
|
2017-08-02T07:55:55.073+0000 W STORAGE [initandlisten] Recovering data from the last clean checkpoint.
|
2017-08-02T07:55:55.074+0000 I STORAGE [initandlisten]
|
2017-08-02T07:55:55.074+0000 I STORAGE [initandlisten] ** WARNING: Using the XFS filesystem is strongly recommended with the WiredTiger storage engine
|
2017-08-02T07:55:55.074+0000 I STORAGE [initandlisten] ** See http://dochub.mongodb.org/core/prodnotes-filesystem
|
2017-08-02T07:55:55.074+0000 I STORAGE [initandlisten] wiredtiger_open config: create,cache_size=1369M,session_max=20000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),statistics_log=(wait=0),verbose=(recovery_progress),
|
2017-08-02T07:55:55.178+0000 I STORAGE [initandlisten] WiredTiger message [1501660555:178135][1:0x7f20b5c79d40], txn-recover: Main recovery loop: starting at 20/32106368
|
2017-08-02T07:55:55.179+0000 I STORAGE [initandlisten] WiredTiger message [1501660555:179041][1:0x7f20b5c79d40], txn-recover: Recovering log 20 through 21
|
2017-08-02T07:55:55.179+0000 I STORAGE [initandlisten] WiredTiger message [1501660555:179729][1:0x7f20b5c79d40], txn-recover: Recovering log 21 through 21
|
2017-08-02T07:55:55.272+0000 I CONTROL [initandlisten]
|
2017-08-02T07:55:55.272+0000 I CONTROL [initandlisten] ** NOTE: This is a development version (3.5.9) of MongoDB.
|
2017-08-02T07:55:55.272+0000 I CONTROL [initandlisten] ** Not recommended for production.
|
2017-08-02T07:55:55.272+0000 I CONTROL [initandlisten]
|
2017-08-02T07:55:55.272+0000 I CONTROL [initandlisten]
|
2017-08-02T07:55:55.272+0000 I CONTROL [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/enabled is 'always'.
|
2017-08-02T07:55:55.272+0000 I CONTROL [initandlisten] ** We suggest setting it to 'never'
|
2017-08-02T07:55:55.272+0000 I CONTROL [initandlisten]
|
2017-08-02T07:55:55.272+0000 I CONTROL [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/defrag is 'always'.
|
2017-08-02T07:55:55.272+0000 I CONTROL [initandlisten] ** We suggest setting it to 'never'
|
2017-08-02T07:55:55.272+0000 I CONTROL [initandlisten]
|
2017-08-02T07:55:55.281+0000 I FTDC [initandlisten] Initializing full-time diagnostic data capture with directory '/data/db/diagnostic.data'
|
2017-08-02T07:55:55.437+0000 I NETWORK [listener] connection accepted from 10.42.103.91:45582 #1 (0 connections now open)
|
2017-08-02T07:55:56.007+0000 I FTDC [ftdc] Unclean full-time diagnostic data capture shutdown detected, found interim file, some metrics may have been lost. OK
|
Attachments
Issue Links
- is duplicated by
-
SERVER-30576 junk data on the wire causes segfault in latest dev build
-
- Closed
-
-
SERVER-30694 Large legacy wire protocol messages cause crash in ServiceStateMachine
-
- Closed
-
- related to
-
SERVER-30902 mongod aborts rather then just discarding the socket that failed
-
- Closed
-