[SERVER-9850] replsets/sync_passive.js fails on Windows 32-bit Created: 03/Jun/13  Updated: 11/Jul/16  Resolved: 16/Jul/13

Status: Closed
Project: Core Server
Component/s: Testing Infrastructure
Affects Version/s: 2.5.0
Fix Version/s: 2.5.1

Type: Bug Priority: Major - P3
Reporter: Tad Marshall Assignee: Tad Marshall
Resolution: Done Votes: 0
Labels: buildbot
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

buildbot Windows 32-bit
buildbot Nightly Windows 32-bit


Issue Links:
Related
is related to SERVER-10236 Make logging work during thread destr... Closed
is related to SERVER-11826 DataFileSync thread should shutdown i... Closed
Backwards Compatibility: Fully Compatible
Operating System: Windows
Participants:

 Description   

jstests/replsets/sync_passive.js failed on Windows 32-bit:
http://buildbot.mongodb.org/builders/Windows%2032-bit/builds/5843/steps/test_9/logs/stdio
http://buildlogs.mongodb.org/Windows%2032-bit/builds/5843/test/replica%20sets/sync_passive.js

For some reason, the server on port 31000 didn't finish shutting down in a timely fashion, but the test proceeded anyway, announcing that the server had been stopped when it was in fact still running.

ReplSetTest stop *** Shutting down mongod in port 31000 ***
 m31000| Mon Jun 03 06:36:00.024 [initandlisten] connection accepted from 127.0.0.1:57852 #13 (5 connections now open)
 m31000| Mon Jun 03 06:36:00.024 [conn13] terminating, shutdown command received
 m31000| Mon Jun 03 06:36:00.024 dbexit: shutdown called
 m31000| Mon Jun 03 06:36:00.024 [conn13] shutdown: going to close listening sockets...
 m31000| Mon Jun 03 06:36:00.024 [conn13] closing listening socket: 476
 m31000| Mon Jun 03 06:36:00.024 [conn13] shutdown: going to flush diaglog...
 m31000| Mon Jun 03 06:36:00.024 [conn13] shutdown: going to close sockets...
 m31000| Mon Jun 03 06:36:00.024 [conn13] shutdown: waiting for fs preallocator...
 m31000| Mon Jun 03 06:36:00.024 [conn13] shutdown: closing all files...
 m31002| Mon Jun 03 06:36:00.024 [conn2] end connection 10.151.17.233:57822 (1 connection now open)
 m31000| Mon Jun 03 06:36:00.024 [conn1] end connection 127.0.0.1:57815 (4 connections now open)
 m31002| Mon Jun 03 06:36:00.024 [rsBackgroundSync] replSet db exception in producer: 10278 dbclient error communicating with server: EC2AMAZ-EXWX6MN:31000
 m31000| Mon Jun 03 06:36:00.024 [conn6] end connection 10.151.17.233:57835 (4 connections now open)
 m31002| Mon Jun 03 06:36:00.024 [rsSyncNotifier] replset tracking exception: exception: 10278 dbclient error communicating with server: EC2AMAZ-EXWX6MN:31000
Mon Jun 03 06:36:00.024 DBClientCursor::init call() failed
Mon Jun 03 06:36:01.038 shell: stopped mongo program on port 31000
// ... snip ...
ReplSetTest (Re)Starting....
Mon Jun 03 06:36:25.889 shell: started program mongod.exe --oplogSize 40 --port 31000 --noprealloc --smallfiles --rest --replSet sync_passive --dbpath /data/db/sync_passive-0 --setParameter enableTestCommands=1
 m31000| note: noprealloc may hurt performance in many applications
 m31000| Mon Jun 03 06:36:25.920 
 m31000| Mon Jun 03 06:36:25.920 warning: 32-bit servers don't have journaling enabled by default. Please use --journal if you want durability.
 m31000| Mon Jun 03 06:36:25.920 
 m31000| Mon Jun 03 06:36:25.920 [initandlisten] MongoDB starting : pid=4804 port=31000 dbpath=/data/db/sync_passive-0 32-bit host=EC2AMAZ-EXWX6MN
 m31000| Mon Jun 03 06:36:25.920 [initandlisten] 
 m31000| Mon Jun 03 06:36:25.920 [initandlisten] ** NOTE: This is a development version (2.5.1-pre-) of MongoDB.
 m31000| Mon Jun 03 06:36:25.920 [initandlisten] **       Not recommended for production.
 m31000| Mon Jun 03 06:36:25.920 [initandlisten] 
 m31000| Mon Jun 03 06:36:25.920 [initandlisten] ** NOTE: This is a 32 bit MongoDB binary.
 m31000| Mon Jun 03 06:36:25.920 [initandlisten] **       32 bit builds are limited to less than 2GB of data (or less with --journal).
 m31000| Mon Jun 03 06:36:25.920 [initandlisten] **       Note that journaling defaults to off for 32 bit and is currently off.
 m31000| Mon Jun 03 06:36:25.920 [initandlisten] **       See http://dochub.mongodb.org/core/32bit
 m31000| Mon Jun 03 06:36:25.920 [initandlisten] 
 m31000| Mon Jun 03 06:36:25.920 [initandlisten] db version v2.5.1-pre-
 m31000| Mon Jun 03 06:36:25.920 [initandlisten] git version: 7652fb20c47fb3847a53bb2231ea23ee8e485623
 m31000| Mon Jun 03 06:36:25.920 [initandlisten] build info: windows sys.getwindowsversion(major=6, minor=0, build=6002, platform=2, service_pack='Service Pack 2') BOOST_LIB_VERSION=1_49
 m31000| Mon Jun 03 06:36:25.920 [initandlisten] allocator: system
 m31000| Mon Jun 03 06:36:25.920 [initandlisten] options: { dbpath: "/data/db/sync_passive-0", noprealloc: true, oplogSize: 40, port: 31000, replSet: "sync_passive", rest: true, setParameter: [ "enableTestCommands=1" ], smallfiles: true }
 m31000| ************** 
 m31000| Unclean shutdown detected.
 m31000| Please visit http://dochub.mongodb.org/core/repair for recovery instructions.
 m31000| *************
 m31000| Mon Jun 03 06:36:25.920 [initandlisten] exception in initAndListen: 12596 old lock file, terminating
 m31000| Mon Jun 03 06:36:25.920 dbexit: 
 m31000| Mon Jun 03 06:36:25.920 [initandlisten] shutdown: going to close listening sockets...
 m31000| Mon Jun 03 06:36:25.920 [initandlisten] shutdown: going to flush diaglog...
 m31000| Mon Jun 03 06:36:25.920 [initandlisten] shutdown: going to close sockets...
 m31000| Mon Jun 03 06:36:25.920 [initandlisten] shutdown: waiting for fs preallocator...
 m31000| Mon Jun 03 06:36:25.920 [initandlisten] shutdown: closing all files...
 m31000| Mon Jun 03 06:36:25.920 [initandlisten] closeAllFiles() finished
 m31000| Mon Jun 03 06:36:25.920 dbexit: really exiting now

The shell announced:

Mon Jun 03 06:36:01.038 shell: stopped mongo program on port 31000

but the server on port 31000 had not printed "dbexit: really exiting now", so it was still running. This caused the restart to fail, causing the test to fail.



 Comments   
Comment by auto [ 16/Jul/13 ]

Author:

{u'username': u'tadmarshall', u'name': u'Tad Marshall', u'email': u'tad@10gen.com'}

Message: SERVER-9850 Disable logging in the Client destructor
Branch: master
https://github.com/mongodb/mongo/commit/2cf30807f82d325ef706211667cd80e008e8ca68

Comment by Tad Marshall [ 16/Jul/13 ]

Removing the messages (I commented them out for my test) does work around the problem. The test passes in 32-bit release Windows, even with the sleeps in the closeAllFiles() loop.

This seems like an adequate fix for this milestone, but we should file a ticket to force the LogstreamBuilder's threadOstreamCache to be the last TSP deleted so that we don't trip over this again.

Comment by Tad Marshall [ 16/Jul/13 ]

Yes, I think that removing the message would work around the problem. There is a second message (just above it) that should also be removed if we take this approach.

I'll verify that removing the message makes the access violation go away and will report back.

Comment by Eric Milkie [ 16/Jul/13 ]

Can we remove the message from Client destructor? It's a message that goes pretty much ignored everywhere anyway.

Comment by Tad Marshall [ 16/Jul/13 ]

I was able to reproduce the crash on the build slave (by adding a sleep within the closeAllFiles() loop).

This is a problem that we have seen before but have not solved.

Here's the call stack of the crashing thread:

>Debug.ListCallStack
 Index  Function
--------------------------------------------------------------------------------
*1      mongod.exe!mongo::logger::LogstreamBuilder::makeStream() 
 2      mongod.exe!mongo::Client::~Client() 
 3      mongod.exe!mongo::Client::`scalar deleting destructor'() 
 4      mongod.exe!boost::thread_specific_ptr<mongo::Client>::delete_data::operator()(void * data=0x02068ea0) 
 5      mongod.exe!boost::`anonymous namespace'::run_thread_exit_callbacks() 
 6      mongod.exe!boost::`anonymous namespace'::thread_start_function(void * param=0x01b8bba0) 
 7      mongod.exe!_callthreadstartex() 
 8      mongod.exe!_threadstartex(void * ptd=0x02081310) 
 9      kernel32.dll!@BaseThreadInitThunk@12() 
 10     ntdll.dll!___RtlUserThreadStart@8() 
 11     ntdll.dll!__RtlUserThreadStart@8() 
 
>

The boost thread termination code is cleaning up thread_specific_ptrs and it has deleted the threadOstreamCache before deleting the Client object. Moreover, shutdown() was not called on the Client object, and it is trying to log this fact:

    Client::~Client() {
        _god = 0;
 
        if ( _context )
            error() << "Client::~Client _context should be null but is not; client:" << _desc << endl;
 
        if ( ! _shutdown ) {
            error() << "Client::shutdown not called: " << _desc << endl;
        }

The code is executing line 8 in the excerpt above when it crashes.

The crash causes an access violation, which transfers control to the unhandled exception handler. It tries to use the deleted log() object to log the access violation, and generates a nested exception when it tries to do this. On the double-exception, Windows immediately terminates the process and there is no log output to indicate what happened.

I wrote a comment in an earlier Jira ticket when I saw this before, but I'm having trouble finding the ticket.

This affects 64-bit Windows also, though the symptoms are a little different. For whatever reason, some log output is produced around the crash:

kill master
ReplSetTest n: 0 ports: [ 31000, 31001, 31002, 31003, 31004 ]   31000 number
ReplSetTest stop *** Shutting down mongod in port 31000 ***
 m31000| Tue Jul 16 08:10:49.959 [initandlisten] connection accepted from 127.0.0.1:55585 #27 (6 connections now open)
 m31000| Tue Jul 16 08:10:49.960 [conn27] terminating, shutdown command received
 m31000| dbexit: shutdown calledTue Jul 16 08:10:49.960 [conn27] shutdown: going to close listening sockets...
 m31000| Tue Jul 16 08:10:49.960 [conn27] closing listening socket: 848
Tue Jul 16 08:10:49.961  m31000| Tue Jul 16 08:10:49.960 [conn27] closing listening socket: 864
DBClientCursor::init call() failed
 m31000| Tue Jul 16 08:10:49.961 [conn27] shutdown: going to flush diaglog...
 m31000| Tue Jul 16 08:10:49.961 [conn27] shutdown: going to close sockets...
 m31000| Tue Jul 16 08:10:49.961 [conn27] shutdown: waiting for fs preallocator...
 m31000| Tue Jul 16 08:10:49.961 [conn27] shutdown: lock for final commit...
 m31000| Tue Jul 16 08:10:49.961 [conn1] end connection 127.0.0.1:55273 (5 connections now open)
 m31000| Tue Jul 16 08:10:49.961 [conn25] end connection 192.168.1.2:55566 (5 connections now open)
 m31000| Tue Jul 16 08:10:49.961 [conn27] shutdown: final commit...
 m31001| Tue Jul 16 08:10:49.961 [conn19] end connection 192.168.1.2:55555 (2 connections now open)
 m31002| Tue Jul 16 08:10:49.961 [conn16] end connection 192.168.1.2:55494 (2 connections now open)
 m31000| Tue Jul 16 08:10:49.961 [conn26] end connection 192.168.1.2:55568 (5 connections now open)
 m31000| Tue Jul 16 08:10:49.962 [conn1] thread conn1 stack usage was 40440 bytes,  which is the most so far
 m31002| Tue Jul 16 08:10:49.961 [rsSyncNotifier] replset tracking exception: exception: 10278 dbclient error communicating with server: MissLucy:31000
 m31002| Tue Jul 16 08:10:49.962 [rsBackgroundSync] replSet sync source problem: 10278 dbclient error communicating with server: MissLucy:31000
 m31002| Tue Jul 16 08:10:49.962 [rsBackgroundSync] replSet syncing to: MissLucy:31000
 m31000| Tue Jul 16 08:10:50.012 [conn27] shutdown: closing all files...
 m31000| Tue Jul 16 08:10:50.831 [slaveTracking] ERROR: Client::shutdown not called: slaveTracking
 m31000| Tue Jul 16 08:10:50.833 [slaveTracking] *** unhandled exception (access violation) at 0x0000000140478604, terminating

The above excerpt is the last output from the mongod.exe on port 31000.

The 64-bit version recovers using the journal when it is restarted:

ReplSetTest (Re)Starting....
Tue Jul 16 08:11:42.139 shell: started program mongod.exe --oplogSize 40 --port 31000 --noprealloc --smallfiles --rest --replSet sync_passive2 --dbpath /data/db/sync_passive2-0 --s
etParameter enableTestCommands=1
 m31000| Tue Jul 16 08:11:42.185 ** WARNING: --rest is specified without --httpinterface,
 m31000| Tue Jul 16 08:11:42.186 **          enabling http interface
 m31000| note: noprealloc may hurt performance in many applications
 m31000| Tue Jul 16 08:11:42.231 [initandlisten] MongoDB starting : pid=7036 port=31000 dbpath=/data/db/sync_passive2-0 64-bit host=MissLucy
 m31000| Tue Jul 16 08:11:42.231 [initandlisten] _DEBUG build (which is slower)
 m31000| Tue Jul 16 08:11:42.231 [initandlisten]
 m31000| Tue Jul 16 08:11:42.232 [initandlisten] ** NOTE: This is a development version (2.5.1-pre-) of MongoDB.
 m31000| Tue Jul 16 08:11:42.232 [initandlisten] **       Not recommended for production.
 m31000| Tue Jul 16 08:11:42.232 [initandlisten]
 m31000| Tue Jul 16 08:11:42.232 [initandlisten] db version v2.5.1-pre-
 m31000| Tue Jul 16 08:11:42.232 [initandlisten] git version: 704dc4fdf5248077c53271f249260478d6c56cd3
 m31000| Tue Jul 16 08:11:42.232 [initandlisten] build info: windows sys.getwindowsversion(major=6, minor=1, build=7601, platform=2, service_pack='Service Pack 1') BOOST_LIB_VERSIO
N=1_49
 m31000| Tue Jul 16 08:11:42.232 [initandlisten] allocator: system
 m31000| Tue Jul 16 08:11:42.232 [initandlisten] options: { dbpath: "/data/db/sync_passive2-0", noprealloc: true, oplogSize: 40, port: 31000, replSet: "sync_passive2", rest: true,
setParameter: [ "enableTestCommands=1" ], smallfiles: true }
 m31000| Tue Jul 16 08:11:42.236 [initandlisten] journal dir=/data/db/sync_passive2-0\journal
 m31000| Tue Jul 16 08:11:42.237 [initandlisten] recover begin
 m31000| Tue Jul 16 08:11:42.237 [initandlisten] recover lsn: 59692
 m31000| Tue Jul 16 08:11:42.237 [initandlisten] recover /data/db/sync_passive2-0\journal\j._0
 m31000| Tue Jul 16 08:11:42.238 [initandlisten] recover skipping application of section seq:0 < lsn:59692
 m31000| Tue Jul 16 08:11:42.238 [initandlisten] recover skipping application of section seq:2842 < lsn:59692
 m31000| Tue Jul 16 08:11:42.253 [initandlisten] checkHash len:2023 hash:3937054BE9FBFCEE4F9A67309F36DDAD current:3937054BE9FBFCEE4F9A67309F36DDAD
 m31000| Tue Jul 16 08:11:42.256 [initandlisten] checkHash len:7179 hash:B6AE402CD0843B6CAF66DA9B5216D974 current:B6AE402CD0843B6CAF66DA9B5216D974
 m31000| Tue Jul 16 08:11:42.257 [initandlisten] checkHash len:12781 hash:D976406446E835F99728D3214393A90A current:D976406446E835F99728D3214393A90A
 m31000| Tue Jul 16 08:11:42.258 [initandlisten] checkHash len:4860 hash:0D59CA8DA5DCC57A4315A7F927272437 current:0D59CA8DA5DCC57A4315A7F927272437
 m31000| Tue Jul 16 08:11:42.259 [initandlisten] checkHash len:8520 hash:5671FFBEDB1AC38FDAD2075407539BEF current:5671FFBEDB1AC38FDAD2075407539BEF
 m31000| Tue Jul 16 08:11:42.260 [initandlisten] checkHash len:5893 hash:082848ACB0BE35A040E7DE10C296A5FA current:082848ACB0BE35A040E7DE10C296A5FA
 m31000| Tue Jul 16 08:11:42.262 [initandlisten] checkHash len:13825 hash:039C9924217F374DD85798231B3B584D current:039C9924217F374DD85798231B3B584D
 m31000| Tue Jul 16 08:11:42.263 [initandlisten] checkHash len:7813 hash:77818067233D10BCE002C8D6304F129F current:77818067233D10BCE002C8D6304F129F
 m31000| Tue Jul 16 08:11:42.264 [initandlisten] checkHash len:4499 hash:9BE71A6D15B63D4F145F9879F01B8A88 current:9BE71A6D15B63D4F145F9879F01B8A88
 m31000| Tue Jul 16 08:11:42.265 [initandlisten] checkHash len:7469 hash:06E981F3573718CF3DE6B43E3203A538 current:06E981F3573718CF3DE6B43E3203A538
 m31000| Tue Jul 16 08:11:42.266 [initandlisten] checkHash len:15000 hash:02A05C630C41F4AB747DD4837C8D9730 current:02A05C630C41F4AB747DD4837C8D9730
 m31000| Tue Jul 16 08:11:42.267 [initandlisten] checkHash len:6454 hash:83C55765D0EEDBDA91DC513B710FED9C current:83C55765D0EEDBDA91DC513B710FED9C
 m31004| Tue Jul 16 08:11:42.268 [rsHealthPoll] couldn't connect to MissLucy:31000: couldn't connect to server MissLucy:31000
 m31000| Tue Jul 16 08:11:42.268 [initandlisten] checkHash len:7105 hash:82A68BA8B2C1512B0460E257DD76C9B6 current:82A68BA8B2C1512B0460E257DD76C9B6
 m31000| Tue Jul 16 08:11:42.269 [initandlisten] checkHash len:10811 hash:3D9DCBFEB4D68AC56CAD5BC430EF225E current:3D9DCBFEB4D68AC56CAD5BC430EF225E
 m31002| Tue Jul 16 08:11:42.270 [rsHealthPoll] couldn't connect to MissLucy:31000: couldn't connect to server MissLucy:31000
 m31000| Tue Jul 16 08:11:42.270 [initandlisten] checkHash len:7675 hash:E50EA9CF4F968279BEC7B83F0D35330C current:E50EA9CF4F968279BEC7B83F0D35330C
 m31000| Tue Jul 16 08:11:42.271 [initandlisten] checkHash len:8005 hash:0F6A66E869D6014E34770BA2763D877C current:0F6A66E869D6014E34770BA2763D877C
 m31000| Tue Jul 16 08:11:42.272 [initandlisten] checkHash len:7405 hash:22A0851715958CF4A63E359FEB4F510B current:22A0851715958CF4A63E359FEB4F510B
 m31000| Tue Jul 16 08:11:42.273 [initandlisten] checkHash len:12834 hash:DA745A7F39E05BBF482B662B2EAC13CD current:DA745A7F39E05BBF482B662B2EAC13CD
 m31000| Tue Jul 16 08:11:42.274 [initandlisten] checkHash len:6421 hash:271B4F00C18C6D2D7A9B8E9FB80CFA47 current:271B4F00C18C6D2D7A9B8E9FB80CFA47
 m31000| Tue Jul 16 08:11:42.275 [initandlisten] checkHash len:8223 hash:A8FF97607EE5DEEFE8D697C84385C7CE current:A8FF97607EE5DEEFE8D697C84385C7CE
 m31000| Tue Jul 16 08:11:42.276 [initandlisten] checkHash len:5557 hash:91BEA52707F9329E7247CC08999BF887 current:91BEA52707F9329E7247CC08999BF887
 m31000| Tue Jul 16 08:11:42.278 [initandlisten] checkHash len:14409 hash:85F0D26B3CF103A14C003EF662C4E2C3 current:85F0D26B3CF103A14C003EF662C4E2C3
 m31000| Tue Jul 16 08:11:42.279 [initandlisten] checkHash len:7307 hash:FAF2CFE187072F71B36DEE9A68A6A2B8 current:FAF2CFE187072F71B36DEE9A68A6A2B8
 m31000| Tue Jul 16 08:11:42.280 [initandlisten] checkHash len:6926 hash:0E1382F85B1E5ED5CFD03F5443CDE0B2 current:0E1382F85B1E5ED5CFD03F5443CDE0B2
 m31000| Tue Jul 16 08:11:42.281 [initandlisten] checkHash len:10035 hash:330FD539C88696CB8E765150723B15A7 current:330FD539C88696CB8E765150723B15A7
 m31000| Tue Jul 16 08:11:42.282 [initandlisten] checkHash len:10198 hash:A6055BD9B42817FE88F0E919E3826ECE current:A6055BD9B42817FE88F0E919E3826ECE
 m31000| Tue Jul 16 08:11:42.283 [initandlisten] checkHash len:5606 hash:8C35733E3816CB5D98EE40F666BF8C71 current:8C35733E3816CB5D98EE40F666BF8C71
 m31002| Tue Jul 16 08:11:42.284 [conn3] end connection 192.168.1.2:55774 (8 connections now open)
 m31000| Tue Jul 16 08:11:42.284 [initandlisten] checkHash len:8303 hash:4338290EC362B058941900D4804802DA current:4338290EC362B058941900D4804802DA
 m31002| Tue Jul 16 08:11:42.284 [initandlisten] connection accepted from 192.168.1.2:55819 #14 (10 connections now open)
 m31000| Tue Jul 16 08:11:42.285 [initandlisten] checkHash len:12788 hash:D9FE3DE7E8362D0ADF0A21D27B4193C5 current:D9FE3DE7E8362D0ADF0A21D27B4193C5
 m31000| Tue Jul 16 08:11:42.286 [initandlisten] checkHash len:6910 hash:6983DB7D545EB4ED8B642D24B6B7701C current:6983DB7D545EB4ED8B642D24B6B7701C
 m31000| Tue Jul 16 08:11:42.287 [initandlisten] checkHash len:8089 hash:9CA42CDCE8E7674B38CB2AC1008FE7C8 current:9CA42CDCE8E7674B38CB2AC1008FE7C8
 m31000| Tue Jul 16 08:11:42.288 [initandlisten] checkHash len:11077 hash:D57C96D998056D07025FC8A79C03126F current:D57C96D998056D07025FC8A79C03126F
 m31000| Tue Jul 16 08:11:42.289 [initandlisten] checkHash len:7957 hash:42D1C33464EED245A2E495CF812F22EB current:42D1C33464EED245A2E495CF812F22EB
 m31000| Tue Jul 16 08:11:42.290 [initandlisten] checkHash len:7674 hash:AAA3D0615B6C66E79F0264C913256B2F current:AAA3D0615B6C66E79F0264C913256B2F
 m31000| Tue Jul 16 08:11:42.291 [initandlisten] checkHash len:7275 hash:835AF9FD12D8714DEA7421E579086D59 current:835AF9FD12D8714DEA7421E579086D59
 m31000| Tue Jul 16 08:11:42.292 [initandlisten] checkHash len:12583 hash:F88E221FFD1E24B36B023F21FE705ABE current:F88E221FFD1E24B36B023F21FE705ABE
 m31000| Tue Jul 16 08:11:42.293 [initandlisten] checkHash len:7002 hash:97817DF13C1787325B027D2443A47EBC current:97817DF13C1787325B027D2443A47EBC
 m31000| Tue Jul 16 08:11:42.294 [initandlisten] checkHash len:7583 hash:BC385FBF29EF5349C6436201FAA51E9A current:BC385FBF29EF5349C6436201FAA51E9A
 m31000| Tue Jul 16 08:11:42.296 [initandlisten] checkHash len:12086 hash:97B659359171B0B9A6529E148BFDD158 current:97B659359171B0B9A6529E148BFDD158
 m31000| Tue Jul 16 08:11:42.297 [initandlisten] checkHash len:7145 hash:5BADE2E6BD2477EAE9CFC755DCC55113 current:5BADE2E6BD2477EAE9CFC755DCC55113
 m31000| Tue Jul 16 08:11:42.297 [initandlisten] checkHash len:4843 hash:F716F30C9A5FDCD49815381C71C41AAE current:F716F30C9A5FDCD49815381C71C41AAE
 m31000| Tue Jul 16 08:11:42.299 [initandlisten] checkHash len:10014 hash:C305418B3CF3FE776EAE4991E3BB72BF current:C305418B3CF3FE776EAE4991E3BB72BF
 m31002| Tue Jul 16 08:11:42.299 [conn5] end connection 192.168.1.2:55775 (8 connections now open)
 m31002| Tue Jul 16 08:11:42.299 [initandlisten] connection accepted from 192.168.1.2:55820 #15 (10 connections now open)
 m31000| Tue Jul 16 08:11:42.300 [initandlisten] checkHash len:10631 hash:43BFED748A63870F9CA15E3D5B9C10BB current:43BFED748A63870F9CA15E3D5B9C10BB
 m31000| Tue Jul 16 08:11:42.301 [initandlisten] checkHash len:7994 hash:A3698F1D28AF5ECBB350825E4FDA3D87 current:A3698F1D28AF5ECBB350825E4FDA3D87
 m31000| Tue Jul 16 08:11:42.302 [initandlisten] checkHash len:8582 hash:4016062E13E30ACB006C729BBEE49E1D current:4016062E13E30ACB006C729BBEE49E1D
 m31000| Tue Jul 16 08:11:42.303 [initandlisten] checkHash len:12209 hash:A810F259061B8FE81C8F180A9CD68C62 current:A810F259061B8FE81C8F180A9CD68C62
 m31000| Tue Jul 16 08:11:42.304 [initandlisten] checkHash len:6692 hash:4BDAE531518DF6D4E01D491F1DCBC6A3 current:4BDAE531518DF6D4E01D491F1DCBC6A3
 m31000| Tue Jul 16 08:11:42.305 [initandlisten] checkHash len:6632 hash:F8858AC3E1FAC2C8AEC7735084D5EA6A current:F8858AC3E1FAC2C8AEC7735084D5EA6A
 m31000| Tue Jul 16 08:11:42.306 [initandlisten] checkHash len:7676 hash:F9F5536DC5748FBAEC70BD38292E089A current:F9F5536DC5748FBAEC70BD38292E089A
 m31000| Tue Jul 16 08:11:42.307 [initandlisten] checkHash len:11824 hash:2B2BC92CD2805CA6CC7DB672D6D10D57 current:2B2BC92CD2805CA6CC7DB672D6D10D57
 m31000| Tue Jul 16 08:11:42.308 [initandlisten] checkHash len:8427 hash:00B7C8423D3F161E26F9CE182771CC55 current:00B7C8423D3F161E26F9CE182771CC55
 m31000| Tue Jul 16 08:11:42.309 [initandlisten] checkHash len:7221 hash:1FC31172A25A2F898305749296C22922 current:1FC31172A25A2F898305749296C22922
 m31000| Tue Jul 16 08:11:42.311 [initandlisten] checkHash len:12731 hash:84C2D1B272B6FE304A9BEBED71996C93 current:84C2D1B272B6FE304A9BEBED71996C93
 m31000| Tue Jul 16 08:11:42.311 [initandlisten] checkHash len:6590 hash:B228C598F2AB6F7CE2A913EE7B1E670F current:B228C598F2AB6F7CE2A913EE7B1E670F
 m31000| Tue Jul 16 08:11:42.312 [initandlisten] checkHash len:5201 hash:AE60118CCB38046A3FB1EED837CD9420 current:AE60118CCB38046A3FB1EED837CD9420
 m31000| Tue Jul 16 08:11:42.313 [initandlisten] checkHash len:6809 hash:C429E89F5B3FA42C164F80571FCE3653 current:C429E89F5B3FA42C164F80571FCE3653
 m31000| Tue Jul 16 08:11:42.315 [initandlisten] checkHash len:15514 hash:396FF8973BD8463F0B9261DFA2CBE7C2 current:396FF8973BD8463F0B9261DFA2CBE7C2
 m31000| Tue Jul 16 08:11:42.316 [initandlisten] checkHash len:5792 hash:C7E8BFC3BBF1EB0714BA267AA9F62EF6 current:C7E8BFC3BBF1EB0714BA267AA9F62EF6
 m31000| Tue Jul 16 08:11:42.317 [initandlisten] checkHash len:6728 hash:5774A5917D9AEB728383C1C394756218 current:5774A5917D9AEB728383C1C394756218
 m31000| Tue Jul 16 08:11:42.318 [initandlisten] checkHash len:9481 hash:F1AF181677CE7993D675CBFB10E9D483 current:F1AF181677CE7993D675CBFB10E9D483
 m31000| Tue Jul 16 08:11:42.319 [initandlisten] checkHash len:13463 hash:8CB4634D914834FA720E4311A9AE9D8D current:8CB4634D914834FA720E4311A9AE9D8D
 m31000| Tue Jul 16 08:11:42.320 [initandlisten] checkHash len:6176 hash:4B00DEA46AFA0C7B84C28E6730E6A9CC current:4B00DEA46AFA0C7B84C28E6730E6A9CC
 m31000| Tue Jul 16 08:11:42.321 [initandlisten] checkHash len:8121 hash:EC2B054EE03A002BD7C5718E6FA8EC39 current:EC2B054EE03A002BD7C5718E6FA8EC39
 m31000| Tue Jul 16 08:11:42.322 [initandlisten] checkHash len:9995 hash:227BE1ECDEC3330C027A02C4AA3C5094 current:227BE1ECDEC3330C027A02C4AA3C5094
 m31000| Tue Jul 16 08:11:42.323 [initandlisten] checkHash len:9403 hash:46577882911013D39C90AD923C96ED62 current:46577882911013D39C90AD923C96ED62
 m31000| Tue Jul 16 08:11:42.324 [initandlisten] checkHash len:5958 hash:4CABC0D34B7B5D03648CC80EF523A431 current:4CABC0D34B7B5D03648CC80EF523A431
 m31000| Tue Jul 16 08:11:42.325 [initandlisten] checkHash len:6774 hash:591C03B4366580579B6BA9AAECF1E766 current:591C03B4366580579B6BA9AAECF1E766
 m31000| Tue Jul 16 08:11:42.326 [initandlisten] checkHash len:13181 hash:EC987516EAAA534C74581B56944194EC current:EC987516EAAA534C74581B56944194EC
 m31000| Tue Jul 16 08:11:42.327 [initandlisten] checkHash len:6800 hash:781B4EA2CA330C01EB31B66874164BD3 current:781B4EA2CA330C01EB31B66874164BD3
 m31000| Tue Jul 16 08:11:42.328 [initandlisten] checkHash len:7683 hash:862CE84ACCC38F98F9C3482450DAB241 current:862CE84ACCC38F98F9C3482450DAB241
 m31000| Tue Jul 16 08:11:42.329 [initandlisten] checkHash len:5753 hash:ED2D349B2A2E09C330E4BF690C302F81 current:ED2D349B2A2E09C330E4BF690C302F81
 m31000| Tue Jul 16 08:11:42.330 [initandlisten] checkHash len:13844 hash:12510BDBFF44715C198F2D172095AAD2 current:12510BDBFF44715C198F2D172095AAD2
 m31000| Tue Jul 16 08:11:42.332 [initandlisten] checkHash len:7142 hash:307FA3AC57A93C66FA9D9FFBB42FE795 current:307FA3AC57A93C66FA9D9FFBB42FE795
 m31000| Tue Jul 16 08:11:42.332 [initandlisten] checkHash len:6545 hash:1F0D65C366B0345E9CBBA6E13190C3E2 current:1F0D65C366B0345E9CBBA6E13190C3E2
 m31000| Tue Jul 16 08:11:42.333 [initandlisten] checkHash len:11314 hash:C9DD4FA68DA62B610FCB094D0B3A38CD current:C9DD4FA68DA62B610FCB094D0B3A38CD
 m31000| Tue Jul 16 08:11:42.335 [initandlisten] checkHash len:8137 hash:1DC71E1041BD802AE5A70DF650C992DE current:1DC71E1041BD802AE5A70DF650C992DE
 m31000| Tue Jul 16 08:11:42.336 [initandlisten] checkHash len:6359 hash:77FE570DE21875DCC0F0DCBBCEBD6CBA current:77FE570DE21875DCC0F0DCBBCEBD6CBA
 m31000| Tue Jul 16 08:11:42.336 [initandlisten] checkHash len:7360 hash:3A0236C9C367118EE92F624C86BE6497 current:3A0236C9C367118EE92F624C86BE6497
 m31000| Tue Jul 16 08:11:42.338 [initandlisten] checkHash len:12689 hash:B3D7765D427183F3528F8910CC03E0C9 current:B3D7765D427183F3528F8910CC03E0C9
 m31000| Tue Jul 16 08:11:42.339 [initandlisten] checkHash len:7130 hash:0B9F6A776C5C1BFB8DD495D5C1BFD75B current:0B9F6A776C5C1BFB8DD495D5C1BFD75B
 m31000| Tue Jul 16 08:11:42.340 [initandlisten] checkHash len:7150 hash:8AEF78DBCCA0951FC242FA105F0DEDB1 current:8AEF78DBCCA0951FC242FA105F0DEDB1
 m31000| Tue Jul 16 08:11:42.341 [initandlisten] checkHash len:6148 hash:5AB47F36D3955DE171990289D9173557 current:5AB47F36D3955DE171990289D9173557
 m31000| Tue Jul 16 08:11:42.342 [initandlisten] checkHash len:12378 hash:BCAAD310D3D4A276EBD93A85B45E1C3C current:BCAAD310D3D4A276EBD93A85B45E1C3C
 m31000| Tue Jul 16 08:11:42.343 [initandlisten] checkHash len:7778 hash:CC233057B2865CBAF81E2842CD706891 current:CC233057B2865CBAF81E2842CD706891
 m31000| Tue Jul 16 08:11:42.344 [initandlisten] checkHash len:5643 hash:5314D3C053F0B43CA65A8B27D507342F current:5314D3C053F0B43CA65A8B27D507342F
 m31000| Tue Jul 16 08:11:42.345 [initandlisten] checkHash len:12672 hash:EC9C0BC1B205BC9A18BD2D5615AC74E0 current:EC9C0BC1B205BC9A18BD2D5615AC74E0
 m31000| Tue Jul 16 08:11:42.346 [initandlisten] checkHash len:8056 hash:1C3F7C8F0E3108523AB11A7488ABD669 current:1C3F7C8F0E3108523AB11A7488ABD669
 m31000| Tue Jul 16 08:11:42.347 [initandlisten] checkHash len:7579 hash:05F060D29CEEEF5EC1CB3AD0D10378B9 current:05F060D29CEEEF5EC1CB3AD0D10378B9
 m31000| Tue Jul 16 08:11:42.348 [initandlisten] checkHash len:6861 hash:427DB1384B9668D8221260277E504A82 current:427DB1384B9668D8221260277E504A82
 m31000| Tue Jul 16 08:11:42.349 [initandlisten] checkHash len:13228 hash:5623C60ECD24A7BD4F2ECA1EB6CFF155 current:5623C60ECD24A7BD4F2ECA1EB6CFF155
 m31000| Tue Jul 16 08:11:42.350 [initandlisten] checkHash len:6129 hash:B955C8ED07CE24F6A69DEECB567E5461 current:B955C8ED07CE24F6A69DEECB567E5461
 m31000| Tue Jul 16 08:11:42.351 [initandlisten] checkHash len:6350 hash:CC49272F8486B1EA1D747B530027D2E3 current:CC49272F8486B1EA1D747B530027D2E3
 m31000| Tue Jul 16 08:11:42.352 [initandlisten] checkHash len:13074 hash:0C577FFD45BEFC827C6E1EAA51B7B45E current:0C577FFD45BEFC827C6E1EAA51B7B45E
 m31000| Tue Jul 16 08:11:42.353 [initandlisten] checkHash len:7650 hash:E0C88621F3825746906136E58C6E75B0 current:E0C88621F3825746906136E58C6E75B0
 m31000| Tue Jul 16 08:11:42.354 [initandlisten] checkHash len:7360 hash:D22851D3D70F368ACB92A0A76B011271 current:D22851D3D70F368ACB92A0A76B011271
 m31000| Tue Jul 16 08:11:42.355 [initandlisten] checkHash len:5332 hash:6938F8C3DC1C0C6E191D8B9476CF36EC current:6938F8C3DC1C0C6E191D8B9476CF36EC
 m31000| Tue Jul 16 08:11:42.356 [initandlisten] checkHash len:13464 hash:17B8A5FB721F13B644E9B91C8F4378D5 current:17B8A5FB721F13B644E9B91C8F4378D5
 m31000| Tue Jul 16 08:11:42.357 [initandlisten] checkHash len:7159 hash:52EA74467DAC3A339EE41E5097C8F9E6 current:52EA74467DAC3A339EE41E5097C8F9E6
 m31000| Tue Jul 16 08:11:42.358 [initandlisten] checkHash len:5648 hash:4325B710937CE88BB0832C1626CA51A2 current:4325B710937CE88BB0832C1626CA51A2
 m31000| Tue Jul 16 08:11:42.359 [initandlisten] checkHash len:7610 hash:F7C70F84CAA6E2009F6CDC60EFA74017 current:F7C70F84CAA6E2009F6CDC60EFA74017
 m31000| Tue Jul 16 08:11:42.361 [initandlisten] checkHash len:11993 hash:D8C882BF2F350EEE1795330ADAC0F76C current:D8C882BF2F350EEE1795330ADAC0F76C
 m31000| Tue Jul 16 08:11:42.361 [initandlisten] checkHash len:7546 hash:3957C9C7FF4A072D627B2E9A03CD20D2 current:3957C9C7FF4A072D627B2E9A03CD20D2
 m31000| Tue Jul 16 08:11:42.362 [initandlisten] checkHash len:7840 hash:D4B37D2A8EA3C6D4779F74F1DB680EBC current:D4B37D2A8EA3C6D4779F74F1DB680EBC
 m31000| Tue Jul 16 08:11:42.364 [initandlisten] checkHash len:11920 hash:18EFFFA49E930556C042049FB5B43FA4 current:18EFFFA49E930556C042049FB5B43FA4
 m31000| Tue Jul 16 08:11:42.365 [initandlisten] checkHash len:5818 hash:1E909EFFAC9A7A8E055E19A00671DFCE current:1E909EFFAC9A7A8E055E19A00671DFCE
 m31000| Tue Jul 16 08:11:42.366 [initandlisten] checkHash len:6991 hash:44DF6F0BA40E5BF9F3071F278B494D33 current:44DF6F0BA40E5BF9F3071F278B494D33
 m31000| Tue Jul 16 08:11:42.366 [initandlisten] checkHash len:7412 hash:B452DD4DD5F6BA0412B493B7FCC26D29 current:B452DD4DD5F6BA0412B493B7FCC26D29
 m31000| Tue Jul 16 08:11:42.368 [initandlisten] checkHash len:10792 hash:148D171233D34681FF70B2D0A2CEE582 current:148D171233D34681FF70B2D0A2CEE582
 m31000| Tue Jul 16 08:11:42.369 [initandlisten] checkHash len:8014 hash:E26B99F4BF296F0E7DBBC1594E9D6B78 current:E26B99F4BF296F0E7DBBC1594E9D6B78
 m31000| Tue Jul 16 08:11:42.370 [initandlisten] checkHash len:7145 hash:3BB3C391CB522CAF4BEB60831BFF5E54 current:3BB3C391CB522CAF4BEB60831BFF5E54
 m31000| Tue Jul 16 08:11:42.371 [initandlisten] checkHash len:8149 hash:9700551F83BFF7716305F363D8CAB005 current:9700551F83BFF7716305F363D8CAB005
 m31000| Tue Jul 16 08:11:42.372 [initandlisten] checkHash len:12820 hash:1AE6FD292EFA6AE37D24104F2FF5AD0D current:1AE6FD292EFA6AE37D24104F2FF5AD0D
 m31000| Tue Jul 16 08:11:42.373 [initandlisten] checkHash len:6401 hash:5169A4E45880CBCF5F05A90CC383B0BE current:5169A4E45880CBCF5F05A90CC383B0BE
 m31000| Tue Jul 16 08:11:42.374 [initandlisten] checkHash len:7320 hash:417792549AE83C4F142914E451A92C12 current:417792549AE83C4F142914E451A92C12
 m31000| Tue Jul 16 08:11:42.375 [initandlisten] checkHash len:10327 hash:F6C0A876661026A0DBD9F0CA06A0C1FE current:F6C0A876661026A0DBD9F0CA06A0C1FE
 m31000| Tue Jul 16 08:11:42.376 [initandlisten] checkHash len:8438 hash:CEF055D9DFC4FFF3740633C8AE23E363 current:CEF055D9DFC4FFF3740633C8AE23E363
 m31000| Tue Jul 16 08:11:42.377 [initandlisten] checkHash len:7168 hash:478FBC25E3A3AAF1057932FDA35CA458 current:478FBC25E3A3AAF1057932FDA35CA458
 m31000| Tue Jul 16 08:11:42.378 [initandlisten] checkHash len:6183 hash:2639053C2F08AED1783FF9C61998F720 current:2639053C2F08AED1783FF9C61998F720
 m31000| Tue Jul 16 08:11:42.379 [initandlisten] checkHash len:12917 hash:9FFCD7E32B2650605E7DF41B10550EE4 current:9FFCD7E32B2650605E7DF41B10550EE4
 m31000| Tue Jul 16 08:11:42.380 [initandlisten] checkHash len:5713 hash:ACE668E2E45B31C5BEF585FFF5F539E3 current:ACE668E2E45B31C5BEF585FFF5F539E3
 m31000| Tue Jul 16 08:11:42.381 [initandlisten] checkHash len:7510 hash:FBBFA59E57EBCCB3F20E31F870247756 current:FBBFA59E57EBCCB3F20E31F870247756
 m31000| Tue Jul 16 08:11:42.382 [initandlisten] checkHash len:9052 hash:EAC23DA1D9137A4133D0D20E3504C727 current:EAC23DA1D9137A4133D0D20E3504C727
 m31000| Tue Jul 16 08:11:42.383 [initandlisten] checkHash len:12651 hash:E124417ACAE09614DE2E1791FFDC35BA current:E124417ACAE09614DE2E1791FFDC35BA
 m31000| Tue Jul 16 08:11:42.385 [initandlisten] checkHash len:8608 hash:0A001A1F3A78198EB8A5FBCD61175266 current:0A001A1F3A78198EB8A5FBCD61175266
 m31000| Tue Jul 16 08:11:42.385 [initandlisten] checkHash len:5858 hash:98C7BF91393AF090FD34682CF1725318 current:98C7BF91393AF090FD34682CF1725318
 m31000| Tue Jul 16 08:11:42.386 [initandlisten] checkHash len:15018 hash:DE022892617BADBA8860E7B5139D8F35 current:DE022892617BADBA8860E7B5139D8F35
 m31000| Tue Jul 16 08:11:42.388 [initandlisten] checkHash len:7270 hash:BD852DFE709F1A044DA950F2981BD140 current:BD852DFE709F1A044DA950F2981BD140
 m31000| Tue Jul 16 08:11:42.389 [initandlisten] checkHash len:6742 hash:0038B5854709005AE8D355EFD091B679 current:0038B5854709005AE8D355EFD091B679
 m31000| Tue Jul 16 08:11:42.390 [initandlisten] checkHash len:12458 hash:299A59BE8146479151A9E4FC5B32F947 current:299A59BE8146479151A9E4FC5B32F947
 m31000| Tue Jul 16 08:11:42.391 [initandlisten] checkHash len:7409 hash:95004EA8A0427DF89A146BAA1B3AF86B current:95004EA8A0427DF89A146BAA1B3AF86B
 m31000| Tue Jul 16 08:11:42.392 [initandlisten] checkHash len:4446 hash:8CBCD3CF93A7288291BD7523603AFE9D current:8CBCD3CF93A7288291BD7523603AFE9D
 m31000| Tue Jul 16 08:11:42.393 [initandlisten] checkHash len:9008 hash:23B33BC6089785E4001B5A9CEF7BFD70 current:23B33BC6089785E4001B5A9CEF7BFD70
 m31000| Tue Jul 16 08:11:42.394 [initandlisten] checkHash len:12785 hash:ED92FB564905BB8098856577C0BDCA98 current:ED92FB564905BB8098856577C0BDCA98
 m31000| Tue Jul 16 08:11:42.395 [initandlisten] checkHash len:7206 hash:AF1721AF6C4C4EC446F41751582C0006 current:AF1721AF6C4C4EC446F41751582C0006
 m31000| Tue Jul 16 08:11:42.396 [initandlisten] checkHash len:6646 hash:A98204424D00754C05C6D71A47F38550 current:A98204424D00754C05C6D71A47F38550
 m31000| Tue Jul 16 08:11:42.397 [initandlisten] checkHash len:6839 hash:A5FD4611BB1301614460D0A6DBF70E6B current:A5FD4611BB1301614460D0A6DBF70E6B
 m31000| Tue Jul 16 08:11:42.398 [initandlisten] checkHash len:12178 hash:BA109EFDE655F876EC038E0F3FA6D2DD current:BA109EFDE655F876EC038E0F3FA6D2DD
 m31000| Tue Jul 16 08:11:42.399 [initandlisten] checkHash len:7430 hash:C995D55A5B91FE96DB2DAAFE04562592 current:C995D55A5B91FE96DB2DAAFE04562592
 m31000| Tue Jul 16 08:11:42.400 [initandlisten] checkHash len:9512 hash:7BDA12FAAF922A901E733C1D8EDD7CFA current:7BDA12FAAF922A901E733C1D8EDD7CFA
 m31000| Tue Jul 16 08:11:42.401 [initandlisten] checkHash len:14614 hash:BD11F53CA40168447992B2A2F1E8AE59 current:BD11F53CA40168447992B2A2F1E8AE59
 m31000| Tue Jul 16 08:11:42.403 [initandlisten] checkHash len:6711 hash:35CDC78E1B30C375D0E4B1A3D8838DB5 current:35CDC78E1B30C375D0E4B1A3D8838DB5
 m31000| Tue Jul 16 08:11:42.403 [initandlisten] checkHash len:6603 hash:6B63FA9D90D2AABABC6059C72DEF5A72 current:6B63FA9D90D2AABABC6059C72DEF5A72
 m31000| Tue Jul 16 08:11:42.404 [initandlisten] checkHash len:8770 hash:7829E2956F0F1F5B71C6DBE9BD97FA97 current:7829E2956F0F1F5B71C6DBE9BD97FA97
 m31000| Tue Jul 16 08:11:42.406 [initandlisten] checkHash len:2073 hash:E016855CC06D87312A13D217A3AF115E current:E016855CC06D87312A13D217A3AF115E
 m31000| Tue Jul 16 08:11:42.406 [initandlisten] checkHash len:59 hash:24FB3E973C95F85167CACF49008E9B9A current:24FB3E973C95F85167CACF49008E9B9A
 m31000| Tue Jul 16 08:11:42.406 [initandlisten] checkHash len:52 hash:2CFB3E971E95F85136311A0A258E9B9A current:2CFB3E971E95F85136311A0A258E9B9A
 m31000| Tue Jul 16 08:11:42.407 [initandlisten] checkHash len:798 hash:AEC88E392F37E3052420A386B037D194 current:AEC88E392F37E3052420A386B037D194
 m31000| Tue Jul 16 08:11:42.408 [initandlisten] checkHash len:13498 hash:E682AF133C06A5D80B046ED885981A0B current:E682AF133C06A5D80B046ED885981A0B
 m31000| Tue Jul 16 08:11:42.409 [initandlisten] checkHash len:7356 hash:748D737B8A78E71BDF2223F4233066B5 current:748D737B8A78E71BDF2223F4233066B5
 m31000| Tue Jul 16 08:11:42.410 [initandlisten] checkHash len:7191 hash:4C1B1022050CF136E0D140618B5A1EBF current:4C1B1022050CF136E0D140618B5A1EBF
 m31000| Tue Jul 16 08:11:42.411 [initandlisten] checkHash len:13803 hash:01A880413CA516B919C9DEA8BCDF3122 current:01A880413CA516B919C9DEA8BCDF3122
 m31000| Tue Jul 16 08:11:42.412 [initandlisten] checkHash len:7169 hash:3B1E8C9042CC21A4065EA006B3C20194 current:3B1E8C9042CC21A4065EA006B3C20194
 m31000| Tue Jul 16 08:11:42.413 [initandlisten] checkHash len:7531 hash:6B69F0D955740ED08DF541E18E078387 current:6B69F0D955740ED08DF541E18E078387
 m31000| Tue Jul 16 08:11:42.414 [initandlisten] checkHash len:7187 hash:94F85A1E7B3B30769E40C1395665FC41 current:94F85A1E7B3B30769E40C1395665FC41
 m31000| Tue Jul 16 08:11:42.415 [initandlisten] checkHash len:13191 hash:9DB51AF9B80EFCEF15C8E96660E892F3 current:9DB51AF9B80EFCEF15C8E96660E892F3
 m31000| Tue Jul 16 08:11:42.416 [initandlisten] checkHash len:6759 hash:3E2E44527244935B36948E055F60A06F current:3E2E44527244935B36948E055F60A06F
 m31000| Tue Jul 16 08:11:42.417 [initandlisten] checkHash len:7802 hash:E1A9967FC55B82E204EF09B14C35ADF1 current:E1A9967FC55B82E204EF09B14C35ADF1
 m31000| Tue Jul 16 08:11:42.418 [initandlisten] checkHash len:12794 hash:B348AD0E2DA40541BC446ED46BCBAECA current:B348AD0E2DA40541BC446ED46BCBAECA
 m31000| Tue Jul 16 08:11:42.419 [initandlisten] checkHash len:7024 hash:010559645B9C68A2930578EDC47CEE90 current:010559645B9C68A2930578EDC47CEE90
 m31000| Tue Jul 16 08:11:42.420 [initandlisten] checkHash len:6731 hash:620A1CA700495C102B041EC729363DA6 current:620A1CA700495C102B041EC729363DA6
 m31000| Tue Jul 16 08:11:42.421 [initandlisten] checkHash len:7308 hash:23D4793311C1BE7433BB34786F901A6E current:23D4793311C1BE7433BB34786F901A6E
 m31000| Tue Jul 16 08:11:42.422 [initandlisten] checkHash len:14534 hash:A5B80F451E15509EC6BB87361BAB66EC current:A5B80F451E15509EC6BB87361BAB66EC
 m31000| Tue Jul 16 08:11:42.424 [initandlisten] checkHash len:7218 hash:9370E5C65F8F4E58984FC70D558AC334 current:9370E5C65F8F4E58984FC70D558AC334
 m31000| Tue Jul 16 08:11:42.424 [initandlisten] checkHash len:7068 hash:C0911C4DAA4720161EC951DF256EA4ED current:C0911C4DAA4720161EC951DF256EA4ED
 m31000| Tue Jul 16 08:11:42.425 [initandlisten] checkHash len:6399 hash:16DEF83A48206E2080DA091E3E5225B8 current:16DEF83A48206E2080DA091E3E5225B8
 m31000| Tue Jul 16 08:11:42.427 [initandlisten] checkHash len:14206 hash:5DF1BEAC891FC338C9AE181FD8182081 current:5DF1BEAC891FC338C9AE181FD8182081
 m31000| Tue Jul 16 08:11:42.428 [initandlisten] checkHash len:7079 hash:F1A3928AA5499F23FDC6C6CF874C3BAA current:F1A3928AA5499F23FDC6C6CF874C3BAA
 m31000| Tue Jul 16 08:11:42.429 [initandlisten] checkHash len:8451 hash:5A6D9A5AEA2507A412989D9668F877E0 current:5A6D9A5AEA2507A412989D9668F877E0
 m31000| Tue Jul 16 08:11:42.430 [initandlisten] checkHash len:12695 hash:D017F44D5C8059FD423A97CB135B1D9C current:D017F44D5C8059FD423A97CB135B1D9C
 m31000| Tue Jul 16 08:11:42.431 [initandlisten] checkHash len:7662 hash:38CF308F59EFE8775D1CFE57757E478E current:38CF308F59EFE8775D1CFE57757E478E
 m31000| Tue Jul 16 08:11:42.432 [initandlisten] checkHash len:7350 hash:3B1BFA24272C4E2AFAC70A4E01DA32CB current:3B1BFA24272C4E2AFAC70A4E01DA32CB
 m31000| Tue Jul 16 08:11:42.433 [initandlisten] checkHash len:7251 hash:BA19190786938F65D2384ED24933A7F0 current:BA19190786938F65D2384ED24933A7F0
 m31000| Tue Jul 16 08:11:42.434 [initandlisten] checkHash len:13638 hash:7C6AEA280FF1DE7890793E0A5D0A7D29 current:7C6AEA280FF1DE7890793E0A5D0A7D29
 m31000| Tue Jul 16 08:11:42.435 [initandlisten] checkHash len:7182 hash:676AFF7A58CE1FF95707895C0A682842 current:676AFF7A58CE1FF95707895C0A682842
 m31000| Tue Jul 16 08:11:42.436 [initandlisten] checkHash len:8047 hash:B8E6BE4D0BFE81A6EC1E726EC4AC6453 current:B8E6BE4D0BFE81A6EC1E726EC4AC6453
 m31000| Tue Jul 16 08:11:42.437 [initandlisten] checkHash len:12957 hash:E70C06425282A93C04B723CFAC218D26 current:E70C06425282A93C04B723CFAC218D26
 m31000| Tue Jul 16 08:11:42.438 [initandlisten] checkHash len:7939 hash:9DE7708E0D61C94BD47BAF1BC76E2373 current:9DE7708E0D61C94BD47BAF1BC76E2373
 m31000| Tue Jul 16 08:11:42.439 [initandlisten] checkHash len:6320 hash:EB890DBB14FD737A6C2C97901CFB035C current:EB890DBB14FD737A6C2C97901CFB035C
 m31000| Tue Jul 16 08:11:42.440 [initandlisten] checkHash len:8387 hash:954463599FE062FF0AF6C2204E8AE8D2 current:954463599FE062FF0AF6C2204E8AE8D2
 m31000| Tue Jul 16 08:11:42.442 [initandlisten] checkHash len:13689 hash:ADCC64E05EE7D56FC64890B26B9F91A1 current:ADCC64E05EE7D56FC64890B26B9F91A1
 m31000| Tue Jul 16 08:11:42.443 [initandlisten] checkHash len:7484 hash:78317CC1BFF5FF97A8BD4E4B3FF1CE2B current:78317CC1BFF5FF97A8BD4E4B3FF1CE2B
 m31000| Tue Jul 16 08:11:42.444 [initandlisten] checkHash len:6986 hash:0E3A5A2E0DF07CA9C8E2966880EB3167 current:0E3A5A2E0DF07CA9C8E2966880EB3167
 m31000| Tue Jul 16 08:11:42.445 [initandlisten] checkHash len:13185 hash:70FBE00924345C4CD09420C04E06F19A current:70FBE00924345C4CD09420C04E06F19A
 m31000| Tue Jul 16 08:11:42.446 [initandlisten] checkHash len:6946 hash:F4B0F8451C922DE8FBDDEC1391E19467 current:F4B0F8451C922DE8FBDDEC1391E19467
 m31000| Tue Jul 16 08:11:42.447 [initandlisten] checkHash len:7191 hash:426165DB064B67DB6F0E289BC3D2C1E1 current:426165DB064B67DB6F0E289BC3D2C1E1
 m31000| Tue Jul 16 08:11:42.448 [initandlisten] checkHash len:5791 hash:F92E5D4139BEA49037CD4025193FA23D current:F92E5D4139BEA49037CD4025193FA23D
 m31000| Tue Jul 16 08:11:42.449 [initandlisten] checkHash len:14880 hash:9CE6D6CF1FF75AE62D29BA6D825D8EE3 current:9CE6D6CF1FF75AE62D29BA6D825D8EE3
 m31000| Tue Jul 16 08:11:42.450 [initandlisten] checkHash len:6599 hash:2484A066E7747C5234D02589F072B3B8 current:2484A066E7747C5234D02589F072B3B8
 m31000| Tue Jul 16 08:11:42.451 [initandlisten] checkHash len:8274 hash:EF0350E8AF40AC57F12E9FE7D1239121 current:EF0350E8AF40AC57F12E9FE7D1239121
 m31000| Tue Jul 16 08:11:42.452 [initandlisten] checkHash len:12953 hash:404987E71B83B7D483C3B9B06C5C77A3 current:404987E71B83B7D483C3B9B06C5C77A3
 m31000| Tue Jul 16 08:11:42.453 [initandlisten] checkHash len:7333 hash:3F188CAB2B279FE3E527CDCD5D983226 current:3F188CAB2B279FE3E527CDCD5D983226
 m31000| Tue Jul 16 08:11:42.454 [initandlisten] checkHash len:7410 hash:8D629C3A5DC3AF15B4F2711086BB35DB current:8D629C3A5DC3AF15B4F2711086BB35DB
 m31000| Tue Jul 16 08:11:42.455 [initandlisten] checkHash len:6725 hash:4FA3F8A5067074F079ABA6C79D3D8C2C current:4FA3F8A5067074F079ABA6C79D3D8C2C
 m31000| Tue Jul 16 08:11:42.456 [initandlisten] checkHash len:12518 hash:B7D3E0CAF5D724E7E120CB138F7EE8B4 current:B7D3E0CAF5D724E7E120CB138F7EE8B4
 m31000| Tue Jul 16 08:11:42.457 [initandlisten] checkHash len:7116 hash:68496AB047D83C6C1276FC7C23C80DE0 current:68496AB047D83C6C1276FC7C23C80DE0
 m31000| Tue Jul 16 08:11:42.458 [initandlisten] checkHash len:7613 hash:4B8DB7FCFD2508486B2017B4F1787F36 current:4B8DB7FCFD2508486B2017B4F1787F36
 m31000| Tue Jul 16 08:11:42.459 [initandlisten] checkHash len:6865 hash:B7993C6F3474AC29B29275BFE1516177 current:B7993C6F3474AC29B29275BFE1516177
 m31000| Tue Jul 16 08:11:42.461 [initandlisten] checkHash len:12593 hash:4B882BC689E99D8EE96148936288148E current:4B882BC689E99D8EE96148936288148E
 m31000| Tue Jul 16 08:11:42.462 [initandlisten] checkHash len:7891 hash:EA778FDFE914729A5886657C98D28B45 current:EA778FDFE914729A5886657C98D28B45
 m31000| Tue Jul 16 08:11:42.462 [initandlisten] checkHash len:7114 hash:219D64C44A878C11D96B59F10390EFE1 current:219D64C44A878C11D96B59F10390EFE1
 m31000| Tue Jul 16 08:11:42.464 [initandlisten] checkHash len:11176 hash:ABD4C52F978ABC24B39BE9A3171FF6E7 current:ABD4C52F978ABC24B39BE9A3171FF6E7
 m31000| Tue Jul 16 08:11:42.465 [initandlisten] checkHash len:7933 hash:A93CBA38098DD06D0DF74378BB00B52F current:A93CBA38098DD06D0DF74378BB00B52F
 m31000| Tue Jul 16 08:11:42.466 [initandlisten] checkHash len:7467 hash:1E8B7262B75C49335BE0CC6C7E75A6BF current:1E8B7262B75C49335BE0CC6C7E75A6BF
 m31000| Tue Jul 16 08:11:42.467 [initandlisten] checkHash len:7150 hash:EAC32DD549134B8EC42B0C3621F2E218 current:EAC32DD549134B8EC42B0C3621F2E218
 m31000| Tue Jul 16 08:11:42.468 [initandlisten] checkHash len:12016 hash:C9E6D48AA3DA4DEB5BE36ED59DE12DA1 current:C9E6D48AA3DA4DEB5BE36ED59DE12DA1
 m31000| Tue Jul 16 08:11:42.469 [initandlisten] checkHash len:7821 hash:358B2467FEDC6DE5F9A5CCB0EBF22757 current:358B2467FEDC6DE5F9A5CCB0EBF22757
 m31000| Tue Jul 16 08:11:42.470 [initandlisten] checkHash len:7078 hash:4D74CEFFAC84E85DB79F6D0549F80843 current:4D74CEFFAC84E85DB79F6D0549F80843
 m31000| Tue Jul 16 08:11:42.471 [initandlisten] checkHash len:11542 hash:DF7C25FDCEF055AB14A25C11FFB343E6 current:DF7C25FDCEF055AB14A25C11FFB343E6
 m31000| Tue Jul 16 08:11:42.472 [initandlisten] checkHash len:7328 hash:21EBAD84249C53A06D5F569831F8F5C9 current:21EBAD84249C53A06D5F569831F8F5C9
 m31000| Tue Jul 16 08:11:42.473 [initandlisten] checkHash len:6563 hash:336E229394909A4290283F760DDE563A current:336E229394909A4290283F760DDE563A
 m31000| Tue Jul 16 08:11:42.474 [initandlisten] checkHash len:7374 hash:671F440529611E219B67F3AFCA989F57 current:671F440529611E219B67F3AFCA989F57
 m31000| Tue Jul 16 08:11:42.475 [initandlisten] checkHash len:12262 hash:BB9CFF7F1397EE7FEACE85C8906BA979 current:BB9CFF7F1397EE7FEACE85C8906BA979
 m31000| Tue Jul 16 08:11:42.476 [initandlisten] checkHash len:7239 hash:8E28BE4FD54F4F71BAF95300BF7483F7 current:8E28BE4FD54F4F71BAF95300BF7483F7
 m31000| Tue Jul 16 08:11:42.477 [initandlisten] checkHash len:7414 hash:2A91DC28443D87C55322E419DD81A337 current:2A91DC28443D87C55322E419DD81A337
 m31000| Tue Jul 16 08:11:42.478 [initandlisten] checkHash len:7388 hash:441BC21B25139B42B07769532BFAF41C current:441BC21B25139B42B07769532BFAF41C
 m31000| Tue Jul 16 08:11:42.479 [initandlisten] checkHash len:12361 hash:60AFFC755412331281F0B198CC0A3777 current:60AFFC755412331281F0B198CC0A3777
 m31000| Tue Jul 16 08:11:42.480 [initandlisten] checkHash len:7503 hash:9E6C48724B80B84AE282C94BDF51A211 current:9E6C48724B80B84AE282C94BDF51A211
 m31000| Tue Jul 16 08:11:42.481 [initandlisten] checkHash len:6178 hash:F65A4ADCE0D8FEF7BF237BC19947519E current:F65A4ADCE0D8FEF7BF237BC19947519E
 m31000| Tue Jul 16 08:11:42.482 [initandlisten] checkHash len:12817 hash:8319DC45734772F761ACB8704B69200D current:8319DC45734772F761ACB8704B69200D
 m31000| Tue Jul 16 08:11:42.484 [initandlisten] checkHash len:6575 hash:E792EBED40967C92050DD5AB1E00EFF6 current:E792EBED40967C92050DD5AB1E00EFF6
 m31000| Tue Jul 16 08:11:42.485 [initandlisten] checkHash len:7394 hash:3A58A9C6DF17FADFA95D2420C0BE587B current:3A58A9C6DF17FADFA95D2420C0BE587B
 m31000| Tue Jul 16 08:11:42.485 [initandlisten] checkHash len:7181 hash:006E258E1994828D9C6FA09861A9B33C current:006E258E1994828D9C6FA09861A9B33C
 m31000| Tue Jul 16 08:11:42.487 [initandlisten] checkHash len:12214 hash:CB76558A15048412A7399823403BE94F current:CB76558A15048412A7399823403BE94F
 m31000| Tue Jul 16 08:11:42.488 [initandlisten] checkHash len:7562 hash:37E747D31DB175E37CEEFB06EBCFF589 current:37E747D31DB175E37CEEFB06EBCFF589
 m31000| Tue Jul 16 08:11:42.489 [initandlisten] checkHash len:6690 hash:A1E353A41161441E4047AB69C635D168 current:A1E353A41161441E4047AB69C635D168
 m31000| Tue Jul 16 08:11:42.490 [initandlisten] checkHash len:12255 hash:95D48FEDAFE371D3E772A807A1E63500 current:95D48FEDAFE371D3E772A807A1E63500
 m31000| Tue Jul 16 08:11:42.491 [initandlisten] checkHash len:7008 hash:52C41D5BF0DC29D72A53AD5E48AB0DE2 current:52C41D5BF0DC29D72A53AD5E48AB0DE2
 m31000| Tue Jul 16 08:11:42.492 [initandlisten] checkHash len:7936 hash:8201F592148B2AC457C5D3AFCD8FD969 current:8201F592148B2AC457C5D3AFCD8FD969
 m31000| Tue Jul 16 08:11:42.493 [initandlisten] checkHash len:6950 hash:89B3A8656AD440B6D9D750DF08DD47AB current:89B3A8656AD440B6D9D750DF08DD47AB
 m31000| Tue Jul 16 08:11:42.494 [initandlisten] checkHash len:12172 hash:B34AC70894C8CA9930DFDDA95917E15F current:B34AC70894C8CA9930DFDDA95917E15F
 m31000| Tue Jul 16 08:11:42.495 [initandlisten] checkHash len:6858 hash:96F079AAE21AEE7208A1BFABB8572514 current:96F079AAE21AEE7208A1BFABB8572514
 m31000| Tue Jul 16 08:11:42.496 [initandlisten] checkHash len:7536 hash:DC21553A1952878C68A6A58D88A19C9A current:DC21553A1952878C68A6A58D88A19C9A
 m31000| Tue Jul 16 08:11:42.497 [initandlisten] checkHash len:7825 hash:C25B9E9227A4A01C3CE9EE3E5C3402A4 current:C25B9E9227A4A01C3CE9EE3E5C3402A4
 m31000| Tue Jul 16 08:11:42.498 [initandlisten] checkHash len:12363 hash:B32F2AA048962DA0CA8D1B316D583853 current:B32F2AA048962DA0CA8D1B316D583853
 m31000| Tue Jul 16 08:11:42.499 [initandlisten] checkHash len:6917 hash:5995DBA080E4397F93ABF9F12775FACD current:5995DBA080E4397F93ABF9F12775FACD
 m31000| Tue Jul 16 08:11:42.500 [initandlisten] checkHash len:7577 hash:C11A3EF0D947840D89F6EA87A3AE9C17 current:C11A3EF0D947840D89F6EA87A3AE9C17
 m31000| Tue Jul 16 08:11:42.501 [initandlisten] checkHash len:12560 hash:34A45DF88BC9BF939F3D68CC66ECDB2C current:34A45DF88BC9BF939F3D68CC66ECDB2C
 m31000| Tue Jul 16 08:11:42.502 [initandlisten] checkHash len:7699 hash:A324B807027F28CF707BD11B8B7266A3 current:A324B807027F28CF707BD11B8B7266A3
 m31000| Tue Jul 16 08:11:42.503 [initandlisten] checkHash len:6956 hash:FF1ECAF333D2D69656CAAE139649BA40 current:FF1ECAF333D2D69656CAAE139649BA40
 m31000| Tue Jul 16 08:11:42.504 [initandlisten] checkHash len:7519 hash:EFE9E68E09B9AF83C964665C2C8162F9 current:EFE9E68E09B9AF83C964665C2C8162F9
 m31000| Tue Jul 16 08:11:42.505 [initandlisten] checkHash len:12344 hash:FD11BAAD554F396B76C74E929748AB65 current:FD11BAAD554F396B76C74E929748AB65
 m31000| Tue Jul 16 08:11:42.506 [initandlisten] checkHash len:7303 hash:52587EC0E3E488D345CFCF15604E56FC current:52587EC0E3E488D345CFCF15604E56FC
 m31000| Tue Jul 16 08:11:42.507 [initandlisten] checkHash len:7033 hash:20F2A0F9141FE6AA12AB6067F8A3F983 current:20F2A0F9141FE6AA12AB6067F8A3F983
 m31000| Tue Jul 16 08:11:42.508 [initandlisten] checkHash len:12853 hash:26E1202D4B613CFBA4B0FB5B1474BA7E current:26E1202D4B613CFBA4B0FB5B1474BA7E
 m31000| Tue Jul 16 08:11:42.509 [initandlisten] checkHash len:6745 hash:D56BA4A8C9E0CCA354219A6C0102BB7A current:D56BA4A8C9E0CCA354219A6C0102BB7A
 m31000| Tue Jul 16 08:11:42.510 [initandlisten] checkHash len:7639 hash:A2EC8A66B1656E3F3B385D725117E15D current:A2EC8A66B1656E3F3B385D725117E15D
 m31000| Tue Jul 16 08:11:42.511 [initandlisten] checkHash len:6893 hash:E2D7445F8EBB67D9935256F189B9471A current:E2D7445F8EBB67D9935256F189B9471A
 m31000| Tue Jul 16 08:11:42.513 [initandlisten] checkHash len:12603 hash:21A88025FEFF109A2E280350E770E3EF current:21A88025FEFF109A2E280350E770E3EF
 m31000| Tue Jul 16 08:11:42.513 [initandlisten] checkHash len:6392 hash:F26FD570239B8179C010471336C3FEAC current:F26FD570239B8179C010471336C3FEAC
 m31000| Tue Jul 16 08:11:42.514 [initandlisten] checkHash len:7634 hash:14084B411D3630FC96ABB0AA99A0D1CA current:14084B411D3630FC96ABB0AA99A0D1CA
 m31000| Tue Jul 16 08:11:42.516 [initandlisten] checkHash len:12213 hash:AFDDB1379AE513193FD1018AB5CD28F6 current:AFDDB1379AE513193FD1018AB5CD28F6
 m31000| Tue Jul 16 08:11:42.517 [initandlisten] checkHash len:7595 hash:6415B3EA13C84DB35C6B9997BA3792D4 current:6415B3EA13C84DB35C6B9997BA3792D4
 m31000| Tue Jul 16 08:11:42.518 [initandlisten] checkHash len:7021 hash:8F6A94AF4CDC0BB73C92663BC57E3EA0 current:8F6A94AF4CDC0BB73C92663BC57E3EA0
 m31000| Tue Jul 16 08:11:42.519 [initandlisten] checkHash len:7525 hash:45CDE24ABC54761637D8318F7F7C30A8 current:45CDE24ABC54761637D8318F7F7C30A8
 m31000| Tue Jul 16 08:11:42.520 [initandlisten] checkHash len:11921 hash:D14616A0B70C84D8E86A0796A7F92A5E current:D14616A0B70C84D8E86A0796A7F92A5E
 m31000| Tue Jul 16 08:11:42.521 [initandlisten] checkHash len:7055 hash:25352334DA50826661A217775B674C55 current:25352334DA50826661A217775B674C55
 m31000| Tue Jul 16 08:11:42.522 [initandlisten] checkHash len:7548 hash:1283FDC8C09885D977F2C606A013D730 current:1283FDC8C09885D977F2C606A013D730
 m31000| Tue Jul 16 08:11:42.523 [initandlisten] checkHash len:6547 hash:7703E66194A40B6BAA78C85D0C70D800 current:7703E66194A40B6BAA78C85D0C70D800
 m31000| Tue Jul 16 08:11:42.524 [initandlisten] checkHash len:12827 hash:564DC7D3B45FCA7D9AFC1100D941C187 current:564DC7D3B45FCA7D9AFC1100D941C187
 m31000| Tue Jul 16 08:11:42.525 [initandlisten] checkHash len:7634 hash:7ABD4583606F8C143269D050101B852C current:7ABD4583606F8C143269D050101B852C
 m31000| Tue Jul 16 08:11:42.526 [initandlisten] checkHash len:7432 hash:4FEC818FE3D257832A297042C5D2DCD9 current:4FEC818FE3D257832A297042C5D2DCD9
 m31000| Tue Jul 16 08:11:42.527 [initandlisten] checkHash len:11964 hash:F8C57875096256B74580B90E0C833CB9 current:F8C57875096256B74580B90E0C833CB9
 m31000| Tue Jul 16 08:11:42.528 [initandlisten] checkHash len:7178 hash:133A9858572B42B92DE6E78CA1F11639 current:133A9858572B42B92DE6E78CA1F11639
 m31000| Tue Jul 16 08:11:42.529 [initandlisten] checkHash len:7462 hash:BBC1D80FDD5F83E8E93F2CB81E644A83 current:BBC1D80FDD5F83E8E93F2CB81E644A83
 m31000| Tue Jul 16 08:11:42.530 [initandlisten] checkHash len:7272 hash:5F1CA87BA074D1FE720C62DF8907F78A current:5F1CA87BA074D1FE720C62DF8907F78A
 m31000| Tue Jul 16 08:11:42.531 [initandlisten] checkHash len:12193 hash:0A8194BE6174796F32B79F51FB789851 current:0A8194BE6174796F32B79F51FB789851
 m31000| Tue Jul 16 08:11:42.532 [initandlisten] checkHash len:7557 hash:171393273AF9863F9487B30F4241542B current:171393273AF9863F9487B30F4241542B
 m31000| Tue Jul 16 08:11:42.533 [initandlisten] checkHash len:6593 hash:E26C7233E53E93C4D071BFEB7F1DAB92 current:E26C7233E53E93C4D071BFEB7F1DAB92
 m31000| Tue Jul 16 08:11:42.534 [initandlisten] checkHash len:11965 hash:16D3CBA61D20F3F3137C41901B423B38 current:16D3CBA61D20F3F3137C41901B423B38
 m31000| Tue Jul 16 08:11:42.536 [initandlisten] checkHash len:7598 hash:098BEBB35CCD9C2F027BD4B56EB666D5 current:098BEBB35CCD9C2F027BD4B56EB666D5
 m31000| Tue Jul 16 08:11:42.536 [initandlisten] checkHash len:7509 hash:CCB59F8106809267459D250AB1B53202 current:CCB59F8106809267459D250AB1B53202
 m31000| Tue Jul 16 08:11:42.537 [initandlisten] checkHash len:6894 hash:C1C6DB7180A36A8A70769C1781B08099 current:C1C6DB7180A36A8A70769C1781B08099
 m31000| Tue Jul 16 08:11:42.539 [initandlisten] checkHash len:12293 hash:3E5F26C986A8C109B30852E768DA8C09 current:3E5F26C986A8C109B30852E768DA8C09
 m31000| Tue Jul 16 08:11:42.540 [initandlisten] checkHash len:7603 hash:ACC5E85FE48B4670379A2C88DD3D47DE current:ACC5E85FE48B4670379A2C88DD3D47DE
 m31000| Tue Jul 16 08:11:42.541 [initandlisten] checkHash len:6404 hash:C1DF72885A75BDB14B689012E6F26064 current:C1DF72885A75BDB14B689012E6F26064
 m31000| Tue Jul 16 08:11:42.542 [initandlisten] checkHash len:8239 hash:F5F341F1F6EA6B14EDD5D8FC4AAEDE46 current:F5F341F1F6EA6B14EDD5D8FC4AAEDE46
 m31000| Tue Jul 16 08:11:42.543 [initandlisten] checkHash len:13376 hash:6192BDCC126348F0C048B23156C7CF4D current:6192BDCC126348F0C048B23156C7CF4D
 m31000| Tue Jul 16 08:11:42.544 [initandlisten] checkHash len:7021 hash:D6AB1BA3F36FFEFE7AB792F061FA5D66 current:D6AB1BA3F36FFEFE7AB792F061FA5D66
 m31000| Tue Jul 16 08:11:42.545 [initandlisten] checkHash len:7613 hash:E9E2C0CEEF425F0AED98724854341714 current:E9E2C0CEEF425F0AED98724854341714
 m31000| Tue Jul 16 08:11:42.546 [initandlisten] checkHash len:12063 hash:841C833ACC998FE36CD9F851AC3E2151 current:841C833ACC998FE36CD9F851AC3E2151
 m31000| Tue Jul 16 08:11:42.547 [initandlisten] checkHash len:7130 hash:944E896FA4699725C5FE109B9D7D2A08 current:944E896FA4699725C5FE109B9D7D2A08
 m31000| Tue Jul 16 08:11:42.548 [initandlisten] checkHash len:7257 hash:D73320C3C9F0E62F629EC2C4E651E05E current:D73320C3C9F0E62F629EC2C4E651E05E
 m31000| Tue Jul 16 08:11:42.549 [initandlisten] checkHash len:7331 hash:7D9E7BDFC25515FABD99BD62D05DE66E current:7D9E7BDFC25515FABD99BD62D05DE66E
 m31000| Tue Jul 16 08:11:42.550 [initandlisten] checkHash len:13206 hash:EE058266EE54B682248BF784D1621B13 current:EE058266EE54B682248BF784D1621B13
 m31000| Tue Jul 16 08:11:42.551 [initandlisten] checkHash len:6881 hash:429396E2EEB464FECAE2D0895132A7BF current:429396E2EEB464FECAE2D0895132A7BF
 m31000| Tue Jul 16 08:11:42.552 [initandlisten] checkHash len:7539 hash:3767CF140C7E933CBE047B6312824268 current:3767CF140C7E933CBE047B6312824268
 m31000| Tue Jul 16 08:11:42.553 [initandlisten] checkHash len:11890 hash:C1E0CBF896D091290A72E1B1833D9192 current:C1E0CBF896D091290A72E1B1833D9192
 m31000| Tue Jul 16 08:11:42.554 [initandlisten] checkHash len:7895 hash:1453AE894E3A0881E8FB2DE385C3EB52 current:1453AE894E3A0881E8FB2DE385C3EB52
 m31000| Tue Jul 16 08:11:42.555 [initandlisten] checkHash len:2988 hash:E7B2FAE3113D394528C34D9AF64EAFA1 current:E7B2FAE3113D394528C34D9AF64EAFA1
 m31000| Tue Jul 16 08:11:42.556 [initandlisten] checkHash len:82 hash:6F7B7D8B54065DB74631AC98785CC0CE current:6F7B7D8B54065DB74631AC98785CC0CE
 m31000| Tue Jul 16 08:11:42.623 [initandlisten] recover cleaning up
 m31000| Tue Jul 16 08:11:42.623 [initandlisten] removeJournalFiles
 m31000| Tue Jul 16 08:11:42.624 [initandlisten] recover done
 m31000| Tue Jul 16 08:11:42.636 [initandlisten] opening db:  local
 m31000| Tue Jul 16 08:11:42.661 [initandlisten] opening db:  test
 m31000| Tue Jul 16 08:11:42.676 [initandlisten]
 m31000| debug have W lock but w would suffice for command create
 m31000| Tue Jul 16 08:11:42.676 [initandlisten] opening db:  local
 m31000| Tue Jul 16 08:11:42.680 [initandlisten] info PageFaultRetryableSection will not yield, already locked upon reaching
 m31000| Tue Jul 16 08:11:42.681 [initandlisten] waiting for connections on port 31000
 m31000| Tue Jul 16 08:11:42.681 [websvr] admin web console waiting for connections on port 32000
 m31000| Tue Jul 16 08:11:42.681 [IndexRebuilder] _DEBUG ReadContext db wasn't open, will try to open test.system.namespaces
 m31000| Tue Jul 16 08:11:42.681 [IndexRebuilder] opening db:  test
 m31000| Tue Jul 16 08:11:42.685 [IndexRebuilder] thread IndexRebuilder stack usage was 28216 bytes,  which is the most so far
 m31000| Tue Jul 16 08:11:42.687 [initandlisten] connection accepted from 192.168.1.2:55821 #1 (1 connection now open)
 m31000| Tue Jul 16 08:11:42.687 [conn1] end connection 192.168.1.2:55821 (0 connections now open)
 m31000| Tue Jul 16 08:11:42.687 [rsStart] replSet I am MissLucy:31000
 m31000| Tue Jul 16 08:11:42.688 [rsStart] starting rsHealthPoll for MissLucy:31004
 m31000| Tue Jul 16 08:11:42.688 [rsStart] starting rsHealthPoll for MissLucy:31003
 m31000| Tue Jul 16 08:11:42.688 [rsStart] starting rsHealthPoll for MissLucy:31002
 m31000| Tue Jul 16 08:11:42.688 [rsStart] starting rsHealthPoll for MissLucy:31001
 m31000| Tue Jul 16 08:11:42.688 [rsStart] replSet STARTUP2
 m31003| Tue Jul 16 08:11:42.690 [initandlisten] connection accepted from 192.168.1.2:55822 #10 (5 connections now open)
 m31000| Tue Jul 16 08:11:42.690 [rsSync] replSet SECONDARY

Later in the same run, we get crashes on other servers, some with more output:

ReplSetTest stop *** Shutting down mongod in port 31002 ***
 m31002| Tue Jul 16 08:12:45.069 [initandlisten] connection accepted from 127.0.0.1:55992 #25 (8 connections now open)
 m31002| Tue Jul 16 08:12:45.070 [conn25] terminating, shutdown command received
 m31002| dbexit: shutdown calledTue Jul 16 08:12:45.070 [conn25] shutdown: going to close listening sockets...
Tue Jul 16 08:12:45.071  m31002| Tue Jul 16 08:12:45.070 [conn25] closing listening socket: 696
DBClientCursor::init call() failed
 m31002| Tue Jul 16 08:12:45.070 [conn25] closing listening socket: 724
 m31002| Tue Jul 16 08:12:45.070 [conn25] shutdown: going to flush diaglog...
 m31002| Tue Jul 16 08:12:45.070 [conn25] shutdown: going to close sockets...
 m31002| Tue Jul 16 08:12:45.070 [conn25] shutdown: waiting for fs preallocator...
 m31002| Tue Jul 16 08:12:45.071 [conn25] shutdown: lock for final commit...
 m31002| Tue Jul 16 08:12:45.071 [conn25] shutdown: final commit...
 m31003| Tue Jul 16 08:12:45.071 [rsBackgroundSync] replSet sync source problem: 10278 dbclient error communicating with server: MissLucy:31002
 m31004| Tue Jul 16 08:12:45.071 [rsBackgroundSync] replSet sync source problem: 10278 dbclient error communicating with server: MissLucy:31002
 m31002| Tue Jul 16 08:12:45.071 [rsHealthPoll] couldn't connect to MissLucy:31001: couldn't connect to server MissLucy:31001
 m31002| Tue Jul 16 08:12:45.071 [conn23] end connection 192.168.1.2:55889 (7 connections now open)
 m31002| Tue Jul 16 08:12:45.071 [conn12] end connection 192.168.1.2:55782 (7 connections now open)
 m31002| Tue Jul 16 08:12:45.071 [conn24] end connection 192.168.1.2:55891 (7 connections now open)
 m31002| Tue Jul 16 08:12:45.071 [conn8] end connection 127.0.0.1:55767 (7 connections now open)
 m31002| Tue Jul 16 08:12:45.071 [conn20] end connection 192.168.1.2:55850 (7 connections now open)
 m31002| Tue Jul 16 08:12:45.072 [rsBackgroundSync] Socket recv() errno:10004 A blocking operation was interrupted by a call to WSACancelBlockingCall. 192.168.1.2:31003
 m31002| Tue Jul 16 08:12:45.072 [rsBackgroundSync] SocketException: remote: 192.168.1.2:31003 error: 9001 socket exception [RECV_ERROR] server [192.168.1.2:31003]
 m31004| Tue Jul 16 08:12:45.071 [conn15] end connection 192.168.1.2:55932 (2 connections now open)
 m31003| Tue Jul 16 08:12:45.072 [conn16] end connection 192.168.1.2:55890 (3 connections now open)
 m31002| Tue Jul 16 08:12:45.072 [rsHealthPoll] couldn't connect to MissLucy:31000: couldn't connect to server MissLucy:31000
 m31002| Tue Jul 16 08:12:45.072 [rsBackgroundSync] replSet sync source problem: 10278 dbclient error communicating with server: MissLucy:31003
 m31002| Tue Jul 16 08:12:45.073 [rsBackgroundSync] thread rsBackgroundSync stack usage was 32440 bytes,  which is the most so far
 m31002| Tue Jul 16 08:12:45.076 [conn25] shutdown: closing all files...
 m31002| Tue Jul 16 08:12:45.768 [slaveTracking] ERROR: Client::shutdown not called: slaveTracking
 m31002| Tue Jul 16 08:12:45.768 [slaveTracking] *** unhandled exception (access violation) at 0x0000000140478604, terminating
 m31002| Tue Jul 16 08:12:45.768 [slaveTracking] *** access violation was a read from 0xFFFFFFFFFFFFFFFF
 m31002| Tue Jul 16 08:12:45.768 [slaveTracking] *** stack trace for unhandled exception:

ReplSetTest stop *** Shutting down mongod in port 31003 ***
 m31003| Tue Jul 16 08:12:47.087 [initandlisten] connection accepted from 127.0.0.1:56007 #19 (4 connections now open)
 m31003| Tue Jul 16 08:12:47.088 [conn19] terminating, shutdown command received
 m31003| dbexit: shutdown calledTue Jul 16 08:12:47.088 [conn19] shutdown: going to close listening sockets...
Tue Jul 16 08:12:47.089  m31003| Tue Jul 16 08:12:47.088 [conn19] closing listening socket: 672
DBClientCursor::init call() failed
 m31003| Tue Jul 16 08:12:47.088 [conn19] closing listening socket: 716
 m31003| Tue Jul 16 08:12:47.088 [conn19] shutdown: going to flush diaglog...
 m31003| Tue Jul 16 08:12:47.088 [conn19] shutdown: going to close sockets...
 m31003| Tue Jul 16 08:12:47.088 [conn19] shutdown: waiting for fs preallocator...
 m31003| Tue Jul 16 08:12:47.089 [conn19] shutdown: lock for final commit...
 m31003| Tue Jul 16 08:12:47.089 [conn19] shutdown: final commit...
 m31003| Tue Jul 16 08:12:47.089 [conn2] end connection 127.0.0.1:55665 (3 connections now open)
 m31003| Tue Jul 16 08:12:47.089 [conn18] end connection 192.168.1.2:55930 (3 connections now open)
 m31004| Tue Jul 16 08:12:47.089 [conn16] end connection 192.168.1.2:55934 (1 connection now open)
 m31003| Tue Jul 16 08:12:47.089 [rsHealthPoll] replSet info MissLucy:31002 is down (or slow to respond):
 m31003| Tue Jul 16 08:12:47.089 [rsHealthPoll] couldn't connect to MissLucy:31001: couldn't connect to server MissLucy:31001
 m31003| Tue Jul 16 08:12:47.089 [rsHealthPoll] replSet member MissLucy:31002 is now in state DOWN
 m31003| Tue Jul 16 08:12:47.089 [rsHealthPoll] replset info MissLucy:31000 heartbeat failed, retrying
 m31003| Tue Jul 16 08:12:47.094 [conn19] shutdown: closing all files...
 m31004| Tue Jul 16 08:12:47.840 [rsHealthPoll] replSet info MissLucy:31002 is down (or slow to respond):
 m31004| Tue Jul 16 08:12:47.840 [rsHealthPoll] replSet member MissLucy:31002 is now in state DOWN
 m31004| Tue Jul 16 08:12:47.860 [rsHealthPoll] replset info MissLucy:31000 heartbeat failed, retrying
 m31003| Tue Jul 16 08:12:47.868 [slaveTracking] ERROR: Client::shutdown not called: slaveTracking
 m31003| Tue Jul 16 08:12:47.868 [slaveTracking] *** unhandled exception (access violation) at 0x0000000140478604, terminating
 m31003| Tue Jul 16 08:12:47.868 [slaveTracking] *** access violation was a read from 0xFFFFFFFFFFFFFFFF
 m31003| Tue Jul 16 08:12:47.868 [slaveTracking] *** stack trace for unhandled exception:

No stack trace is printed for m31002 or m31003.

The 64-bit test "passes" even with the access violations, because they happen in servers that were being shut down anyway (and they recover from the journal when restarted):

ReplSetTest stop *** Shutting down mongod in port 31004 ***
 m31004| Tue Jul 16 08:12:49.104 [initandlisten] connection accepted from 127.0.0.1:56015 #18 (2 connections now open)
 m31004| Tue Jul 16 08:12:49.105 [conn18] terminating, shutdown command received
 m31004| dbexit: shutdown calledTue Jul 16 08:12:49.105 [conn18] shutdown: going to close listening sockets...
Tue Jul 16 08:12:49.106  m31004| Tue Jul 16 08:12:49.105 [conn18] closing listening socket: 672
DBClientCursor::init call() failed
 m31004| Tue Jul 16 08:12:49.105 [conn18] closing listening socket: 700
 m31004| Tue Jul 16 08:12:49.105 [conn18] shutdown: going to flush diaglog...
 m31004| Tue Jul 16 08:12:49.105 [conn18] shutdown: going to close sockets...
 m31004| Tue Jul 16 08:12:49.106 [conn18] shutdown: waiting for fs preallocator...
 m31004| Tue Jul 16 08:12:49.106 [conn18] shutdown: lock for final commit...
 m31004| Tue Jul 16 08:12:49.106 [conn18] shutdown: final commit...
 m31004| Tue Jul 16 08:12:49.106 [conn4] end connection 127.0.0.1:55658 (1 connection now open)
 m31004| Tue Jul 16 08:12:49.106 [rsHealthPoll] couldn't connect to MissLucy:31000: couldn't connect to server MissLucy:31000
 m31004| Tue Jul 16 08:12:49.106 [rsHealthPoll] replSet info MissLucy:31003 is down (or slow to respond):
 m31004| Tue Jul 16 08:12:49.106 [rsHealthPoll] replSet member MissLucy:31003 is now in state DOWN
 m31004| Tue Jul 16 08:12:49.116 [conn18] shutdown: closing all files...
 m31004| Tue Jul 16 08:12:50.104 [rsHealthPoll] couldn't connect to MissLucy:31001: couldn't connect to server MissLucy:31001
 m31004| Tue Jul 16 08:12:51.105 [rsHealthPoll] couldn't connect to MissLucy:31000: couldn't connect to server MissLucy:31000
 m31004| Tue Jul 16 08:12:52.117 [conn18]               Progress: 1/5   20%     (File Closing Progress)
 m31004| Tue Jul 16 08:12:55.118 [conn18]               Progress: 2/5   40%     (File Closing Progress)
 m31004| Tue Jul 16 08:12:58.118 [conn18]               Progress: 3/5   60%     (File Closing Progress)
 m31004| Tue Jul 16 08:13:01.118 [conn18]               Progress: 4/5   80%     (File Closing Progress)
 m31004| Tue Jul 16 08:13:04.118 [conn18]               Progress: 5/5   100%    (File Closing Progress)
 m31004| Tue Jul 16 08:13:04.118 [conn18] closeAllFiles() finished
 m31004| Tue Jul 16 08:13:04.118 [conn18] journalCleanup...
 m31004| Tue Jul 16 08:13:04.118 [conn18] removeJournalFiles
 m31004| Tue Jul 16 08:13:04.119 [conn18] shutdown: removing fs lock...
 m31004| dbexit: really exiting nowTue Jul 16 08:13:04.119 [conn18] thread conn18 stack usage was 36008 bytes,  which is the most so far
Tue Jul 16 08:13:09.110 shell: stopped mongo program on port 31004
ReplSetTest stopSet deleting all dbpaths
ReplSetTest stopSet *** Shut down repl set - test worked ****
Tue Jul 16 08:13:09.147 [conn2] end connection 127.0.0.1:55272 (0 connections now open)
                    4.2992 minutes
Tue Jul 16 08:13:09.155 [initandlisten] connection accepted from 127.0.0.1:56024 #3 (1 connection now open)
 
1 tests succeeded

I'll try to think of a solution for this issue. schwerin and milkie, can you think of a good way to solve this?

Comment by Tad Marshall [ 16/Jul/13 ]

I tried again to reproduce this, this time on a slow 32-bit Windows XP laptop, and was again unable to reproduce the bug. The closeAllFiles step completed in 0 ms on this machine.

Examining the build slave, I saw the same thing that milkie reported; there is an entry in the Windows Event Log matching the time of the failure that indicates that mongod.exe had an access violation. Examining the reported address, it seemed that this was related to recent logging changes. My current speculation is that the code triggered an access violation while already handling an exception. This would cause a double exception, leading to immediate termination, and would explain why there was no indication of the crash in the log (i.e. the crash reported crashed). But this is just speculation at this point.

Comment by Tad Marshall [ 15/Jul/13 ]

From investigation by milkie, it seems that the mongod.exe on port 31000 silently exits (crashes) before removing the mongod.lock file, leading to the "unclean shutdown detected" error on restart (because journaling is not enabled).

I've tried to reproduce the failure by running sync_passive.js and sync_passive2.js individually (with, for example, "buildscripts\smoke.py jstests\replsets\sync_passive2.js") and also with "scons smokeReplSets", so far without success (i.e. no failures so far).

In all of http://buildlogs.mongodb.org/Windows%2032-bit/builds/5843/test/replica%20sets/sync_passive.js , http://buildlogs.mongodb.org/Windows%2032-bit/builds/5982/test/replica%20sets/sync_passive.js and http://buildlogs.mongodb.org/Nightly%20Windows%2032-bit/builds/1340/test/replica%20sets/sync_passive2.js , the last step being executed by the shutdown thread is closeAllFiles, suggesting that the error happens within that function (since it never displays "closeAllFiles() finished").

Comment by Matt Kangas [ 14/Jul/13 ]

Another example, this time on replsets\sync_passive2.js

Nightly Windows 32-bit Build #1340 Sat July 13 (rev f204f7fdc3a)

http://buildbot.mongodb.org/builders/Nightly%20Windows%2032-bit/builds/1340/steps/test_9/logs/stdio
http://buildlogs.mongodb.org/Nightly%20Windows%2032-bit/builds/1340/test/replica%20sets/sync_passive2.js

kill master
ReplSetTest n: 0 ports: [ 31000, 31001, 31002, 31003, 31004 ]	31000 number
ReplSetTest stop *** Shutting down mongod in port 31000 ***
 m31000| Sun Jul 14 02:45:13.515 [initandlisten] connection accepted from 127.0.0.1:63443 #20 (6 connections now open)
 m31000| Sun Jul 14 02:45:13.515 [conn20] terminating, shutdown command received
 ...
 m31000| dbexit: shutdown calledSun Jul 14 02:45:13.515 [conn20] shutdown: going to close listening sockets...
 m31000| Sun Jul 14 02:45:15.184 [conn20] 		Progress: 1/5	20%	(File Closing Progress)
 
(last message from m31000 until...)
 
ReplSetTest (Re)Starting....
Sun Jul 14 02:45:35.573 shell: started program mongod.exe --oplogSize 40 --port 31000 --noprealloc --smallfiles --rest --replSet sync_passive2 --dbpath /data/db/sync_passive2-0 --setParameter enableTestCommands=1
 ...
 m31000| ************** 
 m31000| Unclean shutdown detected.
 m31000| Please visit http://dochub.mongodb.org/core/repair for recovery instructions.
 m31000| *************
 m31000| Sun Jul 14 02:45:35.604 [initandlisten] exception in initAndListen: 12596 old lock file, terminating
 
ReplSetTest getMaster failed: "[Finding master] timed out after 60000ms ( 31 tries )"
Error: Printing Stack Trace
    at printStackTrace (src/mongo/shell/utils.js:37:15)
    at ReplSetTest.getMaster (src/mongo/shell/replsettest.js:413:5)
    at D:\slave\Windows_32bit_Nightly\mongo\jstests\replsets\sync_passive2.js:128:19
Sun Jul 14 02:46:39.000 [Finding master] timed out after 60000ms ( 31 tries ) at src/mongo/shell/replsettest.js:414
failed to load: D:\slave\Windows_32bit_Nightly\mongo\jstests\replsets\sync_passive2.js

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