Vinod Kone created MESOS-1013:
---------------------------------
Summary: ExamplesTest.JavaLog is flaky
Key: MESOS-1013
URL: https://issues.apache.org/jira/browse/MESOS-1013
Project: Mesos
Issue Type: Story
Affects Versions: 0.19.0
Reporter: Vinod Kone
Fix For: 0.19.0
[ RUN ] ExamplesTest.JavaLog
Using temporary directory '/tmp/ExamplesTest_JavaLog_WBWEb9'
Feb 18, 2014 12:10:57 PM TestLog main
INFO: Starting a local ZooKeeper server
log4j:WARN No appenders could be found for logger
(org.apache.zookeeper.server.ZooKeeperServer).
log4j:WARN Please initialize the log4j system properly.
Feb 18, 2014 12:10:57 PM TestLog main
INFO: Initializing log /tmp/mesos-epljTr/log1 with
/var/jenkins/workspace/mesos-fedora-19-clang/src/mesos-log
WARNING: Logging before InitGoogleLogging() is written to STDERR
I0218 12:10:58.107450 17404 process.cpp:1591] libprocess is initialized on
192.168.122.134:36627 for 8 cpus
I0218 12:10:58.111640 17404 leveldb.cpp:166] Opened db in 3.145702ms
I0218 12:10:58.113097 17404 leveldb.cpp:173] Compacted db in 770230ns
I0218 12:10:58.113137 17404 leveldb.cpp:188] Created db iterator in 20506ns
I0218 12:10:58.113152 17404 leveldb.cpp:194] Seeked to beginning of db in
12095ns
I0218 12:10:58.113198 17404 leveldb.cpp:255] Iterated through 1 keys in the db
in 43127ns
I0218 12:10:58.113248 17404 replica.cpp:732] Replica recovered with log
positions 0 -> 0 with 1 holes and 0 unlearned
2014-02-18 12:10:58,115:17397(0x7f79152d9700):ZOO_INFO@log_env@712: Client
environment:zookeeper.version=zookeeper C client 3.4.5
2014-02-18 12:10:58,115:17397(0x7f79152d9700):ZOO_INFO@log_env@716: Client
environment:host.name=fedora-19
2014-02-18 12:10:58,115:17397(0x7f79152d9700):ZOO_INFO@log_env@723: Client
environment:os.name=Linux
2014-02-18 12:10:58,115:17397(0x7f79152d9700):ZOO_INFO@log_env@724: Client
environment:os.arch=3.12.9-201.fc19.x86_64
2014-02-18 12:10:58,115:17397(0x7f79152d9700):ZOO_INFO@log_env@725: Client
environment:os.version=#1 SMP Wed Jan 29 15:44:35 UTC 2014
2014-02-18 12:10:58,115:17397(0x7f79152d9700):ZOO_INFO@log_env@733: Client
environment:user.name=jenkins
2014-02-18 12:10:58,115:17397(0x7f79152d9700):ZOO_INFO@log_env@741: Client
environment:user.home=/home/jenkins
2014-02-18 12:10:58,115:17397(0x7f79152d9700):ZOO_INFO@log_env@753: Client
environment:user.dir=/tmp/ExamplesTest_JavaLog_WBWEb9
2014-02-18 12:10:58,115:17397(0x7f79152d9700):ZOO_INFO@zookeeper_init@786:
Initiating client connection, host=0:0:0:0:0:0:0:0:40410 sessionTimeout=3000
watcher=0x7f792228c440 sessionId=0 sessionPasswd=<null> context=0x13089c0
flags=0
2014-02-18 12:10:58,117:17397(0x7f7921407700):ZOO_INFO@log_env@712: Client
environment:zookeeper.version=zookeeper C client 3.4.5
2014-02-18 12:10:58,118:17397(0x7f7921407700):ZOO_INFO@log_env@716: Client
environment:host.name=fedora-19
2014-02-18 12:10:58,118:17397(0x7f7921407700):ZOO_INFO@log_env@723: Client
environment:os.name=Linux
2014-02-18 12:10:58,118:17397(0x7f7921407700):ZOO_INFO@log_env@724: Client
environment:os.arch=3.12.9-201.fc19.x86_64
2014-02-18 12:10:58,118:17397(0x7f7921407700):ZOO_INFO@log_env@725: Client
environment:os.version=#1 SMP Wed Jan 29 15:44:35 UTC 2014
2014-02-18 12:10:58,118:17397(0x7f7921407700):ZOO_INFO@log_env@733: Client
environment:user.name=jenkins
2014-02-18 12:10:58,118:17397(0x7f7921407700):ZOO_INFO@log_env@741: Client
environment:user.home=/home/jenkins
2014-02-18 12:10:58,118:17397(0x7f7921407700):ZOO_INFO@log_env@753: Client
environment:user.dir=/tmp/ExamplesTest_JavaLog_WBWEb9
2014-02-18 12:10:58,118:17397(0x7f7921407700):ZOO_INFO@zookeeper_init@786:
Initiating client connection, host=0:0:0:0:0:0:0:0:40410 sessionTimeout=3000
watcher=0x7f792228c440 sessionId=0 sessionPasswd=<null> context=0x7f7904000e40
flags=0
I0218 12:10:58.119313 17452 log.cpp:222] Attempting to join replica to
ZooKeeper group
I0218 12:10:58.119781 17452 recover.cpp:103] Start recovering a replica
I0218 12:10:58.119881 17452 recover.cpp:139] Replica is in VOTING status
I0218 12:10:58.119923 17452 recover.cpp:117] Recover process terminated
Feb 18, 2014 12:10:58 PM TestLog main
INFO: Initializing log /tmp/mesos-epljTr/log2 with
/var/jenkins/workspace/mesos-fedora-19-clang/src/mesos-log
2014-02-18 12:10:58,126:17397(0x7f78fcff9700):ZOO_INFO@check_events@1703:
initiated connection to server [:::40410]
2014-02-18 12:10:58,131:17397(0x7f78fdffb700):ZOO_INFO@check_events@1703:
initiated connection to server [:::40410]
2014-02-18 12:10:58,165:17397(0x7f78fcff9700):ZOO_INFO@check_events@1750:
session establishment complete on server [:::40410],
sessionId=0x144469f6ec10000, negotiated timeout=6000
I0218 12:10:58.166499 17453 group.cpp:310] Group process
((3)@192.168.122.134:36627) connected to ZooKeeper
I0218 12:10:58.166889 17453 group.cpp:775] Syncing group operations: queue size
(joins, cancels, datas) = (1, 0, 0)
I0218 12:10:58.166934 17453 group.cpp:382] Trying to create path '/log' in
ZooKeeper
2014-02-18 12:10:58,171:17397(0x7f78fdffb700):ZOO_INFO@check_events@1750:
session establishment complete on server [:::40410],
sessionId=0x144469f6ec10001, negotiated timeout=6000
I0218 12:10:58.171569 17451 group.cpp:310] Group process
((2)@192.168.122.134:36627) connected to ZooKeeper
I0218 12:10:58.171603 17451 group.cpp:775] Syncing group operations: queue size
(joins, cancels, datas) = (0, 0, 0)
I0218 12:10:58.171612 17451 group.cpp:382] Trying to create path '/log' in
ZooKeeper
I0218 12:10:58.241775 17451 network.hpp:404] ZooKeeper group memberships changed
I0218 12:10:58.241930 17451 group.cpp:652] Trying to get '/log/0000000000' in
ZooKeeper
I0218 12:10:58.249292 17451 network.hpp:441] ZooKeeper group PIDs: {
log-replica(1)@192.168.122.134:36627 }
I0218 12:10:58.277336 17404 leveldb.cpp:166] Opened db in 762457ns
I0218 12:10:58.279114 17404 leveldb.cpp:173] Compacted db in 1.762574ms
I0218 12:10:58.279160 17404 leveldb.cpp:188] Created db iterator in 16348ns
I0218 12:10:58.279181 17404 leveldb.cpp:194] Seeked to beginning of db in
17514ns
I0218 12:10:58.279213 17404 leveldb.cpp:255] Iterated through 1 keys in the db
in 25417ns
I0218 12:10:58.279249 17404 replica.cpp:732] Replica recovered with log
positions 0 -> 0 with 1 holes and 0 unlearned
2014-02-18 12:10:58,280:17397(0x7f79152d9700):ZOO_INFO@log_env@712: Client
environment:zookeeper.version=zookeeper C client 3.4.5
2014-02-18 12:10:58,280:17397(0x7f79152d9700):ZOO_INFO@log_env@716: Client
environment:host.name=fedora-19
2014-02-18 12:10:58,280:17397(0x7f79152d9700):ZOO_INFO@log_env@723: Client
environment:os.name=Linux
2014-02-18 12:10:58,280:17397(0x7f79152d9700):ZOO_INFO@log_env@724: Client
environment:os.arch=3.12.9-201.fc19.x86_64
2014-02-18 12:10:58,280:17397(0x7f79152d9700):ZOO_INFO@log_env@725: Client
environment:os.version=#1 SMP Wed Jan 29 15:44:35 UTC 2014
2014-02-18 12:10:58,280:17397(0x7f79152d9700):ZOO_INFO@log_env@733: Client
environment:user.name=jenkins
2014-02-18 12:10:58,280:17397(0x7f79152d9700):ZOO_INFO@log_env@741: Client
environment:user.home=/home/jenkins
2014-02-18 12:10:58,280:17397(0x7f79152d9700):ZOO_INFO@log_env@753: Client
environment:user.dir=/tmp/ExamplesTest_JavaLog_WBWEb9
2014-02-18 12:10:58,280:17397(0x7f79152d9700):ZOO_INFO@zookeeper_init@786:
Initiating client connection, host=0:0:0:0:0:0:0:0:40410 sessionTimeout=3000
watcher=0x7f792228c440 sessionId=0 sessionPasswd=<null> context=0x130d380
flags=0
2014-02-18 12:10:58,282:17397(0x7f7921c08700):ZOO_INFO@log_env@712: Client
environment:zookeeper.version=zookeeper C client 3.4.5
2014-02-18 12:10:58,282:17397(0x7f7921c08700):ZOO_INFO@log_env@716: Client
environment:host.name=fedora-19
2014-02-18 12:10:58,282:17397(0x7f7921c08700):ZOO_INFO@log_env@723: Client
environment:os.name=Linux
2014-02-18 12:10:58,282:17397(0x7f7921c08700):ZOO_INFO@log_env@724: Client
environment:os.arch=3.12.9-201.fc19.x86_64
2014-02-18 12:10:58,282:17397(0x7f7921c08700):ZOO_INFO@log_env@725: Client
environment:os.version=#1 SMP Wed Jan 29 15:44:35 UTC 2014
2014-02-18 12:10:58,282:17397(0x7f7921c08700):ZOO_INFO@log_env@733: Client
environment:user.name=jenkins
2014-02-18 12:10:58,282:17397(0x7f7921c08700):ZOO_INFO@log_env@741: Client
environment:user.home=/home/jenkins
2014-02-18 12:10:58,282:17397(0x7f7921c08700):ZOO_INFO@log_env@753: Client
environment:user.dir=/tmp/ExamplesTest_JavaLog_WBWEb9
2014-02-18 12:10:58,282:17397(0x7f7921c08700):ZOO_INFO@zookeeper_init@786:
Initiating client connection, host=0:0:0:0:0:0:0:0:40410 sessionTimeout=3000
watcher=0x7f792228c440 sessionId=0 sessionPasswd=<null> context=0x130d2f0
flags=0
I0218 12:10:58.284261 17451 log.cpp:222] Attempting to join replica to
ZooKeeper group
I0218 12:10:58.284461 17451 recover.cpp:103] Start recovering a replica
I0218 12:10:58.284586 17451 recover.cpp:139] Replica is in VOTING status
I0218 12:10:58.284636 17451 recover.cpp:117] Recover process terminated
Feb 18, 2014 12:10:58 PM TestLog main
INFO: Initializing log /tmp/mesos-epljTr/log3 with
/var/jenkins/workspace/mesos-fedora-19-clang/src/mesos-log
2014-02-18 12:10:58,292:17397(0x7f78faff5700):ZOO_INFO@check_events@1703:
initiated connection to server [:::40410]
2014-02-18 12:10:58,294:17397(0x7f78faff5700):ZOO_INFO@check_events@1750:
session establishment complete on server [:::40410],
sessionId=0x144469f6ec10002, negotiated timeout=6000
I0218 12:10:58.295696 17452 group.cpp:310] Group process
((7)@192.168.122.134:36627) connected to ZooKeeper
I0218 12:10:58.295732 17452 group.cpp:775] Syncing group operations: queue size
(joins, cancels, datas) = (1, 0, 0)
I0218 12:10:58.295742 17452 group.cpp:382] Trying to create path '/log' in
ZooKeeper
2014-02-18 12:10:58,305:17397(0x7f78fbff7700):ZOO_INFO@check_events@1703:
initiated connection to server [:::40410]
2014-02-18 12:10:58,306:17397(0x7f78fbff7700):ZOO_INFO@check_events@1750:
session establishment complete on server [:::40410],
sessionId=0x144469f6ec10003, negotiated timeout=6000
I0218 12:10:58.308791 17451 group.cpp:310] Group process
((6)@192.168.122.134:36627) connected to ZooKeeper
I0218 12:10:58.308822 17451 group.cpp:775] Syncing group operations: queue size
(joins, cancels, datas) = (0, 0, 0)
I0218 12:10:58.308831 17451 group.cpp:382] Trying to create path '/log' in
ZooKeeper
I0218 12:10:58.316406 17447 network.hpp:404] ZooKeeper group memberships changed
I0218 12:10:58.316493 17447 group.cpp:652] Trying to get '/log/0000000000' in
ZooKeeper
I0218 12:10:58.318897 17451 network.hpp:404] ZooKeeper group memberships changed
I0218 12:10:58.318971 17451 group.cpp:652] Trying to get '/log/0000000000' in
ZooKeeper
I0218 12:10:58.320674 17447 group.cpp:652] Trying to get '/log/0000000001' in
ZooKeeper
I0218 12:10:58.322448 17451 group.cpp:652] Trying to get '/log/0000000001' in
ZooKeeper
I0218 12:10:58.324615 17447 network.hpp:441] ZooKeeper group PIDs: {
log-replica(1)@192.168.122.134:36627, log-replica(2)@192.168.122.134:36627 }
I0218 12:10:58.325924 17451 network.hpp:441] ZooKeeper group PIDs: {
log-replica(1)@192.168.122.134:36627, log-replica(2)@192.168.122.134:36627 }
I0218 12:10:58.373469 17404 leveldb.cpp:166] Opened db in 812300ns
I0218 12:10:58.374752 17404 leveldb.cpp:173] Compacted db in 1.266146ms
I0218 12:10:58.374783 17404 leveldb.cpp:188] Created db iterator in 10213ns
I0218 12:10:58.374799 17404 leveldb.cpp:194] Seeked to beginning of db in
10788ns
I0218 12:10:58.374817 17404 leveldb.cpp:255] Iterated through 1 keys in the db
in 16506ns
I0218 12:10:58.374836 17404 replica.cpp:732] Replica recovered with log
positions 0 -> 0 with 1 holes and 0 unlearned
2014-02-18 12:10:58,375:17397(0x7f79152d9700):ZOO_INFO@log_env@712: Client
environment:zookeeper.version=zookeeper C client 3.4.5
2014-02-18 12:10:58,375:17397(0x7f79152d9700):ZOO_INFO@log_env@716: Client
environment:host.name=fedora-19
2014-02-18 12:10:58,375:17397(0x7f79152d9700):ZOO_INFO@log_env@723: Client
environment:os.name=Linux
2014-02-18 12:10:58,375:17397(0x7f79152d9700):ZOO_INFO@log_env@724: Client
environment:os.arch=3.12.9-201.fc19.x86_64
2014-02-18 12:10:58,375:17397(0x7f79152d9700):ZOO_INFO@log_env@725: Client
environment:os.version=#1 SMP Wed Jan 29 15:44:35 UTC 2014
2014-02-18 12:10:58,375:17397(0x7f79152d9700):ZOO_INFO@log_env@733: Client
environment:user.name=jenkins
2014-02-18 12:10:58,375:17397(0x7f79152d9700):ZOO_INFO@log_env@741: Client
environment:user.home=/home/jenkins
2014-02-18 12:10:58,375:17397(0x7f79152d9700):ZOO_INFO@log_env@753: Client
environment:user.dir=/tmp/ExamplesTest_JavaLog_WBWEb9
2014-02-18 12:10:58,375:17397(0x7f79152d9700):ZOO_INFO@zookeeper_init@786:
Initiating client connection, host=0:0:0:0:0:0:0:0:40410 sessionTimeout=3000
watcher=0x7f792228c440 sessionId=0 sessionPasswd=<null> context=0x1312990
flags=0
2014-02-18 12:10:58,376:17397(0x7f7921c08700):ZOO_INFO@log_env@712: Client
environment:zookeeper.version=zookeeper C client 3.4.5
2014-02-18 12:10:58,376:17397(0x7f7921c08700):ZOO_INFO@log_env@716: Client
environment:host.name=fedora-19
2014-02-18 12:10:58,376:17397(0x7f7921c08700):ZOO_INFO@log_env@723: Client
environment:os.name=Linux
2014-02-18 12:10:58,376:17397(0x7f7921c08700):ZOO_INFO@log_env@724: Client
environment:os.arch=3.12.9-201.fc19.x86_64
2014-02-18 12:10:58,376:17397(0x7f7921c08700):ZOO_INFO@log_env@725: Client
environment:os.version=#1 SMP Wed Jan 29 15:44:35 UTC 2014
2014-02-18 12:10:58,376:17397(0x7f7921c08700):ZOO_INFO@log_env@733: Client
environment:user.name=jenkins
2014-02-18 12:10:58,377:17397(0x7f7921c08700):ZOO_INFO@log_env@741: Client
environment:user.home=/home/jenkins
2014-02-18 12:10:58,377:17397(0x7f7921c08700):ZOO_INFO@log_env@753: Client
environment:user.dir=/tmp/ExamplesTest_JavaLog_WBWEb9
2014-02-18 12:10:58,377:17397(0x7f7921c08700):ZOO_INFO@zookeeper_init@786:
Initiating client connection, host=0:0:0:0:0:0:0:0:40410 sessionTimeout=3000
watcher=0x7f792228c440 sessionId=0 sessionPasswd=<null> context=0x1312930
flags=0
I0218 12:10:58.377923 17451 log.cpp:222] Attempting to join replica to
ZooKeeper group
I0218 12:10:58.378037 17451 recover.cpp:103] Start recovering a replica
I0218 12:10:58.378074 17451 recover.cpp:139] Replica is in VOTING status
I0218 12:10:58.378093 17451 recover.cpp:117] Recover process terminated
Feb 18, 2014 12:10:58 PM TestLog main
INFO: Initializing writer
I0218 12:10:58.383002 17404 log.cpp:799] Attempting to get elected within 3secs
I0218 12:10:58.385498 17453 replica.cpp:481] Replica received implicit promise
request with proposal 1
I0218 12:10:58.385622 17453 leveldb.cpp:299] Persisting metadata (8 bytes) to
leveldb took 103396ns
I0218 12:10:58.385637 17453 replica.cpp:349] Persisted promised to 1
I0218 12:10:58.385664 17453 replica.cpp:481] Replica received implicit promise
request with proposal 1
I0218 12:10:58.385697 17453 leveldb.cpp:299] Persisting metadata (8 bytes) to
leveldb took 31518ns
I0218 12:10:58.385707 17453 replica.cpp:349] Persisted promised to 1
I0218 12:10:58.385946 17453 coordinator.cpp:229] Coordinator attemping to fill
missing position
I0218 12:10:58.386360 17453 replica.cpp:382] Replica received explicit promise
request for position 0 with proposal 1
I0218 12:10:58.386391 17453 replica.cpp:382] Replica received explicit promise
request for position 0 with proposal 1
2014-02-18 12:10:58,389:17397(0x7f78f8ff1700):ZOO_INFO@check_events@1703:
initiated connection to server [:::40410]
2014-02-18 12:10:58,390:17397(0x7f78f8ff1700):ZOO_INFO@check_events@1750:
session establishment complete on server [:::40410],
sessionId=0x144469f6ec10004, negotiated timeout=6000
I0218 12:10:58.391302 17449 group.cpp:310] Group process
((12)@192.168.122.134:36627) connected to ZooKeeper
I0218 12:10:58.391336 17449 group.cpp:775] Syncing group operations: queue size
(joins, cancels, datas) = (1, 0, 0)
I0218 12:10:58.391346 17449 group.cpp:382] Trying to create path '/log' in
ZooKeeper
2014-02-18 12:10:58,401:17397(0x7f78f9ff3700):ZOO_INFO@check_events@1703:
initiated connection to server [:::40410]
2014-02-18 12:10:58,406:17397(0x7f78f9ff3700):ZOO_INFO@check_events@1750:
session establishment complete on server [:::40410],
sessionId=0x144469f6ec10005, negotiated timeout=6000
I0218 12:10:58.408061 17450 group.cpp:310] Group process
((11)@192.168.122.134:36627) connected to ZooKeeper
I0218 12:10:58.408092 17450 group.cpp:775] Syncing group operations: queue size
(joins, cancels, datas) = (0, 0, 0)
I0218 12:10:58.408102 17450 group.cpp:382] Trying to create path '/log' in
ZooKeeper
I0218 12:10:58.409957 17447 network.hpp:404] ZooKeeper group memberships changed
I0218 12:10:58.410037 17447 group.cpp:652] Trying to get '/log/0000000000' in
ZooKeeper
I0218 12:10:58.411797 17446 network.hpp:404] ZooKeeper group memberships changed
I0218 12:10:58.411874 17446 group.cpp:652] Trying to get '/log/0000000000' in
ZooKeeper
I0218 12:10:58.414819 17447 group.cpp:652] Trying to get '/log/0000000001' in
ZooKeeper
I0218 12:10:58.416474 17446 group.cpp:652] Trying to get '/log/0000000001' in
ZooKeeper
I0218 12:10:58.418153 17450 network.hpp:404] ZooKeeper group memberships changed
I0218 12:10:58.418264 17450 group.cpp:652] Trying to get '/log/0000000000' in
ZooKeeper
I0218 12:10:58.419865 17447 group.cpp:652] Trying to get '/log/0000000002' in
ZooKeeper
I0218 12:10:58.421427 17446 group.cpp:652] Trying to get '/log/0000000002' in
ZooKeeper
I0218 12:10:58.422986 17450 group.cpp:652] Trying to get '/log/0000000001' in
ZooKeeper
I0218 12:10:58.424687 17447 network.hpp:441] ZooKeeper group PIDs: {
log-replica(1)@192.168.122.134:36627, log-replica(2)@192.168.122.134:36627,
log-replica(3)@192.168.122.134:36627 }
I0218 12:10:58.426110 17446 network.hpp:441] ZooKeeper group PIDs: {
log-replica(1)@192.168.122.134:36627, log-replica(2)@192.168.122.134:36627,
log-replica(3)@192.168.122.134:36627 }
I0218 12:10:58.427469 17450 group.cpp:652] Trying to get '/log/0000000002' in
ZooKeeper
I0218 12:10:58.429147 17450 network.hpp:441] ZooKeeper group PIDs: {
log-replica(1)@192.168.122.134:36627, log-replica(2)@192.168.122.134:36627,
log-replica(3)@192.168.122.134:36627 }
I0218 12:10:58.533013 17450 replica.cpp:382] Replica received explicit promise
request for position 0 with proposal 2
I0218 12:10:58.533131 17450 leveldb.cpp:330] Persisting action (8 bytes) to
leveldb took 63963ns
I0218 12:10:58.533145 17450 replica.cpp:671] Persisted action at 0
I0218 12:10:58.533182 17450 replica.cpp:382] Replica received explicit promise
request for position 0 with proposal 2
I0218 12:10:58.533202 17450 leveldb.cpp:330] Persisting action (8 bytes) to
leveldb took 16113ns
I0218 12:10:58.533211 17450 replica.cpp:671] Persisted action at 0
I0218 12:10:58.533224 17450 replica.cpp:382] Replica received explicit promise
request for position 0 with proposal 2
I0218 12:10:58.533274 17450 leveldb.cpp:330] Persisting action (8 bytes) to
leveldb took 47849ns
I0218 12:10:58.533284 17450 replica.cpp:671] Persisted action at 0
I0218 12:10:58.533740 17450 replica.cpp:515] Replica received write request for
position 0
I0218 12:10:58.533774 17450 leveldb.cpp:415] Reading position from leveldb took
24134ns
I0218 12:10:58.533804 17450 leveldb.cpp:330] Persisting action (14 bytes) to
leveldb took 18269ns
I0218 12:10:58.533813 17450 replica.cpp:671] Persisted action at 0
I0218 12:10:58.533838 17450 replica.cpp:515] Replica received write request for
position 0
I0218 12:10:58.533850 17450 leveldb.cpp:415] Reading position from leveldb took
10091ns
I0218 12:10:58.533869 17450 leveldb.cpp:330] Persisting action (14 bytes) to
leveldb took 13313ns
I0218 12:10:58.533876 17450 replica.cpp:671] Persisted action at 0
I0218 12:10:58.533890 17450 replica.cpp:515] Replica received write request for
position 0
I0218 12:10:58.533900 17450 leveldb.cpp:415] Reading position from leveldb took
8953ns
I0218 12:10:58.533917 17450 leveldb.cpp:330] Persisting action (14 bytes) to
leveldb took 12169ns
I0218 12:10:58.533924 17450 replica.cpp:671] Persisted action at 0
I0218 12:10:58.534090 17450 replica.cpp:650] Replica received learned notice
for position 0
I0218 12:10:58.534117 17450 leveldb.cpp:330] Persisting action (16 bytes) to
leveldb took 18239ns
I0218 12:10:58.534126 17450 replica.cpp:671] Persisted action at 0
I0218 12:10:58.534132 17450 replica.cpp:656] Replica learned NOP action at
position 0
I0218 12:10:58.534147 17450 replica.cpp:650] Replica received learned notice
for position 0
I0218 12:10:58.534163 17450 leveldb.cpp:330] Persisting action (16 bytes) to
leveldb took 13311ns
I0218 12:10:58.534170 17450 replica.cpp:671] Persisted action at 0
I0218 12:10:58.534176 17450 replica.cpp:656] Replica learned NOP action at
position 0
I0218 12:10:58.534184 17450 replica.cpp:650] Replica received learned notice
for position 0
I0218 12:10:58.534198 17450 leveldb.cpp:330] Persisting action (16 bytes) to
leveldb took 11985ns
I0218 12:10:58.534205 17450 replica.cpp:671] Persisted action at 0
I0218 12:10:58.534211 17450 replica.cpp:656] Replica learned NOP action at
position 0
I0218 12:10:58.535334 17404 log.cpp:823] Elected with current position 0
I0218 12:10:58.536350 17404 log.cpp:849] Attempting to append 1024 bytes to the
log
I0218 12:10:58.536561 17448 coordinator.cpp:335] Coordinator attempting to
write APPEND action at position 1
I0218 12:10:58.536878 17448 replica.cpp:515] Replica received write request for
position 1
I0218 12:10:58.536927 17448 leveldb.cpp:330] Persisting action (1043 bytes) to
leveldb took 37829ns
I0218 12:10:58.536938 17448 replica.cpp:671] Persisted action at 1
I0218 12:10:58.536957 17448 replica.cpp:515] Replica received write request for
position 1
I0218 12:10:58.536981 17448 leveldb.cpp:330] Persisting action (1043 bytes) to
leveldb took 19766ns
I0218 12:10:58.536989 17448 replica.cpp:671] Persisted action at 1
I0218 12:10:58.537003 17448 replica.cpp:515] Replica received write request for
position 1
I0218 12:10:58.537024 17448 leveldb.cpp:330] Persisting action (1043 bytes) to
leveldb took 17186ns
I0218 12:10:58.537032 17448 replica.cpp:671] Persisted action at 1
I0218 12:10:58.538137 17448 replica.cpp:650] Replica received learned notice
for position 1
I0218 12:10:58.538179 17448 leveldb.cpp:330] Persisting action (1045 bytes) to
leveldb took 28073ns
I0218 12:10:58.538190 17448 replica.cpp:671] Persisted action at 1
I0218 12:10:58.538197 17448 replica.cpp:656] Replica learned APPEND action at
position 1
I0218 12:10:58.538209 17448 replica.cpp:650] Replica received learned notice
for position 1
I0218 12:10:58.538228 17448 leveldb.cpp:330] Persisting action (1045 bytes) to
leveldb took 18113ns
I0218 12:10:58.538238 17448 replica.cpp:671] Persisted action at 1
I0218 12:10:58.538244 17448 replica.cpp:656] Replica learned APPEND action at
position 1
I0218 12:10:58.538254 17448 replica.cpp:650] Replica received learned notice
for position 1
I0218 12:10:58.538271 17448 leveldb.cpp:330] Persisting action (1045 bytes) to
leveldb took 16484ns
I0218 12:10:58.538280 17448 replica.cpp:671] Persisted action at 1
I0218 12:10:58.538285 17448 replica.cpp:656] Replica learned APPEND action at
position 1
Feb 18, 2014 12:10:58 PM TestLog main
INFO: Time: 1392754258539 Appended 1024 bytes in 3244306 ns
I0218 12:10:58.543907 17404 log.cpp:849] Attempting to append 10240 bytes to
the log
I0218 12:10:58.544630 17452 coordinator.cpp:335] Coordinator attempting to
write APPEND action at position 2
I0218 12:10:58.545094 17447 replica.cpp:515] Replica received write request for
position 2
I0218 12:10:58.545198 17447 leveldb.cpp:330] Persisting action (10259 bytes) to
leveldb took 91630ns
I0218 12:10:58.545212 17447 replica.cpp:671] Persisted action at 2
I0218 12:10:58.545269 17453 replica.cpp:515] Replica received write request for
position 2
I0218 12:10:58.545353 17453 leveldb.cpp:330] Persisting action (10259 bytes) to
leveldb took 77722ns
I0218 12:10:58.545366 17453 replica.cpp:671] Persisted action at 2
I0218 12:10:58.546172 17452 replica.cpp:515] Replica received write request for
position 2
I0218 12:10:58.546286 17452 leveldb.cpp:330] Persisting action (10259 bytes) to
leveldb took 91093ns
I0218 12:10:58.546301 17452 replica.cpp:671] Persisted action at 2
I0218 12:10:58.546565 17451 replica.cpp:650] Replica received learned notice
for position 2
I0218 12:10:58.546630 17451 leveldb.cpp:330] Persisting action (10261 bytes) to
leveldb took 56996ns
I0218 12:10:58.546643 17451 replica.cpp:671] Persisted action at 2
I0218 12:10:58.546649 17451 replica.cpp:656] Replica learned APPEND action at
position 2
I0218 12:10:58.546664 17451 replica.cpp:650] Replica received learned notice
for position 2
I0218 12:10:58.546715 17451 leveldb.cpp:330] Persisting action (10261 bytes) to
leveldb took 49788ns
I0218 12:10:58.546726 17451 replica.cpp:671] Persisted action at 2
I0218 12:10:58.546732 17451 replica.cpp:656] Replica learned APPEND action at
position 2
I0218 12:10:58.546746 17451 replica.cpp:650] Replica received learned notice
for position 2
I0218 12:10:58.546795 17451 leveldb.cpp:330] Persisting action (10261 bytes) to
leveldb took 48192ns
I0218 12:10:58.546805 17451 replica.cpp:671] Persisted action at 2
I0218 12:10:58.546811 17451 replica.cpp:656] Replica learned APPEND action at
position 2
Feb 18, 2014 12:10:58 PM TestLog main
INFO: Time: 1392754258547 Appended 10240 bytes in 3969505 ns
I0218 12:10:58.566014 17404 log.cpp:849] Attempting to append 102400 bytes to
the log
I0218 12:10:58.567073 17449 coordinator.cpp:335] Coordinator attempting to
write APPEND action at position 3
I0218 12:10:58.567934 17448 replica.cpp:515] Replica received write request for
position 3
I0218 12:10:58.568506 17448 leveldb.cpp:330] Persisting action (102422 bytes)
to leveldb took 494687ns
I0218 12:10:58.568549 17448 replica.cpp:671] Persisted action at 3
I0218 12:10:58.569246 17450 replica.cpp:515] Replica received write request for
position 3
I0218 12:10:58.569782 17450 leveldb.cpp:330] Persisting action (102422 bytes)
to leveldb took 476066ns
I0218 12:10:58.569800 17450 replica.cpp:671] Persisted action at 3
I0218 12:10:58.570041 17450 replica.cpp:650] Replica received learned notice
for position 3
I0218 12:10:58.570503 17450 leveldb.cpp:330] Persisting action (102424 bytes)
to leveldb took 455686ns
I0218 12:10:58.570519 17450 replica.cpp:671] Persisted action at 3
I0218 12:10:58.571387 17449 replica.cpp:650] Replica received learned notice
for position 3
I0218 12:10:58.572661 17448 replica.cpp:650] Replica received learned notice
for position 3
I0218 12:10:58.573004 17448 leveldb.cpp:330] Persisting action (102424 bytes)
to leveldb took 330662ns
I0218 12:10:58.573020 17448 replica.cpp:671] Persisted action at 3
I0218 12:10:58.573029 17448 replica.cpp:656] Replica learned APPEND action at
position 3
I0218 12:10:58.573809 17449 leveldb.cpp:330] Persisting action (102424 bytes)
to leveldb took 2.411244ms
I0218 12:10:58.573843 17449 replica.cpp:671] Persisted action at 3
I0218 12:10:58.573851 17449 replica.cpp:656] Replica learned APPEND action at
position 3
I0218 12:10:58.574415 17450 replica.cpp:656] Replica learned APPEND action at
position 3
I0218 12:10:58.574498 17450 replica.cpp:515] Replica received write request for
position 3
I0218 12:10:58.574607 17450 leveldb.cpp:415] Reading position from leveldb took
105366ns
I0218 12:10:58.574949 17450 leveldb.cpp:330] Persisting action (102422 bytes)
to leveldb took 296157ns
I0218 12:10:58.574965 17450 replica.cpp:671] Persisted action at 3
F0218 12:10:58.575036 17450 coordinator.cpp:394] Check failed: !missing Not
expecting local replica to be missing position 3 after the writing is done
*** Check failure stack trace: ***
tests/script.cpp:81: Failure
Failed
java_log_test.sh terminated with signal 'Aborted'
[ FAILED ] ExamplesTest.JavaLog (2166 ms)
--
This message was sent by Atlassian JIRA
(v6.1.5#6160)
