-
Type:
Bug
-
Resolution: Done
-
Priority:
Major - P3
-
Affects Version/s: None
-
Component/s: Testing Infrastructure
-
Environment:All Windows build slaves (32 & 64-bit, debug and release)
-
Windows
Failure in Windows 64-bit:
http://buildlogs.mongodb.org/Windows%2064-bit/builds/5256/test/sharding/gle_error_message.js
Wed Nov 21 00:54:41.672 [conn41] end connection 127.0.0.1:57498 (0 connections now open)
Wed Nov 21 00:55:06.538 [initandlisten] connection accepted from 127.0.0.1:57555 #42 (1 connection now open)
MongoDB shell version: 2.3.1-pre-
null
----
Starting sharded cluster...
----
Resetting db path '/data/db/test0'
Wed Nov 21 00:55:06.959 shell: started program mongod.exe --port 30000 --dbpath /data/db/test0
m30000| Wed Nov 21 00:55:06.991 [initandlisten] MongoDB starting : pid=10904 port=30000 dbpath=/data/db/test0 64-bit host=AMAZONA-JD1A6QA
m30000| Wed Nov 21 00:55:06.991 [initandlisten]
m30000| Wed Nov 21 00:55:06.991 [initandlisten] ** NOTE: This is a development version (2.3.1-pre-) of MongoDB.
m30000| Wed Nov 21 00:55:06.991 [initandlisten] ** Not recommended for production.
m30000| Wed Nov 21 00:55:06.991 [initandlisten]
m30000| Wed Nov 21 00:55:06.991 [initandlisten] db version v2.3.1-pre-, pdfile version 4.5
m30000| Wed Nov 21 00:55:06.991 [initandlisten] git version: cb14cf83102cca848e572ffd8b95c6fa35594175
m30000| Wed Nov 21 00:55:06.991 [initandlisten] build info: windows sys.getwindowsversion(major=6, minor=1, build=7601, platform=2, service_pack='Service Pack 1') BOOST_LIB_VERSION=1_49
m30000| Wed Nov 21 00:55:06.991 [initandlisten] options: { dbpath: "/data/db/test0", port: 30000 }
m30000| Wed Nov 21 00:55:07.006 [initandlisten] journal dir=/data/db/test0\journal
m30000| Wed Nov 21 00:55:07.006 [initandlisten] recover : no journal files present, no recovery needed
m30000| Wed Nov 21 00:55:07.147 [websvr] admin web console waiting for connections on port 31000
m30000| Wed Nov 21 00:55:07.147 [initandlisten] waiting for connections on port 30000
m30000| Wed Nov 21 00:55:07.474 [initandlisten] connection accepted from 127.0.0.1:57564 #1 (1 connection now open)
Resetting db path '/data/db/test1'
Wed Nov 21 00:55:07.490 shell: started program mongod.exe --port 30001 --dbpath /data/db/test1
m30001| Wed Nov 21 00:55:07.521 [initandlisten] MongoDB starting : pid=2836 port=30001 dbpath=/data/db/test1 64-bit host=AMAZONA-JD1A6QA
m30001| Wed Nov 21 00:55:07.521 [initandlisten]
m30001| Wed Nov 21 00:55:07.521 [initandlisten] ** NOTE: This is a development version (2.3.1-pre-) of MongoDB.
m30001| Wed Nov 21 00:55:07.521 [initandlisten] ** Not recommended for production.
m30001| Wed Nov 21 00:55:07.521 [initandlisten]
m30001| Wed Nov 21 00:55:07.521 [initandlisten] db version v2.3.1-pre-, pdfile version 4.5
m30001| Wed Nov 21 00:55:07.521 [initandlisten] git version: cb14cf83102cca848e572ffd8b95c6fa35594175
m30001| Wed Nov 21 00:55:07.521 [initandlisten] build info: windows sys.getwindowsversion(major=6, minor=1, build=7601, platform=2, service_pack='Service Pack 1') BOOST_LIB_VERSION=1_49
m30001| Wed Nov 21 00:55:07.521 [initandlisten] options: { dbpath: "/data/db/test1", port: 30001 }
m30001| Wed Nov 21 00:55:07.537 [initandlisten] journal dir=/data/db/test1\journal
m30001| Wed Nov 21 00:55:07.537 [initandlisten] recover : no journal files present, no recovery needed
m30001| Wed Nov 21 00:55:07.677 [websvr] admin web console waiting for connections on port 31001
m30001| Wed Nov 21 00:55:07.677 [initandlisten] waiting for connections on port 30001
m30001| Wed Nov 21 00:55:08.005 [initandlisten] connection accepted from 127.0.0.1:57565 #1 (1 connection now open)
Resetting db path '/data/db/test2'
Wed Nov 21 00:55:08.005 shell: started program mongod.exe --port 30002 --dbpath /data/db/test2
m30002| Wed Nov 21 00:55:08.036 [initandlisten] MongoDB starting : pid=10968 port=30002 dbpath=/data/db/test2 64-bit host=AMAZONA-JD1A6QA
m30002| Wed Nov 21 00:55:08.036 [initandlisten]
m30002| Wed Nov 21 00:55:08.036 [initandlisten] ** NOTE: This is a development version (2.3.1-pre-) of MongoDB.
m30002| Wed Nov 21 00:55:08.036 [initandlisten] ** Not recommended for production.
m30002| Wed Nov 21 00:55:08.036 [initandlisten]
m30002| Wed Nov 21 00:55:08.036 [initandlisten] db version v2.3.1-pre-, pdfile version 4.5
m30002| Wed Nov 21 00:55:08.036 [initandlisten] git version: cb14cf83102cca848e572ffd8b95c6fa35594175
m30002| Wed Nov 21 00:55:08.036 [initandlisten] build info: windows sys.getwindowsversion(major=6, minor=1, build=7601, platform=2, service_pack='Service Pack 1') BOOST_LIB_VERSION=1_49
m30002| Wed Nov 21 00:55:08.036 [initandlisten] options: { dbpath: "/data/db/test2", port: 30002 }
m30002| Wed Nov 21 00:55:08.051 [initandlisten] journal dir=/data/db/test2\journal
m30002| Wed Nov 21 00:55:08.051 [initandlisten] recover : no journal files present, no recovery needed
m30002| Wed Nov 21 00:55:08.285 [websvr] admin web console waiting for connections on port 31002
m30002| Wed Nov 21 00:55:08.285 [initandlisten] waiting for connections on port 30002
m30002| Wed Nov 21 00:55:08.519 [initandlisten] connection accepted from 127.0.0.1:57566 #1 (1 connection now open)
Resetting db path '/data/db/test-config0'
Wed Nov 21 00:55:08.519 shell: started program mongod.exe --port 29000 --dbpath /data/db/test-config0 --configsvr
m29000| Wed Nov 21 00:55:08.551 [initandlisten] MongoDB starting : pid=2868 port=29000 dbpath=/data/db/test-config0 64-bit host=AMAZONA-JD1A6QA
m29000| Wed Nov 21 00:55:08.551 [initandlisten]
m29000| Wed Nov 21 00:55:08.551 [initandlisten] ** NOTE: This is a development version (2.3.1-pre-) of MongoDB.
m29000| Wed Nov 21 00:55:08.551 [initandlisten] ** Not recommended for production.
m29000| Wed Nov 21 00:55:08.551 [initandlisten]
m29000| Wed Nov 21 00:55:08.551 [initandlisten] db version v2.3.1-pre-, pdfile version 4.5
m29000| Wed Nov 21 00:55:08.551 [initandlisten] git version: cb14cf83102cca848e572ffd8b95c6fa35594175
m29000| Wed Nov 21 00:55:08.551 [initandlisten] build info: windows sys.getwindowsversion(major=6, minor=1, build=7601, platform=2, service_pack='Service Pack 1') BOOST_LIB_VERSION=1_49
m29000| Wed Nov 21 00:55:08.551 [initandlisten] options: { configsvr: true, dbpath: "/data/db/test-config0", port: 29000 }
m29000| Wed Nov 21 00:55:08.551 [initandlisten] journal dir=/data/db/test-config0\journal
m29000| Wed Nov 21 00:55:08.551 [initandlisten] recover : no journal files present, no recovery needed
m29000| Wed Nov 21 00:55:08.707 [initandlisten] waiting for connections on port 29000
m29000| Wed Nov 21 00:55:08.707 [websvr] listen(): bind() failed errno:10048 Only one usage of each socket address (protocol/network address/port) is normally permitted. for socket: 0.0.0.0:30000
m29000| Wed Nov 21 00:55:09.034 [initandlisten] connection accepted from 127.0.0.1:57567 #1 (1 connection now open)
"localhost:29000"
m29000| Wed Nov 21 00:55:09.034 [initandlisten] connection accepted from 127.0.0.1:57568 #2 (2 connections now open)
ShardingTest test :
{
"config" : "localhost:29000",
"shards" : [
connection to localhost:30000,
connection to localhost:30001,
connection to localhost:30002
]
}
Wed Nov 21 00:55:09.034 shell: started program mongos.exe --port 30999 --configdb localhost:29000 -vvv --chunkSize 50
m30999| Wed Nov 21 00:55:09.034 running with 1 config server should be done only for testing purposes and is not recommended for production
m30999| Wed Nov 21 00:55:09.050 [mongosMain] MongoS version 2.3.1-pre- starting: pid=6732 port=30999 64-bit host=AMAZONA-JD1A6QA (--help for usage)
m30999| Wed Nov 21 00:55:09.050 [mongosMain] git version: cb14cf83102cca848e572ffd8b95c6fa35594175
m30999| Wed Nov 21 00:55:09.050 [mongosMain] build info: windows sys.getwindowsversion(major=6, minor=1, build=7601, platform=2, service_pack='Service Pack 1') BOOST_LIB_VERSION=1_49
m30999| Wed Nov 21 00:55:09.050 [mongosMain] options: { chunkSize: 50, configdb: "localhost:29000", port: 30999, vvv: true }
m30999| Wed Nov 21 00:55:09.050 [mongosMain] config string : localhost:29000
m30999| Wed Nov 21 00:55:09.050 [mongosMain] creating new connection to:localhost:29000
m30999| Wed Nov 21 00:55:09.050 BackgroundJob starting: ConnectBG
m29000| Wed Nov 21 00:55:09.050 [initandlisten] connection accepted from 127.0.0.1:57571 #3 (3 connections now open)
m30999| Wed Nov 21 00:55:09.065 [mongosMain] connected connection!
m30999| Wed Nov 21 00:55:09.065 BackgroundJob starting: CheckConfigServers
m30999| Wed Nov 21 00:55:09.065 [CheckConfigServers] creating new connection to:localhost:29000
m30999| Wed Nov 21 00:55:09.065 BackgroundJob starting: ConnectBG
m30999| Wed Nov 21 00:55:09.065 [CheckConfigServers] connected connection!
m29000| Wed Nov 21 00:55:09.065 [initandlisten] connection accepted from 127.0.0.1:57572 #4 (4 connections now open)
m30999| Wed Nov 21 00:55:09.065 [mongosMain] creating new connection to:localhost:29000
m30999| Wed Nov 21 00:55:09.065 BackgroundJob starting: ConnectBG
m29000| Wed Nov 21 00:55:09.065 [initandlisten] connection accepted from 127.0.0.1:57573 #5 (5 connections now open)
m30999| Wed Nov 21 00:55:09.065 [mongosMain] connected connection!
m29000| Wed Nov 21 00:55:09.065 [FileAllocator] allocating new datafile /data/db/test-config0\config.ns, filling with zeroes...
m29000| Wed Nov 21 00:55:09.065 [FileAllocator] creating directory /data/db/test-config0\_tmp
m29000| Wed Nov 21 00:55:09.112 [FileAllocator] done allocating datafile /data/db/test-config0\config.ns, size: 16MB, took 0.047 secs
m29000| Wed Nov 21 00:55:09.112 [FileAllocator] allocating new datafile /data/db/test-config0\config.0, filling with zeroes...
m29000| Wed Nov 21 00:55:09.159 [FileAllocator] done allocating datafile /data/db/test-config0\config.0, size: 16MB, took 0.047 secs
m29000| Wed Nov 21 00:55:09.159 [FileAllocator] allocating new datafile /data/db/test-config0\config.1, filling with zeroes...
m29000| Wed Nov 21 00:55:09.159 [conn5] build index config.version { _id: 1 }
m29000| Wed Nov 21 00:55:09.159 [conn5] build index done. scanned 0 total records. 0 secs
m29000| Wed Nov 21 00:55:09.159 [conn3] build index config.settings { _id: 1 }
m30999| Wed Nov 21 00:55:09.159 BackgroundJob starting: Balancer
m30999| Wed Nov 21 00:55:09.159 [Balancer] about to contact config servers and shards
m30999| Wed Nov 21 00:55:09.159 [websvr] admin web console waiting for connections on port 31999
m30999| Wed Nov 21 00:55:09.159 [mongosMain] waiting for connections on port 30999
m30999| Wed Nov 21 00:55:09.159 BackgroundJob starting: cursorTimeout
m30999| Wed Nov 21 00:55:09.159 BackgroundJob starting: PeriodicTask::Runner
m29000| Wed Nov 21 00:55:09.175 [conn3] build index done. scanned 0 total records. 0.006 secs
m30999| Wed Nov 21 00:55:09.175 [Balancer] config servers and shards contacted successfully
m30999| Wed Nov 21 00:55:09.175 [Balancer] balancer id: AMAZONA-JD1A6QA:30999 started at Nov 21 00:55:09
m30999| Wed Nov 21 00:55:09.175 [Balancer] created new distributed lock for balancer on localhost:29000 ( lock timeout : 900000, ping interval : 30000, process : 0 )
m30999| Wed Nov 21 00:55:09.175 [Balancer] creating new connection to:localhost:29000
m29000| Wed Nov 21 00:55:09.175 [conn3] build index config.chunks { _id: 1 }
m30999| Wed Nov 21 00:55:09.175 BackgroundJob starting: ConnectBG
m30999| Wed Nov 21 00:55:09.175 [Balancer] connected connection!
m29000| Wed Nov 21 00:55:09.175 [initandlisten] connection accepted from 127.0.0.1:57575 #6 (6 connections now open)
m29000| Wed Nov 21 00:55:09.175 [conn3] build index done. scanned 0 total records. 0 secs
m29000| Wed Nov 21 00:55:09.175 [conn3] info: creating collection config.chunks on add index
m29000| Wed Nov 21 00:55:09.175 [conn3] build index config.chunks { ns: 1, min: 1 }
m29000| Wed Nov 21 00:55:09.175 [conn3] build index done. scanned 0 total records. 0 secs
m29000| Wed Nov 21 00:55:09.175 [conn5] build index config.mongos { _id: 1 }
m29000| Wed Nov 21 00:55:09.175 [conn5] build index done. scanned 0 total records. 0 secs
m29000| Wed Nov 21 00:55:09.175 [conn3] build index config.chunks { ns: 1, shard: 1, min: 1 }
m29000| Wed Nov 21 00:55:09.175 [conn3] build index done. scanned 0 total records. 0 secs
m29000| Wed Nov 21 00:55:09.175 [conn3] build index config.chunks { ns: 1, lastmod: 1 }
m30999| Wed Nov 21 00:55:09.175 [Balancer] Refreshing MaxChunkSize: 50
m29000| Wed Nov 21 00:55:09.175 [conn3] build index done. scanned 0 total records. 0 secs
m29000| Wed Nov 21 00:55:09.175 [conn3] build index config.shards { _id: 1 }
m29000| Wed Nov 21 00:55:09.175 [conn3] build index done. scanned 0 total records. 0 secs
m29000| Wed Nov 21 00:55:09.175 [conn3] info: creating collection config.shards on add index
m29000| Wed Nov 21 00:55:09.175 [conn3] build index config.shards { host: 1 }
m29000| Wed Nov 21 00:55:09.175 [conn3] build index done. scanned 0 total records. 0 secs
m30999| Wed Nov 21 00:55:09.175 [Balancer] skew from remote server localhost:29000 found: 0
m30999| Wed Nov 21 00:55:09.175 [Balancer] skew from remote server localhost:29000 found: 0
m30999| Wed Nov 21 00:55:09.175 [Balancer] skew from remote server localhost:29000 found: 0
m30999| Wed Nov 21 00:55:09.175 [Balancer] total clock skew of 0ms for servers localhost:29000 is in 30000ms bounds.
m30999| Wed Nov 21 00:55:09.175 [LockPinger] creating distributed lock ping thread for localhost:29000 and process AMAZONA-JD1A6QA:30999:1353477309:41 (sleeping for 30000ms)
m30999| Wed Nov 21 00:55:09.175 [LockPinger] distributed lock pinger 'localhost:29000/AMAZONA-JD1A6QA:30999:1353477309:41' about to ping.
m30999| Wed Nov 21 00:55:09.175 [Balancer] inserting initial doc in config.locks for lock balancer
m30999| Wed Nov 21 00:55:09.175 [Balancer] about to acquire distributed lock 'balancer/AMAZONA-JD1A6QA:30999:1353477309:41:
m30999| { "state" : 1,
m30999| "who" : "AMAZONA-JD1A6QA:30999:1353477309:41:Balancer:18467",
m30999| "process" : "AMAZONA-JD1A6QA:30999:1353477309:41",
m30999| "when" : { "$date" : "Wed Nov 21 00:55:09 2012" },
m30999| "why" : "doing balance round",
m30999| "ts" : { "$oid" : "50ac6cbdfaf2e30ed017368e" } }
m30999| { "_id" : "balancer",
m30999| "state" : 0 }
m29000| Wed Nov 21 00:55:09.175 [conn3] build index config.lockpings { _id: 1 }
m29000| Wed Nov 21 00:55:09.175 [conn3] build index done. scanned 0 total records. 0 secs
m29000| Wed Nov 21 00:55:09.175 [conn6] build index config.locks { _id: 1 }
m29000| Wed Nov 21 00:55:09.175 [conn6] build index done. scanned 0 total records. 0 secs
m30999| Wed Nov 21 00:55:09.175 [LockPinger] cluster localhost:29000 pinged successfully at Wed Nov 21 00:55:09 2012 by distributed lock pinger 'localhost:29000/AMAZONA-JD1A6QA:30999:1353477309:41', sleeping for 30000ms
m29000| Wed Nov 21 00:55:09.175 [conn3] build index config.lockpings { ping: new Date(1) }
m29000| Wed Nov 21 00:55:09.175 [conn3] build index done. scanned 1 total records. 0 secs
m30999| Wed Nov 21 00:55:09.175 [Balancer] distributed lock 'balancer/AMAZONA-JD1A6QA:30999:1353477309:41' acquired, ts : 50ac6cbdfaf2e30ed017368e
m30999| Wed Nov 21 00:55:09.175 [Balancer] *** start balancing round
m30999| Wed Nov 21 00:55:09.175 [Balancer] no collections to balance
m30999| Wed Nov 21 00:55:09.175 [Balancer] no need to move any chunk
m30999| Wed Nov 21 00:55:09.175 [Balancer] *** end of balancing round
m30999| Wed Nov 21 00:55:09.175 [Balancer] distributed lock 'balancer/AMAZONA-JD1A6QA:30999:1353477309:41' unlocked.
m29000| Wed Nov 21 00:55:09.253 [FileAllocator] done allocating datafile /data/db/test-config0\config.1, size: 32MB, took 0.094 secs
m30999| Wed Nov 21 00:55:09.549 [mongosMain] connection accepted from 127.0.0.1:57570 #1 (1 connection now open)
m30999| Wed Nov 21 00:55:09.549 [conn1] couldn't find database [admin] in config db
m29000| Wed Nov 21 00:55:09.549 [conn3] build index config.databases { _id: 1 }
Wed Nov 21 00:55:09.549 shell: started program mongos.exe --port 30998 --configdb localhost:29000 -vvv --chunkSize 50
m29000| Wed Nov 21 00:55:09.549 [conn3] build index done. scanned 0 total records. 0 secs
m30999| Wed Nov 21 00:55:09.549 [conn1] put [admin] on: config:localhost:29000
m30999| Wed Nov 21 00:55:09.549 [conn1] scoped connection to localhost:29000 not being returned to the pool
m29000| Wed Nov 21 00:55:09.549 [conn3] end connection 127.0.0.1:57571 (5 connections now open)
m30998| Wed Nov 21 00:55:09.549 running with 1 config server should be done only for testing purposes and is not recommended for production
m30998| Wed Nov 21 00:55:09.549 [mongosMain] MongoS version 2.3.1-pre- starting: pid=7740 port=30998 64-bit host=AMAZONA-JD1A6QA (--help for usage)
m30998| Wed Nov 21 00:55:09.549 [mongosMain] git version: cb14cf83102cca848e572ffd8b95c6fa35594175
m30998| Wed Nov 21 00:55:09.549 [mongosMain] build info: windows sys.getwindowsversion(major=6, minor=1, build=7601, platform=2, service_pack='Service Pack 1') BOOST_LIB_VERSION=1_49
m30998| Wed Nov 21 00:55:09.549 [mongosMain] options: { chunkSize: 50, configdb: "localhost:29000", port: 30998, vvv: true }
m30998| Wed Nov 21 00:55:09.549 [mongosMain] config string : localhost:29000
m30998| Wed Nov 21 00:55:09.549 [mongosMain] creating new connection to:localhost:29000
m30998| Wed Nov 21 00:55:09.549 BackgroundJob starting: ConnectBG
m29000| Wed Nov 21 00:55:09.549 [initandlisten] connection accepted from 127.0.0.1:57577 #7 (6 connections now open)
m30998| Wed Nov 21 00:55:09.565 [mongosMain] connected connection!
m30998| Wed Nov 21 00:55:09.565 BackgroundJob starting: CheckConfigServers
m30998| Wed Nov 21 00:55:09.565 [CheckConfigServers] creating new connection to:localhost:29000
m30998| Wed Nov 21 00:55:09.565 BackgroundJob starting: ConnectBG
m30998| Wed Nov 21 00:55:09.565 [mongosMain] MaxChunkSize: 50
m29000| Wed Nov 21 00:55:09.565 [initandlisten] connection accepted from 127.0.0.1:57578 #8 (7 connections now open)
m30998| Wed Nov 21 00:55:09.565 [CheckConfigServers] connected connection!
m30998| Wed Nov 21 00:55:09.565 BackgroundJob starting: Balancer
m30998| Wed Nov 21 00:55:09.565 [Balancer] about to contact config servers and shards
m30998| Wed Nov 21 00:55:09.565 [Balancer] creating new connection to:localhost:29000
m30998| Wed Nov 21 00:55:09.565 BackgroundJob starting: cursorTimeout
m30998| Wed Nov 21 00:55:09.565 [mongosMain] waiting for connections on port 30998
m30998| Wed Nov 21 00:55:09.565 [websvr] admin web console waiting for connections on port 31998
m30998| Wed Nov 21 00:55:09.565 BackgroundJob starting: PeriodicTask::Runner
m30998| Wed Nov 21 00:55:09.565 BackgroundJob starting: ConnectBG
m29000| Wed Nov 21 00:55:09.565 [initandlisten] connection accepted from 127.0.0.1:57579 #9 (8 connections now open)
m30998| Wed Nov 21 00:55:09.565 [Balancer] connected connection!
m30998| Wed Nov 21 00:55:09.565 [Balancer] config servers and shards contacted successfully
m30998| Wed Nov 21 00:55:09.565 [Balancer] balancer id: AMAZONA-JD1A6QA:30998 started at Nov 21 00:55:09
m30998| Wed Nov 21 00:55:09.565 [Balancer] created new distributed lock for balancer on localhost:29000 ( lock timeout : 900000, ping interval : 30000, process : 0 )
m30998| Wed Nov 21 00:55:09.565 [Balancer] creating new connection to:localhost:29000
m30998| Wed Nov 21 00:55:09.565 BackgroundJob starting: ConnectBG
m30998| Wed Nov 21 00:55:09.565 [Balancer] connected connection!
m29000| Wed Nov 21 00:55:09.565 [initandlisten] connection accepted from 127.0.0.1:57580 #10 (9 connections now open)
m30998| Wed Nov 21 00:55:09.565 [Balancer] Refreshing MaxChunkSize: 50
m30998| Wed Nov 21 00:55:09.565 [Balancer] skew from remote server localhost:29000 found: 0
m30998| Wed Nov 21 00:55:09.565 [Balancer] skew from remote server localhost:29000 found: 0
m30998| Wed Nov 21 00:55:09.565 [Balancer] skew from remote server localhost:29000 found: 0
m30998| Wed Nov 21 00:55:09.565 [Balancer] total clock skew of 0ms for servers localhost:29000 is in 30000ms bounds.
m30998| Wed Nov 21 00:55:09.565 [LockPinger] creating distributed lock ping thread for localhost:29000 and process AMAZONA-JD1A6QA:30998:1353477309:41 (sleeping for 30000ms)
m30998| Wed Nov 21 00:55:09.565 [LockPinger] distributed lock pinger 'localhost:29000/AMAZONA-JD1A6QA:30998:1353477309:41' about to ping.
m30998| Wed Nov 21 00:55:09.565 [Balancer] about to acquire distributed lock 'balancer/AMAZONA-JD1A6QA:30998:1353477309:41:
m30998| { "state" : 1,
m30998| "who" : "AMAZONA-JD1A6QA:30998:1353477309:41:Balancer:18467",
m30998| "process" : "AMAZONA-JD1A6QA:30998:1353477309:41",
m30998| "when" : { "$date" : "Wed Nov 21 00:55:09 2012" },
m30998| "why" : "doing balance round",
m30998| "ts" : { "$oid" : "50ac6cbd7da0aefafa1c6ae0" } }
m30998| { "_id" : "balancer",
m30998| "state" : 0,
m30998| "ts" : { "$oid" : "50ac6cbdfaf2e30ed017368e" } }
m30998| Wed Nov 21 00:55:09.565 [LockPinger] cluster localhost:29000 pinged successfully at Wed Nov 21 00:55:09 2012 by distributed lock pinger 'localhost:29000/AMAZONA-JD1A6QA:30998:1353477309:41', sleeping for 30000ms
m30998| Wed Nov 21 00:55:09.565 [Balancer] distributed lock 'balancer/AMAZONA-JD1A6QA:30998:1353477309:41' acquired, ts : 50ac6cbd7da0aefafa1c6ae0
m30998| Wed Nov 21 00:55:09.565 [Balancer] *** start balancing round
m30998| Wed Nov 21 00:55:09.565 [Balancer] no collections to balance
m30998| Wed Nov 21 00:55:09.565 [Balancer] no need to move any chunk
m30998| Wed Nov 21 00:55:09.565 [Balancer] *** end of balancing round
m30998| Wed Nov 21 00:55:09.565 [Balancer] distributed lock 'balancer/AMAZONA-JD1A6QA:30998:1353477309:41' unlocked.
m30998| Wed Nov 21 00:55:10.064 [mongosMain] connection accepted from 127.0.0.1:57576 #1 (1 connection now open)
m30998| Wed Nov 21 00:55:10.064 [conn1] DBConfig unserialize: admin { _id: "admin", partitioned: false, primary: "config" }
ShardingTest undefined going to add shard : localhost:30000
m30998| Wed Nov 21 00:55:10.064 [conn1] found 0 dropped collections and 0 sharded collections for database admin
m30998| Wed Nov 21 00:55:10.064 [conn1] scoped connection to localhost:29000 not being returned to the pool
m29000| Wed Nov 21 00:55:10.064 [conn8] end connection 127.0.0.1:57578 (8 connections now open)
m30999| Wed Nov 21 00:55:10.064 [conn1] Request::process begin ns: admin.$cmd msg id: 0 op: 2004 attempt: 0
m30999| Wed Nov 21 00:55:10.064 [conn1] single query: admin.$cmd { addshard: "localhost:30000" } ntoreturn: -1 options : 0
m30999| Wed Nov 21 00:55:10.064 [conn1] creating new connection to:localhost:30000
m30999| Wed Nov 21 00:55:10.064 BackgroundJob starting: ConnectBG
m30999| Wed Nov 21 00:55:10.064 [conn1] connected connection!
m30000| Wed Nov 21 00:55:10.064 [initandlisten] connection accepted from 127.0.0.1:57581 #2 (2 connections now open)
m30999| Wed Nov 21 00:55:10.064 [conn1] going to add shard: { _id: "shard0000", host: "localhost:30000" }
m30999| Wed Nov 21 00:55:10.064 [conn1] Request::process end ns: admin.$cmd msg id: 0 op: 2004 attempt: 0 2ms
{ "shardAdded" : "shard0000", "ok" : 1 }
ShardingTest undefined going to add shard : localhost:30001
m30999| Wed Nov 21 00:55:10.064 [conn1] Request::process begin ns: admin.$cmd msg id: 1 op: 2004 attempt: 0
m30999| Wed Nov 21 00:55:10.064 [conn1] single query: admin.$cmd { addshard: "localhost:30001" } ntoreturn: -1 options : 0
m30999| Wed Nov 21 00:55:10.064 [conn1] creating new connection to:localhost:30001
m30999| Wed Nov 21 00:55:10.064 BackgroundJob starting: ConnectBG
m30999| Wed Nov 21 00:55:10.064 [conn1] connected connection!
m30001| Wed Nov 21 00:55:10.064 [initandlisten] connection accepted from 127.0.0.1:57582 #2 (2 connections now open)
m30999| Wed Nov 21 00:55:10.064 [conn1] going to add shard: { _id: "shard0001", host: "localhost:30001" }
m30999| Wed Nov 21 00:55:10.064 [conn1] Request::process end ns: admin.$cmd msg id: 1 op: 2004 attempt: 0 2ms
{ "shardAdded" : "shard0001", "ok" : 1 }
ShardingTest undefined going to add shard : localhost:30002
m30999| Wed Nov 21 00:55:10.064 [conn1] Request::process begin ns: admin.$cmd msg id: 2 op: 2004 attempt: 0
m30999| Wed Nov 21 00:55:10.064 [conn1] single query: admin.$cmd { addshard: "localhost:30002" } ntoreturn: -1 options : 0
m30999| Wed Nov 21 00:55:10.064 [conn1] creating new connection to:localhost:30002
m30999| Wed Nov 21 00:55:10.064 BackgroundJob starting: ConnectBG
m30999| Wed Nov 21 00:55:10.064 [conn1] connected connection!
m30002| Wed Nov 21 00:55:10.064 [initandlisten] connection accepted from 127.0.0.1:57583 #2 (2 connections now open)
m30999| Wed Nov 21 00:55:10.064 [conn1] going to add shard: { _id: "shard0002", host: "localhost:30002" }
m30999| Wed Nov 21 00:55:10.064 [conn1] Request::process end ns: admin.$cmd msg id: 2 op: 2004 attempt: 0 2ms
{ "shardAdded" : "shard0002", "ok" : 1 }
m30999| Wed Nov 21 00:55:10.064 [conn1] Request::process begin ns: config.settings msg id: 3 op: 2001 attempt: 0
m30999| Wed Nov 21 00:55:10.064 [conn1] write: config.settings
m30999| Wed Nov 21 00:55:10.064 [conn1] creating new connection to:localhost:30000
m30999| Wed Nov 21 00:55:10.064 BackgroundJob starting: ConnectBG
m30000| Wed Nov 21 00:55:10.064 [initandlisten] connection accepted from 127.0.0.1:57585 #3 (3 connections now open)
m30999| Wed Nov 21 00:55:10.064 [conn1] connected connection!
m30999| Wed Nov 21 00:55:10.064 [conn1] creating WriteBackListener for: localhost:30000 serverID: 50ac6cbdfaf2e30ed017368d
m30999| Wed Nov 21 00:55:10.064 [conn1] initializing shard connection to localhost:30000
m30999| Wed Nov 21 00:55:10.064 [conn1] initial sharding settings : { setShardVersion: "", init: true, configdb: "localhost:29000", serverID: ObjectId('50ac6cbdfaf2e30ed017368d'), authoritative: true }
m30999| Wed Nov 21 00:55:10.064 BackgroundJob starting: WriteBackListener-localhost:30000
m30999| Wed Nov 21 00:55:10.064 [conn1] initial sharding result : { initialized: true, ok: 1.0 }
m30999| Wed Nov 21 00:55:10.064 [conn1] creating new connection to:localhost:30001
m30999| Wed Nov 21 00:55:10.064 BackgroundJob starting: ConnectBG
m30999| Wed Nov 21 00:55:10.064 [conn1] connected connection!
m30999| Wed Nov 21 00:55:10.064 [conn1] creating WriteBackListener for: localhost:30001 serverID: 50ac6cbdfaf2e30ed017368d
m30001| Wed Nov 21 00:55:10.064 [initandlisten] connection accepted from 127.0.0.1:57586 #3 (3 connections now open)
m30999| Wed Nov 21 00:55:10.064 [conn1] initializing shard connection to localhost:30001
m30999| Wed Nov 21 00:55:10.064 [conn1] initial sharding settings : { setShardVersion: "", init: true, configdb: "localhost:29000", serverID: ObjectId('50ac6cbdfaf2e30ed017368d'), authoritative: true }
m30999| Wed Nov 21 00:55:10.064 BackgroundJob starting: WriteBackListener-localhost:30001
m30999| Wed Nov 21 00:55:10.064 [conn1] initial sharding result : { initialized: true, ok: 1.0 }
m30999| Wed Nov 21 00:55:10.064 [conn1] creating new connection to:localhost:30002
m30999| Wed Nov 21 00:55:10.064 BackgroundJob starting: ConnectBG
m30002| Wed Nov 21 00:55:10.064 [initandlisten] connection accepted from 127.0.0.1:57587 #3 (3 connections now open)
m30999| Wed Nov 21 00:55:10.064 [conn1] connected connection!
m30999| Wed Nov 21 00:55:10.064 [conn1] creating WriteBackListener for: localhost:30002 serverID: 50ac6cbdfaf2e30ed017368d
m30999| Wed Nov 21 00:55:10.064 [conn1] initializing shard connection to localhost:30002
m30999| Wed Nov 21 00:55:10.064 [conn1] initial sharding settings : { setShardVersion: "", init: true, configdb: "localhost:29000", serverID: ObjectId('50ac6cbdfaf2e30ed017368d'), authoritative: true }
m30999| Wed Nov 21 00:55:10.064 BackgroundJob starting: WriteBackListener-localhost:30002
m30999| Wed Nov 21 00:55:10.064 [conn1] initial sharding result : { initialized: true, ok: 1.0 }
m30999| Wed Nov 21 00:55:10.064 [conn1] creating new connection to:localhost:29000
m30999| Wed Nov 21 00:55:10.064 BackgroundJob starting: ConnectBG
m29000| Wed Nov 21 00:55:10.064 [initandlisten] connection accepted from 127.0.0.1:57588 #11 (9 connections now open)
m30999| Wed Nov 21 00:55:10.064 [conn1] connected connection!
m30999| Wed Nov 21 00:55:10.079 [conn1] creating WriteBackListener for: localhost:29000 serverID: 50ac6cbdfaf2e30ed017368d
Waiting for active hosts... m30999| Wed Nov 21 00:55:10.079 [conn1] initializing shard connection to localhost:29000
m30999| Wed Nov 21 00:55:10.079 [conn1] initial sharding settings : { setShardVersion: "", init: true, configdb: "localhost:29000", serverID: ObjectId('50ac6cbdfaf2e30ed017368d'), authoritative: true }
m30999| Wed Nov 21 00:55:10.079 BackgroundJob starting: WriteBackListener-localhost:29000
m30999| Wed Nov 21 00:55:10.079 [WriteBackListener-localhost:29000] localhost:29000 is not a shard node
m30999| Wed Nov 21 00:55:10.079 [conn1] initial sharding result : { initialized: true, ok: 1.0 }
m30999| Wed Nov 21 00:55:10.079 [conn1] Request::process end ns: config.settings msg id: 3 op: 2001 attempt: 0 4ms
m30999| Wed Nov 21 00:55:10.079 [conn1] Request::process begin ns: config.mongos msg id: 4 op: 2004 attempt: 0
m30999| Wed Nov 21 00:55:10.079 [conn1] shard query: config.mongos {}
m30999| Wed Nov 21 00:55:10.079 [conn1] creating pcursor over QSpec { ns: "config.mongos", n2skip: 0, n2return: 0, options: 0, query: {}, fields: {} } and CInfo { v_ns: "", filter: {} }
m30999| Wed Nov 21 00:55:10.079 [conn1] initializing over 1 shards required by [unsharded @ config:localhost:29000]
m30999| Wed Nov 21 00:55:10.079 [conn1] initializing on shard config:localhost:29000, current connection state is { state: {}, retryNext: false, init: false, finish: false, errored: false }
m30999| Wed Nov 21 00:55:10.079 [conn1] initialized query (lazily) on shard config:localhost:29000, current connection state is { state: { conn: "localhost:29000", vinfo: "config:localhost:29000", cursor: "(empty)", count: 0, done: false }, retryNext: false, init: true, finish: false, errored: false }
m30999| Wed Nov 21 00:55:10.079 [conn1] finishing over 1 shards
m30999| Wed Nov 21 00:55:10.079 [conn1] finishing on shard config:localhost:29000, current connection state is { state: { conn: "localhost:29000", vinfo: "config:localhost:29000", cursor: "(empty)", count: 0, done: false }, retryNext: false, init: true, finish: false, errored: false }
m30999| Wed Nov 21 00:55:10.079 [conn1] finished on shard config:localhost:29000, current connection state is { state: { conn: "(done)", vinfo: "config:localhost:29000", cursor: { _id: "AMAZONA-JD1A6QA:30999", ping: new Date(1353477309175), up: 0, waiting: true }, count: 0, done: false }, retryNext: false, init: true, finish: true, errored: false }
m30999| Wed Nov 21 00:55:10.079 [conn1] Request::process end ns: config.mongos msg id: 4 op: 2004 attempt: 0 0ms
Waiting for the balancer lock...
m30999| Wed Nov 21 00:55:10.142 [conn1] Request::process begin ns: config.locks msg id: 5 op: 2004 attempt: 0
m30999| Wed Nov 21 00:55:10.142 [conn1] shard query: config.locks { _id: "balancer" }
m30999| Wed Nov 21 00:55:10.142 [conn1] creating pcursor over QSpec { ns: "config.locks", n2skip: 0, n2return: -1, options: 0, query: { _id: "balancer" }, fields: {} } and CInfo { v_ns: "", filter: {} }
m30999| Wed Nov 21 00:55:10.142 [conn1] initializing over 1 shards required by [unsharded @ config:localhost:29000]
m30999| Wed Nov 21 00:55:10.142 [conn1] initializing on shard config:localhost:29000, current connection state is { state: {}, retryNext: false, init: false, finish: false, errored: false }
m30999| Wed Nov 21 00:55:10.142 [conn1] initialized query (lazily) on shard config:localhost:29000, current connection state is { state: { conn: "localhost:29000", vinfo: "config:localhost:29000", cursor: "(empty)", count: 0, done: false }, retryNext: false, init: true, finish: false, errored: false }
m30999| Wed Nov 21 00:55:10.142 [conn1] finishing over 1 shards
m30999| Wed Nov 21 00:55:10.142 [conn1] finishing on shard config:localhost:29000, current connection state is { state: { conn: "localhost:29000", vinfo: "config:localhost:29000", cursor: "(empty)", count: 0, done: false }, retryNext: false, init: true, finish: false, errored: false }
m30999| Wed Nov 21 00:55:10.142 [conn1] finished on shard config:localhost:29000, current connection state is { state: { conn: "(done)", vinfo: "config:localhost:29000", cursor: { _id: "balancer", process: "AMAZONA-JD1A6QA:30998:1353477309:41", state: 0, ts: ObjectId('50ac6cbd7da0aefafa1c6ae0'), when: new Date(1353477309565), who: "AMAZONA-JD1A6QA:30998:1353477309:41:Balancer:18467", why: "doing balance round" }, count: 0, done: false }, retryNext: false, init: true, finish: true, errored: false }
Waiting again for active hosts after balancer is off...
m30999| Wed Nov 21 00:55:10.142 [conn1] Request::process end ns: config.locks msg id: 5 op: 2004 attempt: 0 0ms
m30999| Wed Nov 21 00:55:10.142 [conn1] Request::process begin ns: config.shards msg id: 6 op: 2004 attempt: 0
m30999| Wed Nov 21 00:55:10.142 [conn1] shard query: config.shards {}
m30999| Wed Nov 21 00:55:10.142 [conn1] creating pcursor over QSpec { ns: "config.shards", n2skip: 0, n2return: 0, options: 0, query: {}, fields: {} } and CInfo { v_ns: "", filter: {} }
m30999| Wed Nov 21 00:55:10.142 [conn1] initializing over 1 shards required by [unsharded @ config:localhost:29000]
m30999| Wed Nov 21 00:55:10.142 [conn1] initializing on shard config:localhost:29000, current connection state is { state: {}, retryNext: false, init: false, finish: false, errored: false }
m30999| Wed Nov 21 00:55:10.142 [conn1] initialized query (lazily) on shard config:localhost:29000, current connection state is { state: { conn: "localhost:29000", vinfo: "config:localhost:29000", cursor: "(empty)", count: 0, done: false }, retryNext: false, init: true, finish: false, errored: false }
m30999| Wed Nov 21 00:55:10.142 [conn1] finishing over 1 shards
m30999| Wed Nov 21 00:55:10.142 [conn1] finishing on shard config:localhost:29000, current connection state is { state: { conn: "localhost:29000", vinfo: "config:localhost:29000", cursor: "(empty)", count: 0, done: false }, retryNext: false, init: true, finish: false, errored: false }
m30999| Wed Nov 21 00:55:10.142 [conn1] finished on shard config:localhost:29000, current connection state is { state: { conn: "(done)", vinfo: "config:localhost:29000", cursor: { _id: "shard0000", host: "localhost:30000" }, count: 0, done: false }, retryNext: false, init: true, finish: true, errored: false }
m30999| Wed Nov 21 00:55:10.142 [conn1] Request::process end ns: config.shards msg id: 6 op: 2004 attempt: 0 0ms
----
Enabling sharding...
----
m30999| Wed Nov 21 00:55:10.142 [conn1] Request::process begin ns: admin.$cmd msg id: 7 op: 2004 attempt: 0
m30999| Wed Nov 21 00:55:10.142 [conn1] single query: admin.$cmd { enableSharding: "gle_error_message" } ntoreturn: -1 options : 0
m30999| Wed Nov 21 00:55:10.142 [conn1] couldn't find database [gle_error_message] in config db
m30999| Wed Nov 21 00:55:10.142 [conn1] creating new connection to:localhost:30000
m30999| Wed Nov 21 00:55:10.142 BackgroundJob starting: ConnectBG
m30999| Wed Nov 21 00:55:10.142 [conn1] connected connection!
m30000| Wed Nov 21 00:55:10.142 [initandlisten] connection accepted from 127.0.0.1:57590 #4 (4 connections now open)
m30999| Wed Nov 21 00:55:10.142 [conn1] creating new connection to:localhost:30001
m30999| Wed Nov 21 00:55:10.142 BackgroundJob starting: ConnectBG
m30999| Wed Nov 21 00:55:10.142 [conn1] connected connection!
m30001| Wed Nov 21 00:55:10.142 [initandlisten] connection accepted from 127.0.0.1:57591 #4 (4 connections now open)
m30999| Wed Nov 21 00:55:10.142 [conn1] creating new connection to:localhost:30002
m30999| Wed Nov 21 00:55:10.142 BackgroundJob starting: ConnectBG
m30999| Wed Nov 21 00:55:10.142 [conn1] connected connection!
m30002| Wed Nov 21 00:55:10.142 [initandlisten] connection accepted from 127.0.0.1:57592 #4 (4 connections now open)
m30999| Wed Nov 21 00:55:10.142 [conn1] best shard for new allocation is shard: shard0000:localhost:30000 mapped: 0 writeLock: 0
m30999| Wed Nov 21 00:55:10.142 [conn1] put [gle_error_message] on: shard0000:localhost:30000
m30999| Wed Nov 21 00:55:10.142 [conn1] enabling sharding on: gle_error_message
m30999| Wed Nov 21 00:55:10.142 [conn1] Request::process end ns: admin.$cmd msg id: 7 op: 2004 attempt: 0 4ms
{ "ok" : 1 }
m30999| Wed Nov 21 00:55:10.142 [conn1] Request::process begin ns: admin.$cmd msg id: 8 op: 2004 attempt: 0
m30999| Wed Nov 21 00:55:10.142 [conn1] single query: admin.$cmd { movePrimary: "gle_error_message", to: "shard0000" } ntoreturn: -1 options : 0
m30999| Wed Nov 21 00:55:10.142 [conn1] DBConfig unserialize: gle_error_message { _id: "gle_error_message", partitioned: true, primary: "shard0000" }
m30999| Wed Nov 21 00:55:10.142 [conn1] found 0 dropped collections and 0 sharded collections for database gle_error_message
m30999| Wed Nov 21 00:55:10.142 [conn1] Request::process end ns: admin.$cmd msg id: 8 op: 2004 attempt: 0 1ms
{ "ok" : 0, "errmsg" : "it is already the primary" }
m30999| Wed Nov 21 00:55:10.142 [conn1] DBConfig unserialize: admin { _id: "admin", partitioned: false, primary: "config" }
m30999| Wed Nov 21 00:55:10.142 [conn1] found 0 dropped collections and 0 sharded collections for database admin
m30999| Wed Nov 21 00:55:10.142 [conn1] Request::process begin ns: admin.$cmd msg id: 9 op: 2004 attempt: 0
m30999| Wed Nov 21 00:55:10.142 [conn1] single query: admin.$cmd { shardCollection: "gle_error_message.coll", key: { _id: 1.0 } } ntoreturn: -1 options : 0
m30000| Wed Nov 21 00:55:10.142 [FileAllocator] allocating new datafile /data/db/test0\gle_error_message.ns, filling with zeroes...
m30000| Wed Nov 21 00:55:10.142 [FileAllocator] creating directory /data/db/test0\_tmp
m30000| Wed Nov 21 00:55:10.204 [FileAllocator] done allocating datafile /data/db/test0\gle_error_message.ns, size: 16MB, took 0.047 secs
m30000| Wed Nov 21 00:55:10.204 [FileAllocator] allocating new datafile /data/db/test0\gle_error_message.0, filling with zeroes...
m30000| Wed Nov 21 00:55:10.391 [FileAllocator] done allocating datafile /data/db/test0\gle_error_message.0, size: 64MB, took 0.191 secs
m30000| Wed Nov 21 00:55:10.391 [FileAllocator] allocating new datafile /data/db/test0\gle_error_message.1, filling with zeroes...
m30000| Wed Nov 21 00:55:10.391 [conn4] build index gle_error_message.coll { _id: 1 }
m30000| Wed Nov 21 00:55:10.391 [conn4] build index done. scanned 0 total records. 0.001 secs
m30000| Wed Nov 21 00:55:10.391 [conn4] info: creating collection gle_error_message.coll on add index
m30000| Wed Nov 21 00:55:10.391 [conn4] insert gle_error_message.system.indexes keyUpdates:0 locks(micros) w:243814 243ms
m30999| Wed Nov 21 00:55:10.391 [conn1] CMD: shardcollection: { shardCollection: "gle_error_message.coll", key: { _id: 1.0 } }
m30999| Wed Nov 21 00:55:10.391 [conn1] enable sharding on: gle_error_message.coll with shard key: { _id: 1.0 }
m30999| Wed Nov 21 00:55:10.391 [conn1] going to create 1 chunk(s) for: gle_error_message.coll using new epoch 50ac6cbefaf2e30ed017368f
m30999| Wed Nov 21 00:55:10.391 [conn1] major version query from 0|0||50ac6cbefaf2e30ed017368f and over 0 shards is { ns: "gle_error_message.coll", $or: [ { lastmod: { $gte: Timestamp 0|0 } } ] }
m30999| Wed Nov 21 00:55:10.391 [conn1] found 1 new chunks for collection gle_error_message.coll (tracking 1), new version is 0000000001DFAA00
m30999| Wed Nov 21 00:55:10.391 [conn1] loaded 1 chunks into new chunk manager for gle_error_message.coll with version 1|0||50ac6cbefaf2e30ed017368f
m30999| Wed Nov 21 00:55:10.391 [conn1] ChunkManager: time to load chunks for gle_error_message.coll: 0ms sequenceNumber: 2 version: 1|0||50ac6cbefaf2e30ed017368f based on: (empty)
m29000| Wed Nov 21 00:55:10.391 [conn4] build index config.collections { _id: 1 }
m29000| Wed Nov 21 00:55:10.391 [conn4] build index done. scanned 0 total records. 0 secs
m30999| Wed Nov 21 00:55:10.391 [conn1] have to set shard version for conn: localhost:30000 ns:gle_error_message.coll my last seq: 0 current: 2 version: 1|0||50ac6cbefaf2e30ed017368f manager: 0000000001DFA8F0
m30999| Wed Nov 21 00:55:10.391 [conn1] setShardVersion shard0000 localhost:30000 gle_error_message.coll { setShardVersion: "gle_error_message.coll", configdb: "localhost:29000", version: Timestamp 1000|0, versionEpoch: ObjectId('50ac6cbefaf2e30ed017368f'), serverID: ObjectId('50ac6cbdfaf2e30ed017368d'), shard: "shard0000", shardHost: "localhost:30000" } 0000000001DF6160 2
m30999| Wed Nov 21 00:55:10.391 [conn1] setShardVersion failed!
m30999| { oldVersion: Timestamp 0|0, oldVersionEpoch: ObjectId('000000000000000000000000'), ns: "gle_error_message.coll", need_authoritative: true, errmsg: "first time for collection 'gle_error_message.coll'", ok: 0.0 }
m30999| Wed Nov 21 00:55:10.391 [conn1] have to set shard version for conn: localhost:30000 ns:gle_error_message.coll my last seq: 0 current: 2 version: 1|0||50ac6cbefaf2e30ed017368f manager: 0000000001DFA8F0
m30999| Wed Nov 21 00:55:10.391 [conn1] setShardVersion shard0000 localhost:30000 gle_error_message.coll { setShardVersion: "gle_error_message.coll", configdb: "localhost:29000", version: Timestamp 1000|0, versionEpoch: ObjectId('50ac6cbefaf2e30ed017368f'), serverID: ObjectId('50ac6cbdfaf2e30ed017368d'), authoritative: true, shard: "shard0000", shardHost: "localhost:30000" } 0000000001DF6160 2
m30000| Wed Nov 21 00:55:10.391 [conn3] no current chunk manager found for this shard, will initialize
m29000| Wed Nov 21 00:55:10.391 [initandlisten] connection accepted from 127.0.0.1:57593 #12 (10 connections now open)
m30999| Wed Nov 21 00:55:10.407 [conn1] setShardVersion success: { oldVersion: Timestamp 0|0, oldVersionEpoch: ObjectId('000000000000000000000000'), ok: 1.0 }
m30999| Wed Nov 21 00:55:10.407 [conn1] resetting shard version of gle_error_message.coll on localhost:30001, version is zero
m30999| Wed Nov 21 00:55:10.407 [conn1] have to set shard version for conn: localhost:30001 ns:gle_error_message.coll my last seq: 0 current: 2 version: 0|0||000000000000000000000000 manager: 0000000001DFA8F0
m30999| Wed Nov 21 00:55:10.407 [conn1] setShardVersion shard0001 localhost:30001 gle_error_message.coll { setShardVersion: "gle_error_message.coll", configdb: "localhost:29000", version: Timestamp 0|0, versionEpoch: ObjectId('000000000000000000000000'), serverID: ObjectId('50ac6cbdfaf2e30ed017368d'), shard: "shard0001", shardHost: "localhost:30001" } 0000000001DF6A60 2
m30999| Wed Nov 21 00:55:10.407 [conn1] setShardVersion success: { oldVersion: Timestamp 0|0, oldVersionEpoch: ObjectId('000000000000000000000000'), ok: 1.0 }
m30999| Wed Nov 21 00:55:10.407 [conn1] resetting shard version of gle_error_message.coll on localhost:30002, version is zero
m30999| Wed Nov 21 00:55:10.407 [conn1] have to set shard version for conn: localhost:30002 ns:gle_error_message.coll my last seq: 0 current: 2 version: 0|0||000000000000000000000000 manager: 0000000001DFA8F0
m30999| Wed Nov 21 00:55:10.407 [conn1] setShardVersion shard0002 localhost:30002 gle_error_message.coll { setShardVersion: "gle_error_message.coll", configdb: "localhost:29000", version: Timestamp 0|0, versionEpoch: ObjectId('000000000000000000000000'), serverID: ObjectId('50ac6cbdfaf2e30ed017368d'), shard: "shard0002", shardHost: "localhost:30002" } 0000000001DF9840 2
m30999| Wed Nov 21 00:55:10.407 [conn1] setShardVersion success: { oldVersion: Timestamp 0|0, oldVersionEpoch: ObjectId('000000000000000000000000'), ok: 1.0 }
m30999| Wed Nov 21 00:55:10.407 [conn1] Request::process end ns: admin.$cmd msg id: 9 op: 2004 attempt: 0 252ms
{ "collectionsharded" : "gle_error_message.coll", "ok" : 1 }
m30999| Wed Nov 21 00:55:10.407 [conn1] Request::process begin ns: admin.$cmd msg id: 10 op: 2004 attempt: 0
m30999| Wed Nov 21 00:55:10.407 [conn1] single query: admin.$cmd { split: "gle_error_message.coll", middle: { _id: 0.0 } } ntoreturn: -1 options : 0
m30999| Wed Nov 21 00:55:10.407 [conn1] splitting: gle_error_message.coll shard: ns:gle_error_message.collshard: shard0000:localhost:30000lastmod: 1|0||000000000000000000000000min: { _id: MinKey }max: { _id: MaxKey }
m29000| Wed Nov 21 00:55:10.407 [initandlisten] connection accepted from 127.0.0.1:57594 #13 (11 connections now open)
m30000| Wed Nov 21 00:55:10.407 [conn4] received splitChunk request: { splitChunk: "gle_error_message.coll", keyPattern: { _id: 1.0 }, min: { _id: MinKey }, max: { _id: MaxKey }, from: "shard0000", splitKeys: [ { _id: 0.0 } ], shardId: "gle_error_message.coll-_id_MinKey", configdb: "localhost:29000" }
m30000| Wed Nov 21 00:55:10.407 [conn4] created new distributed lock for gle_error_message.coll on localhost:29000 ( lock timeout : 900000, ping interval : 30000, process : 0 )
m30000| Wed Nov 21 00:55:10.407 [LockPinger] creating distributed lock ping thread for localhost:29000 and process AMAZONA-JD1A6QA:30000:1353477310:41 (sleeping for 30000ms)
m30000| Wed Nov 21 00:55:10.407 [conn4] distributed lock 'gle_error_message.coll/AMAZONA-JD1A6QA:30000:1353477310:41' acquired, ts : 50ac6cbecd24b37a7591f578
m30000| Wed Nov 21 00:55:10.407 [conn4] splitChunk accepted at version 1|0||50ac6cbefaf2e30ed017368f
m30000| Wed Nov 21 00:55:10.407 [conn4] about to log metadata event: { _id: "AMAZONA-JD1A6QA-2012-11-21T05:55:10-0", server: "AMAZONA-JD1A6QA", clientAddr: "127.0.0.1:57590", time: new Date(1353477310407), what: "split", ns: "gle_error_message.coll", details: { before: { min: { _id: MinKey }, max: { _id: MaxKey }, lastmod: Timestamp 1000|0, lastmodEpoch: ObjectId('000000000000000000000000') }, left: { min: { _id: MinKey }, max: { _id: 0.0 }, lastmod: Timestamp 1000|1, lastmodEpoch: ObjectId('50ac6cbefaf2e30ed017368f') }, right: { min: { _id: 0.0 }, max: { _id: MaxKey }, lastmod: Timestamp 1000|2, lastmodEpoch: ObjectId('50ac6cbefaf2e30ed017368f') } } }
m29000| Wed Nov 21 00:55:10.407 [conn12] build index config.changelog { _id: 1 }
m29000| Wed Nov 21 00:55:10.407 [conn12] build index done. scanned 0 total records. 0 secs
m30000| Wed Nov 21 00:55:10.407 [conn4] distributed lock 'gle_error_message.coll/AMAZONA-JD1A6QA:30000:1353477310:41' unlocked.
m30999| Wed Nov 21 00:55:10.407 [conn1] loading chunk manager for collection gle_error_message.coll using old chunk manager w/ version 1|0||50ac6cbefaf2e30ed017368f and 1 chunks
m30999| Wed Nov 21 00:55:10.407 [conn1] major version query from 1|0||50ac6cbefaf2e30ed017368f and over 1 shards is { ns: "gle_error_message.coll", $or: [ { lastmod: { $gte: Timestamp 1000|0 } }, { shard: "shard0000", lastmod: { $gt: Timestamp 1000|0 } } ] }
m30999| Wed Nov 21 00:55:10.407 [conn1] found 2 new chunks for collection gle_error_message.coll (tracking 2), new version is 0000000001DFF8D0
m30999| Wed Nov 21 00:55:10.407 [conn1] loaded 2 chunks into new chunk manager for gle_error_message.coll with version 1|2||50ac6cbefaf2e30ed017368f
m30999| Wed Nov 21 00:55:10.407 [conn1] ChunkManager: time to load chunks for gle_error_message.coll: 0ms sequenceNumber: 3 version: 1|2||50ac6cbefaf2e30ed017368f based on: 1|0||50ac6cbefaf2e30ed017368f
m30999| Wed Nov 21 00:55:10.407 [conn1] Request::process end ns: admin.$cmd msg id: 10 op: 2004 attempt: 0 9ms
{ "ok" : 1 }
m30999| Wed Nov 21 00:55:10.407 [conn1] Request::process begin ns: admin.$cmd msg id: 11 op: 2004 attempt: 0
m30999| Wed Nov 21 00:55:10.407 [conn1] single query: admin.$cmd { moveChunk: "gle_error_message.coll", find: { _id: 0.0 }, to: "shard0001" } ntoreturn: -1 options : 0
m30999| Wed Nov 21 00:55:10.407 [conn1] CMD: movechunk: { moveChunk: "gle_error_message.coll", find: { _id: 0.0 }, to: "shard0001" }
m30999| Wed Nov 21 00:55:10.407 [conn1] moving chunk ns: gle_error_message.coll moving ( ns:gle_error_message.collshard: shard0000:localhost:30000lastmod: 1|2||000000000000000000000000min: { _id: 0.0 }max: { _id: MaxKey }) shard0000:localhost:30000 -> shard0001:localhost:30001
m30000| Wed Nov 21 00:55:10.407 [conn4] received moveChunk request: { moveChunk: "gle_error_message.coll", from: "localhost:30000", to: "localhost:30001", fromShard: "shard0000", toShard: "shard0001", min: { _id: 0.0 }, max: { _id: MaxKey }, maxChunkSizeBytes: 52428800, shardId: "gle_error_message.coll-_id_0.0", configdb: "localhost:29000", secondaryThrottle: false }
m30000| Wed Nov 21 00:55:10.407 [conn4] created new distributed lock for gle_error_message.coll on localhost:29000 ( lock timeout : 900000, ping interval : 30000, process : 0 )
m30000| Wed Nov 21 00:55:10.407 [conn4] distributed lock 'gle_error_message.coll/AMAZONA-JD1A6QA:30000:1353477310:41' acquired, ts : 50ac6cbecd24b37a7591f579
m30000| Wed Nov 21 00:55:10.407 [conn4] about to log metadata event: { _id: "AMAZONA-JD1A6QA-2012-11-21T05:55:10-1", server: "AMAZONA-JD1A6QA", clientAddr: "127.0.0.1:57590", time: new Date(1353477310407), what: "moveChunk.start", ns: "gle_error_message.coll", details: { min: { _id: 0.0 }, max: { _id: MaxKey }, from: "shard0000", to: "shard0001" } }
m30000| Wed Nov 21 00:55:10.407 [conn4] moveChunk request accepted at version 1|2||50ac6cbefaf2e30ed017368f
m30000| Wed Nov 21 00:55:10.407 [conn4] moveChunk number of documents: 0
m30001| Wed Nov 21 00:55:10.407 [initandlisten] connection accepted from 127.0.0.1:57595 #5 (5 connections now open)
m30000| Wed Nov 21 00:55:10.407 [initandlisten] connection accepted from 127.0.0.1:57596 #5 (5 connections now open)
m30000| Wed Nov 21 00:55:10.423 [conn4] moveChunk data transfer progress: { active: true, ns: "gle_error_message.coll", from: "localhost:30000", min: { _id: 0.0 }, max: { _id: MaxKey }, shardKeyPattern: { _id: 1.0 }, state: "ready", counts: { cloned: 0, clonedBytes: 0, catchup: 0, steady: 0 }, ok: 1.0 } my mem used: 0
m30001| Wed Nov 21 00:55:10.423 [FileAllocator] allocating new datafile /data/db/test1\gle_error_message.ns, filling with zeroes...
m30001| Wed Nov 21 00:55:10.423 [FileAllocator] creating directory /data/db/test1\_tmp
m30000| Wed Nov 21 00:55:10.438 [conn4] moveChunk data transfer progress: { active: true, ns: "gle_error_message.coll", from: "localhost:30000", min: { _id: 0.0 }, max: { _id: MaxKey }, shardKeyPattern: { _id: 1.0 }, state: "ready", counts: { cloned: 0, clonedBytes: 0, catchup: 0, steady: 0 }, ok: 1.0 } my mem used: 0
m30000| Wed Nov 21 00:55:10.454 [conn4] moveChunk data transfer progress: { active: true, ns: "gle_error_message.coll", from: "localhost:30000", min: { _id: 0.0 }, max: { _id: MaxKey }, shardKeyPattern: { _id: 1.0 }, state: "ready", counts: { cloned: 0, clonedBytes: 0, catchup: 0, steady: 0 }, ok: 1.0 } my mem used: 0
m30000| Wed Nov 21 00:55:10.469 [conn4] moveChunk data transfer progress: { active: true, ns: "gle_error_message.coll", from: "localhost:30000", min: { _id: 0.0 }, max: { _id: MaxKey }, shardKeyPattern: { _id: 1.0 }, state: "ready", counts: { cloned: 0, clonedBytes: 0, catchup: 0, steady: 0 }, ok: 1.0 } my mem used: 0
m30001| Wed Nov 21 00:55:10.469 [FileAllocator] done allocating datafile /data/db/test1\gle_error_message.ns, size: 16MB, took 0.053 secs
m30001| Wed Nov 21 00:55:10.469 [FileAllocator] allocating new datafile /data/db/test1\gle_error_message.0, filling with zeroes...
m30000| Wed Nov 21 00:55:10.501 [conn4] moveChunk data transfer progress: { active: true, ns: "gle_error_message.coll", from: "localhost:30000", min: { _id: 0.0 }, max: { _id: MaxKey }, shardKeyPattern: { _id: 1.0 }, state: "ready", counts: { cloned: 0, clonedBytes: 0, catchup: 0, steady: 0 }, ok: 1.0 } my mem used: 0
m30000| Wed Nov 21 00:55:10.547 [conn4] moveChunk data transfer progress: { active: true, ns: "gle_error_message.coll", from: "localhost:30000", min: { _id: 0.0 }, max: { _id: MaxKey }, shardKeyPattern: { _id: 1.0 }, state: "ready", counts: { cloned: 0, clonedBytes: 0, catchup: 0, steady: 0 }, ok: 1.0 } my mem used: 0
m30000| Wed Nov 21 00:55:10.625 [conn4] moveChunk data transfer progress: { active: true, ns: "gle_error_message.coll", from: "localhost:30000", min: { _id: 0.0 }, max: { _id: MaxKey }, shardKeyPattern: { _id: 1.0 }, state: "ready", counts: { cloned: 0, clonedBytes: 0, catchup: 0, steady: 0 }, ok: 1.0 } my mem used: 0
m30001| Wed Nov 21 00:55:10.688 [FileAllocator] done allocating datafile /data/db/test1\gle_error_message.0, size: 64MB, took 0.212 secs
m30001| Wed Nov 21 00:55:10.688 [FileAllocator] allocating new datafile /data/db/test1\gle_error_message.1, filling with zeroes...
m30001| Wed Nov 21 00:55:10.688 [migrateThread] build index gle_error_message.coll { _id: 1 }
m30001| Wed Nov 21 00:55:10.688 [migrateThread] build index done. scanned 0 total records. 0.001 secs
m30001| Wed Nov 21 00:55:10.688 [migrateThread] info: creating collection gle_error_message.coll on add index
m30001| Wed Nov 21 00:55:10.688 [migrateThread] Waiting for replication to catch up before entering critical section
m30001| Wed Nov 21 00:55:10.688 [migrateThread] migrate commit succeeded flushing to secondaries for 'gle_error_message.coll' { _id: 0.0 } -> { _id: MaxKey }
m30001| Wed Nov 21 00:55:10.688 [migrateThread] migrate commit flushed to journal for 'gle_error_message.coll' { _id: 0.0 } -> { _id: MaxKey }
m30000| Wed Nov 21 00:55:10.766 [conn4] moveChunk data transfer progress: { active: true, ns: "gle_error_message.coll", from: "localhost:30000", min: { _id: 0.0 }, max: { _id: MaxKey }, shardKeyPattern: { _id: 1.0 }, state: "steady", counts: { cloned: 0, clonedBytes: 0, catchup: 0, steady: 0 }, ok: 1.0 } my mem used: 0
m30000| Wed Nov 21 00:55:10.766 [conn4] moveChunk setting version to: 2|0||50ac6cbefaf2e30ed017368f
m30001| Wed Nov 21 00:55:10.766 [initandlisten] connection accepted from 127.0.0.1:57598 #6 (6 connections now open)
m30001| Wed Nov 21 00:55:10.766 [conn6] Waiting for commit to finish
m30001| Wed Nov 21 00:55:10.781 [conn6] Waiting for commit to finish
m30001| Wed Nov 21 00:55:10.781 [migrateThread] migrate commit succeeded flushing to secondaries for 'gle_error_message.coll' { _id: 0.0 } -> { _id: MaxKey }
m30001| Wed Nov 21 00:55:10.781 [migrateThread] migrate commit flushed to journal for 'gle_error_message.coll' { _id: 0.0 } -> { _id: MaxKey }
m30001| Wed Nov 21 00:55:10.781 [migrateThread] about to log metadata event: { _id: "AMAZONA-JD1A6QA-2012-11-21T05:55:10-0", server: "AMAZONA-JD1A6QA", clientAddr: ":27017", time: new Date(1353477310781), what: "moveChunk.to", ns: "gle_error_message.coll", details: { min: { _id: 0.0 }, max: { _id: MaxKey }, step1 of 5: 272, step2 of 5: 5, step3 of 5: 0, step4 of 5: 0, step5 of 5: 80 } }
m29000| Wed Nov 21 00:55:10.781 [initandlisten] connection accepted from 127.0.0.1:57600 #14 (12 connections now open)
m30000| Wed Nov 21 00:55:10.797 [conn4] moveChunk migrate commit accepted by TO-shard: { active: false, ns: "gle_error_message.coll", from: "localhost:30000", min: { _id: 0.0 }, max: { _id: MaxKey }, shardKeyPattern: { _id: 1.0 }, state: "done", counts: { cloned: 0, clonedBytes: 0, catchup: 0, steady: 0 }, ok: 1.0 }
m30000| Wed Nov 21 00:55:10.797 [conn4] moveChunk updating self version to: 2|1||50ac6cbefaf2e30ed017368f through { _id: MinKey } -> { _id: 0.0 } for collection 'gle_error_message.coll'
m29000| Wed Nov 21 00:55:10.797 [initandlisten] connection accepted from 127.0.0.1:57601 #15 (13 connections now open)
m30000| Wed Nov 21 00:55:10.797 [conn4] about to log metadata event: { _id: "AMAZONA-JD1A6QA-2012-11-21T05:55:10-2", server: "AMAZONA-JD1A6QA", clientAddr: "127.0.0.1:57590", time: new Date(1353477310797), what: "moveChunk.commit", ns: "gle_error_message.coll", details: { min: { _id: 0.0 }, max: { _id: MaxKey }, from: "shard0000", to: "shard0001" } }
m30000| Wed Nov 21 00:55:10.797 [conn4] MigrateFromStatus::done About to acquire global write lock to exit critical section
m30000| Wed Nov 21 00:55:10.797 [conn4] MigrateFromStatus::done Global lock acquired
m30000| Wed Nov 21 00:55:10.797 [conn4] doing delete inline
m30000| Wed Nov 21 00:55:10.797 [conn4] moveChunk starting delete for: gle_error_message.coll from { _id: 0.0 } -> { _id: MaxKey }
m30000| Wed Nov 21 00:55:10.797 [conn4] moveChunk deleted 0 documents for gle_error_message.coll from { _id: 0.0 } -> { _id: MaxKey }
m30000| Wed Nov 21 00:55:10.797 [conn4] MigrateFromStatus::done About to acquire global write lock to exit critical section
m30000| Wed Nov 21 00:55:10.797 [conn4] MigrateFromStatus::done Global lock acquired
m30000| Wed Nov 21 00:55:10.797 [conn4] distributed lock 'gle_error_message.coll/AMAZONA-JD1A6QA:30000:1353477310:41' unlocked.
m30000| Wed Nov 21 00:55:10.797 [conn4] about to log metadata event: { _id: "AMAZONA-JD1A6QA-2012-11-21T05:55:10-3", server: "AMAZONA-JD1A6QA", clientAddr: "127.0.0.1:57590", time: new Date(1353477310797), what: "moveChunk.from", ns: "gle_error_message.coll", details: { min: { _id: 0.0 }, max: { _id: MaxKey }, step1 of 6: 0, step2 of 6: 1, step3 of 6: 1, step4 of 6: 344, step5 of 6: 32, step6 of 6: 0 } }
{ "millis" : 382, "ok" : 1 }
m30000| Wed Nov 21 00:55:10.797 [conn4] command admin.$cmd command: { moveChunk: "gle_error_message.coll", from: "localhost:30000", to: "localhost:30001", fromShard: "shard0000", toShard: "shard0001", min: { _id: 0.0 }, max: { _id: MaxKey }, maxChunkSizeBytes: 52428800, shardId: "gle_error_message.coll-_id_0.0", configdb: "localhost:29000", secondaryThrottle: false } ntoreturn:1 keyUpdates:0 locks(micros) W:20 r:85 w:45 reslen:37 380ms
m30000| Wed Nov 21 00:55:10.813 [FileAllocator] done allocating datafile /data/db/test0\gle_error_message.1, size: 128MB, took 0.42 secs
m30999| Wed Nov 21 00:55:10.797 [conn1] moveChunk result: { ok: 1.0 }
m30999| Wed Nov 21 00:55:10.797 [conn1] loading chunk manager for collection gle_error_message.coll using old chunk manager w/ version 1|2||50ac6cbefaf2e30ed017368f and 2 chunks
m30999| Wed Nov 21 00:55:10.797 [conn1] major version query from 1|2||50ac6cbefaf2e30ed017368f and over 1 shards is { ns: "gle_error_message.coll", $or: [ { lastmod: { $gte: Timestamp 1000|2 } }, { shard: "shard0000", lastmod: { $gt: Timestamp 1000|2 } } ] }
m30999| Wed Nov 21 00:55:10.797 [conn1] found 2 new chunks for collection gle_error_message.coll (tracking 2), new version is 0000000001DFA520
m30999| Wed Nov 21 00:55:10.797 [conn1] loaded 2 chunks into new chunk manager for gle_error_message.coll with version 2|1||50ac6cbefaf2e30ed017368f
m30999| Wed Nov 21 00:55:10.797 [conn1] ChunkManager: time to load chunks for gle_error_message.coll: 0ms sequenceNumber: 4 version: 2|1||50ac6cbefaf2e30ed017368f based on: 1|2||50ac6cbefaf2e30ed017368f
m30999| Wed Nov 21 00:55:10.797 [conn1] Request::process end ns: admin.$cmd msg id: 11 op: 2004 attempt: 0 382ms
m30999| Wed Nov 21 00:55:10.813 [conn1] Request::process begin ns: config.version msg id: 12 op: 2004 attempt: 0
m30999| Wed Nov 21 00:55:10.813 [conn1] shard query: config.version {}
m30999| Wed Nov 21 00:55:10.813 [conn1] creating pcursor over QSpec { ns: "config.version", n2skip: 0, n2return: -1, options: 0, query: {}, fields: {} } and CInfo { v_ns: "", filter: {} }
m30999| Wed Nov 21 00:55:10.813 [conn1] initializing over 1 shards required by [unsharded @ config:localhost:29000]
m30999| Wed Nov 21 00:55:10.813 [conn1] initializing on shard config:localhost:29000, current connection state is { state: {}, retryNext: false, init: false, finish: false, errored: false }
m30999| Wed Nov 21 00:55:10.813 [conn1] initialized query (lazily) on shard config:localhost:29000, current connection state is { state: { conn: "localhost:29000", vinfo: "config:localhost:29000", cursor: "(empty)", count: 0, done: false }, retryNext: false, init: true, finish: false, errored: false }
m30999| Wed Nov 21 00:55:10.813 [conn1] finishing over 1 shards
m30999| Wed Nov 21 00:55:10.813 [conn1] finishing on shard config:localhost:29000, current connection state is { state: { conn: "localhost:29000", vinfo: "config:localhost:29000", cursor: "(empty)", count: 0, done: false }, retryNext: false, init: true, finish: false, errored: false }
m30999| Wed Nov 21 00:55:10.813 [conn1] finished on shard config:localhost:29000, current connection state is { state: { conn: "(done)", vinfo: "config:localhost:29000", cursor: { _id: 1, version: 3 }, count: 0, done: false }, retryNext: false, init: true, finish: true, errored: false }
m30999| Wed Nov 21 00:55:10.813 [conn1] Request::process end ns: config.version msg id: 12 op: 2004 attempt: 0 0ms
m30999| Wed Nov 21 00:55:10.813 [conn1] Request::process begin ns: config.version msg id: 13 op: 2004 attempt: 0
m30999| Wed Nov 21 00:55:10.813 [conn1] shard query: config.version {}
m30999| Wed Nov 21 00:55:10.813 [conn1] creating pcursor over QSpec { ns: "config.version", n2skip: 0, n2return: -1, options: 0, query: {}, fields: {} } and CInfo { v_ns: "", filter: {} }
m30999| Wed Nov 21 00:55:10.813 [conn1] initializing over 1 shards required by [unsharded @ config:localhost:29000]
m30999| Wed Nov 21 00:55:10.813 [conn1] initializing on shard config:localhost:29000, current connection state is { state: {}, retryNext: false, init: false, finish: false, errored: false }
m30999| Wed Nov 21 00:55:10.813 [conn1] initialized query (lazily) on shard config:localhost:29000, current connection state is { state: { conn: "localhost:29000", vinfo: "config:localhost:29000", cursor: "(empty)", count: 0, done: false }, retryNext: false, init: true, finish: false, errored: false }
m30999| Wed Nov 21 00:55:10.813 [conn1] finishing over 1 shards
m30999| Wed Nov 21 00:55:10.813 [conn1] finishing on shard config:localhost:29000, current connection state is { state: { conn: "localhost:29000", vinfo: "config:localhost:29000", cursor: "(empty)", count: 0, done: false }, retryNext: false, init: true, finish: false, errored: false }
m30999| Wed Nov 21 00:55:10.813 [conn1] finished on shard config:localhost:29000, current connection state is { state: { conn: "(done)", vinfo: "config:localhost:29000", cursor: { _id: 1, version: 3 }, count: 0, done: false }, retryNext: false, init: true, finish: true, errored: false }
m30999| Wed Nov 21 00:55:10.813 [conn1] Request::process end ns: config.version msg id: 13 op: 2004 attempt: 0 0ms
m30999| Wed Nov 21 00:55:10.813 [conn1] Request::process begin ns: config.shards msg id: 14 op: 2004 attempt: 0
m30999| Wed Nov 21 00:55:10.813 [conn1] shard query: config.shards { query: {}, orderby: { _id: 1.0 } }
m30999| Wed Nov 21 00:55:10.813 [conn1] creating pcursor over QSpec { ns: "config.shards", n2skip: 0, n2return: 0, options: 0, query: { query: {}, orderby: { _id: 1.0 } }, fields: {} } and CInfo { v_ns: "", filter: {} }
m30999| Wed Nov 21 00:55:10.813 [conn1] initializing over 1 shards required by [unsharded @ config:localhost:29000]
m30999| Wed Nov 21 00:55:10.813 [conn1] initializing on shard config:localhost:29000, current connection state is { state: {}, retryNext: false, init: false, finish: false, errored: false }
m30999| Wed Nov 21 00:55:10.813 [conn1] initialized query (lazily) on shard config:localhost:29000, current connection state is { state: { conn: "localhost:29000", vinfo: "config:localhost:29000", cursor: "(empty)", count: 0, done: false }, retryNext: false, init: true, finish: false, errored: false }
m30999| Wed Nov 21 00:55:10.813 [conn1] finishing over 1 shards
m30999| Wed Nov 21 00:55:10.813 [conn1] finishing on shard config:localhost:29000, current connection state is { state: { conn: "localhost:29000", vinfo: "config:localhost:29000", cursor: "(empty)", count: 0, done: false }, retryNext: false, init: true, finish: false, errored: false }
m30999| Wed Nov 21 00:55:10.813 [conn1] finished on shard config:localhost:29000, current connection state is { state: { conn: "(done)", vinfo: "config:localhost:29000", cursor: { _id: "shard0000", host: "localhost:30000" }, count: 0, done: false }, retryNext: false, init: true, finish: true, errored: false }
m30999| Wed Nov 21 00:55:10.813 [conn1] Request::process end ns: config.shards msg id: 14 op: 2004 attempt: 0 0ms
m30999| Wed Nov 21 00:55:10.813 [conn1] Request::process begin ns: config.databases msg id: 15 op: 2004 attempt: 0
m30999| Wed Nov 21 00:55:10.813 [conn1] shard query: config.databases { query: {}, orderby: { name: 1.0 } }
m30999| Wed Nov 21 00:55:10.813 [conn1] creating pcursor over QSpec { ns: "config.databases", n2skip: 0, n2return: 0, options: 0, query: { query: {}, orderby: { name: 1.0 } }, fields: {} } and CInfo { v_ns: "", filter: {} }
m30999| Wed Nov 21 00:55:10.813 [conn1] initializing over 1 shards required by [unsharded @ config:localhost:29000]
m30999| Wed Nov 21 00:55:10.813 [conn1] initializing on shard config:localhost:29000, current connection state is { state: {}, retryNext: false, init: false, finish: false, errored: false }
m30999| Wed Nov 21 00:55:10.813 [conn1] initialized query (lazily) on shard config:localhost:29000, current connection state is { state: { conn: "localhost:29000", vinfo: "config:localhost:29000", cursor: "(empty)", count: 0, done: false }, retryNext: false, init: true, finish: false, errored: false }
m30999| Wed Nov 21 00:55:10.813 [conn1] finishing over 1 shards
m30999| Wed Nov 21 00:55:10.813 [conn1] finishing on shard config:localhost:29000, current connection state is { state: { conn: "localhost:29000", vinfo: "config:localhost:29000", cursor: "(empty)", count: 0, done: false }, retryNext: false, init: true, finish: false, errored: false }
m30999| Wed Nov 21 00:55:10.813 [conn1] finished on shard config:localhost:29000, current connection state is { state: { conn: "(done)", vinfo: "config:localhost:29000", cursor: { _id: "admin", partitioned: false, primary: "config" }, count: 0, done: false }, retryNext: false, init: true, finish: true, errored: false }
m30999| Wed Nov 21 00:55:10.813 [conn1] Request::process end ns: config.databases msg id: 15 op: 2004 attempt: 0 0ms
m30999| Wed Nov 21 00:55:10.813 [conn1] Request::process begin ns: config.collections msg id: 16 op: 2004 attempt: 0
m30999| Wed Nov 21 00:55:10.813 [conn1] shard query: config.collections { query: { _id: /^gle_error_message\./ }, orderby: { _id: 1.0 } }
m30999| Wed Nov 21 00:55:10.813 [conn1] creating pcursor over QSpec { ns: "config.collections", n2skip: 0, n2return: 0, options: 0, query: { query: { _id: /^gle_error_message\./ }, orderby: { _id: 1.0 } }, fields: {} } and CInfo { v_ns: "", filter: {} }
m30999| Wed Nov 21 00:55:10.813 [conn1] initializing over 1 shards required by [unsharded @ config:localhost:29000]
m30999| Wed Nov 21 00:55:10.813 [conn1] initializing on shard config:localhost:29000, current connection state is { state: {}, retryNext: false, init: false, finish: false, errored: false }
m30999| Wed Nov 21 00:55:10.813 [conn1] initialized query (lazily) on shard config:localhost:29000, current connection state is { state: { conn: "localhost:29000", vinfo: "config:localhost:29000", cursor: "(empty)", count: 0, done: false }, retryNext: false, init: true, finish: false, errored: false }
m30999| Wed Nov 21 00:55:10.813 [conn1] finishing over 1 shards
m30999| Wed Nov 21 00:55:10.813 [conn1] finishing on shard config:localhost:29000, current connection state is { state: { conn: "localhost:29000", vinfo: "config:localhost:29000", cursor: "(empty)", count: 0, done: false }, retryNext: false, init: true, finish: false, errored: false }
m30999| Wed Nov 21 00:55:10.813 [conn1] finished on shard config:localhost:29000, current connection state is { state: { conn: "(done)", vinfo: "config:localhost:29000", cursor: { _id: "gle_error_message.coll", lastmod: new Date(1353477310), dropped: false, key: { _id: 1.0 }, unique: false, lastmodEpoch: ObjectId('50ac6cbefaf2e30ed017368f') }, count: 0, done: false }, retryNext: false, init: true, finish: true, errored: false }
m30999| Wed Nov 21 00:55:10.813 [conn1] Request::process end ns: config.collections msg id: 16 op: 2004 attempt: 0 0ms
m30999| Wed Nov 21 00:55:10.813 [conn1] Request::process begin ns: config.$cmd msg id: 17 op: 2004 attempt: 0
m30999| Wed Nov 21 00:55:10.813 [conn1] single query: config.$cmd { group: { cond: { ns: "gle_error_message.coll" }, key: { shard: 1.0 }, initial: { nChunks: 0.0 }, ns: "chunks", $reduce: function ( doc , out ){ out.nChunks++; } } } ntoreturn: -1 options : 0
m29000| Wed Nov 21 00:55:10.859 [conn11] timeoutMs not support for v8 yet code: $reduce = function ( doc , out ){ out.nChunks++; }
m29000| in gc
m30999| Wed Nov 21 00:55:10.859 [conn1] Request::process end ns: config.$cmd msg id: 17 op: 2004 attempt: 0 37ms
m30999| Wed Nov 21 00:55:10.859 [conn1] Request::process begin ns: config.chunks msg id: 18 op: 2004 attempt: 0
m30999| Wed Nov 21 00:55:10.859 [conn1] shard query: config.chunks { query: { ns: "gle_error_message.coll" }, orderby: { min: 1.0 } }
m30999| Wed Nov 21 00:55:10.859 [conn1] creating pcursor over QSpec { ns: "config.chunks", n2skip: 0, n2return: 0, options: 0, query: { query: { ns: "gle_error_message.coll" }, orderby: { min: 1.0 } }, fields: {} } and CInfo { v_ns: "", filter: {} }
m30999| Wed Nov 21 00:55:10.859 [conn1] initializing over 1 shards required by [unsharded @ config:localhost:29000]
m30999| Wed Nov 21 00:55:10.859 [conn1] initializing on shard config:localhost:29000, current connection state is { state: {}, retryNext: false, init: false, finish: false, errored: false }
m30999| Wed Nov 21 00:55:10.859 [conn1] initialized query (lazily) on shard config:localhost:29000, current connection state is { state: { conn: "localhost:29000", vinfo: "config:localhost:29000", cursor: "(empty)", count: 0, done: false }, retryNext: false, init: true, finish: false, errored: false }
m30999| Wed Nov 21 00:55:10.859 [conn1] finishing over 1 shards
m30999| Wed Nov 21 00:55:10.859 [conn1] finishing on shard config:localhost:29000, current connection state is { state: { conn: "localhost:29000", vinfo: "config:localhost:29000", cursor: "(empty)", count: 0, done: false }, retryNext: false, init: true, finish: false, errored: false }
m30999| Wed Nov 21 00:55:10.859 [conn1] finished on shard config:localhost:29000, current connection state is { state: { conn: "(done)", vinfo: "config:localhost:29000", cursor: { _id: "gle_error_message.coll-_id_MinKey", lastmod: Timestamp 2000|1, lastmodEpoch: ObjectId('50ac6cbefaf2e30ed017368f'), ns: "gle_error_message.coll", min: { _id: MinKey }, max: { _id: 0.0 }, shard: "shard0000" }, count: 0, done: false }, retryNext: false, init: true, finish: true, errored: false }
m30999| Wed Nov 21 00:55:10.859 [conn1] Request::process end ns: config.chunks msg id: 18 op: 2004 attempt: 0 0ms
m30999| Wed Nov 21 00:55:10.859 [conn1] Request::process begin ns: config.tags msg id: 19 op: 2004 attempt: 0
m30999| Wed Nov 21 00:55:10.859 [conn1] shard query: config.tags { query: { ns: "gle_error_message.coll" }, orderby: { min: 1.0 } }
m30999| Wed Nov 21 00:55:10.859 [conn1] creating pcursor over QSpec { ns: "config.tags", n2skip: 0, n2return: 0, options: 0, query: { query: { ns: "gle_error_message.coll" }, orderby: { min: 1.0 } }, fields: {} } and CInfo { v_ns: "", filter: {} }
m30999| Wed Nov 21 00:55:10.859 [conn1] initializing over 1 shards required by [unsharded @ config:localhost:29000]
m30999| Wed Nov 21 00:55:10.859 [conn1] initializing on shard config:localhost:29000, current connection state is { state: {}, retryNext: false, init: false, finish: false, errored: false }
m30999| Wed Nov 21 00:55:10.859 [conn1] initialized query (lazily) on shard config:localhost:29000, current connection state is { state: { conn: "localhost:29000", vinfo: "config:localhost:29000", cursor: "(empty)", count: 0, done: false }, retryNext: false, init: true, finish: false, errored: false }
m30999| Wed Nov 21 00:55:10.859 [conn1] finishing over 1 shards
m30999| Wed Nov 21 00:55:10.859 [conn1] finishing on shard config:localhost:29000, current connection state is { state: { conn: "localhost:29000", vinfo: "config:localhost:29000", cursor: "(empty)", count: 0, done: false }, retryNext: false, init: true, finish: false, errored: false }
m30999| Wed Nov 21 00:55:10.859 [conn1] finished on shard config:localhost:29000, current connection state is { state: { conn: "(done)", vinfo: "config:localhost:29000", cursor: "(empty)", count: 0, done: false }, retryNext: false, init: true, finish: true, errored: false }
--- Sharding Status ---
sharding version: { "_id" : 1, "version" : 3 }
shards:
{ "_id" : "shard0000", "host" : "localhost:30000" }
{ "_id" : "shard0001", "host" : "localhost:30001" }
{ "_id" : "shard0002", "host" : "localhost:30002" }
databases:
{ "_id" : "admin", "partitioned" : false, "primary" : "config" }
{ "_id" : "gle_error_message", "partitioned" : true, "primary" : "shard0000" }
gle_error_message.coll
shard key: { "_id" : 1 }
chunks:
shard0000 1
shard0001 1
{ "_id" : { "$MinKey" : true } } -->> { "_id" : 0 } on : shard0000 { "t" : 2000, "i" : 1 }
{ "_id" : 0 } -->> { "_id" : { "$MaxKey" : true } } on : shard0001 { "t" : 2000, "i" : 0 }
m30999| Wed Nov 21 00:55:10.859 [conn1] Request::process end ns: config.tags msg id: 19 op: 2004 attempt: 0 0ms
----
Testing GLE...
----
m30999| Wed Nov 21 00:55:10.859 [conn1] Request::process begin ns: gle_error_message.coll msg id: 20 op: 2002 attempt: 0
m30999| Wed Nov 21 00:55:10.859 [conn1] write: gle_error_message.coll
m30999| Wed Nov 21 00:55:10.859 [conn1] have to set shard version for conn: localhost:30000 ns:gle_error_message.coll my last seq: 2 current: 4 version: 2|1||50ac6cbefaf2e30ed017368f manager: 0000000001DFA410
m30999| Wed Nov 21 00:55:10.859 [conn1] setShardVersion shard0000 localhost:30000 gle_error_message.coll { setShardVersion: "gle_error_message.coll", configdb: "localhost:29000", version: Timestamp 2000|1, versionEpoch: ObjectId('50ac6cbefaf2e30ed017368f'), serverID: ObjectId('50ac6cbdfaf2e30ed017368d'), shard: "shard0000", shardHost: "localhost:30000" } 0000000001DF6160 4
m30999| Wed Nov 21 00:55:10.859 [conn1] setShardVersion success: { oldVersion: Timestamp 1000|0, oldVersionEpoch: ObjectId('50ac6cbefaf2e30ed017368f'), ok: 1.0 }
m30999| Wed Nov 21 00:55:10.859 [conn1] about to initiate autosplit: ns:gle_error_message.collshard: shard0000:localhost:30000lastmod: 2|1||000000000000000000000000min: { _id: MinKey }max: { _id: 0.0 } dataWritten: 5457627 splitThreshold: 471859
m30999| Wed Nov 21 00:55:10.859 [conn1] chunk not full enough to trigger auto-split no split entry
m30999| Wed Nov 21 00:55:10.859 [conn1] Request::process end ns: gle_error_message.coll msg id: 20 op: 2002 attempt: 0 1ms
m30999| Wed Nov 21 00:55:10.859 [conn1] Request::process begin ns: gle_error_message.coll msg id: 21 op: 2002 attempt: 0
m30999| Wed Nov 21 00:55:10.859 [conn1] write: gle_error_message.coll
m30999| Wed Nov 21 00:55:10.859 [conn1] have to set shard version for conn: localhost:30001 ns:gle_error_message.coll my last seq: 2 current: 4 version: 2|0||50ac6cbefaf2e30ed017368f manager: 0000000001DFA410
m30999| Wed Nov 21 00:55:10.859 [conn1] setShardVersion shard0001 localhost:30001 gle_error_message.coll { setShardVersion: "gle_error_message.coll", configdb: "localhost:29000", version: Timestamp 2000|0, versionEpoch: ObjectId('50ac6cbefaf2e30ed017368f'), serverID: ObjectId('50ac6cbdfaf2e30ed017368d'), shard: "shard0001", shardHost: "localhost:30001" } 0000000001DF6A60 4
m30999| Wed Nov 21 00:55:10.859 [conn1] setShardVersion failed!
m30999| { oldVersion: Timestamp 0|0, oldVersionEpoch: ObjectId('000000000000000000000000'), ns: "gle_error_message.coll", need_authoritative: true, errmsg: "first time for collection 'gle_error_message.coll'", ok: 0.0 }
m30999| Wed Nov 21 00:55:10.859 [conn1] have to set shard version for conn: localhost:30001 ns:gle_error_message.coll my last seq: 2 current: 4 version: 2|0||50ac6cbefaf2e30ed017368f manager: 0000000001DFA410
m30999| Wed Nov 21 00:55:10.859 [conn1] setShardVersion shard0001 localhost:30001 gle_error_message.coll { setShardVersion: "gle_error_message.coll", configdb: "localhost:29000", version: Timestamp 2000|0, versionEpoch: ObjectId('50ac6cbefaf2e30ed017368f'), serverID: ObjectId('50ac6cbdfaf2e30ed017368d'), authoritative: true, shard: "shard0001", shardHost: "localhost:30001" } 0000000001DF6A60 4
m30001| Wed Nov 21 00:55:10.859 [conn3] no current chunk manager found for this shard, will initialize
m30999| Wed Nov 21 00:55:10.859 [conn1] setShardVersion success: { oldVersion: Timestamp 0|0, oldVersionEpoch: ObjectId('000000000000000000000000'), ok: 1.0 }
m30999| Wed Nov 21 00:55:10.859 [conn1] about to initiate autosplit: ns:gle_error_message.collshard: shard0001:localhost:30001lastmod: 2|0||000000000000000000000000min: { _id: 0.0 }max: { _id: MaxKey } dataWritten: 5457627 splitThreshold: 471859
m30999| Wed Nov 21 00:55:10.859 [conn1] chunk not full enough to trigger auto-split no split entry
m30999| Wed Nov 21 00:55:10.859 [conn1] Request::process end ns: gle_error_message.coll msg id: 21 op: 2002 attempt: 0 2ms
m30999| Wed Nov 21 00:55:10.859 [conn1] Request::process begin ns: gle_error_message.$cmd msg id: 22 op: 2004 attempt: 0
m30999| Wed Nov 21 00:55:10.859 [conn1] single query: gle_error_message.$cmd { getlasterror: 1.0 } ntoreturn: -1 options : 0
m30999| Wed Nov 21 00:55:10.859 [conn1] Request::process end ns: gle_error_message.$cmd msg id: 22 op: 2004 attempt: 0 0ms
----
GLE : {
"singleShard" : "localhost:30001",
"n" : 0,
"connectionId" : 3,
"err" : null,
"ok" : 1
}
----
----
Testing GLE when writeback host goes down...
----
m30999| Wed Nov 21 00:55:10.859 [conn1] Request::process begin ns: gle_error_message.coll msg id: 23 op: 2002 attempt: 0
m30999| Wed Nov 21 00:55:10.859 [conn1] write: gle_error_message.coll
m30999| Wed Nov 21 00:55:10.859 [conn1] Request::process end ns: gle_error_message.coll msg id: 23 op: 2002 attempt: 0 0ms
m30999| Wed Nov 21 00:55:10.859 [conn1] Request::process begin ns: gle_error_message.coll msg id: 24 op: 2002 attempt: 0
m30999| Wed Nov 21 00:55:10.859 [conn1] write: gle_error_message.coll
m30999| Wed Nov 21 00:55:10.859 [conn1] Request::process end ns: gle_error_message.coll msg id: 24 op: 2002 attempt: 0 0ms
m30000| Wed Nov 21 00:55:10.859 [initandlisten] connection accepted from 127.0.0.1:57602 #6 (6 connections now open)
m30000| Wed Nov 21 00:55:10.859 [conn6] terminating, shutdown command received
m30000| Wed Nov 21 00:55:10.859 dbexit: shutdown called
m30000| Wed Nov 21 00:55:10.859 [conn6] shutdown: going to close listening sockets...
m30000| Wed Nov 21 00:55:10.859 [conn6] closing listening socket: 468
m30000| Wed Nov 21 00:55:10.859 [conn6] closing listening socket: 480
m30000| Wed Nov 21 00:55:10.859 [conn6] shutdown: going to flush diaglog...
m30000| Wed Nov 21 00:55:10.859 [conn6] shutdown: going to close sockets...
m30000| Wed Nov 21 00:55:10.859 [conn6] shutdown: waiting for fs preallocator...
m30000| Wed Nov 21 00:55:10.859 [conn6] shutdown: lock for final commit...
m30000| Wed Nov 21 00:55:10.859 [conn6] shutdown: final commit...
m30999| Wed Nov 21 00:55:10.859 [WriteBackListener-localhost:30000] Socket recv() conn closed? 127.0.0.1:30000
m30999| Wed Nov 21 00:55:10.859 [WriteBackListener-localhost:30000] SocketException: remote: 127.0.0.1:30000 error: 9001 socket exception [0] server [127.0.0.1:30000]
m30999| Wed Nov 21 00:55:10.859 [WriteBackListener-localhost:30000] DBClientCursor::init call() failed
m30999| Wed Nov 21 00:55:10.859 [WriteBackListener-localhost:30000] User Assertion: 10276:DBClientBase::findN: transport error: localhost:30000 ns: admin.$cmd query: { writebacklisten: ObjectId('50ac6cbdfaf2e30ed017368d') }
m30999| Wed Nov 21 00:55:10.859 [WriteBackListener-localhost:30000] Detecting bad connection created at 0 microSec, clearing pool for localhost:30000
m30999| Wed Nov 21 00:55:10.859 [WriteBackListener-localhost:30000] WriteBackListener exception : DBClientBase::findN: transport error: localhost:30000 ns: admin.$cmd query: { writebacklisten: ObjectId('50ac6cbdfaf2e30ed017368d') }
m30000| Wed Nov 21 00:55:10.859 [conn1] end connection 127.0.0.1:57564 (5 connections now open)
m30000| Wed Nov 21 00:55:10.859 [conn3] end connection 127.0.0.1:57585 (5 connections now open)
m30000| Wed Nov 21 00:55:10.859 [conn4] end connection 127.0.0.1:57590 (5 connections now open)
m30000| Wed Nov 21 00:55:10.859 [conn5] end connection 127.0.0.1:57596 (5 connections now open)
m29000| Wed Nov 21 00:55:10.859 [conn12] end connection 127.0.0.1:57593 (12 connections now open)
m29000| Wed Nov 21 00:55:10.859 [conn13] end connection 127.0.0.1:57594 (11 connections now open)
m30001| Wed Nov 21 00:55:10.875 [conn6] end connection 127.0.0.1:57598 (5 connections now open)
m30001| Wed Nov 21 00:55:10.875 [conn5] end connection 127.0.0.1:57595 (4 connections now open)
Wed Nov 21 00:55:10.875 DBClientCursor::init call() failed
m29000| Wed Nov 21 00:55:10.875 [conn15] end connection 127.0.0.1:57601 (10 connections now open)
m30001| Wed Nov 21 00:55:11.078 [FileAllocator] done allocating datafile /data/db/test1\gle_error_message.1, size: 128MB, took 0.394 secs
m30999| Wed Nov 21 00:55:11.889 [WriteBackListener-localhost:30000] creating new connection to:localhost:30000
m30999| Wed Nov 21 00:55:11.889 BackgroundJob starting: ConnectBG
m30999| Wed Nov 21 00:55:12.919 [WriteBackListener-localhost:30000] WriteBackListener exception : socket exception [CONNECT_ERROR] for localhost:30000
m30000| Wed Nov 21 00:55:14.057 [conn6] shutdown: closing all files...
m30000| Wed Nov 21 00:55:14.057 [conn6] closeAllFiles() finished
m30000| Wed Nov 21 00:55:14.057 [conn6] journalCleanup...
m30000| Wed Nov 21 00:55:14.073 [conn6] removeJournalFiles
m30000| Wed Nov 21 00:55:14.073 [conn6] shutdown: removing fs lock...
m30000| Wed Nov 21 00:55:14.073 dbexit: really exiting now
Wed Nov 21 00:55:14.931 shell: stopped mongo program on port 30000
m30999| Wed Nov 21 00:55:14.931 [WriteBackListener-localhost:30000] creating new connection to:localhost:30000
m30999| Wed Nov 21 00:55:14.931 BackgroundJob starting: ConnectBG
m30999| Wed Nov 21 00:55:14.931 [conn1] Request::process begin ns: gle_error_message.$cmd msg id: 26 op: 2004 attempt: 0
m30999| Wed Nov 21 00:55:14.931 [conn1] single query: gle_error_message.$cmd { getlasterror: 1.0 } ntoreturn: -1 options : 0
m30999| Wed Nov 21 00:55:14.931 [conn1] Socket say send() errno:10054 An existing connection was forcibly closed by the remote host. 127.0.0.1:30000
m30999| Wed Nov 21 00:55:14.931 [conn1] Detecting bad connection created at 0 microSec, clearing pool for localhost:30000
m30999| Wed Nov 21 00:55:14.931 [conn1] could not clear last error from shard localhost:30000 :: caused by :: socket exception [SEND_ERROR] for 127.0.0.1:30000
m30999| Wed Nov 21 00:55:14.931 [conn1] Request::process end ns: gle_error_message.$cmd msg id: 26 op: 2004 attempt: 0 0ms
----
GLE : {
"singleShard" : "localhost:30001",
"n" : 0,
"connectionId" : 3,
"err" : null,
"ok" : 1
}
----
Wed Nov 21 00:55:14.931 shell: started program mongod.exe --port 30000 --dbpath /data/db/test0
m30000| Wed Nov 21 00:55:14.962 [initandlisten] MongoDB starting : pid=4000 port=30000 dbpath=/data/db/test0 64-bit host=AMAZONA-JD1A6QA
m30000| Wed Nov 21 00:55:14.962 [initandlisten]
m30000| Wed Nov 21 00:55:14.962 [initandlisten] ** NOTE: This is a development version (2.3.1-pre-) of MongoDB.
m30000| Wed Nov 21 00:55:14.962 [initandlisten] ** Not recommended for production.
m30000| Wed Nov 21 00:55:14.962 [initandlisten]
m30000| Wed Nov 21 00:55:14.962 [initandlisten] db version v2.3.1-pre-, pdfile version 4.5
m30000| Wed Nov 21 00:55:14.962 [initandlisten] git version: cb14cf83102cca848e572ffd8b95c6fa35594175
m30000| Wed Nov 21 00:55:14.962 [initandlisten] build info: windows sys.getwindowsversion(major=6, minor=1, build=7601, platform=2, service_pack='Service Pack 1') BOOST_LIB_VERSION=1_49
m30000| Wed Nov 21 00:55:14.962 [initandlisten] options: { dbpath: "/data/db/test0", port: 30000 }
m30000| Wed Nov 21 00:55:15.025 [initandlisten] journal dir=/data/db/test0\journal
m30000| Wed Nov 21 00:55:15.025 [initandlisten] recover : no journal files present, no recovery needed
m30999| Wed Nov 21 00:55:15.181 [Balancer] Refreshing MaxChunkSize: 50
m30999| Wed Nov 21 00:55:15.181 [Balancer] skipping balancing round because balancing is disabled
m30998| Wed Nov 21 00:55:15.571 [Balancer] Refreshing MaxChunkSize: 50
m30998| Wed Nov 21 00:55:15.571 [Balancer] skipping balancing round because balancing is disabled
m29000| Wed Nov 21 00:55:15.883 [conn9] update config.mongos query: { _id: "AMAZONA-JD1A6QA:30998" } update: { $set: { ping: new Date(1353477315571), up: 6, waiting: false } } idhack:1 nupdated:1 keyUpdates:0 locks(micros) w:88 321ms
m30999| Wed Nov 21 00:55:15.945 [WriteBackListener-localhost:30000] WriteBackListener exception : socket exception [CONNECT_ERROR] for localhost:30000
m30000| Wed Nov 21 00:55:16.039 [initandlisten] preallocateIsFaster=true 16.7
m30000| Wed Nov 21 00:55:16.195 [initandlisten] waiting for connections on port 30000
m30000| Wed Nov 21 00:55:16.195 [websvr] admin web console waiting for connections on port 31000
m30000| Wed Nov 21 00:55:16.663 [initandlisten] connection accepted from 127.0.0.1:57610 #1 (1 connection now open)
----
Testing GLE when main host goes down...
----
m30999| Wed Nov 21 00:55:16.663 [conn1] Request::process begin ns: gle_error_message.coll msg id: 27 op: 2002 attempt: 0
m30999| Wed Nov 21 00:55:16.663 [conn1] write: gle_error_message.coll
m30999| Wed Nov 21 00:55:16.663 [conn1] creating new connection to:localhost:30000
m30999| Wed Nov 21 00:55:16.663 BackgroundJob starting: ConnectBG
m30000| Wed Nov 21 00:55:16.663 [initandlisten] connection accepted from 127.0.0.1:57612 #2 (2 connections now open)
m30001| Wed Nov 21 00:55:16.663 [initandlisten] connection accepted from 127.0.0.1:57611 #7 (5 connections now open)
m30999| Wed Nov 21 00:55:16.663 [conn1] connected connection!
m30999| Wed Nov 21 00:55:16.663 [conn1] initializing shard connection to localhost:30000
m30999| Wed Nov 21 00:55:16.663 [conn1] initial sharding settings : { setShardVersion: "", init: true, configdb: "localhost:29000", serverID: ObjectId('50ac6cbdfaf2e30ed017368d'), authoritative: true }
m30001| Wed Nov 21 00:55:16.663 [conn7] terminating, shutdown command received
m30001| Wed Nov 21 00:55:16.663 dbexit: shutdown called
m30001| Wed Nov 21 00:55:16.663 [conn7] shutdown: going to close listening sockets...
m30001| Wed Nov 21 00:55:16.663 [conn7] closing listening socket: 480
m30001| Wed Nov 21 00:55:16.663 [conn7] closing listening socket: 488
m30001| Wed Nov 21 00:55:16.663 [conn7] shutdown: going to flush diaglog...
m30001| Wed Nov 21 00:55:16.663 [conn7] shutdown: going to close sockets...
m30001| Wed Nov 21 00:55:16.663 [conn7] shutdown: waiting for fs preallocator...
m30001| Wed Nov 21 00:55:16.663 [conn7] shutdown: lock for final commit...
m30001| Wed Nov 21 00:55:16.663 [conn7] shutdown: final commit...
m30001| Wed Nov 21 00:55:16.663 [conn1] end connection 127.0.0.1:57565 (4 connections now open)
m30999| Wed Nov 21 00:55:16.663 [WriteBackListener-localhost:30001] Socket recv() conn closed? 127.0.0.1:30001
m30999| Wed Nov 21 00:55:16.663 [conn1] initial sharding result : { initialized: true, ok: 1.0 }
m30999| Wed Nov 21 00:55:16.663 [WriteBackListener-localhost:30001] SocketException: remote: 127.0.0.1:30001 error: 9001 socket exception [0] server [127.0.0.1:30001]
m30999| Wed Nov 21 00:55:16.663 [conn1] have to set shard version for conn: localhost:30000 ns:gle_error_message.coll my last seq: 0 current: 4 version: 2|1||50ac6cbefaf2e30ed017368f manager: 0000000001DFA410
m30999| Wed Nov 21 00:55:16.663 [WriteBackListener-localhost:30001] DBClientCursor::init call() failed
m30999| Wed Nov 21 00:55:16.663 [WriteBackListener-localhost:30001] User Assertion: 10276:DBClientBase::findN: transport error: localhost:30001 ns: admin.$cmd query: { writebacklisten: ObjectId('50ac6cbdfaf2e30ed017368d') }
m30999| Wed Nov 21 00:55:16.663 [conn1] setShardVersion shard0000 localhost:30000 gle_error_message.coll { setShardVersion: "gle_error_message.coll", configdb: "localhost:29000", version: Timestamp 2000|1, versionEpoch: ObjectId('50ac6cbefaf2e30ed017368f'), serverID: ObjectId('50ac6cbdfaf2e30ed017368d'), shard: "shard0000", shardHost: "localhost:30000" } 0000000001E00F00 4
m30999| Wed Nov 21 00:55:16.663 [WriteBackListener-localhost:30001] Detecting bad connection created at 0 microSec, clearing pool for localhost:30001
m30999| Wed Nov 21 00:55:16.663 [WriteBackListener-localhost:30001] WriteBackListener exception : DBClientBase::findN: transport error: localhost:30001 ns: admin.$cmd query: { writebacklisten: ObjectId('50ac6cbdfaf2e30ed017368d') }
m30999| Wed Nov 21 00:55:16.663 [conn1] setShardVersion failed!
m30999| { oldVersion: Timestamp 0|0, oldVersionEpoch: ObjectId('000000000000000000000000'), ns: "gle_error_message.coll", need_authoritative: true, errmsg: "first time for collection 'gle_error_message.coll'", ok: 0.0 }
Wed Nov 21 00:55:16.663 DBClientCursor::init call() failed
m30001| Wed Nov 21 00:55:16.663 [conn4] end connection 127.0.0.1:57591 (3 connections now open)
m30001| Wed Nov 21 00:55:16.663 [conn3] end connection 127.0.0.1:57586 (2 connections now open)
m29000| Wed Nov 21 00:55:16.663 [conn14] end connection 127.0.0.1:57600 (9 connections now open)
m30999| Wed Nov 21 00:55:16.663 [conn1] have to set shard version for conn: localhost:30000 ns:gle_error_message.coll my last seq: 0 current: 4 version: 2|1||50ac6cbefaf2e30ed017368f manager: 0000000001DFA410
m30999| Wed Nov 21 00:55:16.663 [conn1] setShardVersion shard0000 localhost:30000 gle_error_message.coll { setShardVersion: "gle_error_message.coll", configdb: "localhost:29000", version: Timestamp 2000|1, versionEpoch: ObjectId('50ac6cbefaf2e30ed017368f'), serverID: ObjectId('50ac6cbdfaf2e30ed017368d'), authoritative: true, shard: "shard0000", shardHost: "localhost:30000" } 0000000001E00F00 4
m30000| Wed Nov 21 00:55:16.663 [conn2] no current chunk manager found for this shard, will initialize
m29000| Wed Nov 21 00:55:16.663 [initandlisten] connection accepted from 127.0.0.1:57613 #16 (10 connections now open)
m30999| Wed Nov 21 00:55:16.663 [conn1] setShardVersion success: { oldVersion: Timestamp 0|0, oldVersionEpoch: ObjectId('000000000000000000000000'), ok: 1.0 }
m30999| Wed Nov 21 00:55:16.663 [conn1] Request::process end ns: gle_error_message.coll msg id: 27 op: 2002 attempt: 0 3ms
m30999| Wed Nov 21 00:55:16.663 [conn1] Request::process begin ns: gle_error_message.coll msg id: 28 op: 2002 attempt: 0
m30999| Wed Nov 21 00:55:16.663 [conn1] write: gle_error_message.coll
m30999| Wed Nov 21 00:55:16.663 [conn1] Socket say send() errno:10054 An existing connection was forcibly closed by the remote host. 127.0.0.1:30001
m30999| Wed Nov 21 00:55:16.663 [conn1] User Assertion: 16460:error inserting 1 documents to shard shard0001:localhost:30001 at version 2|1||50ac6cbefaf2e30ed017368f :: caused by :: socket exception [SEND_ERROR] for 127.0.0.1:30001
m30999| Wed Nov 21 00:55:16.663 [conn1] exception during insert :: caused by :: 16460 error inserting 1 documents to shard shard0001:localhost:30001 at version 2|1||50ac6cbefaf2e30ed017368f :: caused by :: socket exception [SEND_ERROR] for 127.0.0.1:30001
m30999| Wed Nov 21 00:55:16.663 [conn1] AssertionException while processing op type : 2002 to : gle_error_message.coll :: caused by :: 16460 error inserting 1 documents to shard shard0001:localhost:30001 at version 2|1||50ac6cbefaf2e30ed017368f :: caused by :: socket exception [SEND_ERROR] for 127.0.0.1:30001
m30999| Wed Nov 21 00:55:17.677 [WriteBackListener-localhost:30001] creating new connection to:localhost:30001
m30999| Wed Nov 21 00:55:17.677 BackgroundJob starting: ConnectBG
m30001| Wed Nov 21 00:55:18.098 [conn7] shutdown: closing all files...
m30001| Wed Nov 21 00:55:18.098 [conn7] closeAllFiles() finished
m30001| Wed Nov 21 00:55:18.098 [conn7] journalCleanup...
m30001| Wed Nov 21 00:55:18.098 [conn7] removeJournalFiles
m30001| Wed Nov 21 00:55:18.098 [conn7] shutdown: removing fs lock...
m30001| Wed Nov 21 00:55:18.098 dbexit: really exiting now
Wed Nov 21 00:55:18.691 shell: stopped mongo program on port 30001
----
Calling GLE!
----
m30999| Wed Nov 21 00:55:18.691 [WriteBackListener-localhost:30001] WriteBackListener exception : socket exception [CONNECT_ERROR] for localhost:30001
m30999| Wed Nov 21 00:55:18.691 [conn1] Request::process begin ns: gle_error_message.$cmd msg id: 30 op: 2004 attempt: 0
m30999| Wed Nov 21 00:55:18.691 [conn1] single query: gle_error_message.$cmd { getlasterror: 1.0 } ntoreturn: -1 options : 0
m30999| Wed Nov 21 00:55:18.691 [conn1] Request::process end ns: gle_error_message.$cmd msg id: 30 op: 2004 attempt: 0 0ms
assert failed
Error: Printing Stack Trace
at printStackTrace (src/mongo/shell/utils.js:37:7)
at doassert (src/mongo/shell/utils.js:58:1)
at assert (src/mongo/shell/utils.js:66:1)
at D:\slave\Windows_64bit\mongo\jstests\sharding\gle_error_message.js:67:5
----
GLE : assert failed
----
assert failed
Error: Printing Stack Trace
at printStackTrace (src/mongo/shell/utils.js:37:7)
at doassert (src/mongo/shell/utils.js:58:1)
at assert (src/mongo/shell/utils.js:66:1)
at D:\slave\Windows_64bit\mongo\jstests\sharding\gle_error_message.js:73:5
Wed Nov 21 00:55:18.691 exec error: src/mongo/shell/utils.js:59 assert failed
throw msg;
^
failed to load: D:\slave\Windows_64bit\mongo\jstests\sharding\gle_error_message.js
m29000| Wed Nov 21 00:55:18.722 [initandlisten] connection accepted from 127.0.0.1:57617 #17 (11 connections now open)
m29000| Wed Nov 21 00:55:18.722 [conn17] terminating, shutdown command received
m29000| Wed Nov 21 00:55:18.722 dbexit: shutdown called
m29000| Wed Nov 21 00:55:18.722 [conn17] shutdown: going to close listening sockets...
m29000| Wed Nov 21 00:55:18.722 [conn17] closing listening socket: 500
m29000| Wed Nov 21 00:55:18.722 [conn17] shutdown: going to flush diaglog...
m29000| Wed Nov 21 00:55:18.722 [conn17] shutdown: going to close sockets...
m29000| Wed Nov 21 00:55:18.722 [conn17] shutdown: waiting for fs preallocator...
m29000| Wed Nov 21 00:55:18.722 [conn17] shutdown: lock for final commit...
m29000| Wed Nov 21 00:55:18.722 [conn17] shutdown: final commit...
m29000| Wed Nov 21 00:55:18.722 [conn4] end connection 127.0.0.1:57572 (10 connections now open)
m29000| Wed Nov 21 00:55:18.722 [conn5] end connection 127.0.0.1:57573 (10 connections now open)
m29000| Wed Nov 21 00:55:18.722 [conn6] end connection 127.0.0.1:57575 (10 connections now open)
m29000| Wed Nov 21 00:55:18.722 [conn2] end connection 127.0.0.1:57568 (10 connections now open)
m29000| Wed Nov 21 00:55:18.722 [conn16] end connection 127.0.0.1:57613 (10 connections now open)
m29000| Wed Nov 21 00:55:18.722 [conn10] end connection 127.0.0.1:57580 (10 connections now open)
m29000| Wed Nov 21 00:55:18.722 [conn1] end connection 127.0.0.1:57567 (10 connections now open)
m29000| Wed Nov 21 00:55:18.722 [conn9] end connection 127.0.0.1:57579 (10 connections now open)
Wed Nov 21 00:55:18.722 DBClientCursor::init call() failed
m29000| Wed Nov 21 00:55:18.722 [conn11] end connection 127.0.0.1:57588 (2 connections now open)
m29000| Wed Nov 21 00:55:18.722 [conn7] end connection 127.0.0.1:57577 (2 connections now open)
m29000| Wed Nov 21 00:55:18.800 [conn17] shutdown: closing all files...
m29000| Wed Nov 21 00:55:18.800 [conn17] closeAllFiles() finished
m29000| Wed Nov 21 00:55:18.800 [conn17] journalCleanup...
m29000| Wed Nov 21 00:55:18.800 [conn17] removeJournalFiles
m29000| Wed Nov 21 00:55:18.800 [conn17] shutdown: removing fs lock...
m29000| Wed Nov 21 00:55:18.800 dbexit: really exiting now
m30999| Wed Nov 21 00:55:18.956 [WriteBackListener-localhost:30000] creating new connection to:localhost:30000
m30999| Wed Nov 21 00:55:18.956 BackgroundJob starting: ConnectBG
m30999| Wed Nov 21 00:55:18.956 [WriteBackListener-localhost:30000] connected connection!
m30000| Wed Nov 21 00:55:18.956 [initandlisten] connection accepted from 127.0.0.1:57618 #3 (3 connections now open)
m30000| Wed Nov 21 00:55:19.736 [initandlisten] connection accepted from 127.0.0.1:57619 #4 (4 connections now open)
m30000| Wed Nov 21 00:55:19.736 [conn4] terminating, shutdown command received
m30000| Wed Nov 21 00:55:19.736 dbexit: shutdown called
m30000| Wed Nov 21 00:55:19.736 [conn4] shutdown: going to close listening sockets...
m30000| Wed Nov 21 00:55:19.736 [conn4] closing listening socket: 552
m30000| Wed Nov 21 00:55:19.736 [conn4] closing listening socket: 556
m30000| Wed Nov 21 00:55:19.736 [conn4] shutdown: going to flush diaglog...
m30000| Wed Nov 21 00:55:19.736 [conn4] shutdown: going to close sockets...
m30000| Wed Nov 21 00:55:19.736 [conn4] shutdown: waiting for fs preallocator...
m30000| Wed Nov 21 00:55:19.736 [conn4] shutdown: lock for final commit...
m30000| Wed Nov 21 00:55:19.736 [conn4] shutdown: final commit...
m30999| Wed Nov 21 00:55:19.736 [WriteBackListener-localhost:30000] Socket recv() conn closed? 127.0.0.1:30000
Wed Nov 21 00:55:19.736 DBClientCursor::init call() failed
m30999| Wed Nov 21 00:55:19.736 [WriteBackListener-localhost:30000] SocketException: remote: 127.0.0.1:30000 error: 9001 socket exception [0] server [127.0.0.1:30000]
m30999| Wed Nov 21 00:55:19.736 [WriteBackListener-localhost:30000] DBClientCursor::init call() failed
m30999| Wed Nov 21 00:55:19.736 [WriteBackListener-localhost:30000] User Assertion: 10276:DBClientBase::findN: transport error: localhost:30000 ns: admin.$cmd query: { writebacklisten: ObjectId('50ac6cbdfaf2e30ed017368d') }
m30000| Wed Nov 21 00:55:19.736 [conn1] end connection 127.0.0.1:57610 (3 connections now open)
m30000| Wed Nov 21 00:55:19.736 [conn2] end connection 127.0.0.1:57612 (3 connections now open)
m30999| Wed Nov 21 00:55:19.736 [WriteBackListener-localhost:30000] Detecting bad connection created at 1353477310066840 microSec, clearing pool for localhost:30000
m30999| Wed Nov 21 00:55:19.736 [WriteBackListener-localhost:30000] WriteBackListener exception : DBClientBase::findN: transport error: localhost:30000 ns: admin.$cmd query: { writebacklisten: ObjectId('50ac6cbdfaf2e30ed017368d') }
m30999| Wed Nov 21 00:55:19.736 [WriteBackListener-localhost:30000] Socket say send() errno:10054 An existing connection was forcibly closed by the remote host. 127.0.0.1:29000
m30999| Wed Nov 21 00:55:19.736 [WriteBackListener-localhost:30000] Detecting bad connection created at 0 microSec, clearing pool for localhost:29000
m30000| Wed Nov 21 00:55:19.736 [conn4] shutdown: closing all files...
m30000| Wed Nov 21 00:55:19.736 [conn4] closeAllFiles() finished
m30000| Wed Nov 21 00:55:19.736 [conn4] journalCleanup...
m30000| Wed Nov 21 00:55:19.736 [conn4] removeJournalFiles
m30000| Wed Nov 21 00:55:19.736 [conn4] shutdown: removing fs lock...
m30000| Wed Nov 21 00:55:19.736 dbexit: really exiting now
m30999| Wed Nov 21 00:55:20.703 [WriteBackListener-localhost:30001] creating new connection to:localhost:30001
m30999| Wed Nov 21 00:55:20.703 BackgroundJob starting: ConnectBG
m30002| Wed Nov 21 00:55:20.750 [initandlisten] connection accepted from 127.0.0.1:57621 #5 (5 connections now open)
m30002| Wed Nov 21 00:55:20.750 [conn5] terminating, shutdown command received
m30002| Wed Nov 21 00:55:20.750 dbexit: shutdown called
m30002| Wed Nov 21 00:55:20.750 [conn5] shutdown: going to close listening sockets...
m30002| Wed Nov 21 00:55:20.750 [conn5] closing listening socket: 488
m30002| Wed Nov 21 00:55:20.750 [conn5] closing listening socket: 500
m30002| Wed Nov 21 00:55:20.750 [conn5] shutdown: going to flush diaglog...
m30002| Wed Nov 21 00:55:20.750 [conn5] shutdown: going to close sockets...
m30002| Wed Nov 21 00:55:20.750 [conn5] shutdown: waiting for fs preallocator...
m30002| Wed Nov 21 00:55:20.750 [conn5] shutdown: lock for final commit...
m30002| Wed Nov 21 00:55:20.750 [conn5] shutdown: final commit...
m30002| Wed Nov 21 00:55:20.750 [conn5] shutdown: closing all files...
m30002| Wed Nov 21 00:55:20.750 [conn5] closeAllFiles() finished
m30002| Wed Nov 21 00:55:20.750 [conn5] journalCleanup...
Wed Nov 21 00:55:20.750 DBClientCursor::init call() failed
m30999| Wed Nov 21 00:55:20.750 [WriteBackListener-localhost:30002] Socket recv() conn closed? 127.0.0.1:30002
m30002| Wed Nov 21 00:55:20.750 [conn1] end connection 127.0.0.1:57566 (4 connections now open)
m30002| Wed Nov 21 00:55:20.750 [conn3] end connection 127.0.0.1:57587 (4 connections now open)
m30002| Wed Nov 21 00:55:20.750 [conn4] end connection 127.0.0.1:57592 (2 connections now open)
m30999| Wed Nov 21 00:55:20.750 [WriteBackListener-localhost:30002] SocketException: remote: 127.0.0.1:30002 error: 9001 socket exception [0] server [127.0.0.1:30002]
m30999| Wed Nov 21 00:55:20.750 [WriteBackListener-localhost:30002] DBClientCursor::init call() failed
m30999| Wed Nov 21 00:55:20.750 [WriteBackListener-localhost:30002] User Assertion: 10276:DBClientBase::findN: transport error: localhost:30002 ns: admin.$cmd query: { writebacklisten: ObjectId('50ac6cbdfaf2e30ed017368d') }
m30999| Wed Nov 21 00:55:20.750 [WriteBackListener-localhost:30002] Detecting bad connection created at 0 microSec, clearing pool for localhost:30002
m30999| Wed Nov 21 00:55:20.750 [WriteBackListener-localhost:30002] WriteBackListener exception : DBClientBase::findN: transport error: localhost:30002 ns: admin.$cmd query: { writebacklisten: ObjectId('50ac6cbdfaf2e30ed017368d') }
m30999| Wed Nov 21 00:55:20.750 [WriteBackListener-localhost:30002] creating new connection to:localhost:29000
m30999| Wed Nov 21 00:55:20.750 BackgroundJob starting: ConnectBG
m30002| Wed Nov 21 00:55:20.750 [conn5] removeJournalFiles
m30002| Wed Nov 21 00:55:20.750 [conn5] shutdown: removing fs lock...
m30002| Wed Nov 21 00:55:20.750 dbexit: really exiting now
m30999| Wed Nov 21 00:55:21.187 [Balancer] creating new connection to:localhost:29000
m30999| Wed Nov 21 00:55:21.187 BackgroundJob starting: ConnectBG
m30998| Wed Nov 21 00:55:21.577 [Balancer] Socket say send() errno:10054 An existing connection was forcibly closed by the remote host. 127.0.0.1:29000
m30998| Wed Nov 21 00:55:21.577 [Balancer] Detecting bad connection created at 0 microSec, clearing pool for localhost:29000
m30998| Wed Nov 21 00:55:21.577 [Balancer] caught exception while doing balance: socket exception [SEND_ERROR] for 127.0.0.1:29000
m30998| Wed Nov 21 00:55:21.577 [Balancer] *** End of balancing round
m30999| Wed Nov 21 00:55:21.717 [WriteBackListener-localhost:30001] WriteBackListener exception : socket exception [CONNECT_ERROR] for localhost:30001
m30999| Wed Nov 21 00:55:21.717 [WriteBackListener-localhost:30001] creating new connection to:localhost:29000
m30999| Wed Nov 21 00:55:21.717 BackgroundJob starting: ConnectBG
m30998| Wed Nov 21 00:55:21.764 [mongosMain] connection accepted from 127.0.0.1:57627 #2 (2 connections now open)
m30998| Wed Nov 21 00:55:21.764 [conn2] scoped connection to localhost:29000 not being returned to the pool
m30998| Wed Nov 21 00:55:21.764 [conn2] Request::process begin ns: admin.$cmd msg id: 34 op: 2004 attempt: 0
m30998| Wed Nov 21 00:55:21.764 [conn2] single query: admin.$cmd { shutdown: 1, force: 1 } ntoreturn: 1 options : 0
m30998| Wed Nov 21 00:55:21.764 [conn2] terminating, shutdown command received
m30998| Wed Nov 21 00:55:21.764 [conn2] dbexit: shutdown called rc:0 shutdown called
Wed Nov 21 00:55:21.764 Socket recv() errno:10054 An existing connection was forcibly closed by the remote host. 127.0.0.1:30998
Wed Nov 21 00:55:21.764 SocketException: remote: 127.0.0.1:30998 error: 9001 socket exception [1] server [127.0.0.1:30998]
Wed Nov 21 00:55:21.764 DBClientCursor::init call() failed
m30999| Wed Nov 21 00:55:21.764 [mongosMain] connection accepted from 127.0.0.1:57628 #2 (2 connections now open)
m30999| Wed Nov 21 00:55:21.764 [conn2] scoped connection to localhost:29000 not being returned to the pool
m30999| Wed Nov 21 00:55:21.764 [conn2] Request::process begin ns: admin.$cmd msg id: 35 op: 2004 attempt: 0
m30999| Wed Nov 21 00:55:21.764 [conn2] single query: admin.$cmd { shutdown: 1, force: 1 } ntoreturn: 1 options : 0
m30999| Wed Nov 21 00:55:21.764 [conn2] terminating, shutdown command received
m30999| Wed Nov 21 00:55:21.764 [conn2] dbexit: shutdown called rc:0 shutdown called
Wed Nov 21 00:55:21.764 Socket recv() errno:10054 An existing connection was forcibly closed by the remote host. 127.0.0.1:30999
Wed Nov 21 00:55:21.764 SocketException: remote: 127.0.0.1:30999 error: 9001 socket exception [1] server [127.0.0.1:30999]
Wed Nov 21 00:55:21.764 DBClientCursor::init call() failed