Loading...

Type: Bug
Resolution: Done
Priority: Major - P3
Fix Version/s: 2.6.0
Affects Version/s: 2.4.10
Component/s: Replication, Security
Labels:
None

Operating System:
ALL
Steps To Reproduce:
Hide

Using mtools from https://github.com/rueckstiess/mtools :

mlaunch --replicaset --nodes 3 --smallfiles --oplogSize 500 --port 12143 --auth mongo --port 12143 -u user -p password test --authenticationDatabase admin

for (i = 0; i < 2000000; i++) { db.test.insert({asldsdfdfdkfjdkfjkdgaghergekjfaldskjf:"alskdfhksdfhjksdfjsdkfjsdfdfdfsdfskdjfaldksfjalskfjhasdl"})} db.test.ensureIndex({asldsdfdfdkfjdkfjkdgaghergekjfaldskjf:1}) db.test.reIndex() // Takes ~10s

In another window, watch for stalls on just making connections:

while :; do date; echo -n "" > /dev/tcp/localhost/12145 ; sleep 0.5; done

In another window, watch for stalls when running whatsmyuri in a single connection:

mongo --port 12145 admin --eval 'while (!sleep(500)) { printjson(new Date()); printjson(db.runCommand({whatsmyuri:1}))}'

In another window, watch for stalls creating connections and issuing whatsmyuri:

mongo --port 12145 admin --eval 'while (!sleep(500)) { printjson(new Date()); connect("localhost:12145/test")}'

To trigger:

mlaunch stop 12145 rm -rf data/replset/rs3/db/* mlaunch start 12145 -v
Show
Using mtools from https://github.com/rueckstiess/mtools : mlaunch --replicaset --nodes 3 --smallfiles --oplogSize 500 --port 12143 --auth mongo --port 12143 -u user -p password test --authenticationDatabase admin for (i = 0; i < 2000000; i++) { db.test.insert({asldsdfdfdkfjdkfjkdgaghergekjfaldskjf: "alskdfhksdfhjksdfjsdkfjsdfdfdfsdfskdjfaldksfjalskfjhasdl" })} db.test.ensureIndex({asldsdfdfdkfjdkfjkdgaghergekjfaldskjf:1}) db.test.reIndex() // Takes ~10s In another window, watch for stalls on just making connections: while :; do date; echo -n "" > /dev/tcp/localhost/12145 ; sleep 0.5; done In another window, watch for stalls when running whatsmyuri in a single connection: mongo --port 12145 admin --eval ' while (!sleep(500)) { printjson( new Date()); printjson(db.runCommand({whatsmyuri:1}))}' In another window, watch for stalls creating connections and issuing whatsmyuri: mongo --port 12145 admin --eval ' while (!sleep(500)) { printjson( new Date()); connect( "localhost:12145/test" )}' To trigger: mlaunch stop 12145 rm -rf data/replset/rs3/db/* mlaunch start 12145 -v
Sprint:
Security [00-02-20-15]

During part of an initial sync of a secondary, new connections sometimes stall when the whatsmyuri command is run immediately after connecting. Appears to be around when indexes are built. Auth must be enabled on the server, but clients need not attempt to authenticate (the problem occurs before trying to authenticate). Happens most times, but not every time.

For the repro steps given, I get the following output:

Pure connections:

Fri May  9 16:46:50 EST 2014
Fri May  9 16:46:50 EST 2014
Fri May  9 16:46:51 EST 2014
Fri May  9 16:46:51 EST 2014
Fri May  9 16:46:52 EST 2014
Fri May  9 16:46:52 EST 2014
Fri May  9 16:46:53 EST 2014
Fri May  9 16:46:53 EST 2014
Fri May  9 16:46:54 EST 2014
Fri May  9 16:46:54 EST 2014
Fri May  9 16:46:55 EST 2014
Fri May  9 16:46:55 EST 2014
Fri May  9 16:46:56 EST 2014
Fri May  9 16:46:56 EST 2014
Fri May  9 16:46:57 EST 2014
Fri May  9 16:46:57 EST 2014
Fri May  9 16:46:58 EST 2014
Fri May  9 16:46:58 EST 2014
Fri May  9 16:46:59 EST 2014
Fri May  9 16:46:59 EST 2014
Fri May  9 16:47:00 EST 2014
Fri May  9 16:47:00 EST 2014
Fri May  9 16:47:01 EST 2014
Fri May  9 16:47:01 EST 2014
Fri May  9 16:47:02 EST 2014
Fri May  9 16:47:02 EST 2014
Fri May  9 16:47:03 EST 2014
Fri May  9 16:47:03 EST 2014
Fri May  9 16:47:04 EST 2014
Fri May  9 16:47:04 EST 2014
Fri May  9 16:47:05 EST 2014
Fri May  9 16:47:05 EST 2014
Fri May  9 16:47:06 EST 2014
Fri May  9 16:47:06 EST 2014
Fri May  9 16:47:07 EST 2014
Fri May  9 16:47:07 EST 2014
Fri May  9 16:47:08 EST 2014
Fri May  9 16:47:08 EST 2014
Fri May  9 16:47:09 EST 2014
Fri May  9 16:47:09 EST 2014
Fri May  9 16:47:10 EST 2014
Fri May  9 16:47:10 EST 2014

whatsmyuri on an existing connection:

ISODate("2014-05-09T06:46:50.354Z")
{ "you" : "127.0.0.1:44067", "ok" : 1 }
ISODate("2014-05-09T06:46:50.855Z")
{ "you" : "127.0.0.1:44067", "ok" : 1 }
ISODate("2014-05-09T06:46:51.355Z")
{ "you" : "127.0.0.1:44067", "ok" : 1 }
ISODate("2014-05-09T06:46:51.856Z")
{ "you" : "127.0.0.1:44067", "ok" : 1 }
ISODate("2014-05-09T06:46:52.357Z")
{ "you" : "127.0.0.1:44067", "ok" : 1 }
ISODate("2014-05-09T06:46:52.857Z")
{ "you" : "127.0.0.1:44067", "ok" : 1 }
ISODate("2014-05-09T06:46:53.358Z")
{ "you" : "127.0.0.1:44067", "ok" : 1 }
ISODate("2014-05-09T06:46:53.859Z")
{ "you" : "127.0.0.1:44067", "ok" : 1 }
ISODate("2014-05-09T06:46:54.360Z")
{ "you" : "127.0.0.1:44067", "ok" : 1 }
ISODate("2014-05-09T06:46:54.860Z")
{ "you" : "127.0.0.1:44067", "ok" : 1 }
ISODate("2014-05-09T06:46:55.361Z")
{ "you" : "127.0.0.1:44067", "ok" : 1 }
ISODate("2014-05-09T06:46:55.862Z")
{ "you" : "127.0.0.1:44067", "ok" : 1 }
ISODate("2014-05-09T06:46:56.363Z")
{ "you" : "127.0.0.1:44067", "ok" : 1 }
ISODate("2014-05-09T06:46:56.864Z")
{ "you" : "127.0.0.1:44067", "ok" : 1 }
ISODate("2014-05-09T06:46:57.364Z")
{ "you" : "127.0.0.1:44067", "ok" : 1 }
ISODate("2014-05-09T06:46:57.865Z")
{ "you" : "127.0.0.1:44067", "ok" : 1 }
ISODate("2014-05-09T06:46:58.366Z")
{ "you" : "127.0.0.1:44067", "ok" : 1 }
ISODate("2014-05-09T06:46:58.866Z")
{ "you" : "127.0.0.1:44067", "ok" : 1 }
ISODate("2014-05-09T06:46:59.367Z")
{ "you" : "127.0.0.1:44067", "ok" : 1 }
ISODate("2014-05-09T06:46:59.868Z")
{ "you" : "127.0.0.1:44067", "ok" : 1 }
ISODate("2014-05-09T06:47:00.368Z")
{ "you" : "127.0.0.1:44067", "ok" : 1 }
ISODate("2014-05-09T06:47:00.869Z")
{ "you" : "127.0.0.1:44067", "ok" : 1 }
ISODate("2014-05-09T06:47:01.370Z")
{ "you" : "127.0.0.1:44067", "ok" : 1 }
ISODate("2014-05-09T06:47:01.870Z")
{ "you" : "127.0.0.1:44067", "ok" : 1 }
ISODate("2014-05-09T06:47:02.371Z")
{ "you" : "127.0.0.1:44067", "ok" : 1 }
ISODate("2014-05-09T06:47:02.872Z")
{ "you" : "127.0.0.1:44067", "ok" : 1 }
ISODate("2014-05-09T06:47:03.372Z")
{ "you" : "127.0.0.1:44067", "ok" : 1 }
ISODate("2014-05-09T06:47:03.874Z")
{ "you" : "127.0.0.1:44067", "ok" : 1 }
ISODate("2014-05-09T06:47:04.375Z")
{ "you" : "127.0.0.1:44067", "ok" : 1 }
ISODate("2014-05-09T06:47:04.877Z")
{ "you" : "127.0.0.1:44067", "ok" : 1 }
ISODate("2014-05-09T06:47:05.378Z")
{ "you" : "127.0.0.1:44067", "ok" : 1 }
ISODate("2014-05-09T06:47:05.879Z")
{ "you" : "127.0.0.1:44067", "ok" : 1 }
ISODate("2014-05-09T06:47:06.380Z")
{ "you" : "127.0.0.1:44067", "ok" : 1 }
ISODate("2014-05-09T06:47:06.881Z")
{ "you" : "127.0.0.1:44067", "ok" : 1 }
ISODate("2014-05-09T06:47:07.382Z")
{ "you" : "127.0.0.1:44067", "ok" : 1 }
ISODate("2014-05-09T06:47:07.883Z")
{ "you" : "127.0.0.1:44067", "ok" : 1 }
ISODate("2014-05-09T06:47:08.384Z")
{ "you" : "127.0.0.1:44067", "ok" : 1 }
ISODate("2014-05-09T06:47:08.886Z")
{ "you" : "127.0.0.1:44067", "ok" : 1 }
ISODate("2014-05-09T06:47:09.387Z")
{ "you" : "127.0.0.1:44067", "ok" : 1 }
ISODate("2014-05-09T06:47:09.889Z")
{ "you" : "127.0.0.1:44067", "ok" : 1 }
ISODate("2014-05-09T06:47:10.390Z")
{ "you" : "127.0.0.1:44067", "ok" : 1 }

whatsmyuri on new connections:

Fri May  9 16:46:50 EST 2014
MongoDB shell version: 2.4.10
connecting to: 127.0.0.1:12145/test
ISODate("2014-05-09T06:46:50.090Z")
Fri May  9 16:46:50 EST 2014
MongoDB shell version: 2.4.10
connecting to: 127.0.0.1:12145/test
ISODate("2014-05-09T06:46:50.625Z")
Fri May  9 16:46:51 EST 2014
MongoDB shell version: 2.4.10
connecting to: 127.0.0.1:12145/test
ISODate("2014-05-09T06:46:51.159Z")
Fri May  9 16:46:51 EST 2014
MongoDB shell version: 2.4.10
connecting to: 127.0.0.1:12145/test
ISODate("2014-05-09T06:46:51.705Z")
Fri May  9 16:46:52 EST 2014
MongoDB shell version: 2.4.10
connecting to: 127.0.0.1:12145/test
ISODate("2014-05-09T06:46:52.241Z")
Fri May  9 16:46:52 EST 2014
MongoDB shell version: 2.4.10
connecting to: 127.0.0.1:12145/test
ISODate("2014-05-09T06:46:52.787Z")
Fri May  9 16:46:53 EST 2014
MongoDB shell version: 2.4.10
connecting to: 127.0.0.1:12145/test
ISODate("2014-05-09T06:46:53.334Z")
Fri May  9 16:46:53 EST 2014
MongoDB shell version: 2.4.10
connecting to: 127.0.0.1:12145/test
ISODate("2014-05-09T06:46:53.870Z")
Fri May  9 16:46:54 EST 2014
MongoDB shell version: 2.4.10
connecting to: 127.0.0.1:12145/test
ISODate("2014-05-09T06:46:54.615Z")
Fri May  9 16:46:55 EST 2014
MongoDB shell version: 2.4.10
connecting to: 127.0.0.1:12145/test
ISODate("2014-05-09T06:46:55.156Z")
Fri May  9 16:46:55 EST 2014
MongoDB shell version: 2.4.10
connecting to: 127.0.0.1:12145/test
ISODate("2014-05-09T06:46:55.740Z")
Fri May  9 16:46:56 EST 2014
MongoDB shell version: 2.4.10
connecting to: 127.0.0.1:12145/test
ISODate("2014-05-09T06:46:56.278Z")
Fri May  9 16:46:56 EST 2014
MongoDB shell version: 2.4.10
connecting to: 127.0.0.1:12145/test
ISODate("2014-05-09T06:47:03.065Z")
Fri May  9 16:47:03 EST 2014
MongoDB shell version: 2.4.10
connecting to: 127.0.0.1:12145/test
ISODate("2014-05-09T06:47:03.616Z")
Fri May  9 16:47:04 EST 2014
MongoDB shell version: 2.4.10
connecting to: 127.0.0.1:12145/test
ISODate("2014-05-09T06:47:04.159Z")
Fri May  9 16:47:04 EST 2014
MongoDB shell version: 2.4.10
connecting to: 127.0.0.1:12145/test
ISODate("2014-05-09T06:47:04.697Z")
Fri May  9 16:47:05 EST 2014
MongoDB shell version: 2.4.10
connecting to: 127.0.0.1:12145/test
ISODate("2014-05-09T06:47:05.248Z")
Fri May  9 16:47:05 EST 2014
MongoDB shell version: 2.4.10
connecting to: 127.0.0.1:12145/test
ISODate("2014-05-09T06:47:05.799Z")
Fri May  9 16:47:06 EST 2014
MongoDB shell version: 2.4.10
connecting to: 127.0.0.1:12145/test
ISODate("2014-05-09T06:47:06.343Z")
Fri May  9 16:47:06 EST 2014
MongoDB shell version: 2.4.10
connecting to: 127.0.0.1:12145/test
ISODate("2014-05-09T06:47:06.890Z")
Fri May  9 16:47:07 EST 2014
MongoDB shell version: 2.4.10
connecting to: 127.0.0.1:12145/test
ISODate("2014-05-09T06:47:07.439Z")
Fri May  9 16:47:07 EST 2014
MongoDB shell version: 2.4.10
connecting to: 127.0.0.1:12145/test
ISODate("2014-05-09T06:47:07.985Z")
Fri May  9 16:47:08 EST 2014
MongoDB shell version: 2.4.10
connecting to: 127.0.0.1:12145/test
ISODate("2014-05-09T06:47:08.541Z")
Fri May  9 16:47:09 EST 2014
MongoDB shell version: 2.4.10
connecting to: 127.0.0.1:12145/test
ISODate("2014-05-09T06:47:09.099Z")
Fri May  9 16:47:09 EST 2014
MongoDB shell version: 2.4.10
connecting to: 127.0.0.1:12145/test
ISODate("2014-05-09T06:47:09.653Z")
Fri May  9 16:47:10 EST 2014
MongoDB shell version: 2.4.10
connecting to: 127.0.0.1:12145/test
ISODate("2014-05-09T06:47:10.196Z")

Note:

connections which do nothing are accepted fine throughout.
whatsmyuri running repeatedly on an existing connection is fine throughout.
making new mongo shell connections (which run whatsmyuri) stall between 16:46:56 and 16:47:03

Loglevel 1 logs from affected secondary attached.

- - Sort By Name
  - Sort By Date
  - Ascending
  - Descending
  - Thumbnails
  - List
  - Download All

mongod.log
129 kB
May 09 2014 07:18:05 AM UTC

Details

Description

Attachments

Attachments

Activity

People

Dates