scalien/scaliendb — Issue #330: Activation gets stuck
Author: mtrencseni
Created: 2011-11-28 18:07:46+00:00
State: open
Labels: mtrencseni

Log shows OnRestartTimeout loop every 100msec but it's not really doing anything:

2011-11-28 18:47:01.257: TCPConnection.cpp:145:TCPConnection::TryFlush(): Flushing, added tcpwrite, fd = 2223376
2011-11-28 18:47:01.257: HTTPConnection.cpp:90:HTTPConnection::OnWrite()
2011-11-28 18:47:01.257: TCPConnection.cpp:167:TCPConnection::OnWrite(): Written 80 bytes on fd 213, bytes: HTTP/1.1 200 OK
2011-11-28 18:47:01.273: TCPConnection.cpp:134:TCPConnection::TryFlush(): Not flushing, fd = 2224288
2011-11-28 18:47:01.273: HTTPConnection.cpp:76:HTTPConnection::OnClose()
2011-11-28 18:47:01.273: TCPConnection.cpp:86:TCPConnection::Close()
2011-11-28 18:47:01.273: IOProcessor_Windows.cpp:217:IOProcessorUnregisterSocket(): fd = 213
2011-11-28 18:47:01.273: TCPServer.h:140:TCPServer::DeleteConn()
2011-11-28 18:47:01.288: StorageEnvironment.cpp:1506:StorageEnvironment::OnBackgroundTimer(): Begin
2011-11-28 18:47:01.288: StorageEnvironment.cpp:1173:StorageEnvironment::TrySerializeChunks()
2011-11-28 18:47:01.288: StorageEnvironment.cpp:1227:StorageEnvironment::TryWriteChunks()
2011-11-28 18:47:01.288: StorageEnvironment.cpp:1259:StorageEnvironment::TryMergeChunks()
2011-11-28 18:47:01.288: StorageEnvironment.cpp:1310:StorageEnvironment::TryArchiveLogSegments()
2011-11-28 18:47:01.288: StorageEnvironment.cpp:1374:StorageEnvironment::TryDeleteLogSegmentFileChunks()
2011-11-28 18:47:01.288: Countdown.cpp:23:Countdown::OnAdd(): expireTime: 1322502422288, delay: 1000
2011-11-28 18:47:01.288: StorageEnvironment.cpp:1514:StorageEnvironment::OnBackgroundTimer(): End
2011-11-28 18:47:01.288: HTTPConnection.cpp:48:HTTPConnection::OnRead()
2011-11-28 18:47:01.288: [192.168.137.235:4992] HTTP: GET /favicon.ico 404 9
2011-11-28 18:47:01.288: TCPConnection.cpp:145:TCPConnection::TryFlush(): Flushing, added tcpwrite, fd = 2224064
2011-11-28 18:47:01.288: HTTPConnection.cpp:90:HTTPConnection::OnWrite()
2011-11-28 18:47:01.288: TCPConnection.cpp:167:TCPConnection::OnWrite(): Written 124 bytes on fd 212, bytes: HTTP/1.1 404 Not found
2011-11-28 18:47:01.288: TCPConnection.cpp:134:TCPConnection::TryFlush(): Not flushing, fd = 2224288
2011-11-28 18:47:01.288: HTTPConnection.cpp:76:HTTPConnection::OnClose()
2011-11-28 18:47:01.288: TCPConnection.cpp:86:TCPConnection::Close()
2011-11-28 18:47:01.288: IOProcessor_Windows.cpp:217:IOProcessorUnregisterSocket(): fd = 212
2011-11-28 18:47:01.288: TCPServer.h:140:TCPServer::DeleteConn()
2011-11-28 18:47:01.335: OnRestartTimeout
2011-11-28 18:47:01.335: PaxosProposer.cpp:93:PaxosProposer::OnRestartTimeout()
2011-11-28 18:47:01.335: Countdown.cpp:23:Countdown::OnAdd(): expireTime: 1322502421435, delay: 100
2011-11-28 18:47:01.398: MessageConnection.cpp:125:MessageConnection::OnRead(): Read buffer: 97:G:96094:29466:24345:0:72:N:0000000023413|P:/288a9983-03e1-4f72-9941-524db48d1cff|l:0000000000000|
2011-11-28 18:47:01.398: Countdown.cpp:23:Countdown::OnAdd(): expireTime: 1322502481398, delay: 60000
2011-11-28 18:47:01.398: ShardDatabaseManager.cpp:843:ShardDatabaseManager::OnExecuteReads(): asyncGet: F
2011-11-28 18:47:01.398: ShardDatabaseManager.cpp:882:ShardDatabaseManager::OnExecuteReads(): blocking
2011-11-28 18:47:01.398: TCPConnection.cpp:145:TCPConnection::TryFlush(): Flushing, added tcpwrite, fd = 2224864
2011-11-28 18:47:01.398: SDBPConnection.cpp:80:SDBPConnection::OnWrite()
2011-11-28 18:47:01.398: Countdown.cpp:23:Countdown::OnAdd(): expireTime: 1322502481398, delay: 60000
2011-11-28 18:47:01.398: TCPConnection.cpp:167:TCPConnection::OnWrite(): Written 9 bytes on fd 63, bytes: 7:F:96094
2011-11-28 18:47:01.398: TCPConnection.cpp:134:TCPConnection::TryFlush(): Not flushing, fd = 2224288
2011-11-28 18:47:01.398: MessageConnection.cpp:125:MessageConnection::OnRead(): Read buffer: 34:Y:96095:29466:24342:11:transaction
2011-11-28 18:47:01.398: Countdown.cpp:23:Countdown::OnAdd(): expireTime: 1322502481398, delay: 60000
2011-11-28 18:47:01.413: ShardDatabaseManager.cpp:826:ShardDatabaseManager::OnYieldStorageThreadsTimer(): readRequests: 0
2011-11-28 18:47:01.413: Countdown.cpp:23:Countdown::OnAdd(): expireTime: 1322502422413, delay: 1000
2011-11-28 18:47:01.445: OnRestartTimeout
2011-11-28 18:47:01.445: PaxosProposer.cpp:93:PaxosProposer::OnRestartTimeout()
2011-11-28 18:47:01.445: Countdown.cpp:23:Countdown::OnAdd(): expireTime: 1322502421545, delay: 100
2011-11-28 18:47:01.554: OnRestartTimeout
2011-11-28 18:47:01.554: PaxosProposer.cpp:93:PaxosProposer::OnRestartTimeout()
2011-11-28 18:47:01.554: Countdown.cpp:23:Countdown::OnAdd(): expireTime: 1322502421654, delay: 100
2011-11-28 18:47:01.663: OnRestartTimeout
2011-11-28 18:47:01.663: PaxosProposer.cpp:93:PaxosProposer::OnRestartTimeout()
2011-11-28 18:47:01.663: Countdown.cpp:23:Countdown::OnAdd(): expireTime: 1322502421763, delay: 100
2011-11-28 18:47:01.663: ShardQuorumProcessor.cpp:308:ShardQuorumProcessor::OnRequestLeaseTimeout()
2011-11-28 18:47:01.663: ShardQuorumProcessor.cpp:314:ShardQuorumProcessor::OnRequestLeaseTimeout(): Requesting lease for quorum 1 with proposalID 17184164675685
2011-11-28 18:47:01.663: Countdown.cpp:23:Countdown::OnAdd(): expireTime: 1322502422163, delay: 500
2011-11-28 18:47:01.663: ShardHeartbeatManager.cpp:42:ShardHeartbeatManager::OnHeartbeatTimeout()
2011-11-28 18:47:01.663: Countdown.cpp:23:Countdown::OnAdd(): expireTime: 1322502422663, delay: 1000
2011-11-28 18:47:01.663: ShardHeartbeatManager.cpp:118:ShardHeartbeatManager::OnHeartbeatTimeout(): Broadcasting heartbeat to controllers
2011-11-28 18:47:01.663: TCPConnection.cpp:145:TCPConnection::TryFlush(): Flushing, added tcpwrite, fd = 2224864
2011-11-28 18:47:01.663: TCPConnection.cpp:145:TCPConnection::TryFlush(): Flushing, added tcpwrite, fd = 2224864
2011-11-28 18:47:01.663: TCPConnection.cpp:145:TCPConnection::TryFlush(): Flushing, added tcpwrite, fd = 2224864
2011-11-28 18:47:01.663: TCPConnection.cpp:167:TCPConnection::OnWrite(): Written 1407 bytes on fd 3, bytes: 41:C:R:101:1:17184164675685:24328907:12:30001358:C:H:101:8090:7090:1:1:24328907:F:0:0:0:28:1:25106:497662784:10:0986890048:T:F:0:0:0:0:0:1:25112:0:0::T:F:0:0:0:0:0:1:25113:262208:16:fileContentTable:T:F:0:0:0:0:0:1:25114:23669384:32:H:0000000048976|N:0000000048976|:T:F:0:0:0:0:0:1:25115:149146016:16:T:0000013962320|:T:F:0:0:0:0:0:1:25116:236821608:72:N:0000000050163|P:/28d92433-07a7-4fd6-9f46-bb5b5cab90b0|l:0000000000000|:T:F:0:0:0:0:0:1:25117:0:0::T:F:0:0:0:0:0:1:25118:138717192:32:N:0000000050148|T:0000000307565|:T:F:0:0:0:0:0:1:25119:36092536:21:C:634580987093339425|:T:F:0:0:0:0:0:1:25120:0:0::T:F:0:0:0:0:0:1:25121:89931048:56:N:0000000050073|P:/c1111abd-af7b-4fe8-8f5d-7917b0236638|:T:F:0:0:0:0:0:1:25122:0:0::T:F:0:0:0:0:0:1:25123:169844008:32:F:0000012476591|T:0000000000000|:T:F:0:0:0:0:0:1:25124:166310760:41:S:2|L:634580987008394566|F:0000019936601|:T:F:0:0:0:0:0:1:25125:169966992:32:T:0000000000
2011-11-28 18:47:01.679: TCPConnection.cpp:134:TCPConnection::TryFlush(): Not flushing, fd = 2224352
2011-11-28 18:47:01.679: TCPConnection.cpp:167:TCPConnection::OnWrite(): Written 1407 bytes on fd 4, bytes: 41:C:R:101:1:17184164675685:24328907:12:30001358:C:H:101:8090:7090:1:1:24328907:F:0:0:0:28:1:25106:497662784:10:0986890048:T:F:0:0:0:0:0:1:25112:0:0::T:F:0:0:0:0:0:1:25113:262208:16:fileContentTable:T:F:0:0:0:0:0:1:25114:23669384:32:H:0000000048976|N:0000000048976|:T:F:0:0:0:0:0:1:25115:149146016:16:T:0000013962320|:T:F:0:0:0:0:0:1:25116:236821608:72:N:0000000050163|P:/28d92433-07a7-4fd6-9f46-bb5b5cab90b0|l:0000000000000|:T:F:0:0:0:0:0:1:25117:0:0::T:F:0:0:0:0:0:1:25118:138717192:32:N:0000000050148|T:0000000307565|:T:F:0:0:0:0:0:1:25119:36092536:21:C:634580987093339425|:T:F:0:0:0:0:0:1:25120:0:0::T:F:0:0:0:0:0:1:25121:89931048:56:N:0000000050073|P:/c1111abd-af7b-4fe8-8f5d-7917b0236638|:T:F:0:0:0:0:0:1:25122:0:0::T:F:0:0:0:0:0:1:25123:169844008:32:F:0000012476591|T:0000000000000|:T:F:0:0:0:0:0:1:25124:166310760:41:S:2|L:634580987008394566|F:0000019936601|:T:F:0:0:0:0:0:1:25125:169966992:32:T:0000000000
2011-11-28 18:47:01.679: TCPConnection.cpp:134:TCPConnection::TryFlush(): Not flushing, fd = 2224352
2011-11-28 18:47:01.679: TCPConnection.cpp:167:TCPConnection::OnWrite(): Written 1407 bytes on fd 5, bytes: 41:C:R:101:1:17184164675685:24328907:12:30001358:C:H:101:8090:7090:1:1:24328907:F:0:0:0:28:1:25106:497662784:10:0986890048:T:F:0:0:0:0:0:1:25112:0:0::T:F:0:0:0:0:0:1:25113:262208:16:fileContentTable:T:F:0:0:0:0:0:1:25114:23669384:32:H:0000000048976|N:0000000048976|:T:F:0:0:0:0:0:1:25115:149146016:16:T:0000013962320|:T:F:0:0:0:0:0:1:25116:236821608:72:N:0000000050163|P:/28d92433-07a7-4fd6-9f46-bb5b5cab90b0|l:0000000000000|:T:F:0:0:0:0:0:1:25117:0:0::T:F:0:0:0:0:0:1:25118:138717192:32:N:0000000050148|T:0000000307565|:T:F:0:0:0:0:0:1:25119:36092536:21:C:634580987093339425|:T:F:0:0:0:0:0:1:25120:0:0::T:F:0:0:0:0:0:1:25121:89931048:56:N:0000000050073|P:/c1111abd-af7b-4fe8-8f5d-7917b0236638|:T:F:0:0:0:0:0:1:25122:0:0::T:F:0:0:0:0:0:1:25123:169844008:32:F:0000012476591|T:0000000000000|:T:F:0:0:0:0:0:1:25124:166310760:41:S:2|L:634580987008394566|F:0000019936601|:T:F:0:0:0:0:0:1:25125:169966992:32:T:0000000000
2011-11-28 18:47:01.679: TCPConnection.cpp:134:TCPConnection::TryFlush(): Not flushing, fd = 2224352
2011-11-28 18:47:01.679: MessageConnection.cpp:125:MessageConnection::OnRead(): Read buffer: 211:C:r:101:1:17184164675685:12:3000:F:1:101:28:25106:25112:25113:25114:25115:25116:25117:25118:25119:25120:25121:25122:25123:25124:25125:25126:25127:25128:25129:25130:25131:25132:25133:25134:25135:25136:25137:25138
2011-11-28 18:47:01.679: ContextTransport.cpp:104:ContextTransport::OnMessage(): C:r:101:1:17184164675685:12:3000:F:1:101:28:25106:25112:25113:25114:25115:25116:25117:25118:25119:25120:25121:25122:25123:25124:25125:25126:25127:25128:25129:25130:25131:25132:25133:25134:25135:25136:25137:25138
2011-11-28 18:47:01.679: ShardServer.cpp:176:ShardServer::OnClusterMessage()
2011-11-28 18:47:01.679: ReplicatedLog.cpp:197:ReplicatedLog::OnLearnLease(): context->IsLeaseOwner() = true
2011-11-28 18:47:01.679: ReplicatedLog.cpp:198:ReplicatedLog::OnLearnLease(): !proposer.IsActive() = false
2011-11-28 18:47:01.679: ReplicatedLog.cpp:199:ReplicatedLog::OnLearnLease(): !proposer.state.multi = true
2011-11-28 18:47:01.679: ShardServer.cpp:213:ShardServer::OnClusterMessage(): Recieved lease, quorumID = 1, proposalID = 17184164675685
2011-11-28 18:47:01.742: MessageConnection.cpp:125:MessageConnection::OnRead(): Read buffer: 97:G:96732:29466:24345:0:72:N:0000000032804|P:/d7ffa991-d063-46dc-aba4-7d5aa8151127|l:0000000000000|
2011-11-28 18:47:01.742: Countdown.cpp:23:Countdown::OnAdd(): expireTime: 1322502481742, delay: 60000
2011-11-28 18:47:01.742: ShardDatabaseManager.cpp:843:ShardDatabaseManager::OnExecuteReads(): asyncGet: F
2011-11-28 18:47:01.742: ShardDatabaseManager.cpp:882:ShardDatabaseManager::OnExecuteReads(): blocking
2011-11-28 18:47:01.742: TCPConnection.cpp:145:TCPConnection::TryFlush(): Flushing, added tcpwrite, fd = 2224864
2011-11-28 18:47:01.742: SDBPConnection.cpp:80:SDBPConnection::OnWrite()
2011-11-28 18:47:01.742: Countdown.cpp:23:Countdown::OnAdd(): expireTime: 1322502481742, delay: 60000
2011-11-28 18:47:01.742: TCPConnection.cpp:167:TCPConnection::OnWrite(): Written 9 bytes on fd 61, bytes: 7:F:96732
2011-11-28 18:47:01.742: TCPConnection.cpp:134:TCPConnection::TryFlush(): Not flushing, fd = 2224288
2011-11-28 18:47:01.742: MessageConnection.cpp:125:MessageConnection::OnRead(): Read buffer: 34:Y:96733:29466:24342:11:transaction
2011-11-28 18:47:01.742: Countdown.cpp:23:Countdown::OnAdd(): expireTime: 1322502481742, delay: 60000
2011-11-28 18:47:01.773: OnRestartTimeout
2011-11-28 18:47:01.773: PaxosProposer.cpp:93:PaxosProposer::OnRestartTimeout()
2011-11-28 18:47:01.773: Countdown.cpp:23:Countdown::OnAdd(): expireTime: 1322502421873, delay: 100
2011-11-28 18:47:01.882: OnRestartTimeout
2011-11-28 18:47:01.882: PaxosProposer.cpp:93:PaxosProposer::OnRestartTimeout()
2011-11-28 18:47:01.882: Countdown.cpp:23:Countdown::OnAdd(): expireTime: 1322502421982, delay: 100
2011-11-28 18:47:01.992: OnRestartTimeout
2011-11-28 18:47:01.992: PaxosProposer.cpp:93:PaxosProposer::OnRestartTimeout()
2011-11-28 18:47:01.992: Countdown.cpp:23:Countdown::OnAdd(): expireTime: 1322502422092, delay: 100
2011-11-28 18:47:02.101: OnRestartTimeout
2011-11-28 18:47:02.101: PaxosProposer.cpp:93:PaxosProposer::OnRestartTimeout()
2011-11-28 18:47:02.101: Countdown.cpp:23:Countdown::OnAdd(): expireTime: 1322502422201, delay: 100
2011-11-28 18:47:02.117: MessageConnection.cpp:125:MessageConnection::OnRead(): Read buffer: 3438:C:C:Y:2:P29466:N:12:1138:24368:25139:104:3:1:8:quorum 1:1:101:1:100:28:25106:25112:25113:25114:25115:25116:25117:25118:25119:25120:25121:25122:25123:25124:25125:25126:25127:25128:25129:25130:25131:25132:25133:25134:25135:25136:25137:25138:12:N:24328907:Y:101:7:8:quorum 7:1:102:0:0:0:N:546815:Y:102:8:8:quorum 8:1:103:0:0:0:N:172090:Y:103:3:1134:4:test:1:24339:1136:7:Storage:1:24341:1137:9:Benchmark:26:24342:24343:24344:24345:24346:24347:24348:24349:24350:24351:24352:24353:24354:24355:24356:24357:24358:24359:24360:24361:24362:24363:24364:24365:24366:24367:28:1134:24339:4:test:F:1:25106:1136:24341:11:transaction:F:1:25112:1137:24342:8:sequence:F:1:25113:1137:24343:22:lastKnownTransactionId:F:1:25114:1137:24344:11:transaction:F:1:25115:1137:24345:33:transactionNetworkIdFullpathIndex:F:1:25116:1137:24346:22:transactionNetworkFile:F:1:25117:1137:24347:29:transactionNetworkTransaction:F:1:25118:1137:24348:27:transacti
2011-11-28 18:47:02.117: ContextTransport.cpp:104:ContextTransport::OnMessage(): C:C:Y:2:P29466:N:12:1138:24368:25139:104:3:1:8:quorum 1:1:101:1:100:28:25106:25112:25113:25114:25115:25116:25117:25118:25119:25120:25121:25122:25123:25124:25125:25126:25127:25128:25129:25130:25131:25132:25133:25134:25135:25136:25137:25138:12:N:24328907:Y:101:7:8:quorum 7:1:102:0:0:0:N:546815:Y:102:8:8:quorum 8:1:103:0:0:0:N:172090:Y:103:3:1134:4:test:1:24339:1136:7:Storage:1:24341:1137:9:Benchmark:26:24342:24343:24344:24345:24346:24347:24348:24349:24350:24351:24352:24353:24354:24355:24356:24357:24358:24359:24360:24361:24362:24363:24364:24365:24366:24367:28:1134:24339:4:test:F:1:25106:1136:24341:11:transaction:F:1:25112:1137:24342:8:sequence:F:1:25113:1137:24343:22:lastKnownTransactionId:F:1:25114:1137:24344:11:transaction:F:1:25115:1137:24345:33:transactionNetworkIdFullpathIndex:F:1:25116:1137:24346:22:transactionNetworkFile:F:1:25117:1137:24347:29:transactionNetworkTransaction:F:1:25118:1137:24348:27:transactionCreatedDateInde
2011-11-28 18:47:02.117: ShardServer.cpp:176:ShardServer::OnClusterMessage()
2011-11-28 18:47:02.117: ReplicatedLog.cpp:151:ReplicatedLog::RegisterPaxosID()
2011-11-28 18:47:02.117: ShardServer.cpp:475:ShardServer::ConfigureQuorum()
2011-11-28 18:47:02.117: ShardServer.cpp:206:ShardServer::OnClusterMessage(): Got new configState, master is 2
2011-11-28 18:47:02.163: ShardQuorumProcessor.cpp:308:ShardQuorumProcessor::OnRequestLeaseTimeout()
2011-11-28 18:47:02.163: ShardQuorumProcessor.cpp:314:ShardQuorumProcessor::OnRequestLeaseTimeout(): Requesting lease for quorum 1 with proposalID 17188459642981
2011-11-28 18:47:02.163: Countdown.cpp:23:Countdown::OnAdd(): expireTime: 1322502422663, delay: 500
2011-11-28 18:47:02.163: TCPConnection.cpp:145:TCPConnection::TryFlush(): Flushing, added tcpwrite, fd = 2224864
2011-11-28 18:47:02.163: TCPConnection.cpp:145:TCPConnection::TryFlush(): Flushing, added tcpwrite, fd = 2224864
2011-11-28 18:47:02.163: TCPConnection.cpp:145:TCPConnection::TryFlush(): Flushing, added tcpwrite, fd = 2224864
2011-11-28 18:47:02.163: TCPConnection.cpp:167:TCPConnection::OnWrite(): Written 44 bytes on fd 3, bytes: 41:C:R:101:1:17188459642981:24328907:12:3000
2011-11-28 18:47:02.163: TCPConnection.cpp:134:TCPConnection::TryFlush(): Not flushing, fd = 2224352
2011-11-28 18:47:02.163: TCPConnection.cpp:167:TCPConnection::OnWrite(): Written 44 bytes on fd 4, bytes: 41:C:R:101:1:17188459642981:24328907:12:3000
2011-11-28 18:47:02.163: TCPConnection.cpp:134:TCPConnection::TryFlush(): Not flushing, fd = 2224352
2011-11-28 18:47:02.163: TCPConnection.cpp:167:TCPConnection::OnWrite(): Written 44 bytes on fd 5, bytes: 41:C:R:101:1:17188459642981:24328907:12:3000
2011-11-28 18:47:02.163: TCPConnection.cpp:134:TCPConnection::TryFlush(): Not flushing, fd = 2224352
2011-11-28 18:47:02.163: MessageConnection.cpp:125:MessageConnection::OnRead(): Read buffer: 211:C:r:101:1:17188459642981:12:3000:F:1:101:28:25106:25112:25113:25114:25115:25116:25117:25118:25119:25120:25121:25122:25123:25124:25125:25126:25127:25128:25129:25130:25131:25132:25133:25134:25135:25136:25137:25138
2011-11-28 18:47:02.163: ContextTransport.cpp:104:ContextTransport::OnMessage(): C:r:101:1:17188459642981:12:3000:F:1:101:28:25106:25112:25113:25114:25115:25116:25117:25118:25119:25120:25121:25122:25123:25124:25125:25126:25127:25128:25129:25130:25131:25132:25133:25134:25135:25136:25137:25138
2011-11-28 18:47:02.163: ShardServer.cpp:176:ShardServer::OnClusterMessage()
2011-11-28 18:47:02.163: ReplicatedLog.cpp:197:ReplicatedLog::OnLearnLease(): context->IsLeaseOwner() = true
2011-11-28 18:47:02.163: ReplicatedLog.cpp:198:ReplicatedLog::OnLearnLease(): !proposer.IsActive() = false
2011-11-28 18:47:02.163: ReplicatedLog.cpp:199:ReplicatedLog::OnLearnLease(): !proposer.state.multi = true
2011-11-28 18:47:02.163: ShardServer.cpp:213:ShardServer::OnClusterMessage(): Recieved lease, quorumID = 1, proposalID = 17188459642981
2011-11-28 18:47:02.210: OnRestartTimeout
2011-11-28 18:47:02.210: PaxosProposer.cpp:93:PaxosProposer::OnRestartTimeout()
2011-11-28 18:47:02.210: Countdown.cpp:23:Countdown::OnAdd(): expireTime: 1322502422310, delay: 100
2011-11-28 18:47:02.288: StorageEnvironment.cpp:1506:StorageEnvironment::OnBackgroundTimer(): Begin
2011-11-28 18:47:02.288: StorageEnvironment.cpp:1173:StorageEnvironment::TrySerializeChunks()
2011-11-28 18:47:02.288: StorageEnvironment.cpp:1227:StorageEnvironment::TryWriteChunks()
2011-11-28 18:47:02.288: StorageEnvironment.cpp:1259:StorageEnvironment::TryMergeChunks()
2011-11-28 18:47:02.288: StorageEnvironment.cpp:1310:StorageEnvironment::TryArchiveLogSegments()
2011-11-28 18:47:02.288: StorageEnvironment.cpp:1374:StorageEnvironment::TryDeleteLogSegmentFileChunks()
2011-11-28 18:47:02.288: Countdown.cpp:23:Countdown::OnAdd(): expireTime: 1322502423288, delay: 1000
2011-11-28 18:47:02.288: StorageEnvironment.cpp:1514:StorageEnvironment::OnBackgroundTimer(): End
2011-11-28 18:47:02.320: OnRestartTimeout
2011-11-28 18:47:02.320: PaxosProposer.cpp:93:PaxosProposer::OnRestartTimeout()
2011-11-28 18:47:02.320: Countdown.cpp:23:Countdown::OnAdd(): expireTime: 1322502422420, delay: 100
2011-11-28 18:47:02.335: MessageConnection.cpp:125:MessageConnection::OnRead(): Read buffer: 97:G:96143:29466:24345:0:72:N:0000000050945|P:/6c568e68-b76a-4f0c-a016-d7429de8aba4|l:0000000000000|