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

Details

    • Icon: Bug Bug
    • Resolution: Done
    • Icon: Major - P3 Major - P3
    • 2.6.0
    • 2.4.10
    • 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]

    Description

      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.

      Attachments

        Activity

          People

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

            Dates

              Created:
              Updated:
              Resolved: