[SERVER-13886] First call to whatsmyuri on a connection hangs during initial sync (with auth) Created: 09/May/14  Updated: 11/Jul/16  Resolved: 20/May/14

Status: Closed
Project: Core Server
Component/s: Replication, Security
Affects Version/s: 2.4.10
Fix Version/s: 2.6.0

Type: Bug Priority: Major - P3
Reporter: Kevin Pulo Assignee: Unassigned
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: File mongod.log    
Issue Links:
Related
Operating System: ALL
Steps To Reproduce:

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]
Participants:

 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.



 Comments   
Comment by Kevin Pulo [ 20/May/14 ]

Correct, I cannot reproduce this in 2.6.0 or 2.6.1.

Comment by Thomas Rueckstiess [ 15/May/14 ]

kevin.pulo@10gen.com, could you repeat the repro with 2.6 and see if it's fixed already?

Comment by Eric Milkie [ 13/May/14 ]

Does this happen with version 2.6? (I suspect it does not)

Generated at Thu Feb 08 03:33:12 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.