Tue Dec 18 20:00:15 [clientcursormon] mem (MB) res:61273 virt:1966680 mapped:982801
Tue Dec 18 20:02:48 [rsHealthPoll] replSet info 10.0.0.107:20012 is down (or slow to respond): socket exception
Tue Dec 18 20:02:48 [rsHealthPoll] replSet member 10.0.0.107:20012 is now in state DOWN
Tue Dec 18 20:02:48 [rsHealthPoll] replSet info 10.0.0.107:20011 is down (or slow to respond): socket exception
Tue Dec 18 20:02:48 [rsHealthPoll] replSet member 10.0.0.107:20011 is now in state DOWN
Tue Dec 18 20:02:49 [rsHealthPoll] replSet info 10.0.0.105:20012 is down (or slow to respond): socket exception
Tue Dec 18 20:02:49 [rsHealthPoll] replSet member 10.0.0.105:20012 is now in state DOWN
Tue Dec 18 20:02:49 [rsHealthPoll] replSet info 10.0.0.106:20011 is down (or slow to respond): socket exception
Tue Dec 18 20:02:49 [rsHealthPoll] replSet member 10.0.0.106:20011 is now in state DOWN
Tue Dec 18 20:02:49 [rsHealthPoll] replSet info 10.0.0.106:20012 is down (or slow to respond): socket exception
Tue Dec 18 20:02:49 [rsHealthPoll] replSet member 10.0.0.106:20012 is now in state DOWN
Tue Dec 18 20:02:50 [rsHealthPoll] replSet member 10.0.0.107:20012 is up
Tue Dec 18 20:02:50 [rsHealthPoll] replSet member 10.0.0.107:20012 is now in state ARBITER
Tue Dec 18 20:02:50 [rsHealthPoll] replSet member 10.0.0.107:20011 is up
Tue Dec 18 20:02:50 [rsHealthPoll] replSet member 10.0.0.107:20011 is now in state SECONDARY
Tue Dec 18 20:02:51 [rsHealthPoll] replSet member 10.0.0.105:20012 is up
Tue Dec 18 20:02:51 [rsHealthPoll] replSet member 10.0.0.105:20012 is now in state ARBITER
Tue Dec 18 20:02:51 [rsHealthPoll] replSet member 10.0.0.106:20011 is up
Tue Dec 18 20:02:51 [rsHealthPoll] replSet member 10.0.0.106:20011 is now in state SECONDARY
Tue Dec 18 20:02:51 [rsHealthPoll] replSet member 10.0.0.106:20012 is up
Tue Dec 18 20:02:51 [rsHealthPoll] replSet member 10.0.0.106:20012 is now in state ARBITER
Tue Dec 18 20:02:57 [rsHealthPoll] replSet member 10.0.0.106:20011 is now in state PRIMARY
Tue Dec 18 20:02:57 [rsSync] replSet syncing to: 10.0.0.106:20011
Tue Dec 18 20:04:15 got kill or ctrl c or hup signal 15 (Terminated), will terminate after current cmd ends
Tue Dec 18 20:04:15 [interruptThread] now exiting
Tue Dec 18 20:04:15 dbexit:
Tue Dec 18 20:04:15 [interruptThread] shutdown: going to close listening sockets...
Tue Dec 18 20:04:15 [interruptThread] closing listening socket: 7
Tue Dec 18 20:04:15 [interruptThread] closing listening socket: 8
Tue Dec 18 20:04:15 [interruptThread] closing listening socket: 9
Tue Dec 18 20:04:15 [interruptThread] removing socket file: /tmp/mongodb-20011.sock
Tue Dec 18 20:04:15 [interruptThread] shutdown: going to flush diaglog...
Tue Dec 18 20:04:15 [interruptThread] shutdown: going to close sockets...
Tue Dec 18 20:04:15 [interruptThread] shutdown: waiting for fs preallocator...
Tue Dec 18 20:04:15 [interruptThread] shutdown: lock for final commit...
Tue Dec 18 20:04:15 [interruptThread] shutdown: final commit...
Tue Dec 18 20:04:15 [interruptThread] shutdown: closing all files...
Tue Dec 18 20:04:15 [rsSync] Socket recv() errno:9 Bad file descriptor 10.0.0.106:20011
Tue Dec 18 20:04:15 [rsSync] SocketException: remote: 10.0.0.106:20011 error: 9001 socket exception [1] server [10.0.0.106:20011]
Tue Dec 18 20:04:15 ERROR: Client::shutdown not called: slaveTracking
Tue Dec 18 20:04:15 [rsSync] replSet syncThread: 10278 dbclient error communicating with server: 10.0.0.106:20011
25/491 5%
392/491 79%
Tue Dec 18 20:04:19 [interruptThread] closeAllFiles() finished
Tue Dec 18 20:04:19 [interruptThread] journalCleanup...
Tue Dec 18 20:04:19 [interruptThread] removeJournalFiles
Tue Dec 18 20:04:19 [interruptThread] shutdown: removing fs lock...
Tue Dec 18 20:04:19 dbexit: really exiting now
***** SERVER RESTARTED *****
Tue Dec 18 20:19:24 [initandlisten] MongoDB starting : pid=10105 port=20011 dbpath=/export/data/mongodb_data/ 64-bit host=xxx.com
Tue Dec 18 20:19:24 [initandlisten] db version v2.0.4, pdfile version 4.5
Tue Dec 18 20:19:24 [initandlisten] git version: 329f3c47fe8136c03392c8f0e548506cb21f8ebf
Tue Dec 18 20:19:24 [initandlisten] build info: Linux ip-10-110-9-236 2.6.21.7-2.ec2.v1.2.fc8xen #1 SMP Fri Nov 20 17:48:28 EST 2009 x86_64 BOOST_LIB_VERSION=1_41
Tue Dec 18 20:19:24 [initandlisten] options: { dbpath: "/export/data/mongodb_data/", directoryperdb: true, fork: true, keyFile: "/export/data/key/key", logappend: true, logpath: "/export/data/logs/rs.log", maxConns: 12000, port: 20011, replSet: "poptask", rest: true }
Tue Dec 18 20:19:24 [initandlisten] journal dir=/export/data/mongodb_data/journal
Tue Dec 18 20:19:24 [initandlisten] recover : no journal files present, no recovery needed
Tue Dec 18 20:19:24 [initandlisten] preallocateIsFaster=true 4.48
Tue Dec 18 20:19:25 [initandlisten] preallocateIsFaster=true 8.12
Tue Dec 18 20:19:26 [initandlisten] preallocateIsFaster=true 7.96
Tue Dec 18 20:19:26 [initandlisten] preallocating a journal file /export/data/mongodb_data/journal/prealloc.0
Tue Dec 18 20:19:30 [initandlisten] preallocating a journal file /export/data/mongodb_data/journal/prealloc.1
Tue Dec 18 20:19:34 [initandlisten] preallocating a journal file /export/data/mongodb_data/journal/prealloc.2
Tue Dec 18 20:19:37 [rsStart] replSet can't get local.system.replset config from self or any seed (EMPTYCONFIG)
Tue Dec 18 20:19:37 [rsStart] replSet info you may need to run replSetInitiate -- rs.initiate() in the shell -- if that is not already done
Tue Dec 18 20:19:47 [rsStart] trying to contact 10.0.0.105:20012
Tue Dec 18 20:19:47 [rsStart] trying to contact 10.0.0.106:20011
Tue Dec 18 20:19:47 [rsStart] trying to contact 10.0.0.106:20012
Tue Dec 18 20:19:47 [rsStart] trying to contact 10.0.0.107:20011
Tue Dec 18 20:19:47 [rsStart] trying to contact 10.0.0.107:20012
Tue Dec 18 20:19:47 [rsStart] replSet got config version 4 from a remote, saving locally
Tue Dec 18 20:19:47 [rsStart] replSet info saving a newer config version to local.system.replset
...
Tue Dec 18 20:19:49 [rsHealthPoll] replSet member 10.0.0.107:20011 is up
Tue Dec 18 20:19:49 [rsHealthPoll] replSet member 10.0.0.106:20011 is up
Tue Dec 18 20:19:49 [rsHealthPoll] replSet member 10.0.0.105:20012 is up
Tue Dec 18 20:19:49 [rsHealthPoll] replSet member 10.0.0.107:20012 is up
Tue Dec 18 20:19:49 [rsHealthPoll] replSet member 10.0.0.106:20011 is now in state PRIMARY
Tue Dec 18 20:19:49 [rsHealthPoll] replSet member 10.0.0.105:20012 is now in state ARBITER
Tue Dec 18 20:19:49 [rsHealthPoll] replSet member 10.0.0.107:20012 is now in state ARBITER
Tue Dec 18 20:19:49 [rsHealthPoll] replSet member 10.0.0.106:20012 is up
Tue Dec 18 20:19:49 [rsHealthPoll] replSet member 10.0.0.107:20011 is now in state SECONDARY
Tue Dec 18 20:19:49 [rsHealthPoll] replSet member 10.0.0.106:20012 is now in state ARBITER
Tue Dec 18 20:22:56 [FileAllocator] done allocating datafile /export/data/mongodb_data/local/local.26, size: 2047MB, took 7.54 secs
Tue Dec 18 20:22:58 [rsSync] ******
Tue Dec 18 20:22:58 [rsSync] replSet initial sync pending
Tue Dec 18 20:22:58 [rsSync] replSet syncing to: 10.0.0.107:20011
Tue Dec 18 20:22:58 [rsSync] build index local.me { _id: 1 }
Tue Dec 18 20:22:58 [rsSync] build index done 0 records 0 secs
Tue Dec 18 20:22:58 [rsSync] replSet initial sync drop all databases
Tue Dec 18 20:22:58 [rsSync] dropAllDatabasesExceptLocal 1
Tue Dec 18 20:22:58 [rsSync] replSet initial sync clone all databases
Tue Dec 18 20:22:58 [rsSync] replSet initial sync cloning db: admin
Tue Dec 18 23:00:36 [rsSync] 643882501 objects cloned so far from collection poptask_mg.TASK_SUCCESS
Tue Dec 18 23:00:48 [rsSync] build index poptask_mg.TASK_SUCCESS { _id: 1 }
Tue Dec 18 23:00:52 [clientcursormon] mem (MB) res:58149 virt:828136 mapped:413735
2137000/644712203 0%
4484800/644712203 0%
6770300/644712203 1%
...
643722400/644712203 99%
Tue Dec 18 23:48:50 [rsSync] external sort used : 645 files in 2881 secs
116300/644712203 0%
...
643308900/644712203 99%
Wed Dec 19 05:42:30 [rsSync] done building bottom layer, going to commit
Wed Dec 19 05:45:33 [rsSync] build index done 644712203 records 24284.9 secs
Wed Dec 19 05:45:35 [rsSync] build index poptask_mg.TASK_EXPIRED { _id: 1 }
Wed Dec 19 05:45:35 [rsSync] build index done 8 records 0.03 secs
Wed Dec 19 05:45:41 [rsSync] build index poptask_mg.TASK_FAILURE { _id: 1 }
Wed Dec 19 05:45:42 [rsSync] build index done 115927 records 0.62 secs
Wed Dec 19 05:45:42 [rsSync] build index poptask_mg.TASK_TO_DO { _id: 1 }
Wed Dec 19 05:45:42 [rsSync] build index done 0 records 0.01 secs
Wed Dec 19 05:46:35 [clientcursormon] mem (MB) res:25750 virt:869184 mapped:434205
Wed Dec 19 05:46:42 [rsSync] clone poptask_mg.TASK_SUCCESS201211 3464575
Wed Dec 19 05:46:43 [rsSync] 3530351 objects cloned so far from collection poptask_mg.TASK_SUCCESS201211
Wed Dec 19 07:31:46 [rsSync] info: indexing in foreground on this replica; was a background index build on the primary
Wed Dec 19 07:31:46 [rsSync] build index poptask_mg.TASK_SUCCESS { taskId: 1.0 }
Wed Dec 19 07:31:49 [clientcursormon] mem (MB) res:53381 virt:1131366 mapped:565213
2164200/644712203 0%
...
643273700/644712203 99%
Wed Dec 19 08:23:09 [rsSync] external sort used : 645 files in 3083 secs
Wed Dec 19 13:25:07 [rsSync] done building bottom layer, going to commit
Wed Dec 19 13:25:22 [rsSync] old journal file will be removed: /export/data/mongodb_data/journal/j._115
Wed Dec 19 13:25:22 [rsSync] old journal file will be removed: /export/data/mongodb_data/journal/j._116
Wed Dec 19 13:26:25 [rsSync] DR101 latency warning on journal file open 659ms
Wed Dec 19 13:27:44 [rsSync] build index done 644712203 records 21357.6 secs
Wed Dec 19 13:27:44 [rsSync] info: indexing in foreground on this replica; was a background index build on the primary
Wed Dec 19 13:27:44 [rsSync] build index poptask_mg.TASK_SUCCESS { externalTaskId: 1.0 }
1451500/644712203 0%
...
644000000/644712203 99%
Wed Dec 19 14:34:52 [rsSync] external sort used : 645 files in 4027 secs
96200/644712203 0%
226100/644712203 0%
...
643000000/644712203 99%
Thu Dec 20 02:05:41 [rsSync] external sort used : 645 files in 3595 secs
169700/644712203 0%
...
643867200/644712203 99%
Thu Dec 20 06:44:39 [rsSync] done building bottom layer, going to commit
Thu Dec 20 06:46:25 [rsSync] DR101 latency warning on journal file open 1695ms
Thu Dec 20 06:47:11 [rsSync] build index done 644712203 records 20485.7 secs
Thu Dec 20 06:47:11 [rsSync] info: indexing in foreground on this replica; was a background index build on the primary
...
Thu Dec 20 06:47:16 [rsSync] build index poptask_mg.TASK_SUCCESS201211 { taskId: 1.0 }
1271200/33636123 3%
...
Thu Dec 20 09:49:13 [rsSync] done building bottom layer, going to commit
Thu Dec 20 09:49:17 [rsSync] old journal file will be removed: /export/data/mongodb_data/journal/j._159
Thu Dec 20 09:49:38 [rsSync] old journal file will be removed: /export/data/mongodb_data/journal/j._160
Thu Dec 20 09:50:01 [rsSync] build index done 197750701 records 2770.61 secs
Thu Dec 20 09:50:01 [rsSync] replSet initial sync query minValid
Thu Dec 20 09:50:12 [rsSync] replSet initial oplog application from 10.0.0.107:20011 starting at Dec 18 20:22:52:11 to Dec 20 09:49:55:d2
Thu Dec 20 09:50:29 [rsSync] replSet initialSyncOplogApplication applied 84000 operations, synced to Dec 18 20:35:44:1c
Thu Dec 20 09:50:40 [rsSync] replSet initialSyncOplogApplication applied 219000 operations, synced to Dec 18 20:59:46:8
...
Thu Dec 20 10:18:29 [rsSync] replSet initialSyncOplogApplication applied 13481000 operations, synced to Dec 20 00:58:42:123
Thu Dec 20 10:18:35 [rsSync] Socket recv() errno:104 Connection reset by peer 10.0.0.107:20011
Thu Dec 20 10:18:35 [rsSync] SocketException: remote: 10.0.0.107:20011 error: 9001 socket exception [1] server [10.0.0.107:20011]
Thu Dec 20 10:18:35 [rsSync] replSet initial sync failing, error applying oplog 10278 dbclient error communicating with server: 10.0.0.107:20011
Thu Dec 20 10:18:35 [rsSync] Socket flush send() errno:32 Broken pipe 10.0.0.107:20011
Thu Dec 20 10:18:35 [rsSync] caught exception (socket exception) in destructor (~PiggyBackData)
Thu Dec 20 10:18:35 [rsSync] replSet initial sync failed during applyoplog
Thu Dec 20 10:18:35 [rsSync] replSet cleaning up [1]
Thu Dec 20 10:18:35 [rsSync] replSet cleaning up [2]
Thu Dec 20 10:18:36 [rsHealthPoll] DBClientCursor::init call() failed
Thu Dec 20 10:18:36 [rsHealthPoll] replSet info 10.0.0.107:20011 is down (or slow to respond): DBClientBase::findN: transport error: 10.0.0.107:20011 query: { replSetHeartbeat: "poptask", v: 4, pv: 1, checkEmpty: false, from: "10.0.0.105:20011" }Thu Dec 20 10:18:36 [rsHealthPoll] replSet member 10.0.0.107:20011 is now in state DOWN
Thu Dec 20 10:18:41 [rsSync] replSet initial sync pending
Thu Dec 20 10:18:41 [rsSync] replSet syncing to: 10.0.0.106:20011
Thu Dec 20 10:18:41 [rsSync] replSet initial sync drop all databases
Thu Dec 20 10:18:41 [rsSync] dropAllDatabasesExceptLocal 3
Thu Dec 20 10:18:41 [rsSync] removeJournalFiles
Thu Dec 20 10:18:42 [rsSync] removeJournalFiles
Thu Dec 20 10:18:43 [conn22750] warning: virtual size (480327MB) - mapped size (471258MB) is large (9003MB). could indicate a memory leak