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)

    • 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
    • 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.

            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: