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/11/08 04:29:13 UTC
Build failed in Jenkins:
Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME #2260
See <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/2260/changes>
Changes:
[toenshoff] Fixed invalid characters in external-containerizer.md
------------------------------------------
[...truncated 70585 lines...]
I1108 03:28:04.612184 14715 authenticator.hpp:166] Creating new server SASL connection
I1108 03:28:04.612319 14716 authenticatee.hpp:224] Received SASL authentication mechanisms: CRAM-MD5
I1108 03:28:04.612354 14716 authenticatee.hpp:250] Attempting to authenticate with mechanism 'CRAM-MD5'
I1108 03:28:04.612452 14706 authenticator.hpp:272] Received SASL authentication start
I1108 03:28:04.612504 14706 authenticator.hpp:394] Authentication requires more steps
I1108 03:28:04.612607 14703 authenticatee.hpp:270] Received SASL authentication step
I1108 03:28:04.612716 14703 authenticator.hpp:300] Received SASL authentication step
I1108 03:28:04.612743 14703 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'proserpina.apache.org' server FQDN: 'proserpina.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1108 03:28:04.612756 14703 auxprop.cpp:171] Looking up auxiliary property '*userPassword'
I1108 03:28:04.612787 14703 auxprop.cpp:171] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1108 03:28:04.612823 14703 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'proserpina.apache.org' server FQDN: 'proserpina.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1108 03:28:04.612839 14703 auxprop.cpp:121] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1108 03:28:04.612848 14703 auxprop.cpp:121] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1108 03:28:04.612865 14703 authenticator.hpp:386] Authentication success
I1108 03:28:04.612946 14708 authenticatee.hpp:310] Authentication success
I1108 03:28:04.612999 14710 master.cpp:3959] Successfully authenticated principal 'test-principal' at scheduler-7f1eab90-172c-4243-8ec9-d80a3f1f58e1@67.195.81.189:38590
I1108 03:28:04.613225 14705 sched.cpp:369] Successfully authenticated with master master@67.195.81.189:38590
I1108 03:28:04.613253 14705 sched.cpp:488] Sending registration request to master@67.195.81.189:38590
I1108 03:28:04.613308 14705 sched.cpp:521] Will retry registration in 1.290447132secs if necessary
I1108 03:28:04.613411 14710 master.cpp:1383] Received registration request for framework 'default' at scheduler-7f1eab90-172c-4243-8ec9-d80a3f1f58e1@67.195.81.189:38590
I1108 03:28:04.613478 14710 master.cpp:1342] Authorizing framework principal 'test-principal' to receive offers for role '*'
I1108 03:28:04.613888 14708 master.cpp:1447] Registering framework 20141108-032804-3176252227-38590-14687-0000 (default) at scheduler-7f1eab90-172c-4243-8ec9-d80a3f1f58e1@67.195.81.189:38590
I1108 03:28:04.614245 14705 hierarchical_allocator_process.hpp:329] Added framework 20141108-032804-3176252227-38590-14687-0000
I1108 03:28:04.614275 14705 hierarchical_allocator_process.hpp:697] No resources available to allocate!
I1108 03:28:04.614294 14705 hierarchical_allocator_process.hpp:659] Performed allocation for 0 slaves in 21729ns
I1108 03:28:04.614405 14713 sched.cpp:419] Framework registered with 20141108-032804-3176252227-38590-14687-0000
I1108 03:28:04.614485 14713 sched.cpp:433] Scheduler::registered took 48041ns
I1108 03:28:04.615409 14687 containerizer.cpp:100] Using isolation: posix/cpu,posix/mem
I1108 03:28:04.619040 14714 slave.cpp:169] Slave started on 223)@67.195.81.189:38590
I1108 03:28:04.619107 14714 credentials.hpp:84] Loading credential for authentication from '/tmp/ReconciliationTest_SlaveInTransition_IQmHDb/credential'
I1108 03:28:04.619242 14714 slave.cpp:276] Slave using credential for: test-principal
I1108 03:28:04.619519 14714 slave.cpp:289] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I1108 03:28:04.665650 14714 slave.cpp:318] Slave hostname: proserpina.apache.org
I1108 03:28:04.665671 14714 slave.cpp:319] Slave checkpoint: true
I1108 03:28:04.666412 14705 state.cpp:33] Recovering state from '/tmp/ReconciliationTest_SlaveInTransition_IQmHDb/meta'
I1108 03:28:04.667301 14707 status_update_manager.cpp:197] Recovering status update manager
I1108 03:28:04.667692 14713 containerizer.cpp:281] Recovering containerizer
I1108 03:28:04.668696 14713 slave.cpp:3464] Finished recovery
I1108 03:28:04.669278 14704 status_update_manager.cpp:171] Pausing sending status updates
I1108 03:28:04.669282 14709 slave.cpp:602] New master detected at master@67.195.81.189:38590
I1108 03:28:04.669328 14709 slave.cpp:665] Authenticating with master master@67.195.81.189:38590
I1108 03:28:04.669483 14709 slave.cpp:638] Detecting new master
I1108 03:28:04.669536 14708 authenticatee.hpp:133] Creating new client SASL connection
I1108 03:28:04.669725 14712 master.cpp:3901] Authenticating slave(223)@67.195.81.189:38590
I1108 03:28:04.669764 14712 master.cpp:3912] Using default CRAM-MD5 authenticator
I1108 03:28:04.669950 14714 authenticator.hpp:166] Creating new server SASL connection
I1108 03:28:04.670166 14716 authenticatee.hpp:224] Received SASL authentication mechanisms: CRAM-MD5
I1108 03:28:04.670192 14716 authenticatee.hpp:250] Attempting to authenticate with mechanism 'CRAM-MD5'
I1108 03:28:04.670284 14714 authenticator.hpp:272] Received SASL authentication start
I1108 03:28:04.670333 14714 authenticator.hpp:394] Authentication requires more steps
I1108 03:28:04.670430 14712 authenticatee.hpp:270] Received SASL authentication step
I1108 03:28:04.670558 14702 authenticator.hpp:300] Received SASL authentication step
I1108 03:28:04.670593 14702 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'proserpina.apache.org' server FQDN: 'proserpina.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1108 03:28:04.670605 14702 auxprop.cpp:171] Looking up auxiliary property '*userPassword'
I1108 03:28:04.670636 14702 auxprop.cpp:171] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1108 03:28:04.670660 14702 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'proserpina.apache.org' server FQDN: 'proserpina.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1108 03:28:04.670672 14702 auxprop.cpp:121] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1108 03:28:04.670680 14702 auxprop.cpp:121] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1108 03:28:04.670697 14702 authenticator.hpp:386] Authentication success
I1108 03:28:04.670790 14713 authenticatee.hpp:310] Authentication success
I1108 03:28:04.670843 14707 master.cpp:3959] Successfully authenticated principal 'test-principal' at slave(223)@67.195.81.189:38590
I1108 03:28:04.671128 14705 slave.cpp:722] Successfully authenticated with master master@67.195.81.189:38590
I1108 03:28:04.671257 14705 slave.cpp:1050] Will retry registration in 5.159226ms if necessary
I1108 03:28:04.671391 14714 master.cpp:3246] Re-registering slave 20141108-032804-3176252227-38590-14687-S0 at slave(223)@67.195.81.189:38590 (proserpina.apache.org)
I1108 03:28:04.671845 14713 registrar.cpp:445] Applied 1 operations in 53551ns; attempting to update the 'registry'
I1108 03:28:04.674818 14703 log.cpp:680] Attempting to append 324 bytes to the log
I1108 03:28:04.674973 14704 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 7
I1108 03:28:04.675817 14716 replica.cpp:508] Replica received write request for position 7
I1108 03:28:04.676594 14716 leveldb.cpp:343] Persisting action (343 bytes) to leveldb took 745770ns
I1108 03:28:04.676621 14716 replica.cpp:676] Persisted action at 7
I1108 03:28:04.677245 14703 replica.cpp:655] Replica received learned notice for position 7
I1108 03:28:04.677448 14706 slave.cpp:1050] Will retry registration in 37.211951ms if necessary
I1108 03:28:04.677659 14709 master.cpp:3239] Ignoring re-register slave message from slave 20141108-032804-3176252227-38590-14687-S0 at slave(223)@67.195.81.189:38590 (proserpina.apache.org) as readmission is already in progress
I1108 03:28:04.677911 14703 leveldb.cpp:343] Persisting action (345 bytes) to leveldb took 632012ns
I1108 03:28:04.677943 14703 replica.cpp:676] Persisted action at 7
I1108 03:28:04.677969 14703 replica.cpp:661] Replica learned APPEND action at position 7
I1108 03:28:04.679134 14710 registrar.cpp:490] Successfully updated the 'registry' in 7.234816ms
I1108 03:28:04.679541 14713 log.cpp:699] Attempting to truncate the log to 7
I1108 03:28:04.679710 14711 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 8
I1108 03:28:04.680584 14706 replica.cpp:508] Replica received write request for position 8
I1108 03:28:04.681125 14706 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 504104ns
I1108 03:28:04.681152 14706 replica.cpp:676] Persisted action at 8
I1108 03:28:04.681807 14704 replica.cpp:655] Replica received learned notice for position 8
I1108 03:28:04.682245 14704 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 406963ns
I1108 03:28:04.682307 14704 leveldb.cpp:401] Deleting ~2 keys from leveldb took 33751ns
I1108 03:28:04.682327 14704 replica.cpp:676] Persisted action at 8
I1108 03:28:04.682349 14704 replica.cpp:661] Replica learned TRUNCATE action at position 8
I1108 03:28:04.682797 14704 master.cpp:3611] Performing explicit task state reconciliation for 1 tasks of framework 20141108-032804-3176252227-38590-14687-0000 (default) at scheduler-7f1eab90-172c-4243-8ec9-d80a3f1f58e1@67.195.81.189:38590
I1108 03:28:04.682899 14704 master.cpp:3673] Ignoring reconciliation request of task becfe965-0a66-4e98-b830-df953843db3c from framework 20141108-032804-3176252227-38590-14687-0000 (default) at scheduler-7f1eab90-172c-4243-8ec9-d80a3f1f58e1@67.195.81.189:38590 because there are transitional slaves
I1108 03:28:04.702714 14687 master.cpp:698] Master terminating
I1108 03:28:04.702744 14710 sched.cpp:779] Stopping framework '20141108-032804-3176252227-38590-14687-0000'
I1108 03:28:04.703184 14716 slave.cpp:2621] master@67.195.81.189:38590 exited
W1108 03:28:04.703214 14716 slave.cpp:2624] Master disconnected! Waiting for a new master to be elected
I1108 03:28:04.717378 14712 slave.cpp:484] Slave terminating
[ OK ] ReconciliationTest.SlaveInTransition (324 ms)
[ RUN ] ReconciliationTest.UnknownSlave
Using temporary directory '/tmp/ReconciliationTest_UnknownSlave_XsKgrd'
I1108 03:28:04.725107 14687 leveldb.cpp:176] Opened db in 2.940181ms
I1108 03:28:04.726068 14687 leveldb.cpp:183] Compacted db in 910163ns
I1108 03:28:04.726109 14687 leveldb.cpp:198] Created db iterator in 4640ns
I1108 03:28:04.726125 14687 leveldb.cpp:204] Seeked to beginning of db in 758ns
I1108 03:28:04.726136 14687 leveldb.cpp:273] Iterated through 0 keys in the db in 308ns
I1108 03:28:04.726166 14687 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I1108 03:28:04.726651 14713 recover.cpp:437] Starting replica recovery
I1108 03:28:04.726935 14713 recover.cpp:463] Replica is in EMPTY status
I1108 03:28:04.728601 14714 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request
I1108 03:28:04.728801 14714 recover.cpp:188] Received a recover response from a replica in EMPTY status
I1108 03:28:04.729280 14712 recover.cpp:554] Updating replica status to STARTING
I1108 03:28:04.730201 14706 master.cpp:318] Master 20141108-032804-3176252227-38590-14687 (proserpina.apache.org) started on 67.195.81.189:38590
I1108 03:28:04.730222 14704 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 812253ns
I1108 03:28:04.730253 14706 master.cpp:364] Master only allowing authenticated frameworks to register
I1108 03:28:04.730254 14704 replica.cpp:320] Persisted replica status to STARTING
I1108 03:28:04.730274 14706 master.cpp:369] Master only allowing authenticated slaves to register
I1108 03:28:04.824995 14706 credentials.hpp:36] Loading credentials for authentication from '/tmp/ReconciliationTest_UnknownSlave_XsKgrd/credentials'
I1108 03:28:04.825242 14707 recover.cpp:463] Replica is in STARTING status
I1108 03:28:04.825345 14706 master.cpp:413] Authorization enabled
I1108 03:28:04.825774 14712 master.cpp:126] No whitelist given. Advertising offers for all slaves
I1108 03:28:04.825865 14707 hierarchical_allocator_process.hpp:299] Initializing hierarchical allocator process with master : master@67.195.81.189:38590
I1108 03:28:04.826510 14715 replica.cpp:638] Replica in STARTING status received a broadcasted recover request
I1108 03:28:04.827030 14710 recover.cpp:188] Received a recover response from a replica in STARTING status
I1108 03:28:04.827163 14706 master.cpp:1263] The newly elected leader is master@67.195.81.189:38590 with id 20141108-032804-3176252227-38590-14687
I1108 03:28:04.827193 14706 master.cpp:1276] Elected as the leading master!
I1108 03:28:04.827211 14706 master.cpp:1094] Recovering from registrar
I1108 03:28:04.827378 14714 registrar.cpp:313] Recovering registrar
I1108 03:28:04.827560 14703 recover.cpp:554] Updating replica status to VOTING
I1108 03:28:04.828222 14716 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 485864ns
I1108 03:28:04.828240 14716 replica.cpp:320] Persisted replica status to VOTING
I1108 03:28:04.828328 14703 recover.cpp:568] Successfully joined the Paxos group
I1108 03:28:04.828573 14703 recover.cpp:452] Recover process terminated
I1108 03:28:04.828977 14703 log.cpp:656] Attempting to start the writer
I1108 03:28:04.830471 14701 replica.cpp:474] Replica received implicit promise request with proposal 1
I1108 03:28:04.830960 14701 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 459006ns
I1108 03:28:04.830986 14701 replica.cpp:342] Persisted promised to 1
I1108 03:28:04.831598 14711 coordinator.cpp:230] Coordinator attemping to fill missing position
I1108 03:28:04.832975 14706 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
I1108 03:28:04.833443 14706 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 440523ns
I1108 03:28:04.833473 14706 replica.cpp:676] Persisted action at 0
I1108 03:28:04.834445 14714 replica.cpp:508] Replica received write request for position 0
I1108 03:28:04.834481 14714 leveldb.cpp:438] Reading position from leveldb took 16091ns
I1108 03:28:04.834970 14714 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 464371ns
I1108 03:28:04.834990 14714 replica.cpp:676] Persisted action at 0
I1108 03:28:04.835474 14716 replica.cpp:655] Replica received learned notice for position 0
I1108 03:28:04.835939 14716 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 440574ns
I1108 03:28:04.835958 14716 replica.cpp:676] Persisted action at 0
I1108 03:28:04.835974 14716 replica.cpp:661] Replica learned NOP action at position 0
I1108 03:28:04.836485 14704 log.cpp:672] Writer started with ending position 0
I1108 03:28:04.837576 14713 leveldb.cpp:438] Reading position from leveldb took 26524ns
I1108 03:28:04.840677 14704 registrar.cpp:346] Successfully fetched the registry (0B) in 13.270016ms
I1108 03:28:04.840776 14704 registrar.cpp:445] Applied 1 operations in 17814ns; attempting to update the 'registry'
I1108 03:28:04.843708 14709 log.cpp:680] Attempting to append 143 bytes to the log
I1108 03:28:04.843885 14708 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
I1108 03:28:04.844647 14711 replica.cpp:508] Replica received write request for position 1
I1108 03:28:04.845298 14711 leveldb.cpp:343] Persisting action (162 bytes) to leveldb took 616348ns
I1108 03:28:04.845329 14711 replica.cpp:676] Persisted action at 1
I1108 03:28:04.845921 14711 replica.cpp:655] Replica received learned notice for position 1
I1108 03:28:04.846539 14711 leveldb.cpp:343] Persisting action (164 bytes) to leveldb took 588207ns
I1108 03:28:04.846566 14711 replica.cpp:676] Persisted action at 1
I1108 03:28:04.846587 14711 replica.cpp:661] Replica learned APPEND action at position 1
I1108 03:28:04.847482 14708 registrar.cpp:490] Successfully updated the 'registry' in 6.654976ms
I1108 03:28:04.847615 14708 registrar.cpp:376] Successfully recovered registrar
I1108 03:28:04.847838 14709 log.cpp:699] Attempting to truncate the log to 1
I1108 03:28:04.847877 14713 master.cpp:1121] Recovered 0 slaves from the Registry (105B) ; allowing 10mins for slaves to re-register
I1108 03:28:04.848003 14704 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
I1108 03:28:04.848845 14704 replica.cpp:508] Replica received write request for position 2
I1108 03:28:04.849423 14704 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 547637ns
I1108 03:28:04.849449 14704 replica.cpp:676] Persisted action at 2
I1108 03:28:04.850144 14707 replica.cpp:655] Replica received learned notice for position 2
I1108 03:28:04.850659 14707 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 486917ns
I1108 03:28:04.850707 14707 leveldb.cpp:401] Deleting ~1 keys from leveldb took 22376ns
I1108 03:28:04.850724 14707 replica.cpp:676] Persisted action at 2
I1108 03:28:04.850746 14707 replica.cpp:661] Replica learned TRUNCATE action at position 2
I1108 03:28:04.863876 14687 sched.cpp:143] Version: 0.22.0
I1108 03:28:04.864425 14712 sched.cpp:239] New master detected at master@67.195.81.189:38590
I1108 03:28:04.864475 14712 sched.cpp:295] Authenticating with master master@67.195.81.189:38590
I1108 03:28:04.864639 14709 authenticatee.hpp:133] Creating new client SASL connection
I1108 03:28:04.864850 14705 master.cpp:3901] Authenticating scheduler-44d59c2b-7ae4-454d-a79f-03bf1a5e1a4e@67.195.81.189:38590
I1108 03:28:04.864888 14705 master.cpp:3912] Using default CRAM-MD5 authenticator
I1108 03:28:04.865072 14706 authenticator.hpp:166] Creating new server SASL connection
I1108 03:28:04.865218 14716 authenticatee.hpp:224] Received SASL authentication mechanisms: CRAM-MD5
I1108 03:28:04.865245 14716 authenticatee.hpp:250] Attempting to authenticate with mechanism 'CRAM-MD5'
I1108 03:28:04.865339 14705 authenticator.hpp:272] Received SASL authentication start
I1108 03:28:04.865383 14705 authenticator.hpp:394] Authentication requires more steps
I1108 03:28:04.865486 14712 authenticatee.hpp:270] Received SASL authentication step
I1108 03:28:04.865604 14710 authenticator.hpp:300] Received SASL authentication step
I1108 03:28:04.865644 14710 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'proserpina.apache.org' server FQDN: 'proserpina.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1108 03:28:04.865661 14710 auxprop.cpp:171] Looking up auxiliary property '*userPassword'
I1108 03:28:04.865694 14710 auxprop.cpp:171] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1108 03:28:04.865720 14710 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'proserpina.apache.org' server FQDN: 'proserpina.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1108 03:28:04.865731 14710 auxprop.cpp:121] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1108 03:28:04.865741 14710 auxprop.cpp:121] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1108 03:28:04.865757 14710 authenticator.hpp:386] Authentication success
I1108 03:28:04.865841 14712 authenticatee.hpp:310] Authentication success
I1108 03:28:04.865864 14705 master.cpp:3959] Successfully authenticated principal 'test-principal' at scheduler-44d59c2b-7ae4-454d-a79f-03bf1a5e1a4e@67.195.81.189:38590
I1108 03:28:04.866180 14715 sched.cpp:369] Successfully authenticated with master master@67.195.81.189:38590
I1108 03:28:04.866206 14715 sched.cpp:488] Sending registration request to master@67.195.81.189:38590
I1108 03:28:04.982702 14715 sched.cpp:521] Will retry registration in 763.331307ms if necessary
I1108 03:28:04.982795 14707 master.cpp:1383] Received registration request for framework 'default' at scheduler-44d59c2b-7ae4-454d-a79f-03bf1a5e1a4e@67.195.81.189:38590
I1108 03:28:04.982862 14707 master.cpp:1342] Authorizing framework principal 'test-principal' to receive offers for role '*'
I1108 03:28:04.983429 14704 master.cpp:1447] Registering framework 20141108-032804-3176252227-38590-14687-0000 (default) at scheduler-44d59c2b-7ae4-454d-a79f-03bf1a5e1a4e@67.195.81.189:38590
I1108 03:28:04.983722 14708 hierarchical_allocator_process.hpp:329] Added framework 20141108-032804-3176252227-38590-14687-0000
I1108 03:28:04.983752 14708 hierarchical_allocator_process.hpp:697] No resources available to allocate!
I1108 03:28:04.983762 14708 hierarchical_allocator_process.hpp:659] Performed allocation for 0 slaves in 15297ns
I1108 03:28:04.983875 14708 sched.cpp:419] Framework registered with 20141108-032804-3176252227-38590-14687-0000
I1108 03:28:04.983944 14708 sched.cpp:433] Scheduler::registered took 46563ns
I1108 03:28:04.989591 14708 master.cpp:3611] Performing explicit task state reconciliation for 1 tasks of framework 20141108-032804-3176252227-38590-14687-0000 (default) at scheduler-44d59c2b-7ae4-454d-a79f-03bf1a5e1a4e@67.195.81.189:38590
I1108 03:28:04.991938 14708 master.cpp:3689] Sending explicit reconciliation state TASK_LOST for task b4a13819-04d0-4f0c-b622-4960163166f2 of framework 20141108-032804-3176252227-38590-14687-0000 (default) at scheduler-44d59c2b-7ae4-454d-a79f-03bf1a5e1a4e@67.195.81.189:38590
I1108 03:28:04.992300 14707 sched.cpp:669] Scheduler::statusUpdate took 74309ns
I1108 03:28:04.992735 14687 master.cpp:698] Master terminating
I1108 03:28:04.992779 14715 sched.cpp:779] Stopping framework '20141108-032804-3176252227-38590-14687-0000'
[ OK ] ReconciliationTest.UnknownSlave (278 ms)
[----------] 10 tests from ReconciliationTest (2401 ms total)
[----------] 1 test from MesosContainerizerExecuteTest
[ RUN ] MesosContainerizerExecuteTest.IoRedirection
Using temporary directory '/tmp/MesosContainerizerExecuteTest_IoRedirection_mXjUXf'
I1108 03:28:04.999016 14687 containerizer.cpp:100] Using isolation: posix/cpu,posix/mem
I1108 03:28:04.999574 14716 containerizer.cpp:424] Starting container 'test_container' for executor 'executor' of framework ''
I1108 03:28:05.003448 14716 launcher.cpp:137] Forked child with pid '20146' for container 'test_container'
I1108 03:28:05.004827 14705 containerizer.cpp:571] Fetching URIs for container 'test_container' using command '<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/src/mesos-fetcher'>
I1108 03:28:05.224258 14704 containerizer.cpp:1117] Executor for container 'test_container' has exited
I1108 03:28:05.224323 14704 containerizer.cpp:946] Destroying container 'test_container'
tests/containerizer_tests.cpp:487: Failure
Value of: (os::read(path::join(directory, "stderr"))).get()
Actual: "I1108 03:28:05.055192 20150 logging.cpp:177] Logging to STDERR\nthis is stderr\n"
Expected: errMsg + "\n"
Which is: "this is stderr\n"
[ FAILED ] MesosContainerizerExecuteTest.IoRedirection (246 ms)
[----------] 1 test from MesosContainerizerExecuteTest (246 ms total)
[----------] Global test environment tear-down
[==========] 455 tests from 71 test cases ran. (391127 ms total)
[ PASSED ] 454 tests.
[ FAILED ] 1 test, listed below:
[ FAILED ] MesosContainerizerExecuteTest.IoRedirection
1 FAILED TEST
YOU HAVE 6 DISABLED TESTS
make[3]: *** [check-local] Error 1
make[3]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/src'>
make[2]: *** [check-am] Error 2
make[2]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/src'>
make[1]: *** [check] Error 2
make[1]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/src'>
make: *** [check-recursive] Error 1
Test finished
Exit status: 2
Build step 'Execute shell' marked build as failure
Recording test results
Jenkins build is back to normal :
Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME #2262
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/2262/changes>
Re: Build failed in Jenkins: Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME
#2261
Posted by Benjamin Mahler <be...@gmail.com>.
MESOS-2048 I believe, shouldn't see any more of these.
On Fri, Nov 7, 2014 at 8:46 PM, Apache Jenkins Server <
jenkins@builds.apache.org> wrote:
> See <
> https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/2261/changes
> >
>
> Changes:
>
> [benjamin.hindman] Abstracted out invoking 'mesos-fetcher'.
>
> ------------------------------------------
> [...truncated 70651 lines...]
> 2014-11-08 04:44:55,244:26166(0x2b3a5c135700):ZOO_INFO@log_env@724:
> Client environment:os.arch=3.13.0-36-lowlatency
> 2014-11-08 04:44:55,244:26166(0x2b3a5c135700):ZOO_INFO@log_env@725:
> Client environment:os.version=#63-Ubuntu SMP PREEMPT Wed Sep 3 21:56:12 UTC
> 2014
> 2014-11-08 04:44:55,244:26166(0x2b3a5c537700):ZOO_INFO@log_env@741:
> Client environment:user.home=/home/jenkins
> 2014-11-08 04:44:55,244:26166(0x2b3a5c537700):ZOO_INFO@log_env@753:
> Client environment:user.dir=/tmp/LogZooKeeperTest_WriteRead_dFYVWf
> 2014-11-08 04:44:55,320:26166(0x2b3a5c537700):ZOO_INFO@zookeeper_init@786:
> Initiating client connection, host=127.0.0.1:42847 sessionTimeout=10000
> watcher=0x2b3a56028b0a sessionId=0 sessionPasswd=<null>
> context=0x2b3a980cc220 flags=0
> 2014-11-08 04:44:55,244:26166(0x2b3a5c135700):ZOO_INFO@log_env@733:
> Client environment:user.name=jenkins
> I1108 04:44:55.244516 26184 recover.cpp:437] Starting replica recovery
> 2014-11-08 04:44:55,320:26166(0x2b3a5c135700):ZOO_INFO@log_env@741:
> Client environment:user.home=/home/jenkins
> 2014-11-08 04:44:55,320:26166(0x2b3a5c135700):ZOO_INFO@log_env@753:
> Client environment:user.dir=/tmp/LogZooKeeperTest_WriteRead_dFYVWf
> 2014-11-08 04:44:55,320:26166(0x2b3a5c135700):ZOO_INFO@zookeeper_init@786:
> Initiating client connection, host=127.0.0.1:42847 sessionTimeout=10000
> watcher=0x2b3a56028b0a sessionId=0 sessionPasswd=<null>
> context=0x2b3a7408e8f0 flags=0
> I1108 04:44:55.247128 26166 leveldb.cpp:176] Opened db in 3.573419ms
> I1108 04:44:55.320708 26184 recover.cpp:463] Replica is in VOTING status
> 2014-11-08 04:44:55,320:26166(0x2b3e0ca04700):ZOO_INFO@check_events@1703:
> initiated connection to server [127.0.0.1:42847]
> 2014-11-08 04:44:55,320:26166(0x2b3e0de2d700):ZOO_INFO@check_events@1703:
> initiated connection to server [127.0.0.1:42847]
> I1108 04:44:55.320850 26184 recover.cpp:452] Recover process terminated
> 2014-11-08 04:44:55,323:26166(0x2b3e0ca04700):ZOO_INFO@check_events@1750:
> session establishment complete on server [127.0.0.1:42847],
> sessionId=0x1498db822360000, negotiated timeout=10000
> I1108 04:44:55.323797 26166 leveldb.cpp:183] Compacted db in 3.326034ms
> I1108 04:44:55.323853 26166 leveldb.cpp:198] Created db iterator in 17790ns
> I1108 04:44:55.323887 26166 leveldb.cpp:204] Seeked to beginning of db in
> 19544ns
> I1108 04:44:55.323922 26166 leveldb.cpp:273] Iterated through 1 keys in
> the db in 20972ns
> I1108 04:44:55.323957 26166 replica.cpp:741] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I1108 04:44:55.323997 26182 group.cpp:313] Group process (group(53)@
> 67.195.81.190:53738) connected to ZooKeeper
> I1108 04:44:55.324029 26182 group.cpp:790] Syncing group operations: queue
> size (joins, cancels, datas) = (0, 0, 0)
> I1108 04:44:55.324050 26182 group.cpp:385] Trying to create path '/log' in
> ZooKeeper
> 2014-11-08 04:44:55,324:26166(0x2b3e0de2d700):ZOO_INFO@check_events@1750:
> session establishment complete on server [127.0.0.1:42847],
> sessionId=0x1498db822360001, negotiated timeout=10000
> 2014-11-08 04:44:55,324:26166(0x2b3a5c336700):ZOO_INFO@log_env@712:
> Client environment:zookeeper.version=zookeeper C client 3.4.5
> 2014-11-08 04:44:55,324:26166(0x2b3a5c336700):ZOO_INFO@log_env@716:
> Client environment:host.name=pietas.apache.org
> 2014-11-08 04:44:55,324:26166(0x2b3a5c336700):ZOO_INFO@log_env@723:
> Client environment:os.name=Linux
> 2014-11-08 04:44:55,324:26166(0x2b3a5c336700):ZOO_INFO@log_env@724:
> Client environment:os.arch=3.13.0-36-lowlatency
> 2014-11-08 04:44:55,324:26166(0x2b3a5c336700):ZOO_INFO@log_env@725:
> Client environment:os.version=#63-Ubuntu SMP PREEMPT Wed Sep 3 21:56:12 UTC
> 2014
> 2014-11-08 04:44:55,324:26166(0x2b3a5c336700):ZOO_INFO@log_env@733:
> Client environment:user.name=jenkins
> 2014-11-08 04:44:55,324:26166(0x2b3a5c336700):ZOO_INFO@log_env@741:
> Client environment:user.home=/home/jenkins
> 2014-11-08 04:44:55,324:26166(0x2b3a5c336700):ZOO_INFO@log_env@753:
> Client environment:user.dir=/tmp/LogZooKeeperTest_WriteRead_dFYVWf
> 2014-11-08 04:44:55,324:26166(0x2b3a5c336700):ZOO_INFO@zookeeper_init@786:
> Initiating client connection, host=127.0.0.1:42847 sessionTimeout=10000
> watcher=0x2b3a56028b0a sessionId=0 sessionPasswd=<null>
> context=0x2b3a900ae0f0 flags=0
> I1108 04:44:55.324905 26184 log.cpp:238] Attempting to join replica to
> ZooKeeper group
> 2014-11-08 04:44:55,325:26166(0x2b3a5bb32700):ZOO_INFO@log_env@712:
> Client environment:zookeeper.version=zookeeper C client 3.4.5
> 2014-11-08 04:44:55,325:26166(0x2b3a5bb32700):ZOO_INFO@log_env@716:
> Client environment:host.name=pietas.apache.org
> 2014-11-08 04:44:55,325:26166(0x2b3a5bb32700):ZOO_INFO@log_env@723:
> Client environment:os.name=Linux
> 2014-11-08 04:44:55,325:26166(0x2b3a5bb32700):ZOO_INFO@log_env@724:
> Client environment:os.arch=3.13.0-36-lowlatency
> 2014-11-08 04:44:55,325:26166(0x2b3a5bb32700):ZOO_INFO@log_env@725:
> Client environment:os.version=#63-Ubuntu SMP PREEMPT Wed Sep 3 21:56:12 UTC
> 2014
> 2014-11-08 04:44:55,325:26166(0x2b3a5bb32700):ZOO_INFO@log_env@733:
> Client environment:user.name=jenkins
> 2014-11-08 04:44:55,325:26166(0x2b3a5bb32700):ZOO_INFO@log_env@741:
> Client environment:user.home=/home/jenkins
> 2014-11-08 04:44:55,325:26166(0x2b3a5bb32700):ZOO_INFO@log_env@753:
> Client environment:user.dir=/tmp/LogZooKeeperTest_WriteRead_dFYVWf
> 2014-11-08 04:44:55,325:26166(0x2b3a5bb32700):ZOO_INFO@zookeeper_init@786:
> Initiating client connection, host=127.0.0.1:42847 sessionTimeout=10000
> watcher=0x2b3a56028b0a sessionId=0 sessionPasswd=<null>
> context=0x2b3a6c0c79b0 flags=0
> I1108 04:44:55.325539 26189 group.cpp:313] Group process (group(54)@
> 67.195.81.190:53738) connected to ZooKeeper
> I1108 04:44:55.325574 26189 group.cpp:790] Syncing group operations: queue
> size (joins, cancels, datas) = (1, 0, 0)
> I1108 04:44:55.325588 26189 group.cpp:385] Trying to create path '/log' in
> ZooKeeper
> I1108 04:44:55.325582 26194 recover.cpp:437] Starting replica recovery
> 2014-11-08 04:44:55,325:26166(0x2b3e0e02e700):ZOO_INFO@check_events@1703:
> initiated connection to server [127.0.0.1:42847]
> I1108 04:44:55.325893 26194 recover.cpp:463] Replica is in VOTING status
> 2014-11-08 04:44:55,325:26166(0x2b3e0d60a700):ZOO_INFO@check_events@1703:
> initiated connection to server [127.0.0.1:42847]
> I1108 04:44:55.326051 26194 recover.cpp:452] Recover process terminated
> I1108 04:44:55.326891 26187 log.cpp:656] Attempting to start the writer
> 2014-11-08 04:44:55,328:26166(0x2b3e0e02e700):ZOO_INFO@check_events@1750:
> session establishment complete on server [127.0.0.1:42847],
> sessionId=0x1498db822360002, negotiated timeout=10000
> I1108 04:44:55.329056 26190 group.cpp:313] Group process (group(55)@
> 67.195.81.190:53738) connected to ZooKeeper
> I1108 04:44:55.329090 26190 group.cpp:790] Syncing group operations: queue
> size (joins, cancels, datas) = (0, 0, 0)
> I1108 04:44:55.329113 26190 group.cpp:385] Trying to create path '/log' in
> ZooKeeper
> 2014-11-08 04:44:55,329:26166(0x2b3e0d60a700):ZOO_INFO@check_events@1750:
> session establishment complete on server [127.0.0.1:42847],
> sessionId=0x1498db822360003, negotiated timeout=10000
> I1108 04:44:55.330327 26188 group.cpp:313] Group process (group(56)@
> 67.195.81.190:53738) connected to ZooKeeper
> I1108 04:44:55.330359 26188 group.cpp:790] Syncing group operations: queue
> size (joins, cancels, datas) = (1, 0, 0)
> I1108 04:44:55.330374 26188 group.cpp:385] Trying to create path '/log' in
> ZooKeeper
> I1108 04:44:55.332345 26192 network.hpp:424] ZooKeeper group memberships
> changed
> I1108 04:44:55.332495 26181 group.cpp:659] Trying to get '/log/0000000000'
> in ZooKeeper
> I1108 04:44:55.333076 26192 network.hpp:424] ZooKeeper group memberships
> changed
> I1108 04:44:55.333212 26191 group.cpp:659] Trying to get '/log/0000000000'
> in ZooKeeper
> I1108 04:44:55.334625 26194 network.hpp:466] ZooKeeper group PIDs: {
> log-replica(438)@67.195.81.190:53738 }
> I1108 04:44:55.335556 26186 network.hpp:466] ZooKeeper group PIDs: {
> log-replica(438)@67.195.81.190:53738 }
> I1108 04:44:55.335785 26180 replica.cpp:474] Replica received implicit
> promise request with proposal 1
> I1108 04:44:55.335963 26195 replica.cpp:474] Replica received implicit
> promise request with proposal 1
> I1108 04:44:55.336510 26194 network.hpp:424] ZooKeeper group memberships
> changed
> I1108 04:44:55.336638 26195 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 639914ns
> I1108 04:44:55.336642 26180 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 818147ns
> I1108 04:44:55.336666 26195 replica.cpp:342] Persisted promised to 1
> I1108 04:44:55.336673 26180 replica.cpp:342] Persisted promised to 1
> I1108 04:44:55.336662 26182 group.cpp:659] Trying to get '/log/0000000000'
> in ZooKeeper
> I1108 04:44:55.337342 26186 network.hpp:424] ZooKeeper group memberships
> changed
> I1108 04:44:55.337709 26189 coordinator.cpp:230] Coordinator attemping to
> fill missing position
> I1108 04:44:55.337903 26182 group.cpp:659] Trying to get '/log/0000000001'
> in ZooKeeper
> I1108 04:44:55.452550 26195 group.cpp:659] Trying to get '/log/0000000000'
> in ZooKeeper
> I1108 04:44:55.454025 26195 group.cpp:659] Trying to get '/log/0000000001'
> in ZooKeeper
> I1108 04:44:55.454591 26193 network.hpp:466] ZooKeeper group PIDs: {
> log-replica(438)@67.195.81.190:53738, log-replica(439)@67.195.81.190:53738
> }
> I1108 04:44:55.454737 26187 replica.cpp:375] Replica received explicit
> promise request for position 0 with proposal 2
> I1108 04:44:55.455200 26185 replica.cpp:375] Replica received explicit
> promise request for position 0 with proposal 2
> I1108 04:44:55.455358 26187 leveldb.cpp:343] Persisting action (8 bytes)
> to leveldb took 580678ns
> I1108 04:44:55.455389 26187 replica.cpp:676] Persisted action at 0
> I1108 04:44:55.455752 26185 leveldb.cpp:343] Persisting action (8 bytes)
> to leveldb took 511428ns
> I1108 04:44:55.455786 26185 replica.cpp:676] Persisted action at 0
> I1108 04:44:55.455962 26195 network.hpp:466] ZooKeeper group PIDs: {
> log-replica(438)@67.195.81.190:53738, log-replica(439)@67.195.81.190:53738
> }
> I1108 04:44:55.457196 26187 replica.cpp:508] Replica received write
> request for position 0
> I1108 04:44:55.457259 26187 leveldb.cpp:438] Reading position from leveldb
> took 28672ns
> I1108 04:44:55.457571 26183 replica.cpp:508] Replica received write
> request for position 0
> I1108 04:44:55.457638 26183 leveldb.cpp:438] Reading position from leveldb
> took 29027ns
> I1108 04:44:55.457691 26187 leveldb.cpp:343] Persisting action (14 bytes)
> to leveldb took 390166ns
> I1108 04:44:55.457720 26187 replica.cpp:676] Persisted action at 0
> I1108 04:44:55.458050 26183 leveldb.cpp:343] Persisting action (14 bytes)
> to leveldb took 374875ns
> I1108 04:44:55.458076 26183 replica.cpp:676] Persisted action at 0
> I1108 04:44:55.458554 26192 replica.cpp:655] Replica received learned
> notice for position 0
> I1108 04:44:55.458592 26193 replica.cpp:655] Replica received learned
> notice for position 0
> I1108 04:44:55.459014 26193 leveldb.cpp:343] Persisting action (16 bytes)
> to leveldb took 391444ns
> I1108 04:44:55.459019 26192 leveldb.cpp:343] Persisting action (16 bytes)
> to leveldb took 431750ns
> I1108 04:44:55.459045 26193 replica.cpp:676] Persisted action at 0
> I1108 04:44:55.459055 26192 replica.cpp:676] Persisted action at 0
> I1108 04:44:55.459067 26193 replica.cpp:661] Replica learned NOP action at
> position 0
> I1108 04:44:55.459077 26192 replica.cpp:661] Replica learned NOP action at
> position 0
> I1108 04:44:55.459836 26188 log.cpp:672] Writer started with ending
> position 0
> I1108 04:44:55.460250 26180 log.cpp:680] Attempting to append 11 bytes to
> the log
> I1108 04:44:55.460368 26191 coordinator.cpp:340] Coordinator attempting to
> write APPEND action at position 1
> I1108 04:44:55.461184 26186 replica.cpp:508] Replica received write
> request for position 1
> I1108 04:44:55.461323 26183 replica.cpp:508] Replica received write
> request for position 1
> I1108 04:44:55.461616 26186 leveldb.cpp:343] Persisting action (27 bytes)
> to leveldb took 394737ns
> I1108 04:44:55.461643 26186 replica.cpp:676] Persisted action at 1
> I1108 04:44:55.461727 26183 leveldb.cpp:343] Persisting action (27 bytes)
> to leveldb took 370577ns
> I1108 04:44:55.461750 26183 replica.cpp:676] Persisted action at 1
> I1108 04:44:55.462525 26194 replica.cpp:655] Replica received learned
> notice for position 1
> I1108 04:44:55.462601 26191 replica.cpp:655] Replica received learned
> notice for position 1
> I1108 04:44:55.462906 26191 leveldb.cpp:343] Persisting action (29 bytes)
> to leveldb took 275192ns
> I1108 04:44:55.462906 26194 leveldb.cpp:343] Persisting action (29 bytes)
> to leveldb took 351125ns
> I1108 04:44:55.462939 26191 replica.cpp:676] Persisted action at 1
> I1108 04:44:55.462947 26194 replica.cpp:676] Persisted action at 1
> I1108 04:44:55.462960 26191 replica.cpp:661] Replica learned APPEND action
> at position 1
> I1108 04:44:55.462970 26194 replica.cpp:661] Replica learned APPEND action
> at position 1
> I1108 04:44:55.464081 26181 leveldb.cpp:438] Reading position from leveldb
> took 36464ns
> 2014-11-08 04:44:55,465:26166(0x2b3a53084080):ZOO_INFO@zookeeper_close@2505:
> Closing zookeeper sessionId=0x1498db822360003 to [127.0.0.1:42847]
>
> 2014-11-08 04:44:55,466:26166(0x2b3a5b32e700):ZOO_INFO@zookeeper_close@2505:
> Closing zookeeper sessionId=0x1498db822360002 to [127.0.0.1:42847]
>
> I1108 04:44:55.468557 26186 network.hpp:424] ZooKeeper group memberships
> changed
> I1108 04:44:55.468693 26193 group.cpp:659] Trying to get '/log/0000000000'
> in ZooKeeper
> 2014-11-08 04:44:55,469:26166(0x2b3a5b931700):ZOO_INFO@zookeeper_close@2505:
> Closing zookeeper sessionId=0x1498db822360001 to [127.0.0.1:42847]
>
> 2014-11-08 04:44:55,470:26166(0x2b3a5bf34700):ZOO_INFO@zookeeper_close@2505:
> Closing zookeeper sessionId=0x1498db822360000 to [127.0.0.1:42847]
>
> I1108 04:44:55.471582 26166 zookeeper_test_server.cpp:118] Shutting down
> ZooKeeperTestServer on port 42847
> [ OK ] LogZooKeeperTest.WriteRead (254 ms)
> [ RUN ] LogZooKeeperTest.LostZooKeeper
> I1108 04:44:55.475536 26166 zookeeper_test_server.cpp:158] Started
> ZooKeeperTestServer on port 52306
> I1108 04:44:55.475628 26166 log_tests.cpp:1945] Using temporary directory
> '/tmp/LogZooKeeperTest_LostZooKeeper_B5z3jV'
> I1108 04:44:55.478559 26166 leveldb.cpp:176] Opened db in 2.846954ms
> I1108 04:44:55.479370 26166 leveldb.cpp:183] Compacted db in 775391ns
> I1108 04:44:55.479416 26166 leveldb.cpp:198] Created db iterator in 16244ns
> I1108 04:44:55.479460 26166 leveldb.cpp:204] Seeked to beginning of db in
> 1968ns
> I1108 04:44:55.479472 26166 leveldb.cpp:273] Iterated through 0 keys in
> the db in 482ns
> I1108 04:44:55.479504 26166 replica.cpp:741] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> 2014-11-08 04:44:55,479:26166(0x2b3a5b12d700):ZOO_INFO@log_env@712:
> Client environment:zookeeper.version=zookeeper C client 3.4.5
> 2014-11-08 04:44:55,479:26166(0x2b3a5b12d700):ZOO_INFO@log_env@716:
> Client environment:host.name=pietas.apache.org
> 2014-11-08 04:44:55,479:26166(0x2b3a5b12d700):ZOO_INFO@log_env@723:
> Client environment:os.name=Linux
> 2014-11-08 04:44:55,479:26166(0x2b3a5b12d700):ZOO_INFO@log_env@724:
> Client environment:os.arch=3.13.0-36-lowlatency
> 2014-11-08 04:44:55,479:26166(0x2b3a5b12d700):ZOO_INFO@log_env@725:
> Client environment:os.version=#63-Ubuntu SMP PREEMPT Wed Sep 3 21:56:12 UTC
> 2014
> 2014-11-08 04:44:55,480:26166(0x2b3a5b12d700):ZOO_INFO@log_env@733:
> Client environment:user.name=jenkins
> 2014-11-08 04:44:55,480:26166(0x2b3a5b12d700):ZOO_INFO@log_env@741:
> Client environment:user.home=/home/jenkins
> 2014-11-08 04:44:55,480:26166(0x2b3a5b12d700):ZOO_INFO@log_env@753:
> Client environment:user.dir=/tmp/LogZooKeeperTest_LostZooKeeper_B5z3jV
> I1108 04:44:55.480145 26188 log.cpp:238] Attempting to join replica to
> ZooKeeper group
> 2014-11-08 04:44:55,480:26166(0x2b3a5b12d700):ZOO_INFO@zookeeper_init@786:
> Initiating client connection, host=127.0.0.1:52306 sessionTimeout=10000
> watcher=0x2b3a56028b0a sessionId=0 sessionPasswd=<null>
> context=0x2b3a880a5d90 flags=0
> 2014-11-08 04:44:55,480:26166(0x2b3a5b931700):ZOO_INFO@log_env@712:
> Client environment:zookeeper.version=zookeeper C client 3.4.5
> 2014-11-08 04:44:55,480:26166(0x2b3a5b931700):ZOO_INFO@log_env@716:
> Client environment:host.name=pietas.apache.org
> 2014-11-08 04:44:55,480:26166(0x2b3a5b931700):ZOO_INFO@log_env@723:
> Client environment:os.name=Linux
> 2014-11-08 04:44:55,480:26166(0x2b3a5b931700):ZOO_INFO@log_env@724:
> Client environment:os.arch=3.13.0-36-lowlatency
> 2014-11-08 04:44:55,480:26166(0x2b3a5b931700):ZOO_INFO@log_env@725:
> Client environment:os.version=#63-Ubuntu SMP PREEMPT Wed Sep 3 21:56:12 UTC
> 2014
> 2014-11-08 04:44:55,480:26166(0x2b3a5b931700):ZOO_INFO@log_env@733:
> Client environment:user.name=jenkins
> I1108 04:44:55.480638 26190 recover.cpp:437] Starting replica recovery
> 2014-11-08 04:44:55,480:26166(0x2b3e0ca04700):ZOO_INFO@check_events@1703:
> initiated connection to server [127.0.0.1:52306]
> 2014-11-08 04:44:55,480:26166(0x2b3a5b931700):ZOO_INFO@log_env@741:
> Client environment:user.home=/home/jenkins
> 2014-11-08 04:44:55,624:26166(0x2b3a5b931700):ZOO_INFO@log_env@753:
> Client environment:user.dir=/tmp/LogZooKeeperTest_LostZooKeeper_B5z3jV
> 2014-11-08 04:44:55,624:26166(0x2b3a5b931700):ZOO_INFO@zookeeper_init@786:
> Initiating client connection, host=127.0.0.1:52306 sessionTimeout=10000
> watcher=0x2b3a56028b0a sessionId=0 sessionPasswd=<null>
> context=0x2b3a7c09cad0 flags=0
> I1108 04:44:55.480916 26182 recover.cpp:463] Replica is in EMPTY status
> 2014-11-08 04:44:55,483:26166(0x2b3e0ca04700):ZOO_INFO@check_events@1750:
> session establishment complete on server [127.0.0.1:52306],
> sessionId=0x1498db823320000, negotiated timeout=10000
> 2014-11-08 04:44:55,624:26166(0x2b3e0de2d700):ZOO_INFO@check_events@1703:
> initiated connection to server [127.0.0.1:52306]
> I1108 04:44:55.625049 26189 group.cpp:313] Group process (group(57)@
> 67.195.81.190:53738) connected to ZooKeeper
> I1108 04:44:55.625107 26189 group.cpp:790] Syncing group operations: queue
> size (joins, cancels, datas) = (0, 0, 0)
> I1108 04:44:55.625128 26189 group.cpp:385] Trying to create path '/log' in
> ZooKeeper
> I1108 04:44:55.625675 26192 replica.cpp:638] Replica in EMPTY status
> received a broadcasted recover request
> I1108 04:44:55.626123 26194 recover.cpp:188] Received a recover response
> from a replica in EMPTY status
> 2014-11-08 04:44:55,626:26166(0x2b3e0de2d700):ZOO_INFO@check_events@1750:
> session establishment complete on server [127.0.0.1:52306],
> sessionId=0x1498db823320001, negotiated timeout=10000
> I1108 04:44:55.626602 26188 recover.cpp:554] Updating replica status to
> STARTING
> I1108 04:44:55.627254 26191 group.cpp:313] Group process (group(58)@
> 67.195.81.190:53738) connected to ZooKeeper
> I1108 04:44:55.627338 26191 group.cpp:790] Syncing group operations: queue
> size (joins, cancels, datas) = (1, 0, 0)
> I1108 04:44:55.627353 26191 group.cpp:385] Trying to create path '/log' in
> ZooKeeper
> I1108 04:44:55.627354 26183 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 597985ns
> I1108 04:44:55.627388 26183 replica.cpp:320] Persisted replica status to
> STARTING
> I1108 04:44:55.627671 26187 recover.cpp:463] Replica is in STARTING status
> I1108 04:44:55.628998 26186 replica.cpp:638] Replica in STARTING status
> received a broadcasted recover request
> I1108 04:44:55.629487 26192 recover.cpp:188] Received a recover response
> from a replica in STARTING status
> I1108 04:44:55.629966 26180 recover.cpp:554] Updating replica status to
> VOTING
> I1108 04:44:55.630470 26182 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 365147ns
> I1108 04:44:55.630506 26182 replica.cpp:320] Persisted replica status to
> VOTING
> I1108 04:44:55.630600 26185 recover.cpp:568] Successfully joined the Paxos
> group
> I1108 04:44:55.630774 26185 recover.cpp:452] Recover process terminated
> I1108 04:44:55.631284 26193 log.cpp:656] Attempting to start the writer
> I1108 04:44:55.632472 26186 network.hpp:424] ZooKeeper group memberships
> changed
> I1108 04:44:55.632601 26187 group.cpp:659] Trying to get '/log/0000000000'
> in ZooKeeper
> I1108 04:44:55.632657 26193 replica.cpp:474] Replica received implicit
> promise request with proposal 1
> I1108 04:44:55.633139 26193 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 449102ns
> I1108 04:44:55.633165 26193 replica.cpp:342] Persisted promised to 1
> I1108 04:44:55.633846 26194 coordinator.cpp:230] Coordinator attemping to
> fill missing position
> I1108 04:44:55.634021 26190 network.hpp:466] ZooKeeper group PIDs: {
> log-replica(440)@67.195.81.190:53738 }
> I1108 04:44:55.635151 26180 replica.cpp:375] Replica received explicit
> promise request for position 0 with proposal 2
> I1108 04:44:55.635571 26180 leveldb.cpp:343] Persisting action (8 bytes)
> to leveldb took 382219ns
> I1108 04:44:55.635596 26180 replica.cpp:676] Persisted action at 0
> I1108 04:44:55.636574 26187 replica.cpp:508] Replica received write
> request for position 0
> I1108 04:44:55.636646 26187 leveldb.cpp:438] Reading position from leveldb
> took 30476ns
> I1108 04:44:55.637039 26187 leveldb.cpp:343] Persisting action (14 bytes)
> to leveldb took 357220ns
> I1108 04:44:55.637065 26187 replica.cpp:676] Persisted action at 0
> I1108 04:44:55.637536 26182 replica.cpp:655] Replica received learned
> notice for position 0
> I1108 04:44:55.637980 26182 leveldb.cpp:343] Persisting action (16 bytes)
> to leveldb took 412783ns
> I1108 04:44:55.638011 26182 replica.cpp:676] Persisted action at 0
> I1108 04:44:55.638043 26182 replica.cpp:661] Replica learned NOP action at
> position 0
> I1108 04:44:55.638600 26183 log.cpp:672] Writer started with ending
> position 0
> I1108 04:44:55.638844 26166 zookeeper_test_server.cpp:118] Shutting down
> ZooKeeperTestServer on port 52306
> 2014-11-08
> 04:44:55,639:26166(0x2b3e0ca04700):ZOO_ERROR@handle_socket_error_msg@1721:
> Socket [127.0.0.1:52306] zk retcode=-4, errno=112(Host is down): failed
> while receiving a server response
> 2014-11-08
> 04:44:55,639:26166(0x2b3e0de2d700):ZOO_ERROR@handle_socket_error_msg@1721:
> Socket [127.0.0.1:52306] zk retcode=-4, errno=112(Host is down): failed
> while receiving a server response
> I1108 04:44:55.640256 26183 group.cpp:418] Lost connection to ZooKeeper,
> attempting to reconnect ...
> I1108 04:44:55.640638 26184 group.cpp:418] Lost connection to ZooKeeper,
> attempting to reconnect ...
> I1108 04:44:55.641289 26188 log.cpp:680] Attempting to append 11 bytes to
> the log
> I1108 04:44:55.641464 26182 coordinator.cpp:340] Coordinator attempting to
> write APPEND action at position 1
> I1108 04:44:55.642262 26184 replica.cpp:508] Replica received write
> request for position 1
> I1108 04:44:55.642676 26184 leveldb.cpp:343] Persisting action (27 bytes)
> to leveldb took 375727ns
> I1108 04:44:55.642704 26184 replica.cpp:676] Persisted action at 1
> I1108 04:44:55.643218 26182 replica.cpp:655] Replica received learned
> notice for position 1
> I1108 04:44:55.643797 26182 leveldb.cpp:343] Persisting action (29 bytes)
> to leveldb took 551262ns
> I1108 04:44:55.643828 26182 replica.cpp:676] Persisted action at 1
> I1108 04:44:55.643854 26182 replica.cpp:661] Replica learned APPEND action
> at position 1
> I1108 04:44:55.644922 26185 leveldb.cpp:438] Reading position from leveldb
> took 33977ns
> 2014-11-08 04:44:55,646:26166(0x2b3a5a929700):ZOO_INFO@zookeeper_close@2522:
> Freeing zookeeper resources for sessionId=0x1498db823320001
>
> 2014-11-08 04:44:55,647:26166(0x2b3a5c336700):ZOO_INFO@zookeeper_close@2522:
> Freeing zookeeper resources for sessionId=0x1498db823320000
>
> [ OK ] LogZooKeeperTest.LostZooKeeper (176 ms)
> [----------] 2 tests from LogZooKeeperTest (430 ms total)
>
> [----------] Global test environment tear-down
> [==========] 458 tests from 71 test cases ran. (373138 ms total)
> [ PASSED ] 457 tests.
> [ FAILED ] 1 test, listed below:
> [ FAILED ] MesosContainerizerExecuteTest.IoRedirection
>
> 1 FAILED TEST
> YOU HAVE 6 DISABLED TESTS
>
> make[3]: *** [check-local] Error 1
> make[3]: Leaving directory `<
> https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/src
> '>
> make[2]: *** [check-am] Error 2
> make[2]: Leaving directory `<
> https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/src
> '>
> make[1]: *** [check] Error 2
> make[1]: Leaving directory `<
> https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/src
> '>
> make: *** [check-recursive] Error 1
> Test finished
> Exit status: 2
> Build step 'Execute shell' marked build as failure
> Recording test results
>
Build failed in Jenkins:
Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME #2261
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/2261/changes>
Changes:
[benjamin.hindman] Abstracted out invoking 'mesos-fetcher'.
------------------------------------------
[...truncated 70651 lines...]
2014-11-08 04:44:55,244:26166(0x2b3a5c135700):ZOO_INFO@log_env@724: Client environment:os.arch=3.13.0-36-lowlatency
2014-11-08 04:44:55,244:26166(0x2b3a5c135700):ZOO_INFO@log_env@725: Client environment:os.version=#63-Ubuntu SMP PREEMPT Wed Sep 3 21:56:12 UTC 2014
2014-11-08 04:44:55,244:26166(0x2b3a5c537700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
2014-11-08 04:44:55,244:26166(0x2b3a5c537700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/LogZooKeeperTest_WriteRead_dFYVWf
2014-11-08 04:44:55,320:26166(0x2b3a5c537700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:42847 sessionTimeout=10000 watcher=0x2b3a56028b0a sessionId=0 sessionPasswd=<null> context=0x2b3a980cc220 flags=0
2014-11-08 04:44:55,244:26166(0x2b3a5c135700):ZOO_INFO@log_env@733: Client environment:user.name=jenkins
I1108 04:44:55.244516 26184 recover.cpp:437] Starting replica recovery
2014-11-08 04:44:55,320:26166(0x2b3a5c135700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
2014-11-08 04:44:55,320:26166(0x2b3a5c135700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/LogZooKeeperTest_WriteRead_dFYVWf
2014-11-08 04:44:55,320:26166(0x2b3a5c135700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:42847 sessionTimeout=10000 watcher=0x2b3a56028b0a sessionId=0 sessionPasswd=<null> context=0x2b3a7408e8f0 flags=0
I1108 04:44:55.247128 26166 leveldb.cpp:176] Opened db in 3.573419ms
I1108 04:44:55.320708 26184 recover.cpp:463] Replica is in VOTING status
2014-11-08 04:44:55,320:26166(0x2b3e0ca04700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:42847]
2014-11-08 04:44:55,320:26166(0x2b3e0de2d700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:42847]
I1108 04:44:55.320850 26184 recover.cpp:452] Recover process terminated
2014-11-08 04:44:55,323:26166(0x2b3e0ca04700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:42847], sessionId=0x1498db822360000, negotiated timeout=10000
I1108 04:44:55.323797 26166 leveldb.cpp:183] Compacted db in 3.326034ms
I1108 04:44:55.323853 26166 leveldb.cpp:198] Created db iterator in 17790ns
I1108 04:44:55.323887 26166 leveldb.cpp:204] Seeked to beginning of db in 19544ns
I1108 04:44:55.323922 26166 leveldb.cpp:273] Iterated through 1 keys in the db in 20972ns
I1108 04:44:55.323957 26166 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I1108 04:44:55.323997 26182 group.cpp:313] Group process (group(53)@67.195.81.190:53738) connected to ZooKeeper
I1108 04:44:55.324029 26182 group.cpp:790] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
I1108 04:44:55.324050 26182 group.cpp:385] Trying to create path '/log' in ZooKeeper
2014-11-08 04:44:55,324:26166(0x2b3e0de2d700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:42847], sessionId=0x1498db822360001, negotiated timeout=10000
2014-11-08 04:44:55,324:26166(0x2b3a5c336700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-11-08 04:44:55,324:26166(0x2b3a5c336700):ZOO_INFO@log_env@716: Client environment:host.name=pietas.apache.org
2014-11-08 04:44:55,324:26166(0x2b3a5c336700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
2014-11-08 04:44:55,324:26166(0x2b3a5c336700):ZOO_INFO@log_env@724: Client environment:os.arch=3.13.0-36-lowlatency
2014-11-08 04:44:55,324:26166(0x2b3a5c336700):ZOO_INFO@log_env@725: Client environment:os.version=#63-Ubuntu SMP PREEMPT Wed Sep 3 21:56:12 UTC 2014
2014-11-08 04:44:55,324:26166(0x2b3a5c336700):ZOO_INFO@log_env@733: Client environment:user.name=jenkins
2014-11-08 04:44:55,324:26166(0x2b3a5c336700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
2014-11-08 04:44:55,324:26166(0x2b3a5c336700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/LogZooKeeperTest_WriteRead_dFYVWf
2014-11-08 04:44:55,324:26166(0x2b3a5c336700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:42847 sessionTimeout=10000 watcher=0x2b3a56028b0a sessionId=0 sessionPasswd=<null> context=0x2b3a900ae0f0 flags=0
I1108 04:44:55.324905 26184 log.cpp:238] Attempting to join replica to ZooKeeper group
2014-11-08 04:44:55,325:26166(0x2b3a5bb32700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-11-08 04:44:55,325:26166(0x2b3a5bb32700):ZOO_INFO@log_env@716: Client environment:host.name=pietas.apache.org
2014-11-08 04:44:55,325:26166(0x2b3a5bb32700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
2014-11-08 04:44:55,325:26166(0x2b3a5bb32700):ZOO_INFO@log_env@724: Client environment:os.arch=3.13.0-36-lowlatency
2014-11-08 04:44:55,325:26166(0x2b3a5bb32700):ZOO_INFO@log_env@725: Client environment:os.version=#63-Ubuntu SMP PREEMPT Wed Sep 3 21:56:12 UTC 2014
2014-11-08 04:44:55,325:26166(0x2b3a5bb32700):ZOO_INFO@log_env@733: Client environment:user.name=jenkins
2014-11-08 04:44:55,325:26166(0x2b3a5bb32700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
2014-11-08 04:44:55,325:26166(0x2b3a5bb32700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/LogZooKeeperTest_WriteRead_dFYVWf
2014-11-08 04:44:55,325:26166(0x2b3a5bb32700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:42847 sessionTimeout=10000 watcher=0x2b3a56028b0a sessionId=0 sessionPasswd=<null> context=0x2b3a6c0c79b0 flags=0
I1108 04:44:55.325539 26189 group.cpp:313] Group process (group(54)@67.195.81.190:53738) connected to ZooKeeper
I1108 04:44:55.325574 26189 group.cpp:790] Syncing group operations: queue size (joins, cancels, datas) = (1, 0, 0)
I1108 04:44:55.325588 26189 group.cpp:385] Trying to create path '/log' in ZooKeeper
I1108 04:44:55.325582 26194 recover.cpp:437] Starting replica recovery
2014-11-08 04:44:55,325:26166(0x2b3e0e02e700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:42847]
I1108 04:44:55.325893 26194 recover.cpp:463] Replica is in VOTING status
2014-11-08 04:44:55,325:26166(0x2b3e0d60a700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:42847]
I1108 04:44:55.326051 26194 recover.cpp:452] Recover process terminated
I1108 04:44:55.326891 26187 log.cpp:656] Attempting to start the writer
2014-11-08 04:44:55,328:26166(0x2b3e0e02e700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:42847], sessionId=0x1498db822360002, negotiated timeout=10000
I1108 04:44:55.329056 26190 group.cpp:313] Group process (group(55)@67.195.81.190:53738) connected to ZooKeeper
I1108 04:44:55.329090 26190 group.cpp:790] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
I1108 04:44:55.329113 26190 group.cpp:385] Trying to create path '/log' in ZooKeeper
2014-11-08 04:44:55,329:26166(0x2b3e0d60a700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:42847], sessionId=0x1498db822360003, negotiated timeout=10000
I1108 04:44:55.330327 26188 group.cpp:313] Group process (group(56)@67.195.81.190:53738) connected to ZooKeeper
I1108 04:44:55.330359 26188 group.cpp:790] Syncing group operations: queue size (joins, cancels, datas) = (1, 0, 0)
I1108 04:44:55.330374 26188 group.cpp:385] Trying to create path '/log' in ZooKeeper
I1108 04:44:55.332345 26192 network.hpp:424] ZooKeeper group memberships changed
I1108 04:44:55.332495 26181 group.cpp:659] Trying to get '/log/0000000000' in ZooKeeper
I1108 04:44:55.333076 26192 network.hpp:424] ZooKeeper group memberships changed
I1108 04:44:55.333212 26191 group.cpp:659] Trying to get '/log/0000000000' in ZooKeeper
I1108 04:44:55.334625 26194 network.hpp:466] ZooKeeper group PIDs: { log-replica(438)@67.195.81.190:53738 }
I1108 04:44:55.335556 26186 network.hpp:466] ZooKeeper group PIDs: { log-replica(438)@67.195.81.190:53738 }
I1108 04:44:55.335785 26180 replica.cpp:474] Replica received implicit promise request with proposal 1
I1108 04:44:55.335963 26195 replica.cpp:474] Replica received implicit promise request with proposal 1
I1108 04:44:55.336510 26194 network.hpp:424] ZooKeeper group memberships changed
I1108 04:44:55.336638 26195 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 639914ns
I1108 04:44:55.336642 26180 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 818147ns
I1108 04:44:55.336666 26195 replica.cpp:342] Persisted promised to 1
I1108 04:44:55.336673 26180 replica.cpp:342] Persisted promised to 1
I1108 04:44:55.336662 26182 group.cpp:659] Trying to get '/log/0000000000' in ZooKeeper
I1108 04:44:55.337342 26186 network.hpp:424] ZooKeeper group memberships changed
I1108 04:44:55.337709 26189 coordinator.cpp:230] Coordinator attemping to fill missing position
I1108 04:44:55.337903 26182 group.cpp:659] Trying to get '/log/0000000001' in ZooKeeper
I1108 04:44:55.452550 26195 group.cpp:659] Trying to get '/log/0000000000' in ZooKeeper
I1108 04:44:55.454025 26195 group.cpp:659] Trying to get '/log/0000000001' in ZooKeeper
I1108 04:44:55.454591 26193 network.hpp:466] ZooKeeper group PIDs: { log-replica(438)@67.195.81.190:53738, log-replica(439)@67.195.81.190:53738 }
I1108 04:44:55.454737 26187 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
I1108 04:44:55.455200 26185 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
I1108 04:44:55.455358 26187 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 580678ns
I1108 04:44:55.455389 26187 replica.cpp:676] Persisted action at 0
I1108 04:44:55.455752 26185 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 511428ns
I1108 04:44:55.455786 26185 replica.cpp:676] Persisted action at 0
I1108 04:44:55.455962 26195 network.hpp:466] ZooKeeper group PIDs: { log-replica(438)@67.195.81.190:53738, log-replica(439)@67.195.81.190:53738 }
I1108 04:44:55.457196 26187 replica.cpp:508] Replica received write request for position 0
I1108 04:44:55.457259 26187 leveldb.cpp:438] Reading position from leveldb took 28672ns
I1108 04:44:55.457571 26183 replica.cpp:508] Replica received write request for position 0
I1108 04:44:55.457638 26183 leveldb.cpp:438] Reading position from leveldb took 29027ns
I1108 04:44:55.457691 26187 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 390166ns
I1108 04:44:55.457720 26187 replica.cpp:676] Persisted action at 0
I1108 04:44:55.458050 26183 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 374875ns
I1108 04:44:55.458076 26183 replica.cpp:676] Persisted action at 0
I1108 04:44:55.458554 26192 replica.cpp:655] Replica received learned notice for position 0
I1108 04:44:55.458592 26193 replica.cpp:655] Replica received learned notice for position 0
I1108 04:44:55.459014 26193 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 391444ns
I1108 04:44:55.459019 26192 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 431750ns
I1108 04:44:55.459045 26193 replica.cpp:676] Persisted action at 0
I1108 04:44:55.459055 26192 replica.cpp:676] Persisted action at 0
I1108 04:44:55.459067 26193 replica.cpp:661] Replica learned NOP action at position 0
I1108 04:44:55.459077 26192 replica.cpp:661] Replica learned NOP action at position 0
I1108 04:44:55.459836 26188 log.cpp:672] Writer started with ending position 0
I1108 04:44:55.460250 26180 log.cpp:680] Attempting to append 11 bytes to the log
I1108 04:44:55.460368 26191 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
I1108 04:44:55.461184 26186 replica.cpp:508] Replica received write request for position 1
I1108 04:44:55.461323 26183 replica.cpp:508] Replica received write request for position 1
I1108 04:44:55.461616 26186 leveldb.cpp:343] Persisting action (27 bytes) to leveldb took 394737ns
I1108 04:44:55.461643 26186 replica.cpp:676] Persisted action at 1
I1108 04:44:55.461727 26183 leveldb.cpp:343] Persisting action (27 bytes) to leveldb took 370577ns
I1108 04:44:55.461750 26183 replica.cpp:676] Persisted action at 1
I1108 04:44:55.462525 26194 replica.cpp:655] Replica received learned notice for position 1
I1108 04:44:55.462601 26191 replica.cpp:655] Replica received learned notice for position 1
I1108 04:44:55.462906 26191 leveldb.cpp:343] Persisting action (29 bytes) to leveldb took 275192ns
I1108 04:44:55.462906 26194 leveldb.cpp:343] Persisting action (29 bytes) to leveldb took 351125ns
I1108 04:44:55.462939 26191 replica.cpp:676] Persisted action at 1
I1108 04:44:55.462947 26194 replica.cpp:676] Persisted action at 1
I1108 04:44:55.462960 26191 replica.cpp:661] Replica learned APPEND action at position 1
I1108 04:44:55.462970 26194 replica.cpp:661] Replica learned APPEND action at position 1
I1108 04:44:55.464081 26181 leveldb.cpp:438] Reading position from leveldb took 36464ns
2014-11-08 04:44:55,465:26166(0x2b3a53084080):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x1498db822360003 to [127.0.0.1:42847]
2014-11-08 04:44:55,466:26166(0x2b3a5b32e700):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x1498db822360002 to [127.0.0.1:42847]
I1108 04:44:55.468557 26186 network.hpp:424] ZooKeeper group memberships changed
I1108 04:44:55.468693 26193 group.cpp:659] Trying to get '/log/0000000000' in ZooKeeper
2014-11-08 04:44:55,469:26166(0x2b3a5b931700):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x1498db822360001 to [127.0.0.1:42847]
2014-11-08 04:44:55,470:26166(0x2b3a5bf34700):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x1498db822360000 to [127.0.0.1:42847]
I1108 04:44:55.471582 26166 zookeeper_test_server.cpp:118] Shutting down ZooKeeperTestServer on port 42847
[ OK ] LogZooKeeperTest.WriteRead (254 ms)
[ RUN ] LogZooKeeperTest.LostZooKeeper
I1108 04:44:55.475536 26166 zookeeper_test_server.cpp:158] Started ZooKeeperTestServer on port 52306
I1108 04:44:55.475628 26166 log_tests.cpp:1945] Using temporary directory '/tmp/LogZooKeeperTest_LostZooKeeper_B5z3jV'
I1108 04:44:55.478559 26166 leveldb.cpp:176] Opened db in 2.846954ms
I1108 04:44:55.479370 26166 leveldb.cpp:183] Compacted db in 775391ns
I1108 04:44:55.479416 26166 leveldb.cpp:198] Created db iterator in 16244ns
I1108 04:44:55.479460 26166 leveldb.cpp:204] Seeked to beginning of db in 1968ns
I1108 04:44:55.479472 26166 leveldb.cpp:273] Iterated through 0 keys in the db in 482ns
I1108 04:44:55.479504 26166 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
2014-11-08 04:44:55,479:26166(0x2b3a5b12d700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-11-08 04:44:55,479:26166(0x2b3a5b12d700):ZOO_INFO@log_env@716: Client environment:host.name=pietas.apache.org
2014-11-08 04:44:55,479:26166(0x2b3a5b12d700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
2014-11-08 04:44:55,479:26166(0x2b3a5b12d700):ZOO_INFO@log_env@724: Client environment:os.arch=3.13.0-36-lowlatency
2014-11-08 04:44:55,479:26166(0x2b3a5b12d700):ZOO_INFO@log_env@725: Client environment:os.version=#63-Ubuntu SMP PREEMPT Wed Sep 3 21:56:12 UTC 2014
2014-11-08 04:44:55,480:26166(0x2b3a5b12d700):ZOO_INFO@log_env@733: Client environment:user.name=jenkins
2014-11-08 04:44:55,480:26166(0x2b3a5b12d700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
2014-11-08 04:44:55,480:26166(0x2b3a5b12d700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/LogZooKeeperTest_LostZooKeeper_B5z3jV
I1108 04:44:55.480145 26188 log.cpp:238] Attempting to join replica to ZooKeeper group
2014-11-08 04:44:55,480:26166(0x2b3a5b12d700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:52306 sessionTimeout=10000 watcher=0x2b3a56028b0a sessionId=0 sessionPasswd=<null> context=0x2b3a880a5d90 flags=0
2014-11-08 04:44:55,480:26166(0x2b3a5b931700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-11-08 04:44:55,480:26166(0x2b3a5b931700):ZOO_INFO@log_env@716: Client environment:host.name=pietas.apache.org
2014-11-08 04:44:55,480:26166(0x2b3a5b931700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
2014-11-08 04:44:55,480:26166(0x2b3a5b931700):ZOO_INFO@log_env@724: Client environment:os.arch=3.13.0-36-lowlatency
2014-11-08 04:44:55,480:26166(0x2b3a5b931700):ZOO_INFO@log_env@725: Client environment:os.version=#63-Ubuntu SMP PREEMPT Wed Sep 3 21:56:12 UTC 2014
2014-11-08 04:44:55,480:26166(0x2b3a5b931700):ZOO_INFO@log_env@733: Client environment:user.name=jenkins
I1108 04:44:55.480638 26190 recover.cpp:437] Starting replica recovery
2014-11-08 04:44:55,480:26166(0x2b3e0ca04700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:52306]
2014-11-08 04:44:55,480:26166(0x2b3a5b931700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
2014-11-08 04:44:55,624:26166(0x2b3a5b931700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/LogZooKeeperTest_LostZooKeeper_B5z3jV
2014-11-08 04:44:55,624:26166(0x2b3a5b931700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:52306 sessionTimeout=10000 watcher=0x2b3a56028b0a sessionId=0 sessionPasswd=<null> context=0x2b3a7c09cad0 flags=0
I1108 04:44:55.480916 26182 recover.cpp:463] Replica is in EMPTY status
2014-11-08 04:44:55,483:26166(0x2b3e0ca04700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:52306], sessionId=0x1498db823320000, negotiated timeout=10000
2014-11-08 04:44:55,624:26166(0x2b3e0de2d700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:52306]
I1108 04:44:55.625049 26189 group.cpp:313] Group process (group(57)@67.195.81.190:53738) connected to ZooKeeper
I1108 04:44:55.625107 26189 group.cpp:790] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
I1108 04:44:55.625128 26189 group.cpp:385] Trying to create path '/log' in ZooKeeper
I1108 04:44:55.625675 26192 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request
I1108 04:44:55.626123 26194 recover.cpp:188] Received a recover response from a replica in EMPTY status
2014-11-08 04:44:55,626:26166(0x2b3e0de2d700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:52306], sessionId=0x1498db823320001, negotiated timeout=10000
I1108 04:44:55.626602 26188 recover.cpp:554] Updating replica status to STARTING
I1108 04:44:55.627254 26191 group.cpp:313] Group process (group(58)@67.195.81.190:53738) connected to ZooKeeper
I1108 04:44:55.627338 26191 group.cpp:790] Syncing group operations: queue size (joins, cancels, datas) = (1, 0, 0)
I1108 04:44:55.627353 26191 group.cpp:385] Trying to create path '/log' in ZooKeeper
I1108 04:44:55.627354 26183 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 597985ns
I1108 04:44:55.627388 26183 replica.cpp:320] Persisted replica status to STARTING
I1108 04:44:55.627671 26187 recover.cpp:463] Replica is in STARTING status
I1108 04:44:55.628998 26186 replica.cpp:638] Replica in STARTING status received a broadcasted recover request
I1108 04:44:55.629487 26192 recover.cpp:188] Received a recover response from a replica in STARTING status
I1108 04:44:55.629966 26180 recover.cpp:554] Updating replica status to VOTING
I1108 04:44:55.630470 26182 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 365147ns
I1108 04:44:55.630506 26182 replica.cpp:320] Persisted replica status to VOTING
I1108 04:44:55.630600 26185 recover.cpp:568] Successfully joined the Paxos group
I1108 04:44:55.630774 26185 recover.cpp:452] Recover process terminated
I1108 04:44:55.631284 26193 log.cpp:656] Attempting to start the writer
I1108 04:44:55.632472 26186 network.hpp:424] ZooKeeper group memberships changed
I1108 04:44:55.632601 26187 group.cpp:659] Trying to get '/log/0000000000' in ZooKeeper
I1108 04:44:55.632657 26193 replica.cpp:474] Replica received implicit promise request with proposal 1
I1108 04:44:55.633139 26193 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 449102ns
I1108 04:44:55.633165 26193 replica.cpp:342] Persisted promised to 1
I1108 04:44:55.633846 26194 coordinator.cpp:230] Coordinator attemping to fill missing position
I1108 04:44:55.634021 26190 network.hpp:466] ZooKeeper group PIDs: { log-replica(440)@67.195.81.190:53738 }
I1108 04:44:55.635151 26180 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
I1108 04:44:55.635571 26180 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 382219ns
I1108 04:44:55.635596 26180 replica.cpp:676] Persisted action at 0
I1108 04:44:55.636574 26187 replica.cpp:508] Replica received write request for position 0
I1108 04:44:55.636646 26187 leveldb.cpp:438] Reading position from leveldb took 30476ns
I1108 04:44:55.637039 26187 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 357220ns
I1108 04:44:55.637065 26187 replica.cpp:676] Persisted action at 0
I1108 04:44:55.637536 26182 replica.cpp:655] Replica received learned notice for position 0
I1108 04:44:55.637980 26182 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 412783ns
I1108 04:44:55.638011 26182 replica.cpp:676] Persisted action at 0
I1108 04:44:55.638043 26182 replica.cpp:661] Replica learned NOP action at position 0
I1108 04:44:55.638600 26183 log.cpp:672] Writer started with ending position 0
I1108 04:44:55.638844 26166 zookeeper_test_server.cpp:118] Shutting down ZooKeeperTestServer on port 52306
2014-11-08 04:44:55,639:26166(0x2b3e0ca04700):ZOO_ERROR@handle_socket_error_msg@1721: Socket [127.0.0.1:52306] zk retcode=-4, errno=112(Host is down): failed while receiving a server response
2014-11-08 04:44:55,639:26166(0x2b3e0de2d700):ZOO_ERROR@handle_socket_error_msg@1721: Socket [127.0.0.1:52306] zk retcode=-4, errno=112(Host is down): failed while receiving a server response
I1108 04:44:55.640256 26183 group.cpp:418] Lost connection to ZooKeeper, attempting to reconnect ...
I1108 04:44:55.640638 26184 group.cpp:418] Lost connection to ZooKeeper, attempting to reconnect ...
I1108 04:44:55.641289 26188 log.cpp:680] Attempting to append 11 bytes to the log
I1108 04:44:55.641464 26182 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
I1108 04:44:55.642262 26184 replica.cpp:508] Replica received write request for position 1
I1108 04:44:55.642676 26184 leveldb.cpp:343] Persisting action (27 bytes) to leveldb took 375727ns
I1108 04:44:55.642704 26184 replica.cpp:676] Persisted action at 1
I1108 04:44:55.643218 26182 replica.cpp:655] Replica received learned notice for position 1
I1108 04:44:55.643797 26182 leveldb.cpp:343] Persisting action (29 bytes) to leveldb took 551262ns
I1108 04:44:55.643828 26182 replica.cpp:676] Persisted action at 1
I1108 04:44:55.643854 26182 replica.cpp:661] Replica learned APPEND action at position 1
I1108 04:44:55.644922 26185 leveldb.cpp:438] Reading position from leveldb took 33977ns
2014-11-08 04:44:55,646:26166(0x2b3a5a929700):ZOO_INFO@zookeeper_close@2522: Freeing zookeeper resources for sessionId=0x1498db823320001
2014-11-08 04:44:55,647:26166(0x2b3a5c336700):ZOO_INFO@zookeeper_close@2522: Freeing zookeeper resources for sessionId=0x1498db823320000
[ OK ] LogZooKeeperTest.LostZooKeeper (176 ms)
[----------] 2 tests from LogZooKeeperTest (430 ms total)
[----------] Global test environment tear-down
[==========] 458 tests from 71 test cases ran. (373138 ms total)
[ PASSED ] 457 tests.
[ FAILED ] 1 test, listed below:
[ FAILED ] MesosContainerizerExecuteTest.IoRedirection
1 FAILED TEST
YOU HAVE 6 DISABLED TESTS
make[3]: *** [check-local] Error 1
make[3]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/src'>
make[2]: *** [check-am] Error 2
make[2]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/src'>
make[1]: *** [check] Error 2
make[1]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/src'>
make: *** [check-recursive] Error 1
Test finished
Exit status: 2
Build step 'Execute shell' marked build as failure
Recording test results