You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@mesos.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2014/09/13 09:22:37 UTC
Build failed in Jenkins:
Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui
#2373
See <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/2373/changes>
Changes:
[bmahler] Fixed the flaky FaultToleranceTest.ReconcilePendingTasks.
------------------------------------------
[...truncated 31684 lines...]
I0913 07:19:54.157225 5755 replica.cpp:638] Replica in STARTING status received a broadcasted recover request
I0913 07:19:54.157299 5755 recover.cpp:188] Received a recover response from a replica in STARTING status
I0913 07:19:54.157402 5755 recover.cpp:542] Updating replica status to VOTING
I0913 07:19:54.157693 5755 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 238277ns
I0913 07:19:54.157711 5755 replica.cpp:320] Persisted replica status to VOTING
I0913 07:19:54.157752 5755 recover.cpp:556] Successfully joined the Paxos group
I0913 07:19:54.157805 5755 recover.cpp:440] Recover process terminated
I0913 07:19:54.157912 5755 log.cpp:656] Attempting to start the writer
I0913 07:19:54.158201 5755 replica.cpp:474] Replica received implicit promise request with proposal 1
I0913 07:19:54.158321 5755 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 102959ns
I0913 07:19:54.158336 5755 replica.cpp:342] Persisted promised to 1
I0913 07:19:54.158509 5755 coordinator.cpp:230] Coordinator attemping to fill missing position
I0913 07:19:54.158836 5755 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
I0913 07:19:54.158965 5755 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 110359ns
I0913 07:19:54.158982 5755 replica.cpp:676] Persisted action at 0
I0913 07:19:54.159245 5755 replica.cpp:508] Replica received write request for position 0
I0913 07:19:54.159271 5755 leveldb.cpp:438] Reading position from leveldb took 11152ns
I0913 07:19:54.159390 5755 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 102629ns
I0913 07:19:54.159405 5755 replica.cpp:676] Persisted action at 0
I0913 07:19:54.159548 5755 replica.cpp:655] Replica received learned notice for position 0
I0913 07:19:54.159742 5755 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 177450ns
I0913 07:19:54.159759 5755 replica.cpp:676] Persisted action at 0
I0913 07:19:54.159768 5755 replica.cpp:661] Replica learned NOP action at position 0
I0913 07:19:54.160043 5765 log.cpp:672] Writer started with ending position 0
I0913 07:19:54.160296 5765 leveldb.cpp:438] Reading position from leveldb took 9415ns
I0913 07:19:54.161617 5765 registrar.cpp:346] Successfully fetched the registry (0B)
I0913 07:19:54.161639 5765 registrar.cpp:422] Attempting to update the 'registry'
I0913 07:19:54.163061 5765 log.cpp:680] Attempting to append 138 bytes to the log
I0913 07:19:54.163106 5765 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
I0913 07:19:54.163308 5765 replica.cpp:508] Replica received write request for position 1
I0913 07:19:54.163597 5765 leveldb.cpp:343] Persisting action (157 bytes) to leveldb took 269392ns
I0913 07:19:54.163614 5765 replica.cpp:676] Persisted action at 1
I0913 07:19:54.176707 5762 replica.cpp:655] Replica received learned notice for position 1
I0913 07:19:54.176998 5762 leveldb.cpp:343] Persisting action (159 bytes) to leveldb took 271316ns
I0913 07:19:54.177016 5762 replica.cpp:676] Persisted action at 1
I0913 07:19:54.177026 5762 replica.cpp:661] Replica learned APPEND action at position 1
I0913 07:19:54.177290 5762 registrar.cpp:479] Successfully updated 'registry'
I0913 07:19:54.177328 5762 registrar.cpp:372] Successfully recovered registrar
I0913 07:19:54.177368 5762 log.cpp:699] Attempting to truncate the log to 1
I0913 07:19:54.177435 5762 master.cpp:1070] Recovered 0 slaves from the Registry (100B) ; allowing 10mins for slaves to re-register
I0913 07:19:54.177480 5762 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
I0913 07:19:54.177713 5762 replica.cpp:508] Replica received write request for position 2
I0913 07:19:54.177824 5762 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 93092ns
I0913 07:19:54.177841 5762 replica.cpp:676] Persisted action at 2
I0913 07:19:54.178014 5762 replica.cpp:655] Replica received learned notice for position 2
I0913 07:19:54.178115 5762 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 85568ns
I0913 07:19:54.178143 5762 leveldb.cpp:401] Deleting ~1 keys from leveldb took 12602ns
I0913 07:19:54.178155 5762 replica.cpp:676] Persisted action at 2
I0913 07:19:54.284097 5762 replica.cpp:661] Replica learned TRUNCATE action at position 2
I0913 07:19:54.294366 5764 slave.cpp:169] Slave started on 115)@67.195.81.187:57627
I0913 07:19:54.294389 5764 credentials.hpp:84] Loading credential for authentication from '/tmp/GarbageCollectorIntegrationTest_DiskUsage_1giBe1/credential'
I0913 07:19:54.294466 5764 slave.cpp:276] Slave using credential for: test-principal
I0913 07:19:54.294569 5764 slave.cpp:289] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0913 07:19:54.294627 5764 slave.cpp:317] Slave hostname: pomona.apache.org
I0913 07:19:54.294639 5764 slave.cpp:318] Slave checkpoint: false
I0913 07:19:54.295058 5764 state.cpp:33] Recovering state from '/tmp/GarbageCollectorIntegrationTest_DiskUsage_1giBe1/meta'
I0913 07:19:54.295155 5764 status_update_manager.cpp:193] Recovering status update manager
I0913 07:19:54.295239 5764 slave.cpp:3219] Finished recovery
I0913 07:19:54.295469 5764 slave.cpp:600] New master detected at master@67.195.81.187:57627
I0913 07:19:54.295492 5764 slave.cpp:674] Authenticating with master master@67.195.81.187:57627
I0913 07:19:54.295533 5764 slave.cpp:647] Detecting new master
I0913 07:19:54.295568 5764 status_update_manager.cpp:167] New master detected at master@67.195.81.187:57627
I0913 07:19:54.295603 5764 authenticatee.hpp:128] Creating new client SASL connection
I0913 07:19:54.295697 5764 master.cpp:3653] Authenticating slave(115)@67.195.81.187:57627
I0913 07:19:54.295781 5764 authenticator.hpp:156] Creating new server SASL connection
I0913 07:19:54.295841 5764 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0913 07:19:54.295860 5764 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0913 07:19:54.295886 5764 authenticator.hpp:262] Received SASL authentication start
I0913 07:19:54.295920 5764 authenticator.hpp:384] Authentication requires more steps
I0913 07:19:54.295948 5764 authenticatee.hpp:265] Received SASL authentication step
I0913 07:19:54.295987 5764 authenticator.hpp:290] Received SASL authentication step
I0913 07:19:54.296005 5764 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0913 07:19:54.296015 5764 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I0913 07:19:54.296030 5764 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0913 07:19:54.296042 5764 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0913 07:19:54.296051 5764 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0913 07:19:54.296058 5764 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0913 07:19:54.296073 5764 authenticator.hpp:376] Authentication success
I0913 07:19:54.296103 5764 authenticatee.hpp:305] Authentication success
I0913 07:19:54.296128 5764 master.cpp:3693] Successfully authenticated principal 'test-principal' at slave(115)@67.195.81.187:57627
I0913 07:19:54.296193 5764 slave.cpp:731] Successfully authenticated with master master@67.195.81.187:57627
I0913 07:19:54.296231 5764 slave.cpp:994] Will retry registration in 19.491161ms if necessary
I0913 07:19:54.296299 5764 master.cpp:2843] Registering slave at slave(115)@67.195.81.187:57627 (pomona.apache.org) with id 20140913-071954-3142697795-57627-5741-0
I0913 07:19:54.296406 5764 registrar.cpp:422] Attempting to update the 'registry'
I0913 07:19:54.297817 5764 log.cpp:680] Attempting to append 332 bytes to the log
I0913 07:19:54.297863 5764 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
I0913 07:19:54.298079 5764 replica.cpp:508] Replica received write request for position 3
I0913 07:19:54.298280 5764 leveldb.cpp:343] Persisting action (351 bytes) to leveldb took 180777ns
I0913 07:19:54.298295 5764 replica.cpp:676] Persisted action at 3
I0913 07:19:54.298491 5764 replica.cpp:655] Replica received learned notice for position 3
I0913 07:19:54.298826 5764 leveldb.cpp:343] Persisting action (353 bytes) to leveldb took 318226ns
I0913 07:19:54.298843 5764 replica.cpp:676] Persisted action at 3
I0913 07:19:54.298853 5764 replica.cpp:661] Replica learned APPEND action at position 3
I0913 07:19:54.299161 5764 registrar.cpp:479] Successfully updated 'registry'
I0913 07:19:54.299239 5764 log.cpp:699] Attempting to truncate the log to 3
I0913 07:19:54.299294 5764 master.cpp:2883] Registered slave 20140913-071954-3142697795-57627-5741-0 at slave(115)@67.195.81.187:57627 (pomona.apache.org)
I0913 07:19:54.299310 5764 master.cpp:4126] Adding slave 20140913-071954-3142697795-57627-5741-0 at slave(115)@67.195.81.187:57627 (pomona.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0913 07:19:54.299408 5764 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
I0913 07:19:54.299609 5764 slave.cpp:765] Registered with master master@67.195.81.187:57627; given slave ID 20140913-071954-3142697795-57627-5741-0
I0913 07:19:54.299644 5764 slave.cpp:2346] Received ping from slave-observer(110)@67.195.81.187:57627
I0913 07:19:54.299737 5766 hierarchical_allocator_process.hpp:442] Added slave 20140913-071954-3142697795-57627-5741-0 (pomona.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
I0913 07:19:54.299783 5766 hierarchical_allocator_process.hpp:679] Performed allocation for slave 20140913-071954-3142697795-57627-5741-0 in 9179ns
I0913 07:19:54.300092 5770 replica.cpp:508] Replica received write request for position 4
I0913 07:19:54.300190 5770 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 80047ns
I0913 07:19:54.300207 5770 replica.cpp:676] Persisted action at 4
I0913 07:19:54.300384 5770 replica.cpp:655] Replica received learned notice for position 4
I0913 07:19:54.300495 5770 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 93807ns
I0913 07:19:54.300531 5770 leveldb.cpp:401] Deleting ~2 keys from leveldb took 20239ns
I0913 07:19:54.300544 5770 replica.cpp:676] Persisted action at 4
I0913 07:19:54.300554 5770 replica.cpp:661] Replica learned TRUNCATE action at position 4
I0913 07:19:54.304338 5741 sched.cpp:137] Version: 0.21.0
I0913 07:19:54.304476 5768 sched.cpp:233] New master detected at master@67.195.81.187:57627
I0913 07:19:54.304496 5768 sched.cpp:283] Authenticating with master master@67.195.81.187:57627
I0913 07:19:54.304569 5768 authenticatee.hpp:128] Creating new client SASL connection
I0913 07:19:54.304647 5768 master.cpp:3653] Authenticating scheduler-8a56d4e1-2220-47e9-a0fd-6c104b09aafe@67.195.81.187:57627
I0913 07:19:54.304719 5768 authenticator.hpp:156] Creating new server SASL connection
I0913 07:19:54.304766 5768 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0913 07:19:54.304782 5768 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0913 07:19:54.304807 5768 authenticator.hpp:262] Received SASL authentication start
I0913 07:19:54.304836 5768 authenticator.hpp:384] Authentication requires more steps
I0913 07:19:54.304863 5768 authenticatee.hpp:265] Received SASL authentication step
I0913 07:19:54.304895 5768 authenticator.hpp:290] Received SASL authentication step
I0913 07:19:54.304909 5768 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0913 07:19:54.304919 5768 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I0913 07:19:54.304931 5768 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0913 07:19:54.443526 5768 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0913 07:19:54.443553 5768 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0913 07:19:54.443562 5768 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0913 07:19:54.443584 5768 authenticator.hpp:376] Authentication success
I0913 07:19:54.443661 5768 authenticatee.hpp:305] Authentication success
I0913 07:19:54.443694 5768 master.cpp:3693] Successfully authenticated principal 'test-principal' at scheduler-8a56d4e1-2220-47e9-a0fd-6c104b09aafe@67.195.81.187:57627
I0913 07:19:54.443804 5768 sched.cpp:357] Successfully authenticated with master master@67.195.81.187:57627
I0913 07:19:54.443819 5768 sched.cpp:476] Sending registration request to master@67.195.81.187:57627
I0913 07:19:54.443877 5768 master.cpp:1331] Received registration request from scheduler-8a56d4e1-2220-47e9-a0fd-6c104b09aafe@67.195.81.187:57627
I0913 07:19:54.443897 5768 master.cpp:1291] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0913 07:19:54.444013 5768 master.cpp:1390] Registering framework 20140913-071954-3142697795-57627-5741-0000 at scheduler-8a56d4e1-2220-47e9-a0fd-6c104b09aafe@67.195.81.187:57627
I0913 07:19:54.444118 5768 sched.cpp:407] Framework registered with 20140913-071954-3142697795-57627-5741-0000
I0913 07:19:54.444149 5768 sched.cpp:421] Scheduler::registered took 17894ns
I0913 07:19:54.444187 5768 hierarchical_allocator_process.hpp:329] Added framework 20140913-071954-3142697795-57627-5741-0000
I0913 07:19:54.444243 5768 hierarchical_allocator_process.hpp:734] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140913-071954-3142697795-57627-5741-0 to framework 20140913-071954-3142697795-57627-5741-0000
I0913 07:19:54.444365 5768 hierarchical_allocator_process.hpp:659] Performed allocation for 1 slaves in 161797ns
I0913 07:19:54.444483 5768 master.hpp:861] Adding offer 20140913-071954-3142697795-57627-5741-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140913-071954-3142697795-57627-5741-0 (pomona.apache.org)
I0913 07:19:54.444546 5768 master.cpp:3600] Sending 1 offers to framework 20140913-071954-3142697795-57627-5741-0000
I0913 07:19:54.444841 5768 sched.cpp:544] Scheduler::resourceOffers took 151672ns
I0913 07:19:54.444995 5768 master.hpp:871] Removing offer 20140913-071954-3142697795-57627-5741-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140913-071954-3142697795-57627-5741-0 (pomona.apache.org)
I0913 07:19:54.445056 5768 master.cpp:2201] Processing reply for offers: [ 20140913-071954-3142697795-57627-5741-0 ] on slave 20140913-071954-3142697795-57627-5741-0 at slave(115)@67.195.81.187:57627 (pomona.apache.org) for framework 20140913-071954-3142697795-57627-5741-0000
I0913 07:19:54.445082 5768 master.cpp:2284] Authorizing framework principal 'test-principal' to launch task 0 as user 'jenkins'
I0913 07:19:54.445339 5768 master.hpp:833] Adding task 0 with resources cpus(*):2; mem(*):1024 on slave 20140913-071954-3142697795-57627-5741-0 (pomona.apache.org)
I0913 07:19:54.445369 5768 master.cpp:2350] Launching task 0 of framework 20140913-071954-3142697795-57627-5741-0000 with resources cpus(*):2; mem(*):1024 on slave 20140913-071954-3142697795-57627-5741-0 at slave(115)@67.195.81.187:57627 (pomona.apache.org)
I0913 07:19:54.445502 5768 slave.cpp:1025] Got assigned task 0 for framework 20140913-071954-3142697795-57627-5741-0000
I0913 07:19:54.445680 5768 slave.cpp:1135] Launching task 0 for framework 20140913-071954-3142697795-57627-5741-0000
I0913 07:19:54.448526 5768 exec.cpp:132] Version: 0.21.0
I0913 07:19:54.448623 5768 slave.cpp:1248] Queuing task '0' for executor default of framework '20140913-071954-3142697795-57627-5741-0000
I0913 07:19:54.448680 5768 slave.cpp:2559] Monitoring executor 'default' of framework '20140913-071954-3142697795-57627-5741-0000' in container 'a2addb81-3f56-4cb4-a6bb-15f71470200b'
I0913 07:19:54.448765 5768 hierarchical_allocator_process.hpp:563] Recovered disk(*):1024; ports(*):[31000-32000] (total allocatable: disk(*):1024; ports(*):[31000-32000]) on slave 20140913-071954-3142697795-57627-5741-0 from framework 20140913-071954-3142697795-57627-5741-0000
I0913 07:19:54.448789 5768 hierarchical_allocator_process.hpp:599] Framework 20140913-071954-3142697795-57627-5741-0000 filtered slave 20140913-071954-3142697795-57627-5741-0 for 5secs
I0913 07:19:54.448873 5768 exec.cpp:182] Executor started at: executor(46)@67.195.81.187:57627 with pid 5741
I0913 07:19:54.448938 5768 slave.cpp:554] Successfully attached file '/tmp/GarbageCollectorIntegrationTest_DiskUsage_1giBe1/slaves/20140913-071954-3142697795-57627-5741-0/frameworks/20140913-071954-3142697795-57627-5741-0000/executors/default/runs/a2addb81-3f56-4cb4-a6bb-15f71470200b'
I0913 07:19:54.448966 5768 slave.cpp:1758] Got registration for executor 'default' of framework 20140913-071954-3142697795-57627-5741-0000
I0913 07:19:54.449045 5768 slave.cpp:1876] Flushing queued task 0 for executor 'default' of framework 20140913-071954-3142697795-57627-5741-0000
I0913 07:19:54.449118 5768 exec.cpp:206] Executor registered on slave 20140913-071954-3142697795-57627-5741-0
I0913 07:19:54.450222 5768 exec.cpp:218] Executor::registered took 11985ns
I0913 07:19:54.450271 5768 exec.cpp:293] Executor asked to run task '0'
I0913 07:19:54.450304 5768 exec.cpp:302] Executor::launchTask took 19918ns
I0913 07:19:54.451616 5768 exec.cpp:525] Executor sending status update TASK_RUNNING (UUID: 5bdd3ad8-348b-4305-83ca-2e77d1f1175b) for task 0 of framework 20140913-071954-3142697795-57627-5741-0000
I0913 07:19:54.451692 5768 slave.cpp:2110] Handling status update TASK_RUNNING (UUID: 5bdd3ad8-348b-4305-83ca-2e77d1f1175b) for task 0 of framework 20140913-071954-3142697795-57627-5741-0000 from executor(46)@67.195.81.187:57627
I0913 07:19:54.451771 5768 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 5bdd3ad8-348b-4305-83ca-2e77d1f1175b) for task 0 of framework 20140913-071954-3142697795-57627-5741-0000
I0913 07:19:54.451786 5768 status_update_manager.cpp:499] Creating StatusUpdate stream for task 0 of framework 20140913-071954-3142697795-57627-5741-0000
I0913 07:19:54.451850 5768 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: 5bdd3ad8-348b-4305-83ca-2e77d1f1175b) for task 0 of framework 20140913-071954-3142697795-57627-5741-0000 to master@67.195.81.187:57627
I0913 07:19:54.451954 5768 master.cpp:3212] Forwarding status update TASK_RUNNING (UUID: 5bdd3ad8-348b-4305-83ca-2e77d1f1175b) for task 0 of framework 20140913-071954-3142697795-57627-5741-0000
I0913 07:19:54.451992 5768 master.cpp:3178] Status update TASK_RUNNING (UUID: 5bdd3ad8-348b-4305-83ca-2e77d1f1175b) for task 0 of framework 20140913-071954-3142697795-57627-5741-0000 from slave 20140913-071954-3142697795-57627-5741-0 at slave(115)@67.195.81.187:57627 (pomona.apache.org)
I0913 07:19:54.452024 5768 slave.cpp:2267] Status update manager successfully handled status update TASK_RUNNING (UUID: 5bdd3ad8-348b-4305-83ca-2e77d1f1175b) for task 0 of framework 20140913-071954-3142697795-57627-5741-0000
I0913 07:19:54.452038 5768 slave.cpp:2273] Sending acknowledgement for status update TASK_RUNNING (UUID: 5bdd3ad8-348b-4305-83ca-2e77d1f1175b) for task 0 of framework 20140913-071954-3142697795-57627-5741-0000 to executor(46)@67.195.81.187:57627
I0913 07:19:54.452107 5768 sched.cpp:635] Scheduler::statusUpdate took 12841ns
I0913 07:19:54.452147 5768 exec.cpp:339] Executor received status update acknowledgement 5bdd3ad8-348b-4305-83ca-2e77d1f1175b for task 0 of framework 20140913-071954-3142697795-57627-5741-0000
I0913 07:19:54.452191 5768 master.cpp:2693] Forwarding status update acknowledgement 5bdd3ad8-348b-4305-83ca-2e77d1f1175b for task 0 of framework 20140913-071954-3142697795-57627-5741-0000 to slave 20140913-071954-3142697795-57627-5741-0 at slave(115)@67.195.81.187:57627 (pomona.apache.org)
I0913 07:19:54.452261 5768 status_update_manager.cpp:398] Received status update acknowledgement (UUID: 5bdd3ad8-348b-4305-83ca-2e77d1f1175b) for task 0 of framework 20140913-071954-3142697795-57627-5741-0000
I0913 07:19:54.452311 5768 slave.cpp:1698] Status update manager successfully handled status update acknowledgement (UUID: 5bdd3ad8-348b-4305-83ca-2e77d1f1175b) for task 0 of framework 20140913-071954-3142697795-57627-5741-0000
I0913 07:19:54.452644 5762 slave.cpp:2617] Executor 'default' of framework 20140913-071954-3142697795-57627-5741-0000 exited with status 0
I0913 07:19:54.453768 5762 slave.cpp:2110] Handling status update TASK_LOST (UUID: 3b98bbdf-bc1b-407e-afec-c4e4ec10c159) for task 0 of framework 20140913-071954-3142697795-57627-5741-0000 from @0.0.0.0:0
I0913 07:19:54.453794 5762 slave.cpp:3937] Terminating task 0
I0913 07:19:54.453968 5762 master.cpp:3261] Executor default of framework 20140913-071954-3142697795-57627-5741-0000 on slave 20140913-071954-3142697795-57627-5741-0 at slave(115)@67.195.81.187:57627 (pomona.apache.org) exited with status 0
I0913 07:19:54.454020 5762 status_update_manager.cpp:320] Received status update TASK_LOST (UUID: 3b98bbdf-bc1b-407e-afec-c4e4ec10c159) for task 0 of framework 20140913-071954-3142697795-57627-5741-0000
I0913 07:19:54.454042 5762 status_update_manager.cpp:373] Forwarding status update TASK_LOST (UUID: 3b98bbdf-bc1b-407e-afec-c4e4ec10c159) for task 0 of framework 20140913-071954-3142697795-57627-5741-0000 to master@67.195.81.187:57627
I0913 07:19:54.454145 5762 master.cpp:3212] Forwarding status update TASK_LOST (UUID: 3b98bbdf-bc1b-407e-afec-c4e4ec10c159) for task 0 of framework 20140913-071954-3142697795-57627-5741-0000
I0913 07:19:54.454182 5762 master.cpp:3178] Status update TASK_LOST (UUID: 3b98bbdf-bc1b-407e-afec-c4e4ec10c159) for task 0 of framework 20140913-071954-3142697795-57627-5741-0000 from slave 20140913-071954-3142697795-57627-5741-0 at slave(115)@67.195.81.187:57627 (pomona.apache.org)
I0913 07:19:54.454217 5762 master.hpp:851] Removing task 0 with resources cpus(*):2; mem(*):1024 on slave 20140913-071954-3142697795-57627-5741-0 (pomona.apache.org)
I0913 07:19:54.454282 5762 slave.cpp:2267] Status update manager successfully handled status update TASK_LOST (UUID: 3b98bbdf-bc1b-407e-afec-c4e4ec10c159) for task 0 of framework 20140913-071954-3142697795-57627-5741-0000
I0913 07:19:54.454340 5762 sched.cpp:635] Scheduler::statusUpdate took 8274ns
I0913 07:19:54.454402 5762 hierarchical_allocator_process.hpp:563] Recovered cpus(*):2; mem(*):1024 (total allocatable: disk(*):1024; ports(*):[31000-32000]; cpus(*):2; mem(*):1024) on slave 20140913-071954-3142697795-57627-5741-0 from framework 20140913-071954-3142697795-57627-5741-0000
I0913 07:19:54.454449 5762 master.cpp:2693] Forwarding status update acknowledgement 3b98bbdf-bc1b-407e-afec-c4e4ec10c159 for task 0 of framework 20140913-071954-3142697795-57627-5741-0000 to slave 20140913-071954-3142697795-57627-5741-0 at slave(115)@67.195.81.187:57627 (pomona.apache.org)
I0913 07:19:54.454516 5762 status_update_manager.cpp:398] Received status update acknowledgement (UUID: 3b98bbdf-bc1b-407e-afec-c4e4ec10c159) for task 0 of framework 20140913-071954-3142697795-57627-5741-0000
I0913 07:19:54.454540 5762 status_update_manager.cpp:530] Cleaning up status update stream for task 0 of framework 20140913-071954-3142697795-57627-5741-0000
I0913 07:19:54.454592 5762 slave.cpp:1698] Status update manager successfully handled status update acknowledgement (UUID: 3b98bbdf-bc1b-407e-afec-c4e4ec10c159) for task 0 of framework 20140913-071954-3142697795-57627-5741-0000
I0913 07:19:54.454608 5762 slave.cpp:3976] Completing task 0
I0913 07:19:54.454619 5762 slave.cpp:2753] Cleaning up executor 'default' of framework 20140913-071954-3142697795-57627-5741-0000
I0913 07:19:56.779952 5762 slave.cpp:2828] Cleaning up framework 20140913-071954-3142697795-57627-5741-0000
I0913 07:19:56.780050 5762 gc.cpp:56] Scheduling '/tmp/GarbageCollectorIntegrationTest_DiskUsage_1giBe1/slaves/20140913-071954-3142697795-57627-5741-0/frameworks/20140913-071954-3142697795-57627-5741-0000/executors/default/runs/a2addb81-3f56-4cb4-a6bb-15f71470200b' for gc 1.00000255872weeks in the future
I0913 07:19:56.780107 5762 gc.cpp:56] Scheduling '/tmp/GarbageCollectorIntegrationTest_DiskUsage_1giBe1/slaves/20140913-071954-3142697795-57627-5741-0/frameworks/20140913-071954-3142697795-57627-5741-0000/executors/default' for gc 1.00000255872weeks in the future
I0913 07:19:56.780138 5762 gc.cpp:56] Scheduling '/tmp/GarbageCollectorIntegrationTest_DiskUsage_1giBe1/slaves/20140913-071954-3142697795-57627-5741-0/frameworks/20140913-071954-3142697795-57627-5741-0000' for gc 1.00000255872weeks in the future
I0913 07:19:56.780169 5762 status_update_manager.cpp:282] Closing status update streams for framework 20140913-071954-3142697795-57627-5741-0000
I0913 07:19:56.798529 5762 hierarchical_allocator_process.hpp:734] Offering disk(*):1024; ports(*):[31000-32000]; cpus(*):2; mem(*):1024 on slave 20140913-071954-3142697795-57627-5741-0 to framework 20140913-071954-3142697795-57627-5741-0000
I0913 07:19:56.798661 5762 hierarchical_allocator_process.hpp:659] Performed allocation for 1 slaves in 193142ns
I0913 07:19:56.798741 5762 master.hpp:861] Adding offer 20140913-071954-3142697795-57627-5741-1 with resources disk(*):1024; ports(*):[31000-32000]; cpus(*):2; mem(*):1024 on slave 20140913-071954-3142697795-57627-5741-0 (pomona.apache.org)
I0913 07:19:56.798812 5762 master.cpp:3600] Sending 1 offers to framework 20140913-071954-3142697795-57627-5741-0000
I0913 07:19:56.798944 5762 sched.cpp:544] Scheduler::resourceOffers took 11292ns
I0913 07:19:56.799255 5760 slave.cpp:3074] Current usage 90.00%. Max allowed age: 0ns
../../src/tests/gc_tests.cpp:675: Failure
Value of: os::exists(executorDir)
Actual: true
Expected: false
I0913 07:19:56.828771 5767 master.cpp:741] Framework 20140913-071954-3142697795-57627-5741-0000 disconnected
I0913 07:19:56.828795 5767 master.cpp:1687] Deactivating framework 20140913-071954-3142697795-57627-5741-0000
I0913 07:19:56.828909 5767 master.hpp:871] Removing offer 20140913-071954-3142697795-57627-5741-1 with resources disk(*):1024; ports(*):[31000-32000]; cpus(*):2; mem(*):1024 on slave 20140913-071954-3142697795-57627-5741-0 (pomona.apache.org)
I0913 07:19:56.828982 5767 master.cpp:763] Giving framework 20140913-071954-3142697795-57627-5741-0000 0ns to failover
I0913 07:19:56.829025 5767 hierarchical_allocator_process.hpp:405] Deactivated framework 20140913-071954-3142697795-57627-5741-0000
I0913 07:19:56.829110 5767 hierarchical_allocator_process.hpp:563] Recovered disk(*):1024; ports(*):[31000-32000]; cpus(*):2; mem(*):1024 (total allocatable: disk(*):1024; ports(*):[31000-32000]; cpus(*):2; mem(*):1024) on slave 20140913-071954-3142697795-57627-5741-0 from framework 20140913-071954-3142697795-57627-5741-0000
I0913 07:19:56.829191 5767 master.cpp:3471] Framework failover timeout, removing framework 20140913-071954-3142697795-57627-5741-0000
I0913 07:19:56.829202 5767 master.cpp:3976] Removing framework 20140913-071954-3142697795-57627-5741-0000
I0913 07:19:56.829273 5767 slave.cpp:1431] Asked to shut down framework 20140913-071954-3142697795-57627-5741-0000 by master@67.195.81.187:57627
W0913 07:19:56.829289 5767 slave.cpp:1446] Cannot shut down unknown framework 20140913-071954-3142697795-57627-5741-0000
I0913 07:19:56.829355 5767 hierarchical_allocator_process.hpp:360] Removed framework 20140913-071954-3142697795-57627-5741-0000
I0913 07:19:56.849370 5755 master.cpp:650] Master terminating
I0913 07:19:56.862035 5758 slave.cpp:2378] master@67.195.81.187:57627 exited
W0913 07:19:56.862061 5758 slave.cpp:2381] Master disconnected! Waiting for a new master to be elected
F0913 07:19:56.862061 5741 logging.cpp:57] RAW: Pure virtual method called
@ 0x2ba13b61148d google::LogMessage::Fail()
@ 0x2ba13b618b86 google::RawLog__()
@ 0x4ff0b6 mesos::internal::tests::Cluster::Slaves::shutdown()
@ 0x77bde4 mesos::internal::tests::MesosTest::ShutdownSlaves()
@ 0x944c13 testing::internal::HandleExceptionsInMethodIfSupported<>()
@ 0x93bdb0 testing::Test::Run()
@ 0x93be8e testing::TestInfo::Run()
@ 0x93bf95 testing::TestCase::Run()
@ 0x93c238 testing::internal::UnitTestImpl::RunAllTests()
@ 0x93c4d7 testing::UnitTest::Run()
@ 0x48d3f3 main
@ 0x2ba13d325ec5 (unknown)
@ 0x49a708 (unknown)
make[3]: *** [check-local] Aborted
make[3]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src'>
make[2]: *** [check-am] Error 2
make[2]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src'>
make[1]: *** [check] Error 2
make[1]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src'>
make: *** [check-recursive] Error 1
Test finished
Exit status: 2
Build step 'Execute shell' marked build as failure
Re: Build failed in Jenkins: Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui
#2374
Posted by Timothy Chen <tn...@gmail.com>.
Hi Ben,
Sounds good, I'll take a look sometime tonight or tomorrow.
Tim
On Tue, Sep 16, 2014 at 8:34 PM, Benjamin Mahler
<be...@gmail.com> wrote:
> +Tim Chen
>
> Can you take a look at the health check failure?
> https://issues.apache.org/jira/browse/MESOS-1802
>
> I'll take a look at the Registrar test:
> https://issues.apache.org/jira/browse/MESOS-1803
>
>
> On Tue, Sep 16, 2014 at 4:01 PM, Apache Jenkins Server <
> jenkins@builds.apache.org> wrote:
>
>> See <
>> https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/2374/changes
>> >
>>
>> Changes:
>>
>> [bmahler] Added a Version class to stout.
>>
>> ------------------------------------------
>> [...truncated 58686 lines...]
>> I0916 23:01:05.386067 21051 replica.cpp:676] Persisted action at 0
>> I0916 23:01:05.386090 21051 replica.cpp:661] Replica learned NOP action at
>> position 0
>> I0916 23:01:05.083233 21042 leveldb.cpp:343] Persisting action (16 bytes)
>> to leveldb took 121548ns
>> I0916 23:01:05.386147 21042 replica.cpp:676] Persisted action at 0
>> I0916 23:01:05.386168 21042 replica.cpp:661] Replica learned NOP action at
>> position 0
>> I0916 23:01:05.386436 21040 coordinator.cpp:340] Coordinator attempting to
>> write APPEND action at position 1
>> I0916 23:01:05.386842 21048 replica.cpp:508] Replica received write
>> request for position 1
>> I0916 23:01:05.386904 21040 replica.cpp:508] Replica received write
>> request for position 1
>> I0916 23:01:05.387473 21048 leveldb.cpp:343] Persisting action (27 bytes)
>> to leveldb took 603894ns
>> I0916 23:01:05.387475 21040 leveldb.cpp:343] Persisting action (27 bytes)
>> to leveldb took 538731ns
>> I0916 23:01:05.387511 21048 replica.cpp:676] Persisted action at 1
>> I0916 23:01:05.387524 21040 replica.cpp:676] Persisted action at 1
>> I0916 23:01:05.387969 21043 replica.cpp:655] Replica received learned
>> notice for position 1
>> I0916 23:01:05.387998 21053 replica.cpp:655] Replica received learned
>> notice for position 1
>> I0916 23:01:05.388157 21043 leveldb.cpp:343] Persisting action (29 bytes)
>> to leveldb took 165034ns
>> I0916 23:01:05.388177 21043 replica.cpp:676] Persisted action at 1
>> I0916 23:01:05.388188 21043 replica.cpp:661] Replica learned APPEND action
>> at position 1
>> I0916 23:01:05.388212 21053 leveldb.cpp:343] Persisting action (29 bytes)
>> to leveldb took 190343ns
>> I0916 23:01:05.388236 21053 replica.cpp:676] Persisted action at 1
>> I0916 23:01:05.388245 21053 replica.cpp:661] Replica learned APPEND action
>> at position 1
>> I0916 23:01:05.390319 21026 leveldb.cpp:176] Opened db in 1.951015ms
>> I0916 23:01:05.391607 21026 leveldb.cpp:183] Compacted db in 1.261904ms
>> I0916 23:01:05.391633 21026 leveldb.cpp:198] Created db iterator in 4244ns
>> I0916 23:01:05.391650 21026 leveldb.cpp:204] Seeked to beginning of db in
>> 7069ns
>> I0916 23:01:05.391669 21026 leveldb.cpp:273] Iterated through 1 keys in
>> the db in 8220ns
>> I0916 23:01:05.391685 21026 replica.cpp:741] Replica recovered with log
>> positions 0 -> 0 with 1 holes and 0 unlearned
>> I0916 23:01:05.392328 21047 replica.cpp:474] Replica received implicit
>> promise request with proposal 1
>> I0916 23:01:05.392354 21047 replica.cpp:479] Replica denying promise
>> request with proposal 1
>> I0916 23:01:05.392408 21043 replica.cpp:474] Replica received implicit
>> promise request with proposal 1
>> I0916 23:01:05.392943 21043 leveldb.cpp:306] Persisting metadata (8 bytes)
>> to leveldb took 510019ns
>> I0916 23:01:05.392963 21043 replica.cpp:342] Persisted promised to 1
>> I0916 23:01:05.393698 21055 replica.cpp:474] Replica received implicit
>> promise request with proposal 2
>> I0916 23:01:05.393705 21045 replica.cpp:474] Replica received implicit
>> promise request with proposal 2
>> I0916 23:01:05.394114 21045 leveldb.cpp:306] Persisting metadata (8 bytes)
>> to leveldb took 380162ns
>> I0916 23:01:05.394114 21055 leveldb.cpp:306] Persisting metadata (8 bytes)
>> to leveldb took 390574ns
>> I0916 23:01:05.394136 21045 replica.cpp:342] Persisted promised to 2
>> I0916 23:01:05.394152 21055 replica.cpp:342] Persisted promised to 2
>> I0916 23:01:05.394424 21053 coordinator.cpp:230] Coordinator attemping to
>> fill missing position
>> I0916 23:01:05.395113 21046 replica.cpp:375] Replica received explicit
>> promise request for position 0 with proposal 3
>> I0916 23:01:05.395136 21055 replica.cpp:375] Replica received explicit
>> promise request for position 0 with proposal 3
>> I0916 23:01:05.395153 21046 leveldb.cpp:438] Reading position from leveldb
>> took 16040ns
>> I0916 23:01:05.395339 21055 leveldb.cpp:343] Persisting action (8 bytes)
>> to leveldb took 181686ns
>> I0916 23:01:05.395359 21055 replica.cpp:676] Persisted action at 0
>> I0916 23:01:05.395392 21046 leveldb.cpp:343] Persisting action (16 bytes)
>> to leveldb took 215312ns
>> I0916 23:01:05.395414 21046 replica.cpp:676] Persisted action at 0
>> I0916 23:01:05.395781 21047 replica.cpp:655] Replica received learned
>> notice for position 0
>> I0916 23:01:05.395792 21049 replica.cpp:655] Replica received learned
>> notice for position 0
>> I0916 23:01:05.395972 21047 leveldb.cpp:343] Persisting action (16 bytes)
>> to leveldb took 163947ns
>> I0916 23:01:05.395992 21047 replica.cpp:676] Persisted action at 0
>> I0916 23:01:05.396003 21047 replica.cpp:661] Replica learned NOP action at
>> position 0
>> I0916 23:01:05.396059 21049 leveldb.cpp:343] Persisting action (16 bytes)
>> to leveldb took 198163ns
>> I0916 23:01:05.396105 21049 replica.cpp:676] Persisted action at 0
>> I0916 23:01:05.396118 21049 replica.cpp:661] Replica learned NOP action at
>> position 0
>> I0916 23:01:05.396561 21053 replica.cpp:375] Replica received explicit
>> promise request for position 1 with proposal 3
>> I0916 23:01:05.396602 21053 leveldb.cpp:438] Reading position from leveldb
>> took 17412ns
>> I0916 23:01:05.396661 21048 replica.cpp:375] Replica received explicit
>> promise request for position 1 with proposal 3
>> I0916 23:01:05.396785 21053 leveldb.cpp:343] Persisting action (29 bytes)
>> to leveldb took 158375ns
>> I0916 23:01:05.396806 21053 replica.cpp:676] Persisted action at 1
>> I0916 23:01:05.396877 21048 leveldb.cpp:343] Persisting action (8 bytes)
>> to leveldb took 189711ns
>> I0916 23:01:05.396903 21048 replica.cpp:676] Persisted action at 1
>> I0916 23:01:05.397061 21049 replica.cpp:655] Replica received learned
>> notice for position 1
>> I0916 23:01:05.397063 21042 replica.cpp:655] Replica received learned
>> notice for position 1
>> I0916 23:01:05.397454 21042 leveldb.cpp:343] Persisting action (29 bytes)
>> to leveldb took 353980ns
>> I0916 23:01:05.397455 21049 leveldb.cpp:343] Persisting action (29 bytes)
>> to leveldb took 366829ns
>> I0916 23:01:05.397477 21042 replica.cpp:676] Persisted action at 1
>> I0916 23:01:05.397488 21042 replica.cpp:661] Replica learned APPEND action
>> at position 1
>> I0916 23:01:05.397490 21049 replica.cpp:676] Persisted action at 1
>> I0916 23:01:05.397511 21049 replica.cpp:661] Replica learned APPEND action
>> at position 1
>> I0916 23:01:05.397948 21053 leveldb.cpp:438] Reading position from leveldb
>> took 18632ns
>> [ OK ] CoordinatorTest.Fill (338 ms)
>> [ RUN ] CoordinatorTest.ElectWithClockPaused
>> Using temporary directory
>> '/tmp/CoordinatorTest_ElectWithClockPaused_XPakdP'
>> I0916 23:01:05.401895 21026 leveldb.cpp:176] Opened db in 2.126108ms
>> I0916 23:01:05.402295 21026 leveldb.cpp:183] Compacted db in 372807ns
>> I0916 23:01:05.402319 21026 leveldb.cpp:198] Created db iterator in 3347ns
>> I0916 23:01:05.402335 21026 leveldb.cpp:204] Seeked to beginning of db in
>> 575ns
>> I0916 23:01:05.402346 21026 leveldb.cpp:273] Iterated through 0 keys in
>> the db in 210ns
>> I0916 23:01:05.402362 21026 replica.cpp:741] Replica recovered with log
>> positions 0 -> 0 with 1 holes and 0 unlearned
>> I0916 23:01:05.403061 21041 leveldb.cpp:306] Persisting metadata (8 bytes)
>> to leveldb took 439929ns
>> I0916 23:01:05.403081 21041 replica.cpp:320] Persisted replica status to
>> VOTING
>> I0916 23:01:05.405195 21026 leveldb.cpp:176] Opened db in 1.857658ms
>> I0916 23:01:05.405761 21026 leveldb.cpp:183] Compacted db in 539011ns
>> I0916 23:01:05.405781 21026 leveldb.cpp:198] Created db iterator in 2735ns
>> I0916 23:01:05.405791 21026 leveldb.cpp:204] Seeked to beginning of db in
>> 475ns
>> I0916 23:01:05.405799 21026 leveldb.cpp:273] Iterated through 0 keys in
>> the db in 195ns
>> I0916 23:01:05.405814 21026 replica.cpp:741] Replica recovered with log
>> positions 0 -> 0 with 1 holes and 0 unlearned
>> I0916 23:01:05.406510 21046 leveldb.cpp:306] Persisting metadata (8 bytes)
>> to leveldb took 452694ns
>> I0916 23:01:05.406533 21046 replica.cpp:320] Persisted replica status to
>> VOTING
>> I0916 23:01:05.408746 21026 leveldb.cpp:176] Opened db in 1.965229ms
>> I0916 23:01:05.410229 21026 leveldb.cpp:183] Compacted db in 1.454674ms
>> I0916 23:01:05.410260 21026 leveldb.cpp:198] Created db iterator in 4550ns
>> I0916 23:01:05.410284 21026 leveldb.cpp:204] Seeked to beginning of db in
>> 7785ns
>> I0916 23:01:05.410303 21026 leveldb.cpp:273] Iterated through 1 keys in
>> the db in 8398ns
>> I0916 23:01:05.410320 21026 replica.cpp:741] Replica recovered with log
>> positions 0 -> 0 with 1 holes and 0 unlearned
>> I0916 23:01:10.189376 21026 leveldb.cpp:176] Opened db in 2.600519ms
>> I0916 23:01:10.191403 21026 leveldb.cpp:183] Compacted db in 1.996275ms
>> I0916 23:01:10.191436 21026 leveldb.cpp:198] Created db iterator in 4378ns
>> I0916 23:01:10.191457 21026 leveldb.cpp:204] Seeked to beginning of db in
>> 7234ns
>> I0916 23:01:10.191476 21026 leveldb.cpp:273] Iterated through 1 keys in
>> the db in 8102ns
>> I0916 23:01:10.191493 21026 replica.cpp:741] Replica recovered with log
>> positions 0 -> 0 with 1 holes and 0 unlearned
>> I0916 23:01:10.191894 21049 replica.cpp:474] Replica received implicit
>> promise request with proposal 1
>> I0916 23:01:10.191937 21044 replica.cpp:474] Replica received implicit
>> promise request with proposal 1
>> I0916 23:01:10.192438 21049 leveldb.cpp:306] Persisting metadata (8 bytes)
>> to leveldb took 517437ns
>> I0916 23:01:10.192461 21049 replica.cpp:342] Persisted promised to 1
>> I0916 23:01:10.192517 21044 leveldb.cpp:306] Persisting metadata (8 bytes)
>> to leveldb took 555333ns
>> I0916 23:01:10.192543 21044 replica.cpp:342] Persisted promised to 1
>> I0916 23:01:10.193327 21055 coordinator.cpp:230] Coordinator attemping to
>> fill missing position
>> I0916 23:01:10.194192 21044 replica.cpp:375] Replica received explicit
>> promise request for position 0 with proposal 2
>> I0916 23:01:10.194272 21049 replica.cpp:375] Replica received explicit
>> promise request for position 0 with proposal 2
>> I0916 23:01:10.195019 21049 leveldb.cpp:343] Persisting action (8 bytes)
>> to leveldb took 721630ns
>> I0916 23:01:10.195019 21044 leveldb.cpp:343] Persisting action (8 bytes)
>> to leveldb took 799669ns
>> I0916 23:01:10.195044 21049 replica.cpp:676] Persisted action at 0
>> I0916 23:01:10.195061 21044 replica.cpp:676] Persisted action at 0
>> I0916 23:01:10.195617 21053 replica.cpp:508] Replica received write
>> request for position 0
>> I0916 23:01:10.195672 21053 leveldb.cpp:438] Reading position from leveldb
>> took 13897ns
>> I0916 23:01:10.195801 21051 replica.cpp:508] Replica received write
>> request for position 0
>> I0916 23:01:10.195837 21051 leveldb.cpp:438] Reading position from leveldb
>> took 12352ns
>> I0916 23:01:10.195870 21053 leveldb.cpp:343] Persisting action (14 bytes)
>> to leveldb took 177322ns
>> I0916 23:01:10.195894 21053 replica.cpp:676] Persisted action at 0
>> I0916 23:01:10.196024 21051 leveldb.cpp:343] Persisting action (14 bytes)
>> to leveldb took 161185ns
>> I0916 23:01:10.196045 21051 replica.cpp:676] Persisted action at 0
>> I0916 23:01:10.196480 21043 replica.cpp:655] Replica received learned
>> notice for position 0
>> I0916 23:01:10.196480 21046 replica.cpp:655] Replica received learned
>> notice for position 0
>> I0916 23:01:10.196704 21046 leveldb.cpp:343] Persisting action (16 bytes)
>> to leveldb took 173626ns
>> I0916 23:01:10.196750 21046 replica.cpp:676] Persisted action at 0
>> I0916 23:01:10.196754 21043 leveldb.cpp:343] Persisting action (16 bytes)
>> to leveldb took 237051ns
>> I0916 23:01:10.196761 21046 replica.cpp:661] Replica learned NOP action at
>> position 0
>> I0916 23:01:10.196777 21043 replica.cpp:676] Persisted action at 0
>> I0916 23:01:10.196789 21043 replica.cpp:661] Replica learned NOP action at
>> position 0
>> [ OK ] CoordinatorTest.ElectWithClockPaused (4803 ms)
>> [ RUN ] CoordinatorTest.FillInconsistent
>> Using temporary directory '/tmp/CoordinatorTest_FillInconsistent_ZKE6XE'
>> [ OK ] CoordinatorTest.FillInconsistent (0 ms)
>> [----------] 21 tests from CoordinatorTest (19050 ms total)
>>
>> [----------] 4 tests from ReplicaTest
>> [ RUN ] ReplicaTest.Promise
>> Using temporary directory '/tmp/ReplicaTest_Promise_NBZUIu'
>> I0916 23:01:10.205260 21026 leveldb.cpp:176] Opened db in 2.150092ms
>> I0916 23:01:10.205966 21026 leveldb.cpp:183] Compacted db in 677731ns
>> I0916 23:01:10.205986 21026 leveldb.cpp:198] Created db iterator in 2735ns
>> I0916 23:01:10.205996 21026 leveldb.cpp:204] Seeked to beginning of db in
>> 472ns
>> I0916 23:01:10.206006 21026 leveldb.cpp:273] Iterated through 0 keys in
>> the db in 198ns
>> I0916 23:01:10.206019 21026 replica.cpp:741] Replica recovered with log
>> positions 0 -> 0 with 1 holes and 0 unlearned
>> I0916 23:01:10.206781 21054 leveldb.cpp:306] Persisting metadata (8 bytes)
>> to leveldb took 583987ns
>> I0916 23:01:10.206801 21054 replica.cpp:320] Persisted replica status to
>> VOTING
>> I0916 23:01:10.209231 21026 leveldb.cpp:176] Opened db in 2.210186ms
>> I0916 23:01:10.211395 21026 leveldb.cpp:183] Compacted db in 2.13344ms
>> I0916 23:01:10.211428 21026 leveldb.cpp:198] Created db iterator in 4390ns
>> I0916 23:01:10.211451 21026 leveldb.cpp:204] Seeked to beginning of db in
>> 7710ns
>> I0916 23:01:10.211470 21026 leveldb.cpp:273] Iterated through 1 keys in
>> the db in 8295ns
>> I0916 23:01:10.211487 21026 replica.cpp:741] Replica recovered with log
>> positions 0 -> 0 with 1 holes and 0 unlearned
>> I0916 23:01:10.211709 21054 replica.cpp:474] Replica received implicit
>> promise request with proposal 2
>> I0916 23:01:10.212260 21054 leveldb.cpp:306] Persisting metadata (8 bytes)
>> to leveldb took 526905ns
>> I0916 23:01:10.212280 21054 replica.cpp:342] Persisted promised to 2
>> I0916 23:01:10.212738 21046 replica.cpp:474] Replica received implicit
>> promise request with proposal 1
>> I0916 23:01:10.212757 21046 replica.cpp:479] Replica denying promise
>> request with proposal 1
>> I0916 23:01:10.213058 21047 replica.cpp:474] Replica received implicit
>> promise request with proposal 3
>> I0916 23:01:10.213518 21047 leveldb.cpp:306] Persisting metadata (8 bytes)
>> to leveldb took 433010ns
>> I0916 23:01:10.213537 21047 replica.cpp:342] Persisted promised to 3
>> [ OK ] ReplicaTest.Promise (12 ms)
>> [ RUN ] ReplicaTest.Restore
>> Using temporary directory '/tmp/ReplicaTest_Restore_Hpbyvk'
>> I0916 23:01:10.216367 21026 leveldb.cpp:176] Opened db in 2.043673ms
>> I0916 23:01:10.216773 21026 leveldb.cpp:183] Compacted db in 379902ns
>> I0916 23:01:10.216794 21026 leveldb.cpp:198] Created db iterator in 2885ns
>> I0916 23:01:10.216804 21026 leveldb.cpp:204] Seeked to beginning of db in
>> 500ns
>> I0916 23:01:10.216814 21026 leveldb.cpp:273] Iterated through 0 keys in
>> the db in 200ns
>> I0916 23:01:10.216828 21026 replica.cpp:741] Replica recovered with log
>> positions 0 -> 0 with 1 holes and 0 unlearned
>> I0916 23:01:10.217572 21051 leveldb.cpp:306] Persisting metadata (8 bytes)
>> to leveldb took 469143ns
>> I0916 23:01:10.217592 21051 replica.cpp:320] Persisted replica status to
>> VOTING
>> I0916 23:01:10.219882 21026 leveldb.cpp:176] Opened db in 1.930543ms
>> I0916 23:01:10.221320 21026 leveldb.cpp:183] Compacted db in 1.410263ms
>> I0916 23:01:10.221349 21026 leveldb.cpp:198] Created db iterator in 3975ns
>> I0916 23:01:10.221366 21026 leveldb.cpp:204] Seeked to beginning of db in
>> 7110ns
>> I0916 23:01:10.221385 21026 leveldb.cpp:273] Iterated through 1 keys in
>> the db in 8097ns
>> I0916 23:01:10.221401 21026 replica.cpp:741] Replica recovered with log
>> positions 0 -> 0 with 1 holes and 0 unlearned
>> I0916 23:01:10.221575 21049 replica.cpp:474] Replica received implicit
>> promise request with proposal 1
>> I0916 23:01:10.222064 21049 leveldb.cpp:306] Persisting metadata (8 bytes)
>> to leveldb took 460628ns
>> I0916 23:01:10.222082 21049 replica.cpp:342] Persisted promised to 1
>> I0916 23:01:10.222256 21051 replica.cpp:508] Replica received write
>> request for position 1
>> I0916 23:01:10.222446 21051 leveldb.cpp:343] Persisting action (27 bytes)
>> to leveldb took 160079ns
>> I0916 23:01:10.222465 21051 replica.cpp:676] Persisted action at 1
>> I0916 23:01:10.222645 21046 leveldb.cpp:438] Reading position from leveldb
>> took 21315ns
>> I0916 23:01:10.224990 21026 leveldb.cpp:176] Opened db in 2.097744ms
>> I0916 23:01:10.226565 21026 leveldb.cpp:183] Compacted db in 1.548383ms
>> I0916 23:01:10.226593 21026 leveldb.cpp:198] Created db iterator in 4283ns
>> I0916 23:01:10.226610 21026 leveldb.cpp:204] Seeked to beginning of db in
>> 7267ns
>> I0916 23:01:10.226636 21026 leveldb.cpp:273] Iterated through 2 keys in
>> the db in 14932ns
>> I0916 23:01:10.226655 21026 replica.cpp:741] Replica recovered with log
>> positions 0 -> 1 with 1 holes and 1 unlearned
>> I0916 23:01:10.226730 21047 leveldb.cpp:438] Reading position from leveldb
>> took 29797ns
>> [ OK ] ReplicaTest.Restore (13 ms)
>> [ RUN ] ReplicaTest.NonVoting
>> Using temporary directory '/tmp/ReplicaTest_NonVoting_vDwNJa'
>> I0916 23:01:10.386850 21026 leveldb.cpp:176] Opened db in 2.50423ms
>> I0916 23:01:10.387466 21026 leveldb.cpp:183] Compacted db in 587774ns
>> I0916 23:01:10.387492 21026 leveldb.cpp:198] Created db iterator in 3455ns
>> I0916 23:01:10.387508 21026 leveldb.cpp:204] Seeked to beginning of db in
>> 540ns
>> I0916 23:01:10.387518 21026 leveldb.cpp:273] Iterated through 0 keys in
>> the db in 210ns
>> I0916 23:01:10.387533 21026 replica.cpp:741] Replica recovered with log
>> positions 0 -> 0 with 1 holes and 0 unlearned
>> I0916 23:01:10.387671 21047 replica.cpp:369] Replica ignoring promise
>> request as it is in EMPTY status
>> I0916 23:01:10.397832 21053 replica.cpp:503] Replica ignoring write
>> request as it is in EMPTY status
>> [ OK ] ReplicaTest.NonVoting (24 ms)
>> [ RUN ] ReplicaTest.Append
>> Using temporary directory '/tmp/ReplicaTest_Append_PfpX10'
>> I0916 23:01:10.410902 21026 leveldb.cpp:176] Opened db in 2.480258ms
>> I0916 23:01:10.411463 21026 leveldb.cpp:183] Compacted db in 531801ns
>> I0916 23:01:10.411485 21026 leveldb.cpp:198] Created db iterator in 3215ns
>> I0916 23:01:10.411501 21026 leveldb.cpp:204] Seeked to beginning of db in
>> 550ns
>> I0916 23:01:10.411512 21026 leveldb.cpp:273] Iterated through 0 keys in
>> the db in 188ns
>> I0916 23:01:10.411528 21026 replica.cpp:741] Replica recovered with log
>> positions 0 -> 0 with 1 holes and 0 unlearned
>> I0916 23:01:10.412348 21050 leveldb.cpp:306] Persisting metadata (8 bytes)
>> to leveldb took 632675ns
>> I0916 23:01:10.412370 21050 replica.cpp:320] Persisted replica status to
>> VOTING
>> I0916 23:01:10.415046 21026 leveldb.cpp:176] Opened db in 2.365599ms
>> I0916 23:01:10.416496 21026 leveldb.cpp:183] Compacted db in 1.42057ms
>> I0916 23:01:10.416522 21026 leveldb.cpp:198] Created db iterator in 4235ns
>> I0916 23:01:10.416542 21026 leveldb.cpp:204] Seeked to beginning of db in
>> 7197ns
>> I0916 23:01:10.416559 21026 leveldb.cpp:273] Iterated through 1 keys in
>> the db in 8095ns
>> I0916 23:01:10.416576 21026 replica.cpp:741] Replica recovered with log
>> positions 0 -> 0 with 1 holes and 0 unlearned
>> I0916 23:01:10.416733 21048 replica.cpp:474] Replica received implicit
>> promise request with proposal 1
>> I0916 23:01:10.417361 21048 leveldb.cpp:306] Persisting metadata (8 bytes)
>> to leveldb took 599444ns
>> I0916 23:01:10.417383 21048 replica.cpp:342] Persisted promised to 1
>> I0916 23:01:10.417697 21044 replica.cpp:508] Replica received write
>> request for position 1
>> I0916 23:01:10.417881 21044 leveldb.cpp:343] Persisting action (27 bytes)
>> to leveldb took 157842ns
>> I0916 23:01:10.417899 21044 replica.cpp:676] Persisted action at 1
>> I0916 23:01:10.418081 21044 leveldb.cpp:438] Reading position from leveldb
>> took 21617ns
>> [ OK ] ReplicaTest.Append (11 ms)
>> [----------] 4 tests from ReplicaTest (217 ms total)
>>
>> [----------] Global test environment tear-down
>> [==========] 365 tests from 59 test cases ran. (379816 ms total)
>> [ PASSED ] 363 tests.
>> [ FAILED ] 2 tests, listed below:
>> [ FAILED ] HealthCheckTest.HealthStatusChange
>> [ FAILED ] Strict/RegistrarTest.remove/1, where GetParam() = true
>>
>> 2 FAILED TESTS
>> YOU HAVE 5 DISABLED TESTS
>>
>> make[3]: *** [check-local] Error 1
>> make[3]: Leaving directory `<
>> https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src
>> '>
>> make[2]: *** [check-am] Error 2
>> make[2]: Leaving directory `<
>> https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src
>> '>
>> make[1]: *** [check] Error 2
>> make[1]: Leaving directory `<
>> https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src
>> '>
>> make: *** [check-recursive] Error 1
>> Test finished
>> Exit status: 2
>> Build step 'Execute shell' marked build as failure
>>
Re: Build failed in Jenkins: Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui
#2374
Posted by Benjamin Mahler <be...@gmail.com>.
+Tim Chen
Can you take a look at the health check failure?
https://issues.apache.org/jira/browse/MESOS-1802
I'll take a look at the Registrar test:
https://issues.apache.org/jira/browse/MESOS-1803
On Tue, Sep 16, 2014 at 4:01 PM, Apache Jenkins Server <
jenkins@builds.apache.org> wrote:
> See <
> https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/2374/changes
> >
>
> Changes:
>
> [bmahler] Added a Version class to stout.
>
> ------------------------------------------
> [...truncated 58686 lines...]
> I0916 23:01:05.386067 21051 replica.cpp:676] Persisted action at 0
> I0916 23:01:05.386090 21051 replica.cpp:661] Replica learned NOP action at
> position 0
> I0916 23:01:05.083233 21042 leveldb.cpp:343] Persisting action (16 bytes)
> to leveldb took 121548ns
> I0916 23:01:05.386147 21042 replica.cpp:676] Persisted action at 0
> I0916 23:01:05.386168 21042 replica.cpp:661] Replica learned NOP action at
> position 0
> I0916 23:01:05.386436 21040 coordinator.cpp:340] Coordinator attempting to
> write APPEND action at position 1
> I0916 23:01:05.386842 21048 replica.cpp:508] Replica received write
> request for position 1
> I0916 23:01:05.386904 21040 replica.cpp:508] Replica received write
> request for position 1
> I0916 23:01:05.387473 21048 leveldb.cpp:343] Persisting action (27 bytes)
> to leveldb took 603894ns
> I0916 23:01:05.387475 21040 leveldb.cpp:343] Persisting action (27 bytes)
> to leveldb took 538731ns
> I0916 23:01:05.387511 21048 replica.cpp:676] Persisted action at 1
> I0916 23:01:05.387524 21040 replica.cpp:676] Persisted action at 1
> I0916 23:01:05.387969 21043 replica.cpp:655] Replica received learned
> notice for position 1
> I0916 23:01:05.387998 21053 replica.cpp:655] Replica received learned
> notice for position 1
> I0916 23:01:05.388157 21043 leveldb.cpp:343] Persisting action (29 bytes)
> to leveldb took 165034ns
> I0916 23:01:05.388177 21043 replica.cpp:676] Persisted action at 1
> I0916 23:01:05.388188 21043 replica.cpp:661] Replica learned APPEND action
> at position 1
> I0916 23:01:05.388212 21053 leveldb.cpp:343] Persisting action (29 bytes)
> to leveldb took 190343ns
> I0916 23:01:05.388236 21053 replica.cpp:676] Persisted action at 1
> I0916 23:01:05.388245 21053 replica.cpp:661] Replica learned APPEND action
> at position 1
> I0916 23:01:05.390319 21026 leveldb.cpp:176] Opened db in 1.951015ms
> I0916 23:01:05.391607 21026 leveldb.cpp:183] Compacted db in 1.261904ms
> I0916 23:01:05.391633 21026 leveldb.cpp:198] Created db iterator in 4244ns
> I0916 23:01:05.391650 21026 leveldb.cpp:204] Seeked to beginning of db in
> 7069ns
> I0916 23:01:05.391669 21026 leveldb.cpp:273] Iterated through 1 keys in
> the db in 8220ns
> I0916 23:01:05.391685 21026 replica.cpp:741] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0916 23:01:05.392328 21047 replica.cpp:474] Replica received implicit
> promise request with proposal 1
> I0916 23:01:05.392354 21047 replica.cpp:479] Replica denying promise
> request with proposal 1
> I0916 23:01:05.392408 21043 replica.cpp:474] Replica received implicit
> promise request with proposal 1
> I0916 23:01:05.392943 21043 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 510019ns
> I0916 23:01:05.392963 21043 replica.cpp:342] Persisted promised to 1
> I0916 23:01:05.393698 21055 replica.cpp:474] Replica received implicit
> promise request with proposal 2
> I0916 23:01:05.393705 21045 replica.cpp:474] Replica received implicit
> promise request with proposal 2
> I0916 23:01:05.394114 21045 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 380162ns
> I0916 23:01:05.394114 21055 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 390574ns
> I0916 23:01:05.394136 21045 replica.cpp:342] Persisted promised to 2
> I0916 23:01:05.394152 21055 replica.cpp:342] Persisted promised to 2
> I0916 23:01:05.394424 21053 coordinator.cpp:230] Coordinator attemping to
> fill missing position
> I0916 23:01:05.395113 21046 replica.cpp:375] Replica received explicit
> promise request for position 0 with proposal 3
> I0916 23:01:05.395136 21055 replica.cpp:375] Replica received explicit
> promise request for position 0 with proposal 3
> I0916 23:01:05.395153 21046 leveldb.cpp:438] Reading position from leveldb
> took 16040ns
> I0916 23:01:05.395339 21055 leveldb.cpp:343] Persisting action (8 bytes)
> to leveldb took 181686ns
> I0916 23:01:05.395359 21055 replica.cpp:676] Persisted action at 0
> I0916 23:01:05.395392 21046 leveldb.cpp:343] Persisting action (16 bytes)
> to leveldb took 215312ns
> I0916 23:01:05.395414 21046 replica.cpp:676] Persisted action at 0
> I0916 23:01:05.395781 21047 replica.cpp:655] Replica received learned
> notice for position 0
> I0916 23:01:05.395792 21049 replica.cpp:655] Replica received learned
> notice for position 0
> I0916 23:01:05.395972 21047 leveldb.cpp:343] Persisting action (16 bytes)
> to leveldb took 163947ns
> I0916 23:01:05.395992 21047 replica.cpp:676] Persisted action at 0
> I0916 23:01:05.396003 21047 replica.cpp:661] Replica learned NOP action at
> position 0
> I0916 23:01:05.396059 21049 leveldb.cpp:343] Persisting action (16 bytes)
> to leveldb took 198163ns
> I0916 23:01:05.396105 21049 replica.cpp:676] Persisted action at 0
> I0916 23:01:05.396118 21049 replica.cpp:661] Replica learned NOP action at
> position 0
> I0916 23:01:05.396561 21053 replica.cpp:375] Replica received explicit
> promise request for position 1 with proposal 3
> I0916 23:01:05.396602 21053 leveldb.cpp:438] Reading position from leveldb
> took 17412ns
> I0916 23:01:05.396661 21048 replica.cpp:375] Replica received explicit
> promise request for position 1 with proposal 3
> I0916 23:01:05.396785 21053 leveldb.cpp:343] Persisting action (29 bytes)
> to leveldb took 158375ns
> I0916 23:01:05.396806 21053 replica.cpp:676] Persisted action at 1
> I0916 23:01:05.396877 21048 leveldb.cpp:343] Persisting action (8 bytes)
> to leveldb took 189711ns
> I0916 23:01:05.396903 21048 replica.cpp:676] Persisted action at 1
> I0916 23:01:05.397061 21049 replica.cpp:655] Replica received learned
> notice for position 1
> I0916 23:01:05.397063 21042 replica.cpp:655] Replica received learned
> notice for position 1
> I0916 23:01:05.397454 21042 leveldb.cpp:343] Persisting action (29 bytes)
> to leveldb took 353980ns
> I0916 23:01:05.397455 21049 leveldb.cpp:343] Persisting action (29 bytes)
> to leveldb took 366829ns
> I0916 23:01:05.397477 21042 replica.cpp:676] Persisted action at 1
> I0916 23:01:05.397488 21042 replica.cpp:661] Replica learned APPEND action
> at position 1
> I0916 23:01:05.397490 21049 replica.cpp:676] Persisted action at 1
> I0916 23:01:05.397511 21049 replica.cpp:661] Replica learned APPEND action
> at position 1
> I0916 23:01:05.397948 21053 leveldb.cpp:438] Reading position from leveldb
> took 18632ns
> [ OK ] CoordinatorTest.Fill (338 ms)
> [ RUN ] CoordinatorTest.ElectWithClockPaused
> Using temporary directory
> '/tmp/CoordinatorTest_ElectWithClockPaused_XPakdP'
> I0916 23:01:05.401895 21026 leveldb.cpp:176] Opened db in 2.126108ms
> I0916 23:01:05.402295 21026 leveldb.cpp:183] Compacted db in 372807ns
> I0916 23:01:05.402319 21026 leveldb.cpp:198] Created db iterator in 3347ns
> I0916 23:01:05.402335 21026 leveldb.cpp:204] Seeked to beginning of db in
> 575ns
> I0916 23:01:05.402346 21026 leveldb.cpp:273] Iterated through 0 keys in
> the db in 210ns
> I0916 23:01:05.402362 21026 replica.cpp:741] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0916 23:01:05.403061 21041 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 439929ns
> I0916 23:01:05.403081 21041 replica.cpp:320] Persisted replica status to
> VOTING
> I0916 23:01:05.405195 21026 leveldb.cpp:176] Opened db in 1.857658ms
> I0916 23:01:05.405761 21026 leveldb.cpp:183] Compacted db in 539011ns
> I0916 23:01:05.405781 21026 leveldb.cpp:198] Created db iterator in 2735ns
> I0916 23:01:05.405791 21026 leveldb.cpp:204] Seeked to beginning of db in
> 475ns
> I0916 23:01:05.405799 21026 leveldb.cpp:273] Iterated through 0 keys in
> the db in 195ns
> I0916 23:01:05.405814 21026 replica.cpp:741] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0916 23:01:05.406510 21046 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 452694ns
> I0916 23:01:05.406533 21046 replica.cpp:320] Persisted replica status to
> VOTING
> I0916 23:01:05.408746 21026 leveldb.cpp:176] Opened db in 1.965229ms
> I0916 23:01:05.410229 21026 leveldb.cpp:183] Compacted db in 1.454674ms
> I0916 23:01:05.410260 21026 leveldb.cpp:198] Created db iterator in 4550ns
> I0916 23:01:05.410284 21026 leveldb.cpp:204] Seeked to beginning of db in
> 7785ns
> I0916 23:01:05.410303 21026 leveldb.cpp:273] Iterated through 1 keys in
> the db in 8398ns
> I0916 23:01:05.410320 21026 replica.cpp:741] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0916 23:01:10.189376 21026 leveldb.cpp:176] Opened db in 2.600519ms
> I0916 23:01:10.191403 21026 leveldb.cpp:183] Compacted db in 1.996275ms
> I0916 23:01:10.191436 21026 leveldb.cpp:198] Created db iterator in 4378ns
> I0916 23:01:10.191457 21026 leveldb.cpp:204] Seeked to beginning of db in
> 7234ns
> I0916 23:01:10.191476 21026 leveldb.cpp:273] Iterated through 1 keys in
> the db in 8102ns
> I0916 23:01:10.191493 21026 replica.cpp:741] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0916 23:01:10.191894 21049 replica.cpp:474] Replica received implicit
> promise request with proposal 1
> I0916 23:01:10.191937 21044 replica.cpp:474] Replica received implicit
> promise request with proposal 1
> I0916 23:01:10.192438 21049 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 517437ns
> I0916 23:01:10.192461 21049 replica.cpp:342] Persisted promised to 1
> I0916 23:01:10.192517 21044 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 555333ns
> I0916 23:01:10.192543 21044 replica.cpp:342] Persisted promised to 1
> I0916 23:01:10.193327 21055 coordinator.cpp:230] Coordinator attemping to
> fill missing position
> I0916 23:01:10.194192 21044 replica.cpp:375] Replica received explicit
> promise request for position 0 with proposal 2
> I0916 23:01:10.194272 21049 replica.cpp:375] Replica received explicit
> promise request for position 0 with proposal 2
> I0916 23:01:10.195019 21049 leveldb.cpp:343] Persisting action (8 bytes)
> to leveldb took 721630ns
> I0916 23:01:10.195019 21044 leveldb.cpp:343] Persisting action (8 bytes)
> to leveldb took 799669ns
> I0916 23:01:10.195044 21049 replica.cpp:676] Persisted action at 0
> I0916 23:01:10.195061 21044 replica.cpp:676] Persisted action at 0
> I0916 23:01:10.195617 21053 replica.cpp:508] Replica received write
> request for position 0
> I0916 23:01:10.195672 21053 leveldb.cpp:438] Reading position from leveldb
> took 13897ns
> I0916 23:01:10.195801 21051 replica.cpp:508] Replica received write
> request for position 0
> I0916 23:01:10.195837 21051 leveldb.cpp:438] Reading position from leveldb
> took 12352ns
> I0916 23:01:10.195870 21053 leveldb.cpp:343] Persisting action (14 bytes)
> to leveldb took 177322ns
> I0916 23:01:10.195894 21053 replica.cpp:676] Persisted action at 0
> I0916 23:01:10.196024 21051 leveldb.cpp:343] Persisting action (14 bytes)
> to leveldb took 161185ns
> I0916 23:01:10.196045 21051 replica.cpp:676] Persisted action at 0
> I0916 23:01:10.196480 21043 replica.cpp:655] Replica received learned
> notice for position 0
> I0916 23:01:10.196480 21046 replica.cpp:655] Replica received learned
> notice for position 0
> I0916 23:01:10.196704 21046 leveldb.cpp:343] Persisting action (16 bytes)
> to leveldb took 173626ns
> I0916 23:01:10.196750 21046 replica.cpp:676] Persisted action at 0
> I0916 23:01:10.196754 21043 leveldb.cpp:343] Persisting action (16 bytes)
> to leveldb took 237051ns
> I0916 23:01:10.196761 21046 replica.cpp:661] Replica learned NOP action at
> position 0
> I0916 23:01:10.196777 21043 replica.cpp:676] Persisted action at 0
> I0916 23:01:10.196789 21043 replica.cpp:661] Replica learned NOP action at
> position 0
> [ OK ] CoordinatorTest.ElectWithClockPaused (4803 ms)
> [ RUN ] CoordinatorTest.FillInconsistent
> Using temporary directory '/tmp/CoordinatorTest_FillInconsistent_ZKE6XE'
> [ OK ] CoordinatorTest.FillInconsistent (0 ms)
> [----------] 21 tests from CoordinatorTest (19050 ms total)
>
> [----------] 4 tests from ReplicaTest
> [ RUN ] ReplicaTest.Promise
> Using temporary directory '/tmp/ReplicaTest_Promise_NBZUIu'
> I0916 23:01:10.205260 21026 leveldb.cpp:176] Opened db in 2.150092ms
> I0916 23:01:10.205966 21026 leveldb.cpp:183] Compacted db in 677731ns
> I0916 23:01:10.205986 21026 leveldb.cpp:198] Created db iterator in 2735ns
> I0916 23:01:10.205996 21026 leveldb.cpp:204] Seeked to beginning of db in
> 472ns
> I0916 23:01:10.206006 21026 leveldb.cpp:273] Iterated through 0 keys in
> the db in 198ns
> I0916 23:01:10.206019 21026 replica.cpp:741] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0916 23:01:10.206781 21054 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 583987ns
> I0916 23:01:10.206801 21054 replica.cpp:320] Persisted replica status to
> VOTING
> I0916 23:01:10.209231 21026 leveldb.cpp:176] Opened db in 2.210186ms
> I0916 23:01:10.211395 21026 leveldb.cpp:183] Compacted db in 2.13344ms
> I0916 23:01:10.211428 21026 leveldb.cpp:198] Created db iterator in 4390ns
> I0916 23:01:10.211451 21026 leveldb.cpp:204] Seeked to beginning of db in
> 7710ns
> I0916 23:01:10.211470 21026 leveldb.cpp:273] Iterated through 1 keys in
> the db in 8295ns
> I0916 23:01:10.211487 21026 replica.cpp:741] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0916 23:01:10.211709 21054 replica.cpp:474] Replica received implicit
> promise request with proposal 2
> I0916 23:01:10.212260 21054 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 526905ns
> I0916 23:01:10.212280 21054 replica.cpp:342] Persisted promised to 2
> I0916 23:01:10.212738 21046 replica.cpp:474] Replica received implicit
> promise request with proposal 1
> I0916 23:01:10.212757 21046 replica.cpp:479] Replica denying promise
> request with proposal 1
> I0916 23:01:10.213058 21047 replica.cpp:474] Replica received implicit
> promise request with proposal 3
> I0916 23:01:10.213518 21047 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 433010ns
> I0916 23:01:10.213537 21047 replica.cpp:342] Persisted promised to 3
> [ OK ] ReplicaTest.Promise (12 ms)
> [ RUN ] ReplicaTest.Restore
> Using temporary directory '/tmp/ReplicaTest_Restore_Hpbyvk'
> I0916 23:01:10.216367 21026 leveldb.cpp:176] Opened db in 2.043673ms
> I0916 23:01:10.216773 21026 leveldb.cpp:183] Compacted db in 379902ns
> I0916 23:01:10.216794 21026 leveldb.cpp:198] Created db iterator in 2885ns
> I0916 23:01:10.216804 21026 leveldb.cpp:204] Seeked to beginning of db in
> 500ns
> I0916 23:01:10.216814 21026 leveldb.cpp:273] Iterated through 0 keys in
> the db in 200ns
> I0916 23:01:10.216828 21026 replica.cpp:741] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0916 23:01:10.217572 21051 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 469143ns
> I0916 23:01:10.217592 21051 replica.cpp:320] Persisted replica status to
> VOTING
> I0916 23:01:10.219882 21026 leveldb.cpp:176] Opened db in 1.930543ms
> I0916 23:01:10.221320 21026 leveldb.cpp:183] Compacted db in 1.410263ms
> I0916 23:01:10.221349 21026 leveldb.cpp:198] Created db iterator in 3975ns
> I0916 23:01:10.221366 21026 leveldb.cpp:204] Seeked to beginning of db in
> 7110ns
> I0916 23:01:10.221385 21026 leveldb.cpp:273] Iterated through 1 keys in
> the db in 8097ns
> I0916 23:01:10.221401 21026 replica.cpp:741] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0916 23:01:10.221575 21049 replica.cpp:474] Replica received implicit
> promise request with proposal 1
> I0916 23:01:10.222064 21049 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 460628ns
> I0916 23:01:10.222082 21049 replica.cpp:342] Persisted promised to 1
> I0916 23:01:10.222256 21051 replica.cpp:508] Replica received write
> request for position 1
> I0916 23:01:10.222446 21051 leveldb.cpp:343] Persisting action (27 bytes)
> to leveldb took 160079ns
> I0916 23:01:10.222465 21051 replica.cpp:676] Persisted action at 1
> I0916 23:01:10.222645 21046 leveldb.cpp:438] Reading position from leveldb
> took 21315ns
> I0916 23:01:10.224990 21026 leveldb.cpp:176] Opened db in 2.097744ms
> I0916 23:01:10.226565 21026 leveldb.cpp:183] Compacted db in 1.548383ms
> I0916 23:01:10.226593 21026 leveldb.cpp:198] Created db iterator in 4283ns
> I0916 23:01:10.226610 21026 leveldb.cpp:204] Seeked to beginning of db in
> 7267ns
> I0916 23:01:10.226636 21026 leveldb.cpp:273] Iterated through 2 keys in
> the db in 14932ns
> I0916 23:01:10.226655 21026 replica.cpp:741] Replica recovered with log
> positions 0 -> 1 with 1 holes and 1 unlearned
> I0916 23:01:10.226730 21047 leveldb.cpp:438] Reading position from leveldb
> took 29797ns
> [ OK ] ReplicaTest.Restore (13 ms)
> [ RUN ] ReplicaTest.NonVoting
> Using temporary directory '/tmp/ReplicaTest_NonVoting_vDwNJa'
> I0916 23:01:10.386850 21026 leveldb.cpp:176] Opened db in 2.50423ms
> I0916 23:01:10.387466 21026 leveldb.cpp:183] Compacted db in 587774ns
> I0916 23:01:10.387492 21026 leveldb.cpp:198] Created db iterator in 3455ns
> I0916 23:01:10.387508 21026 leveldb.cpp:204] Seeked to beginning of db in
> 540ns
> I0916 23:01:10.387518 21026 leveldb.cpp:273] Iterated through 0 keys in
> the db in 210ns
> I0916 23:01:10.387533 21026 replica.cpp:741] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0916 23:01:10.387671 21047 replica.cpp:369] Replica ignoring promise
> request as it is in EMPTY status
> I0916 23:01:10.397832 21053 replica.cpp:503] Replica ignoring write
> request as it is in EMPTY status
> [ OK ] ReplicaTest.NonVoting (24 ms)
> [ RUN ] ReplicaTest.Append
> Using temporary directory '/tmp/ReplicaTest_Append_PfpX10'
> I0916 23:01:10.410902 21026 leveldb.cpp:176] Opened db in 2.480258ms
> I0916 23:01:10.411463 21026 leveldb.cpp:183] Compacted db in 531801ns
> I0916 23:01:10.411485 21026 leveldb.cpp:198] Created db iterator in 3215ns
> I0916 23:01:10.411501 21026 leveldb.cpp:204] Seeked to beginning of db in
> 550ns
> I0916 23:01:10.411512 21026 leveldb.cpp:273] Iterated through 0 keys in
> the db in 188ns
> I0916 23:01:10.411528 21026 replica.cpp:741] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0916 23:01:10.412348 21050 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 632675ns
> I0916 23:01:10.412370 21050 replica.cpp:320] Persisted replica status to
> VOTING
> I0916 23:01:10.415046 21026 leveldb.cpp:176] Opened db in 2.365599ms
> I0916 23:01:10.416496 21026 leveldb.cpp:183] Compacted db in 1.42057ms
> I0916 23:01:10.416522 21026 leveldb.cpp:198] Created db iterator in 4235ns
> I0916 23:01:10.416542 21026 leveldb.cpp:204] Seeked to beginning of db in
> 7197ns
> I0916 23:01:10.416559 21026 leveldb.cpp:273] Iterated through 1 keys in
> the db in 8095ns
> I0916 23:01:10.416576 21026 replica.cpp:741] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0916 23:01:10.416733 21048 replica.cpp:474] Replica received implicit
> promise request with proposal 1
> I0916 23:01:10.417361 21048 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 599444ns
> I0916 23:01:10.417383 21048 replica.cpp:342] Persisted promised to 1
> I0916 23:01:10.417697 21044 replica.cpp:508] Replica received write
> request for position 1
> I0916 23:01:10.417881 21044 leveldb.cpp:343] Persisting action (27 bytes)
> to leveldb took 157842ns
> I0916 23:01:10.417899 21044 replica.cpp:676] Persisted action at 1
> I0916 23:01:10.418081 21044 leveldb.cpp:438] Reading position from leveldb
> took 21617ns
> [ OK ] ReplicaTest.Append (11 ms)
> [----------] 4 tests from ReplicaTest (217 ms total)
>
> [----------] Global test environment tear-down
> [==========] 365 tests from 59 test cases ran. (379816 ms total)
> [ PASSED ] 363 tests.
> [ FAILED ] 2 tests, listed below:
> [ FAILED ] HealthCheckTest.HealthStatusChange
> [ FAILED ] Strict/RegistrarTest.remove/1, where GetParam() = true
>
> 2 FAILED TESTS
> YOU HAVE 5 DISABLED TESTS
>
> make[3]: *** [check-local] Error 1
> make[3]: Leaving directory `<
> https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src
> '>
> make[2]: *** [check-am] Error 2
> make[2]: Leaving directory `<
> https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src
> '>
> make[1]: *** [check] Error 2
> make[1]: Leaving directory `<
> https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src
> '>
> make: *** [check-recursive] Error 1
> Test finished
> Exit status: 2
> Build step 'Execute shell' marked build as failure
>
Build failed in Jenkins:
Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui
#2374
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/2374/changes>
Changes:
[bmahler] Added a Version class to stout.
------------------------------------------
[...truncated 58686 lines...]
I0916 23:01:05.386067 21051 replica.cpp:676] Persisted action at 0
I0916 23:01:05.386090 21051 replica.cpp:661] Replica learned NOP action at position 0
I0916 23:01:05.083233 21042 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 121548ns
I0916 23:01:05.386147 21042 replica.cpp:676] Persisted action at 0
I0916 23:01:05.386168 21042 replica.cpp:661] Replica learned NOP action at position 0
I0916 23:01:05.386436 21040 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
I0916 23:01:05.386842 21048 replica.cpp:508] Replica received write request for position 1
I0916 23:01:05.386904 21040 replica.cpp:508] Replica received write request for position 1
I0916 23:01:05.387473 21048 leveldb.cpp:343] Persisting action (27 bytes) to leveldb took 603894ns
I0916 23:01:05.387475 21040 leveldb.cpp:343] Persisting action (27 bytes) to leveldb took 538731ns
I0916 23:01:05.387511 21048 replica.cpp:676] Persisted action at 1
I0916 23:01:05.387524 21040 replica.cpp:676] Persisted action at 1
I0916 23:01:05.387969 21043 replica.cpp:655] Replica received learned notice for position 1
I0916 23:01:05.387998 21053 replica.cpp:655] Replica received learned notice for position 1
I0916 23:01:05.388157 21043 leveldb.cpp:343] Persisting action (29 bytes) to leveldb took 165034ns
I0916 23:01:05.388177 21043 replica.cpp:676] Persisted action at 1
I0916 23:01:05.388188 21043 replica.cpp:661] Replica learned APPEND action at position 1
I0916 23:01:05.388212 21053 leveldb.cpp:343] Persisting action (29 bytes) to leveldb took 190343ns
I0916 23:01:05.388236 21053 replica.cpp:676] Persisted action at 1
I0916 23:01:05.388245 21053 replica.cpp:661] Replica learned APPEND action at position 1
I0916 23:01:05.390319 21026 leveldb.cpp:176] Opened db in 1.951015ms
I0916 23:01:05.391607 21026 leveldb.cpp:183] Compacted db in 1.261904ms
I0916 23:01:05.391633 21026 leveldb.cpp:198] Created db iterator in 4244ns
I0916 23:01:05.391650 21026 leveldb.cpp:204] Seeked to beginning of db in 7069ns
I0916 23:01:05.391669 21026 leveldb.cpp:273] Iterated through 1 keys in the db in 8220ns
I0916 23:01:05.391685 21026 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0916 23:01:05.392328 21047 replica.cpp:474] Replica received implicit promise request with proposal 1
I0916 23:01:05.392354 21047 replica.cpp:479] Replica denying promise request with proposal 1
I0916 23:01:05.392408 21043 replica.cpp:474] Replica received implicit promise request with proposal 1
I0916 23:01:05.392943 21043 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 510019ns
I0916 23:01:05.392963 21043 replica.cpp:342] Persisted promised to 1
I0916 23:01:05.393698 21055 replica.cpp:474] Replica received implicit promise request with proposal 2
I0916 23:01:05.393705 21045 replica.cpp:474] Replica received implicit promise request with proposal 2
I0916 23:01:05.394114 21045 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 380162ns
I0916 23:01:05.394114 21055 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 390574ns
I0916 23:01:05.394136 21045 replica.cpp:342] Persisted promised to 2
I0916 23:01:05.394152 21055 replica.cpp:342] Persisted promised to 2
I0916 23:01:05.394424 21053 coordinator.cpp:230] Coordinator attemping to fill missing position
I0916 23:01:05.395113 21046 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 3
I0916 23:01:05.395136 21055 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 3
I0916 23:01:05.395153 21046 leveldb.cpp:438] Reading position from leveldb took 16040ns
I0916 23:01:05.395339 21055 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 181686ns
I0916 23:01:05.395359 21055 replica.cpp:676] Persisted action at 0
I0916 23:01:05.395392 21046 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 215312ns
I0916 23:01:05.395414 21046 replica.cpp:676] Persisted action at 0
I0916 23:01:05.395781 21047 replica.cpp:655] Replica received learned notice for position 0
I0916 23:01:05.395792 21049 replica.cpp:655] Replica received learned notice for position 0
I0916 23:01:05.395972 21047 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 163947ns
I0916 23:01:05.395992 21047 replica.cpp:676] Persisted action at 0
I0916 23:01:05.396003 21047 replica.cpp:661] Replica learned NOP action at position 0
I0916 23:01:05.396059 21049 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 198163ns
I0916 23:01:05.396105 21049 replica.cpp:676] Persisted action at 0
I0916 23:01:05.396118 21049 replica.cpp:661] Replica learned NOP action at position 0
I0916 23:01:05.396561 21053 replica.cpp:375] Replica received explicit promise request for position 1 with proposal 3
I0916 23:01:05.396602 21053 leveldb.cpp:438] Reading position from leveldb took 17412ns
I0916 23:01:05.396661 21048 replica.cpp:375] Replica received explicit promise request for position 1 with proposal 3
I0916 23:01:05.396785 21053 leveldb.cpp:343] Persisting action (29 bytes) to leveldb took 158375ns
I0916 23:01:05.396806 21053 replica.cpp:676] Persisted action at 1
I0916 23:01:05.396877 21048 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 189711ns
I0916 23:01:05.396903 21048 replica.cpp:676] Persisted action at 1
I0916 23:01:05.397061 21049 replica.cpp:655] Replica received learned notice for position 1
I0916 23:01:05.397063 21042 replica.cpp:655] Replica received learned notice for position 1
I0916 23:01:05.397454 21042 leveldb.cpp:343] Persisting action (29 bytes) to leveldb took 353980ns
I0916 23:01:05.397455 21049 leveldb.cpp:343] Persisting action (29 bytes) to leveldb took 366829ns
I0916 23:01:05.397477 21042 replica.cpp:676] Persisted action at 1
I0916 23:01:05.397488 21042 replica.cpp:661] Replica learned APPEND action at position 1
I0916 23:01:05.397490 21049 replica.cpp:676] Persisted action at 1
I0916 23:01:05.397511 21049 replica.cpp:661] Replica learned APPEND action at position 1
I0916 23:01:05.397948 21053 leveldb.cpp:438] Reading position from leveldb took 18632ns
[ OK ] CoordinatorTest.Fill (338 ms)
[ RUN ] CoordinatorTest.ElectWithClockPaused
Using temporary directory '/tmp/CoordinatorTest_ElectWithClockPaused_XPakdP'
I0916 23:01:05.401895 21026 leveldb.cpp:176] Opened db in 2.126108ms
I0916 23:01:05.402295 21026 leveldb.cpp:183] Compacted db in 372807ns
I0916 23:01:05.402319 21026 leveldb.cpp:198] Created db iterator in 3347ns
I0916 23:01:05.402335 21026 leveldb.cpp:204] Seeked to beginning of db in 575ns
I0916 23:01:05.402346 21026 leveldb.cpp:273] Iterated through 0 keys in the db in 210ns
I0916 23:01:05.402362 21026 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0916 23:01:05.403061 21041 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 439929ns
I0916 23:01:05.403081 21041 replica.cpp:320] Persisted replica status to VOTING
I0916 23:01:05.405195 21026 leveldb.cpp:176] Opened db in 1.857658ms
I0916 23:01:05.405761 21026 leveldb.cpp:183] Compacted db in 539011ns
I0916 23:01:05.405781 21026 leveldb.cpp:198] Created db iterator in 2735ns
I0916 23:01:05.405791 21026 leveldb.cpp:204] Seeked to beginning of db in 475ns
I0916 23:01:05.405799 21026 leveldb.cpp:273] Iterated through 0 keys in the db in 195ns
I0916 23:01:05.405814 21026 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0916 23:01:05.406510 21046 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 452694ns
I0916 23:01:05.406533 21046 replica.cpp:320] Persisted replica status to VOTING
I0916 23:01:05.408746 21026 leveldb.cpp:176] Opened db in 1.965229ms
I0916 23:01:05.410229 21026 leveldb.cpp:183] Compacted db in 1.454674ms
I0916 23:01:05.410260 21026 leveldb.cpp:198] Created db iterator in 4550ns
I0916 23:01:05.410284 21026 leveldb.cpp:204] Seeked to beginning of db in 7785ns
I0916 23:01:05.410303 21026 leveldb.cpp:273] Iterated through 1 keys in the db in 8398ns
I0916 23:01:05.410320 21026 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0916 23:01:10.189376 21026 leveldb.cpp:176] Opened db in 2.600519ms
I0916 23:01:10.191403 21026 leveldb.cpp:183] Compacted db in 1.996275ms
I0916 23:01:10.191436 21026 leveldb.cpp:198] Created db iterator in 4378ns
I0916 23:01:10.191457 21026 leveldb.cpp:204] Seeked to beginning of db in 7234ns
I0916 23:01:10.191476 21026 leveldb.cpp:273] Iterated through 1 keys in the db in 8102ns
I0916 23:01:10.191493 21026 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0916 23:01:10.191894 21049 replica.cpp:474] Replica received implicit promise request with proposal 1
I0916 23:01:10.191937 21044 replica.cpp:474] Replica received implicit promise request with proposal 1
I0916 23:01:10.192438 21049 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 517437ns
I0916 23:01:10.192461 21049 replica.cpp:342] Persisted promised to 1
I0916 23:01:10.192517 21044 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 555333ns
I0916 23:01:10.192543 21044 replica.cpp:342] Persisted promised to 1
I0916 23:01:10.193327 21055 coordinator.cpp:230] Coordinator attemping to fill missing position
I0916 23:01:10.194192 21044 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
I0916 23:01:10.194272 21049 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
I0916 23:01:10.195019 21049 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 721630ns
I0916 23:01:10.195019 21044 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 799669ns
I0916 23:01:10.195044 21049 replica.cpp:676] Persisted action at 0
I0916 23:01:10.195061 21044 replica.cpp:676] Persisted action at 0
I0916 23:01:10.195617 21053 replica.cpp:508] Replica received write request for position 0
I0916 23:01:10.195672 21053 leveldb.cpp:438] Reading position from leveldb took 13897ns
I0916 23:01:10.195801 21051 replica.cpp:508] Replica received write request for position 0
I0916 23:01:10.195837 21051 leveldb.cpp:438] Reading position from leveldb took 12352ns
I0916 23:01:10.195870 21053 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 177322ns
I0916 23:01:10.195894 21053 replica.cpp:676] Persisted action at 0
I0916 23:01:10.196024 21051 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 161185ns
I0916 23:01:10.196045 21051 replica.cpp:676] Persisted action at 0
I0916 23:01:10.196480 21043 replica.cpp:655] Replica received learned notice for position 0
I0916 23:01:10.196480 21046 replica.cpp:655] Replica received learned notice for position 0
I0916 23:01:10.196704 21046 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 173626ns
I0916 23:01:10.196750 21046 replica.cpp:676] Persisted action at 0
I0916 23:01:10.196754 21043 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 237051ns
I0916 23:01:10.196761 21046 replica.cpp:661] Replica learned NOP action at position 0
I0916 23:01:10.196777 21043 replica.cpp:676] Persisted action at 0
I0916 23:01:10.196789 21043 replica.cpp:661] Replica learned NOP action at position 0
[ OK ] CoordinatorTest.ElectWithClockPaused (4803 ms)
[ RUN ] CoordinatorTest.FillInconsistent
Using temporary directory '/tmp/CoordinatorTest_FillInconsistent_ZKE6XE'
[ OK ] CoordinatorTest.FillInconsistent (0 ms)
[----------] 21 tests from CoordinatorTest (19050 ms total)
[----------] 4 tests from ReplicaTest
[ RUN ] ReplicaTest.Promise
Using temporary directory '/tmp/ReplicaTest_Promise_NBZUIu'
I0916 23:01:10.205260 21026 leveldb.cpp:176] Opened db in 2.150092ms
I0916 23:01:10.205966 21026 leveldb.cpp:183] Compacted db in 677731ns
I0916 23:01:10.205986 21026 leveldb.cpp:198] Created db iterator in 2735ns
I0916 23:01:10.205996 21026 leveldb.cpp:204] Seeked to beginning of db in 472ns
I0916 23:01:10.206006 21026 leveldb.cpp:273] Iterated through 0 keys in the db in 198ns
I0916 23:01:10.206019 21026 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0916 23:01:10.206781 21054 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 583987ns
I0916 23:01:10.206801 21054 replica.cpp:320] Persisted replica status to VOTING
I0916 23:01:10.209231 21026 leveldb.cpp:176] Opened db in 2.210186ms
I0916 23:01:10.211395 21026 leveldb.cpp:183] Compacted db in 2.13344ms
I0916 23:01:10.211428 21026 leveldb.cpp:198] Created db iterator in 4390ns
I0916 23:01:10.211451 21026 leveldb.cpp:204] Seeked to beginning of db in 7710ns
I0916 23:01:10.211470 21026 leveldb.cpp:273] Iterated through 1 keys in the db in 8295ns
I0916 23:01:10.211487 21026 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0916 23:01:10.211709 21054 replica.cpp:474] Replica received implicit promise request with proposal 2
I0916 23:01:10.212260 21054 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 526905ns
I0916 23:01:10.212280 21054 replica.cpp:342] Persisted promised to 2
I0916 23:01:10.212738 21046 replica.cpp:474] Replica received implicit promise request with proposal 1
I0916 23:01:10.212757 21046 replica.cpp:479] Replica denying promise request with proposal 1
I0916 23:01:10.213058 21047 replica.cpp:474] Replica received implicit promise request with proposal 3
I0916 23:01:10.213518 21047 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 433010ns
I0916 23:01:10.213537 21047 replica.cpp:342] Persisted promised to 3
[ OK ] ReplicaTest.Promise (12 ms)
[ RUN ] ReplicaTest.Restore
Using temporary directory '/tmp/ReplicaTest_Restore_Hpbyvk'
I0916 23:01:10.216367 21026 leveldb.cpp:176] Opened db in 2.043673ms
I0916 23:01:10.216773 21026 leveldb.cpp:183] Compacted db in 379902ns
I0916 23:01:10.216794 21026 leveldb.cpp:198] Created db iterator in 2885ns
I0916 23:01:10.216804 21026 leveldb.cpp:204] Seeked to beginning of db in 500ns
I0916 23:01:10.216814 21026 leveldb.cpp:273] Iterated through 0 keys in the db in 200ns
I0916 23:01:10.216828 21026 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0916 23:01:10.217572 21051 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 469143ns
I0916 23:01:10.217592 21051 replica.cpp:320] Persisted replica status to VOTING
I0916 23:01:10.219882 21026 leveldb.cpp:176] Opened db in 1.930543ms
I0916 23:01:10.221320 21026 leveldb.cpp:183] Compacted db in 1.410263ms
I0916 23:01:10.221349 21026 leveldb.cpp:198] Created db iterator in 3975ns
I0916 23:01:10.221366 21026 leveldb.cpp:204] Seeked to beginning of db in 7110ns
I0916 23:01:10.221385 21026 leveldb.cpp:273] Iterated through 1 keys in the db in 8097ns
I0916 23:01:10.221401 21026 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0916 23:01:10.221575 21049 replica.cpp:474] Replica received implicit promise request with proposal 1
I0916 23:01:10.222064 21049 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 460628ns
I0916 23:01:10.222082 21049 replica.cpp:342] Persisted promised to 1
I0916 23:01:10.222256 21051 replica.cpp:508] Replica received write request for position 1
I0916 23:01:10.222446 21051 leveldb.cpp:343] Persisting action (27 bytes) to leveldb took 160079ns
I0916 23:01:10.222465 21051 replica.cpp:676] Persisted action at 1
I0916 23:01:10.222645 21046 leveldb.cpp:438] Reading position from leveldb took 21315ns
I0916 23:01:10.224990 21026 leveldb.cpp:176] Opened db in 2.097744ms
I0916 23:01:10.226565 21026 leveldb.cpp:183] Compacted db in 1.548383ms
I0916 23:01:10.226593 21026 leveldb.cpp:198] Created db iterator in 4283ns
I0916 23:01:10.226610 21026 leveldb.cpp:204] Seeked to beginning of db in 7267ns
I0916 23:01:10.226636 21026 leveldb.cpp:273] Iterated through 2 keys in the db in 14932ns
I0916 23:01:10.226655 21026 replica.cpp:741] Replica recovered with log positions 0 -> 1 with 1 holes and 1 unlearned
I0916 23:01:10.226730 21047 leveldb.cpp:438] Reading position from leveldb took 29797ns
[ OK ] ReplicaTest.Restore (13 ms)
[ RUN ] ReplicaTest.NonVoting
Using temporary directory '/tmp/ReplicaTest_NonVoting_vDwNJa'
I0916 23:01:10.386850 21026 leveldb.cpp:176] Opened db in 2.50423ms
I0916 23:01:10.387466 21026 leveldb.cpp:183] Compacted db in 587774ns
I0916 23:01:10.387492 21026 leveldb.cpp:198] Created db iterator in 3455ns
I0916 23:01:10.387508 21026 leveldb.cpp:204] Seeked to beginning of db in 540ns
I0916 23:01:10.387518 21026 leveldb.cpp:273] Iterated through 0 keys in the db in 210ns
I0916 23:01:10.387533 21026 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0916 23:01:10.387671 21047 replica.cpp:369] Replica ignoring promise request as it is in EMPTY status
I0916 23:01:10.397832 21053 replica.cpp:503] Replica ignoring write request as it is in EMPTY status
[ OK ] ReplicaTest.NonVoting (24 ms)
[ RUN ] ReplicaTest.Append
Using temporary directory '/tmp/ReplicaTest_Append_PfpX10'
I0916 23:01:10.410902 21026 leveldb.cpp:176] Opened db in 2.480258ms
I0916 23:01:10.411463 21026 leveldb.cpp:183] Compacted db in 531801ns
I0916 23:01:10.411485 21026 leveldb.cpp:198] Created db iterator in 3215ns
I0916 23:01:10.411501 21026 leveldb.cpp:204] Seeked to beginning of db in 550ns
I0916 23:01:10.411512 21026 leveldb.cpp:273] Iterated through 0 keys in the db in 188ns
I0916 23:01:10.411528 21026 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0916 23:01:10.412348 21050 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 632675ns
I0916 23:01:10.412370 21050 replica.cpp:320] Persisted replica status to VOTING
I0916 23:01:10.415046 21026 leveldb.cpp:176] Opened db in 2.365599ms
I0916 23:01:10.416496 21026 leveldb.cpp:183] Compacted db in 1.42057ms
I0916 23:01:10.416522 21026 leveldb.cpp:198] Created db iterator in 4235ns
I0916 23:01:10.416542 21026 leveldb.cpp:204] Seeked to beginning of db in 7197ns
I0916 23:01:10.416559 21026 leveldb.cpp:273] Iterated through 1 keys in the db in 8095ns
I0916 23:01:10.416576 21026 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0916 23:01:10.416733 21048 replica.cpp:474] Replica received implicit promise request with proposal 1
I0916 23:01:10.417361 21048 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 599444ns
I0916 23:01:10.417383 21048 replica.cpp:342] Persisted promised to 1
I0916 23:01:10.417697 21044 replica.cpp:508] Replica received write request for position 1
I0916 23:01:10.417881 21044 leveldb.cpp:343] Persisting action (27 bytes) to leveldb took 157842ns
I0916 23:01:10.417899 21044 replica.cpp:676] Persisted action at 1
I0916 23:01:10.418081 21044 leveldb.cpp:438] Reading position from leveldb took 21617ns
[ OK ] ReplicaTest.Append (11 ms)
[----------] 4 tests from ReplicaTest (217 ms total)
[----------] Global test environment tear-down
[==========] 365 tests from 59 test cases ran. (379816 ms total)
[ PASSED ] 363 tests.
[ FAILED ] 2 tests, listed below:
[ FAILED ] HealthCheckTest.HealthStatusChange
[ FAILED ] Strict/RegistrarTest.remove/1, where GetParam() = true
2 FAILED TESTS
YOU HAVE 5 DISABLED TESTS
make[3]: *** [check-local] Error 1
make[3]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src'>
make[2]: *** [check-am] Error 2
make[2]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src'>
make[1]: *** [check] Error 2
make[1]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src'>
make: *** [check-recursive] Error 1
Test finished
Exit status: 2
Build step 'Execute shell' marked build as failure