[ https://issues.apache.org/jira/browse/MESOS-1490?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Dominic Hamon updated MESOS-1490: --------------------------------- Assignee: (was: Dominic Hamon) > LogStateTest.FetchAndStoreAndExpungeAndExpunge is flaky > ------------------------------------------------------- > > Key: MESOS-1490 > URL: https://issues.apache.org/jira/browse/MESOS-1490 > Project: Mesos > Issue Type: Bug > Components: test > Reporter: Vinod Kone > > [ RUN ] LogStateTest.FetchAndStoreAndExpungeAndExpunge > Using temporary directory > '/tmp/LogStateTest_FetchAndStoreAndExpungeAndExpunge_GqoTj9' > I0616 12:23:33.629946 2963 leveldb.cpp:176] Opened db in 31.790058ms > I0616 12:23:33.641286 2963 leveldb.cpp:183] Compacted db in 11.009044ms > I0616 12:23:33.641561 2963 leveldb.cpp:198] Created db iterator in 7621ns > I0616 12:23:33.642011 2963 leveldb.cpp:204] Seeked to beginning of db in > 2318ns > I0616 12:23:33.642269 2963 leveldb.cpp:273] Iterated through 0 keys in the > db in 2652ns > I0616 12:23:33.642606 2963 replica.cpp:741] Replica recovered with log > positions 0 -> 0 with 1 holes and 0 unlearned > I0616 12:23:33.651423 2983 leveldb.cpp:306] Persisting metadata (8 bytes) to > leveldb took 8.308421ms > I0616 12:23:33.651461 2983 replica.cpp:320] Persisted replica status to > VOTING > I0616 12:23:33.690558 2963 leveldb.cpp:176] Opened db in 33.770923ms > I0616 12:23:33.703594 2963 leveldb.cpp:183] Compacted db in 12.436491ms > I0616 12:23:33.704098 2963 leveldb.cpp:198] Created db iterator in 8008ns > I0616 12:23:33.704335 2963 leveldb.cpp:204] Seeked to beginning of db in > 2349ns > I0616 12:23:33.704610 2963 leveldb.cpp:273] Iterated through 0 keys in the > db in 2198ns > I0616 12:23:33.704864 2963 replica.cpp:741] Replica recovered with log > positions 0 -> 0 with 1 holes and 0 unlearned > I0616 12:23:33.718089 2990 leveldb.cpp:306] Persisting metadata (8 bytes) to > leveldb took 12.797472ms > I0616 12:23:33.718134 2990 replica.cpp:320] Persisted replica status to > VOTING > I0616 12:23:33.781381 2963 leveldb.cpp:176] Opened db in 59.577736ms > I0616 12:23:33.830924 2963 leveldb.cpp:183] Compacted db in 49.148429ms > I0616 12:23:33.831243 2963 leveldb.cpp:198] Created db iterator in 13355ns > I0616 12:23:33.831506 2963 leveldb.cpp:204] Seeked to beginning of db in > 21193ns > I0616 12:23:33.831795 2963 leveldb.cpp:273] Iterated through 1 keys in the > db in 31083ns > I0616 12:23:33.832051 2963 replica.cpp:741] Replica recovered with log > positions 0 -> 0 with 1 holes and 0 unlearned > I0616 12:23:33.865875 2963 leveldb.cpp:176] Opened db in 33.435268ms > I0616 12:23:33.896766 2963 leveldb.cpp:183] Compacted db in 30.273578ms > I0616 12:23:33.897330 2963 leveldb.cpp:198] Created db iterator in 11028ns > I0616 12:23:33.897594 2963 leveldb.cpp:204] Seeked to beginning of db in > 18381ns > I0616 12:23:33.897863 2963 leveldb.cpp:273] Iterated through 1 keys in the > db in 29669ns > I0616 12:23:33.898108 2963 replica.cpp:741] Replica recovered with log > positions 0 -> 0 with 1 holes and 0 unlearned > I0616 12:23:33.898617 2986 recover.cpp:425] Starting replica recovery > I0616 12:23:33.898692 2986 recover.cpp:451] Replica is in VOTING status > I0616 12:23:33.898727 2986 recover.cpp:440] Recover process terminated > I0616 12:23:33.899284 2986 log.cpp:656] Attempting to start the writer > I0616 12:23:33.899662 2986 replica.cpp:474] Replica received implicit > promise request with proposal 1 > I0616 12:23:33.899907 2990 replica.cpp:474] Replica received implicit > promise request with proposal 1 > I0616 12:23:33.912348 2990 leveldb.cpp:306] Persisting metadata (8 bytes) to > leveldb took 12.40255ms > I0616 12:23:33.912400 2990 replica.cpp:342] Persisted promised to 1 > I0616 12:23:33.912690 2986 leveldb.cpp:306] Persisting metadata (8 bytes) to > leveldb took 12.999899ms > I0616 12:23:33.912757 2986 replica.cpp:342] Persisted promised to 1 > I0616 12:23:33.912905 2986 coordinator.cpp:230] Coordinator attemping to > fill missing position > I0616 12:23:33.913260 2986 replica.cpp:375] Replica received explicit > promise request for position 0 with proposal 2 > I0616 12:23:33.913416 2990 replica.cpp:375] Replica received explicit > promise request for position 0 with proposal 2 > I0616 12:23:33.921795 2990 leveldb.cpp:343] Persisting action (8 bytes) to > leveldb took 8.347839ms > I0616 12:23:33.921831 2990 replica.cpp:676] Persisted action at 0 > I0616 12:23:33.922047 2986 leveldb.cpp:343] Persisting action (8 bytes) to > leveldb took 8.758297ms > I0616 12:23:33.922379 2986 replica.cpp:676] Persisted action at 0 > I0616 12:23:33.924927 2983 replica.cpp:508] Replica received write request > for position 0 > I0616 12:23:33.924969 2983 leveldb.cpp:438] Reading position from leveldb > took 19309ns > I0616 12:23:33.925101 2984 replica.cpp:508] Replica received write request > for position 0 > I0616 12:23:33.925127 2984 leveldb.cpp:438] Reading position from leveldb > took 10079ns > I0616 12:23:33.934978 2984 leveldb.cpp:343] Persisting action (14 bytes) to > leveldb took 9.83074ms > I0616 12:23:33.935020 2984 replica.cpp:676] Persisted action at 0 > I0616 12:23:33.935111 2983 leveldb.cpp:343] Persisting action (14 bytes) to > leveldb took 10.119835ms > I0616 12:23:33.935132 2983 replica.cpp:676] Persisted action at 0 > I0616 12:23:33.935235 2983 replica.cpp:655] Replica received learned notice > for position 0 > I0616 12:23:33.935333 2984 replica.cpp:655] Replica received learned notice > for position 0 > I0616 12:23:33.944811 2984 leveldb.cpp:343] Persisting action (16 bytes) to > leveldb took 9.452885ms > I0616 12:23:33.944859 2984 replica.cpp:676] Persisted action at 0 > I0616 12:23:33.944869 2984 replica.cpp:661] Replica learned NOP action at > position 0 > I0616 12:23:33.945051 2984 log.cpp:672] Writer started with ending position 0 > I0616 12:23:33.945282 2984 leveldb.cpp:438] Reading position from leveldb > took 20921ns > I0616 12:23:33.946615 2983 leveldb.cpp:343] Persisting action (16 bytes) to > leveldb took 11.352783ms > I0616 12:23:33.946643 2983 replica.cpp:676] Persisted action at 0 > I0616 12:23:33.946652 2983 replica.cpp:661] Replica learned NOP action at > position 0 > I0616 12:23:33.948106 2989 log.cpp:680] Attempting to append 49 bytes to the > log > I0616 12:23:33.948148 2989 coordinator.cpp:340] Coordinator attempting to > write APPEND action at position 1 > I0616 12:23:33.948369 2989 replica.cpp:508] Replica received write request > for position 1 > I0616 12:23:33.948531 2985 replica.cpp:508] Replica received write request > for position 1 > I0616 12:23:33.958195 2985 leveldb.cpp:343] Persisting action (65 bytes) to > leveldb took 9.636155ms > I0616 12:23:33.958240 2985 replica.cpp:676] Persisted action at 1 > I0616 12:23:33.958905 2989 leveldb.cpp:343] Persisting action (65 bytes) to > leveldb took 10.510293ms > I0616 12:23:33.958935 2989 replica.cpp:676] Persisted action at 1 > I0616 12:23:33.959096 2989 replica.cpp:655] Replica received learned notice > for position 1 > I0616 12:23:33.959247 2985 replica.cpp:655] Replica received learned notice > for position 1 > I0616 12:23:33.969413 2985 leveldb.cpp:343] Persisting action (67 bytes) to > leveldb took 10.139698ms > I0616 12:23:33.969461 2985 replica.cpp:676] Persisted action at 1 > I0616 12:23:33.969471 2985 replica.cpp:661] Replica learned APPEND action at > position 1 > I0616 12:23:33.969825 2985 log.cpp:699] Attempting to truncate the log to 1 > I0616 12:23:33.969883 2985 coordinator.cpp:340] Coordinator attempting to > write TRUNCATE action at position 2 > I0616 12:23:33.970105 2985 replica.cpp:508] Replica received write request > for position 2 > I0616 12:23:33.970396 2989 leveldb.cpp:343] Persisting action (67 bytes) to > leveldb took 11.26858ms > I0616 12:23:33.970441 2989 replica.cpp:676] Persisted action at 1 > I0616 12:23:33.970453 2989 replica.cpp:661] Replica learned APPEND action at > position 1 > I0616 12:23:33.970468 2989 replica.cpp:508] Replica received write request > for position 2 > I0616 12:23:33.980139 2989 leveldb.cpp:343] Persisting action (16 bytes) to > leveldb took 9.651318ms > I0616 12:23:33.980182 2989 replica.cpp:676] Persisted action at 2 > I0616 12:23:33.980422 2985 leveldb.cpp:343] Persisting action (16 bytes) to > leveldb took 10.293293ms > I0616 12:23:33.980448 2985 replica.cpp:676] Persisted action at 2 > I0616 12:23:33.980654 2985 replica.cpp:655] Replica received learned notice > for position 2 > I0616 12:23:33.980983 2989 replica.cpp:655] Replica received learned notice > for position 2 > I0616 12:23:33.989821 2989 leveldb.cpp:343] Persisting action (18 bytes) to > leveldb took 8.809638ms > I0616 12:23:33.989897 2989 leveldb.cpp:401] Deleting ~1 keys from leveldb > took 33507ns > I0616 12:23:33.989912 2989 replica.cpp:676] Persisted action at 2 > I0616 12:23:33.989922 2989 replica.cpp:661] Replica learned TRUNCATE action > at position 2 > I0616 12:23:33.990144 2989 log.cpp:680] Attempting to append 12 bytes to the > log > I0616 12:23:33.990185 2989 coordinator.cpp:340] Coordinator attempting to > write APPEND action at position 3 > I0616 12:23:33.990409 2989 replica.cpp:508] Replica received write request > for position 3 > I0616 12:23:33.990708 2985 leveldb.cpp:343] Persisting action (18 bytes) to > leveldb took 10.020056ms > I0616 12:23:33.991072 2985 leveldb.cpp:401] Deleting ~1 keys from leveldb > took 30689ns > I0616 12:23:33.991204 2985 replica.cpp:676] Persisted action at 2 > I0616 12:23:33.991216 2985 replica.cpp:661] Replica learned TRUNCATE action > at position 2 > I0616 12:23:33.991232 2985 replica.cpp:508] Replica received write request > for position 3 > I0616 12:23:34.000671 2985 leveldb.cpp:343] Persisting action (28 bytes) to > leveldb took 9.4207ms > I0616 12:23:34.001118 2985 replica.cpp:676] Persisted action at 3 > I0616 12:23:34.001459 2989 leveldb.cpp:343] Persisting action (28 bytes) to > leveldb took 11.028007ms > I0616 12:23:34.005596 2989 replica.cpp:676] Persisted action at 3 > I0616 12:23:34.005770 2989 replica.cpp:655] Replica received learned notice > for position 3 > I0616 12:23:34.006007 2985 replica.cpp:655] Replica received learned notice > for position 3 > I0616 12:23:34.016319 2985 leveldb.cpp:343] Persisting action (30 bytes) to > leveldb took 10.242217ms > I0616 12:23:34.016484 2985 replica.cpp:676] Persisted action at 3 > I0616 12:23:34.016533 2985 replica.cpp:661] Replica learned APPEND action at > position 3 > I0616 12:23:34.017012 2989 leveldb.cpp:343] Persisting action (30 bytes) to > leveldb took 11.219868ms > I0616 12:23:34.017256 2989 replica.cpp:676] Persisted action at 3 > I0616 12:23:34.019745 2989 replica.cpp:661] Replica learned APPEND action at > position 3 > 2014-06-16 > 12:23:36,797:2963(0x7f9014632700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:44689] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > 2014-06-16 > 12:23:40,135:2963(0x7f9014632700):ZOO_WARN@zookeeper_interest@1557: Exceeded > deadline by 67ms > 2014-06-16 > 12:23:40,135:2963(0x7f9014632700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:44689] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > 2014-06-16 > 12:23:43,471:2963(0x7f9014632700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:44689] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > tests/state_tests.cpp:248: Failure > Failed to wait 10secs for future3 > 2014-06-16 > 12:23:46,807:2963(0x7f9014632700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:44689] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > 2014-06-16 > 12:23:50,144:2963(0x7f9014632700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:44689] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > 2014-06-16 > 12:23:53,480:2963(0x7f9014632700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:44689] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > 2014-06-16 > 12:23:56,816:2963(0x7f9014632700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:44689] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > 2014-06-16 > 12:24:00,152:2963(0x7f9014632700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:44689] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > 2014-06-16 > 12:24:03,488:2963(0x7f9014632700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:44689] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > 2014-06-16 > 12:24:06,824:2963(0x7f9014632700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:44689] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > 2014-06-16 > 12:24:10,160:2963(0x7f9014632700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:44689] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > 2014-06-16 > 12:24:13,496:2963(0x7f9014632700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:44689] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > 2014-06-16 > 12:24:16,832:2963(0x7f9014632700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:44689] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > 2014-06-16 > 12:24:20,168:2963(0x7f9014632700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:44689] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client -- This message was sent by Atlassian JIRA (v6.2#6252)