Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-13886

First call to whatsmyuri on a connection hangs during initial sync (with auth)

XMLWordPrintableJSON

    • Type: Icon: Bug Bug
    • Resolution: Done
    • Priority: Icon: Major - P3 Major - P3
    • 2.6.0
    • Affects Version/s: 2.4.10
    • Component/s: Replication, Security
    • Labels:
      None
    • ALL
    • 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
    • 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.

        1. mongod.log
          129 kB

            Assignee:
            Unassigned Unassigned
            Reporter:
            kevin.pulo@mongodb.com Kevin Pulo
            Votes:
            0 Vote for this issue
            Watchers:
            10 Start watching this issue

              Created:
              Updated:
              Resolved: