-
Type: Bug
-
Resolution: Fixed
-
Priority: Major - P3
-
Affects Version/s: 3.5.9
-
Component/s: Networking
-
None
-
Fully Compatible
-
ALL
-
Platforms 2017-08-21
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
- 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