You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@mesos.apache.org by "Vinod Kone (JIRA)" <ji...@apache.org> on 2014/06/17 00:30:03 UTC
[jira] [Created] (MESOS-1490)
LogStateTest.FetchAndStoreAndExpungeAndExpunge is flaky
Vinod Kone created MESOS-1490:
---------------------------------
Summary: 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
Assignee: Dominic Hamon
[ 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)