You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "Marco Massenzio (JIRA)" <ji...@apache.org> on 2015/08/05 20:54:04 UTC
[jira] [Updated] (MESOS-1013) ExamplesTest.JavaLog is flaky
[ https://issues.apache.org/jira/browse/MESOS-1013?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Marco Massenzio updated MESOS-1013:
-----------------------------------
Assignee: Greg Mann
> ExamplesTest.JavaLog is flaky
> -----------------------------
>
> Key: MESOS-1013
> URL: https://issues.apache.org/jira/browse/MESOS-1013
> Project: Mesos
> Issue Type: Bug
> Components: test
> Affects Versions: 0.19.0
> Reporter: Vinod Kone
> Assignee: Greg Mann
> Labels: flaky
>
> [ 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.3.4#6332)