[
https://issues.apache.org/jira/browse/MESOS-1013?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14660771#comment-14660771
]
Greg Mann commented on MESOS-1013:
----------------------------------
[~marco-mesos], this does indeed seem to be the same issue as MESOS-830 - glog
attempting to lock a mutex that has been destroyed, or attempting to destroy a
mutex that is currently locked. The mutex in question is declared at file scope
in glog's logging.cc, so one would think it wouldn't be destroyed until
execution is complete, but the destructor is in fact getting called
prematurely. Perhaps there is a subtlety relating to the calling of these
routines from Java code that is affecting the lifetime of this mutex.
> 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)
