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/05/07 06:37:57 UTC
Build failed in Jenkins: Mesos-Ubuntu-distcheck #79
See <https://builds.apache.org/job/Mesos-Ubuntu-distcheck/79/changes>
Changes:
[benjamin.hindman] Enabled unbundled usage of http-parser.
------------------------------------------
[...truncated 19388 lines...]
I0507 03:27:38.676010 5798 gc.cpp:56] Scheduling '/tmp/GarbageCollectorIntegrationTest_ExitedFramework_fAc62M/slaves/20140507-032738-453759884-58462-5758-0/frameworks/20140507-032738-453759884-58462-5758-0000' for gc 6.99999254958222days in the future
I0507 03:27:38.704622 5786 hierarchical_allocator_process.hpp:687] Performed allocation for 1 slaves in 11228ns
I0507 03:27:38.704907 5791 slave.cpp:2717] Framework 20140507-032738-453759884-58462-5758-0000 seems to have exited. Ignoring registration timeout for executor 'default'
I0507 03:27:38.704932 5794 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0507 03:27:38.705431 5791 slave.cpp:2801] Current usage 67.66%. Max allowed age: 1.563618673822245days
I0507 03:27:38.705549 5780 gc.cpp:134] Deleting /tmp/GarbageCollectorIntegrationTest_ExitedFramework_fAc62M/slaves/20140507-032738-453759884-58462-5758-0/frameworks/20140507-032738-453759884-58462-5758-0000/executors/default/runs/4879ef58-5529-4ba8-9f96-2ed505d57e17
I0507 03:27:38.705714 5780 gc.cpp:143] Deleted '/tmp/GarbageCollectorIntegrationTest_ExitedFramework_fAc62M/slaves/20140507-032738-453759884-58462-5758-0/frameworks/20140507-032738-453759884-58462-5758-0000/executors/default/runs/4879ef58-5529-4ba8-9f96-2ed505d57e17'
I0507 03:27:38.705773 5780 gc.cpp:134] Deleting /tmp/GarbageCollectorIntegrationTest_ExitedFramework_fAc62M/slaves/20140507-032738-453759884-58462-5758-0/frameworks/20140507-032738-453759884-58462-5758-0000/executors/default
I0507 03:27:38.705937 5780 gc.cpp:143] Deleted '/tmp/GarbageCollectorIntegrationTest_ExitedFramework_fAc62M/slaves/20140507-032738-453759884-58462-5758-0/frameworks/20140507-032738-453759884-58462-5758-0000/executors/default'
I0507 03:27:38.705953 5780 gc.cpp:134] Deleting /tmp/GarbageCollectorIntegrationTest_ExitedFramework_fAc62M/slaves/20140507-032738-453759884-58462-5758-0/frameworks/20140507-032738-453759884-58462-5758-0000
I0507 03:27:38.706040 5780 gc.cpp:143] Deleted '/tmp/GarbageCollectorIntegrationTest_ExitedFramework_fAc62M/slaves/20140507-032738-453759884-58462-5758-0/frameworks/20140507-032738-453759884-58462-5758-0000'
I0507 03:27:38.714886 5782 process.cpp:3335] Handling HTTP event for process 'files' with path: '/files/browse.json'
I0507 03:27:38.715406 5801 process.cpp:1037] Socket closed while receiving
I0507 03:27:38.724931 5758 master.cpp:552] Master terminating
I0507 03:27:38.725226 5782 slave.cpp:2152] master@140.211.11.27:58462 exited
W0507 03:27:38.725289 5782 slave.cpp:2155] Master disconnected! Waiting for a new master to be elected
I0507 03:27:38.727746 5758 slave.cpp:415] Slave terminating
[ OK ] GarbageCollectorIntegrationTest.ExitedFramework (371 ms)
[ RUN ] GarbageCollectorIntegrationTest.DiskUsage
Using temporary directory '/tmp/GarbageCollectorIntegrationTest_DiskUsage_pU3Ym7'
I0507 03:27:38.775058 5758 leveldb.cpp:174] Opened db in 44.343989ms
I0507 03:27:38.787498 5758 leveldb.cpp:181] Compacted db in 12.411065ms
I0507 03:27:38.787533 5758 leveldb.cpp:196] Created db iterator in 4008ns
I0507 03:27:38.787545 5758 leveldb.cpp:202] Seeked to beginning of db in 598ns
I0507 03:27:38.787552 5758 leveldb.cpp:271] Iterated through 0 keys in the db in 173ns
I0507 03:27:38.787564 5758 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0507 03:27:38.787858 5777 recover.cpp:425] Starting replica recovery
I0507 03:27:38.788352 5793 master.cpp:267] Master 20140507-032738-453759884-58462-5758 (hemera.apache.org) started on 140.211.11.27:58462
I0507 03:27:38.788377 5793 master.cpp:304] Master only allowing authenticated frameworks to register
I0507 03:27:38.788383 5793 master.cpp:309] Master only allowing authenticated slaves to register
I0507 03:27:38.788389 5793 credentials.hpp:35] Loading credentials for authentication
I0507 03:27:38.789064 5779 recover.cpp:451] Replica is in EMPTY status
W0507 03:27:38.789115 5793 credentials.hpp:48] Failed to stat credentials file 'file:///tmp/GarbageCollectorIntegrationTest_DiskUsage_pU3Ym7/credentials': No such file or directory
I0507 03:27:38.789489 5779 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0507 03:27:38.789531 5778 hierarchical_allocator_process.hpp:301] Initializing hierarchical allocator process with master : master@140.211.11.27:58462
I0507 03:27:38.791007 5788 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request
I0507 03:27:38.791177 5780 master.cpp:921] The newly elected leader is master@140.211.11.27:58462 with id 20140507-032738-453759884-58462-5758
I0507 03:27:38.791198 5780 master.cpp:931] Elected as the leading master!
I0507 03:27:38.791205 5780 master.cpp:752] Recovering from registrar
I0507 03:27:38.791251 5796 recover.cpp:188] Received a recover response from a replica in EMPTY status
I0507 03:27:38.791323 5797 registrar.cpp:313] Recovering registrar
I0507 03:27:38.792137 5795 recover.cpp:542] Updating replica status to STARTING
I0507 03:27:38.807531 5781 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 15.124092ms
I0507 03:27:38.807559 5781 replica.cpp:320] Persisted replica status to STARTING
I0507 03:27:38.807621 5781 recover.cpp:451] Replica is in STARTING status
I0507 03:27:38.809319 5799 replica.cpp:638] Replica in STARTING status received a broadcasted recover request
I0507 03:27:38.809983 5795 recover.cpp:188] Received a recover response from a replica in STARTING status
I0507 03:27:38.811204 5778 recover.cpp:542] Updating replica status to VOTING
I0507 03:27:38.827595 5795 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 16.011355ms
I0507 03:27:38.827627 5795 replica.cpp:320] Persisted replica status to VOTING
I0507 03:27:38.827683 5795 recover.cpp:556] Successfully joined the Paxos group
I0507 03:27:38.827775 5795 recover.cpp:440] Recover process terminated
I0507 03:27:38.828966 5780 log.cpp:656] Attempting to start the writer
I0507 03:27:38.831114 5782 replica.cpp:474] Replica received implicit promise request with proposal 1
I0507 03:27:38.847708 5782 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 16.573137ms
I0507 03:27:38.847739 5782 replica.cpp:342] Persisted promised to 1
I0507 03:27:38.848141 5797 coordinator.cpp:230] Coordinator attemping to fill missing position
I0507 03:27:38.849684 5790 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
I0507 03:27:38.863777 5790 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 14.076775ms
I0507 03:27:38.863801 5790 replica.cpp:676] Persisted action at 0
I0507 03:27:38.864915 5798 replica.cpp:508] Replica received write request for position 0
I0507 03:27:38.864949 5798 leveldb.cpp:436] Reading position from leveldb took 11807ns
I0507 03:27:38.879945 5798 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 14.978446ms
I0507 03:27:38.879976 5798 replica.cpp:676] Persisted action at 0
I0507 03:27:38.880491 5797 replica.cpp:655] Replica received learned notice for position 0
I0507 03:27:38.895969 5797 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 15.459949ms
I0507 03:27:38.895992 5797 replica.cpp:676] Persisted action at 0
I0507 03:27:38.896003 5797 replica.cpp:661] Replica learned NOP action at position 0
I0507 03:27:38.896411 5783 log.cpp:672] Writer started with ending position 0
I0507 03:27:38.898058 5798 leveldb.cpp:436] Reading position from leveldb took 11910ns
I0507 03:27:38.899749 5777 registrar.cpp:346] Successfully fetched the registry (0B)
I0507 03:27:38.899766 5777 registrar.cpp:422] Attempting to update the 'registry'
I0507 03:27:38.901458 5791 log.cpp:680] Attempting to append 137 bytes to the log
I0507 03:27:38.901666 5780 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
I0507 03:27:38.902773 5783 replica.cpp:508] Replica received write request for position 1
I0507 03:27:38.916127 5783 leveldb.cpp:341] Persisting action (156 bytes) to leveldb took 13.225715ms
I0507 03:27:38.916152 5783 replica.cpp:676] Persisted action at 1
I0507 03:27:38.916534 5790 replica.cpp:655] Replica received learned notice for position 1
I0507 03:27:38.928203 5790 leveldb.cpp:341] Persisting action (158 bytes) to leveldb took 11.652434ms
I0507 03:27:38.928225 5790 replica.cpp:676] Persisted action at 1
I0507 03:27:38.928236 5790 replica.cpp:661] Replica learned APPEND action at position 1
I0507 03:27:38.928546 5790 registrar.cpp:479] Successfully updated 'registry'
I0507 03:27:38.928642 5790 registrar.cpp:372] Successfully recovered registrar
I0507 03:27:38.929044 5783 master.cpp:779] Recovered 0 slaves from the Registry (99B) ; allowing 10mins for slaves to re-register
I0507 03:27:38.929502 5799 log.cpp:699] Attempting to truncate the log to 1
I0507 03:27:38.929888 5797 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
I0507 03:27:38.930161 5781 replica.cpp:508] Replica received write request for position 2
I0507 03:27:38.932977 5789 slave.cpp:140] Slave started on 56)@140.211.11.27:58462
I0507 03:27:38.932991 5789 credentials.hpp:35] Loading credentials for authentication
W0507 03:27:38.933567 5789 credentials.hpp:48] Failed to stat credentials file 'file:///tmp/GarbageCollectorIntegrationTest_DiskUsage_A9Pxks/credential': No such file or directory
I0507 03:27:38.933585 5789 slave.cpp:230] Slave using credential for: test-principal
I0507 03:27:38.933765 5789 slave.cpp:243] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0507 03:27:38.933854 5789 slave.cpp:271] Slave hostname: hemera.apache.org
I0507 03:27:38.933863 5789 slave.cpp:272] Slave checkpoint: false
I0507 03:27:38.934239 5778 state.cpp:33] Recovering state from '/tmp/GarbageCollectorIntegrationTest_DiskUsage_A9Pxks/meta'
I0507 03:27:38.934960 5792 status_update_manager.cpp:193] Recovering status update manager
I0507 03:27:38.935123 5779 slave.cpp:2945] Finished recovery
I0507 03:27:38.936998 5779 slave.cpp:526] New master detected at master@140.211.11.27:58462
I0507 03:27:38.937021 5779 slave.cpp:586] Authenticating with master master@140.211.11.27:58462
I0507 03:27:38.937077 5798 status_update_manager.cpp:167] New master detected at master@140.211.11.27:58462
I0507 03:27:38.937306 5779 slave.cpp:559] Detecting new master
I0507 03:27:38.937335 5800 authenticatee.hpp:128] Creating new client SASL connection
I0507 03:27:38.938030 5778 master.cpp:2798] Authenticating slave(56)@140.211.11.27:58462
I0507 03:27:38.938742 5783 authenticator.hpp:148] Creating new server SASL connection
I0507 03:27:38.939312 5786 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0507 03:27:38.939340 5786 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0507 03:27:38.939390 5786 authenticator.hpp:254] Received SASL authentication start
I0507 03:27:38.939553 5786 authenticator.hpp:342] Authentication requires more steps
I0507 03:27:38.939592 5786 authenticatee.hpp:265] Received SASL authentication step
I0507 03:27:38.939715 5786 authenticator.hpp:282] Received SASL authentication step
I0507 03:27:38.939803 5786 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0507 03:27:38.939821 5786 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I0507 03:27:38.939831 5786 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0507 03:27:38.939841 5786 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0507 03:27:38.939851 5786 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0507 03:27:38.939857 5786 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0507 03:27:38.939870 5786 authenticator.hpp:334] Authentication success
I0507 03:27:38.939937 5786 authenticatee.hpp:305] Authentication success
I0507 03:27:38.940016 5778 master.cpp:2838] Successfully authenticated slave(56)@140.211.11.27:58462
I0507 03:27:38.940449 5799 slave.cpp:643] Successfully authenticated with master master@140.211.11.27:58462
I0507 03:27:38.940513 5799 slave.cpp:872] Will retry registration in 5.176207635secs if necessary
I0507 03:27:38.940625 5794 master.cpp:2134] Registering slave at slave(56)@140.211.11.27:58462 (hemera.apache.org) with id 20140507-032738-453759884-58462-5758-0
I0507 03:27:38.940800 5796 registrar.cpp:422] Attempting to update the 'registry'
I0507 03:27:38.940850 5781 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 10.659152ms
I0507 03:27:38.940871 5781 replica.cpp:676] Persisted action at 2
I0507 03:27:38.941843 5788 replica.cpp:655] Replica received learned notice for position 2
I0507 03:27:38.953193 5788 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 11.291343ms
I0507 03:27:38.953258 5788 leveldb.cpp:399] Deleting ~1 keys from leveldb took 33725ns
I0507 03:27:38.953274 5788 replica.cpp:676] Persisted action at 2
I0507 03:27:38.953282 5788 replica.cpp:661] Replica learned TRUNCATE action at position 2
I0507 03:27:38.953541 5797 log.cpp:680] Attempting to append 330 bytes to the log
I0507 03:27:38.953614 5797 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
I0507 03:27:38.954731 5789 replica.cpp:508] Replica received write request for position 3
I0507 03:27:38.965240 5789 leveldb.cpp:341] Persisting action (349 bytes) to leveldb took 10.489719ms
I0507 03:27:38.965261 5789 replica.cpp:676] Persisted action at 3
I0507 03:27:38.966253 5780 replica.cpp:655] Replica received learned notice for position 3
I0507 03:27:38.977375 5780 leveldb.cpp:341] Persisting action (351 bytes) to leveldb took 11.098798ms
I0507 03:27:38.977408 5780 replica.cpp:676] Persisted action at 3
I0507 03:27:38.977421 5780 replica.cpp:661] Replica learned APPEND action at position 3
I0507 03:27:38.977859 5792 registrar.cpp:479] Successfully updated 'registry'
I0507 03:27:38.977926 5780 log.cpp:699] Attempting to truncate the log to 3
I0507 03:27:38.978060 5792 master.cpp:2174] Registered slave 20140507-032738-453759884-58462-5758-0 at slave(56)@140.211.11.27:58462 (hemera.apache.org)
I0507 03:27:38.978112 5792 master.cpp:3283] Adding slave 20140507-032738-453759884-58462-5758-0 at slave(56)@140.211.11.27:58462 (hemera.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0507 03:27:38.978134 5784 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
I0507 03:27:38.978508 5785 slave.cpp:676] Registered with master master@140.211.11.27:58462; given slave ID 20140507-032738-453759884-58462-5758-0
I0507 03:27:38.978631 5786 hierarchical_allocator_process.hpp:444] Added slave 20140507-032738-453759884-58462-5758-0 (hemera.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
I0507 03:27:38.978677 5786 hierarchical_allocator_process.hpp:707] Performed allocation for slave 20140507-032738-453759884-58462-5758-0 in 5421ns
I0507 03:27:38.979872 5796 replica.cpp:508] Replica received write request for position 4
I0507 03:27:38.982084 5758 sched.cpp:121] Version: 0.19.0
I0507 03:27:38.982213 5789 sched.cpp:217] New master detected at master@140.211.11.27:58462
I0507 03:27:38.982228 5789 sched.cpp:268] Authenticating with master master@140.211.11.27:58462
I0507 03:27:38.982347 5788 authenticatee.hpp:128] Creating new client SASL connection
I0507 03:27:38.982676 5788 master.cpp:2798] Authenticating scheduler(59)@140.211.11.27:58462
I0507 03:27:38.983100 5788 authenticator.hpp:148] Creating new server SASL connection
I0507 03:27:38.983294 5788 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0507 03:27:38.983312 5788 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0507 03:27:38.983360 5788 authenticator.hpp:254] Received SASL authentication start
I0507 03:27:38.983505 5788 authenticator.hpp:342] Authentication requires more steps
I0507 03:27:38.984220 5782 authenticatee.hpp:265] Received SASL authentication step
I0507 03:27:38.984275 5782 authenticator.hpp:282] Received SASL authentication step
I0507 03:27:38.984315 5782 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0507 03:27:38.984347 5782 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I0507 03:27:38.984359 5782 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0507 03:27:38.984370 5782 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0507 03:27:38.984377 5782 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0507 03:27:38.984383 5782 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0507 03:27:38.984397 5782 authenticator.hpp:334] Authentication success
I0507 03:27:38.984429 5782 authenticatee.hpp:305] Authentication success
I0507 03:27:38.984469 5795 master.cpp:2838] Successfully authenticated scheduler(59)@140.211.11.27:58462
I0507 03:27:38.985110 5782 sched.cpp:342] Successfully authenticated with master master@140.211.11.27:58462
I0507 03:27:38.985133 5782 sched.cpp:461] Sending registration request to master@140.211.11.27:58462
I0507 03:27:38.985326 5795 master.cpp:980] Received registration request from scheduler(59)@140.211.11.27:58462
I0507 03:27:38.985357 5795 master.cpp:998] Registering framework 20140507-032738-453759884-58462-5758-0000 at scheduler(59)@140.211.11.27:58462
I0507 03:27:38.985424 5795 sched.cpp:392] Framework registered with 20140507-032738-453759884-58462-5758-0000
I0507 03:27:38.985471 5792 hierarchical_allocator_process.hpp:331] Added framework 20140507-032738-453759884-58462-5758-0000
I0507 03:27:38.985610 5795 sched.cpp:406] Scheduler::registered took 36702ns
I0507 03:27:38.985646 5792 hierarchical_allocator_process.hpp:751] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140507-032738-453759884-58462-5758-0 to framework 20140507-032738-453759884-58462-5758-0000
I0507 03:27:38.985954 5792 hierarchical_allocator_process.hpp:687] Performed allocation for 1 slaves in 330895ns
I0507 03:27:38.986001 5789 master.hpp:612] Adding offer 20140507-032738-453759884-58462-5758-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140507-032738-453759884-58462-5758-0 (hemera.apache.org)
I0507 03:27:38.986090 5789 master.cpp:2747] Sending 1 offers to framework 20140507-032738-453759884-58462-5758-0000
I0507 03:27:38.986548 5792 sched.cpp:529] Scheduler::resourceOffers took 162873ns
I0507 03:27:38.986721 5792 master.hpp:622] Removing offer 20140507-032738-453759884-58462-5758-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140507-032738-453759884-58462-5758-0 (hemera.apache.org)
I0507 03:27:38.986781 5792 master.cpp:1812] Processing reply for offers: [ 20140507-032738-453759884-58462-5758-0 ] on slave 20140507-032738-453759884-58462-5758-0 at slave(56)@140.211.11.27:58462 (hemera.apache.org) for framework 20140507-032738-453759884-58462-5758-0000
I0507 03:27:38.986843 5792 master.hpp:584] Adding task 0 with resources cpus(*):2; mem(*):1024 on slave 20140507-032738-453759884-58462-5758-0 (hemera.apache.org)
I0507 03:27:38.986876 5792 master.cpp:2922] Launching task 0 of framework 20140507-032738-453759884-58462-5758-0000 with resources cpus(*):2; mem(*):1024 on slave 20140507-032738-453759884-58462-5758-0 at slave(56)@140.211.11.27:58462 (hemera.apache.org)
I0507 03:27:38.986981 5795 slave.cpp:906] Got assigned task 0 for framework 20140507-032738-453759884-58462-5758-0000
I0507 03:27:38.987180 5795 slave.cpp:1016] Launching task 0 for framework 20140507-032738-453759884-58462-5758-0000
I0507 03:27:38.987203 5787 hierarchical_allocator_process.hpp:546] Framework 20140507-032738-453759884-58462-5758-0000 left disk(*):1024; ports(*):[31000-32000] unused on slave 20140507-032738-453759884-58462-5758-0
I0507 03:27:38.987287 5787 hierarchical_allocator_process.hpp:589] Framework 20140507-032738-453759884-58462-5758-0000 filtered slave 20140507-032738-453759884-58462-5758-0 for 5secs
I0507 03:27:38.991395 5795 exec.cpp:131] Version: 0.19.0
I0507 03:27:38.991497 5779 exec.cpp:181] Executor started at: executor(27)@140.211.11.27:58462 with pid 5758
I0507 03:27:38.991510 5795 slave.cpp:1126] Queuing task '0' for executor default of framework '20140507-032738-453759884-58462-5758-0000
I0507 03:27:38.991566 5795 slave.cpp:487] Successfully attached file '/tmp/GarbageCollectorIntegrationTest_DiskUsage_A9Pxks/slaves/20140507-032738-453759884-58462-5758-0/frameworks/20140507-032738-453759884-58462-5758-0000/executors/default/runs/de776bec-2822-4bbc-befc-eec40eb5f674'
I0507 03:27:38.991595 5795 slave.cpp:2283] Monitoring executor 'default' of framework '20140507-032738-453759884-58462-5758-0000' in container 'de776bec-2822-4bbc-befc-eec40eb5f674'
I0507 03:27:38.991778 5795 slave.cpp:1599] Got registration for executor 'default' of framework 20140507-032738-453759884-58462-5758-0000
I0507 03:27:38.991874 5795 slave.cpp:1718] Flushing queued task 0 for executor 'default' of framework 20140507-032738-453759884-58462-5758-0000
I0507 03:27:38.991935 5780 exec.cpp:205] Executor registered on slave 20140507-032738-453759884-58462-5758-0
I0507 03:27:38.993419 5796 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 13.489998ms
I0507 03:27:38.993449 5796 replica.cpp:676] Persisted action at 4
I0507 03:27:38.994510 5777 replica.cpp:655] Replica received learned notice for position 4
I0507 03:27:38.994753 5780 exec.cpp:217] Executor::registered took 14516ns
I0507 03:27:38.994818 5780 exec.cpp:292] Executor asked to run task '0'
I0507 03:27:38.994849 5780 exec.cpp:301] Executor::launchTask took 18872ns
I0507 03:27:38.996703 5780 exec.cpp:524] Executor sending status update TASK_RUNNING (UUID: be7346ad-e198-4b38-9252-421ff759fdee) for task 0 of framework 20140507-032738-453759884-58462-5758-0000
I0507 03:27:38.996793 5780 slave.cpp:1954] Handling status update TASK_RUNNING (UUID: be7346ad-e198-4b38-9252-421ff759fdee) for task 0 of framework 20140507-032738-453759884-58462-5758-0000 from executor(27)@140.211.11.27:58462
I0507 03:27:38.996888 5780 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: be7346ad-e198-4b38-9252-421ff759fdee) for task 0 of framework 20140507-032738-453759884-58462-5758-0000
I0507 03:27:38.996920 5780 status_update_manager.cpp:499] Creating StatusUpdate stream for task 0 of framework 20140507-032738-453759884-58462-5758-0000
I0507 03:27:38.996968 5780 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: be7346ad-e198-4b38-9252-421ff759fdee) for task 0 of framework 20140507-032738-453759884-58462-5758-0000 to master@140.211.11.27:58462
I0507 03:27:38.997189 5790 master.cpp:2450] Status update TASK_RUNNING (UUID: be7346ad-e198-4b38-9252-421ff759fdee) for task 0 of framework 20140507-032738-453759884-58462-5758-0000 from slave 20140507-032738-453759884-58462-5758-0 at slave(56)@140.211.11.27:58462 (hemera.apache.org)
I0507 03:27:38.997268 5780 slave.cpp:2071] Status update manager successfully handled status update TASK_RUNNING (UUID: be7346ad-e198-4b38-9252-421ff759fdee) for task 0 of framework 20140507-032738-453759884-58462-5758-0000
I0507 03:27:38.997321 5797 sched.cpp:620] Scheduler::statusUpdate took 77906ns
I0507 03:27:38.997336 5780 slave.cpp:2077] Sending acknowledgement for status update TASK_RUNNING (UUID: be7346ad-e198-4b38-9252-421ff759fdee) for task 0 of framework 20140507-032738-453759884-58462-5758-0000 to executor(27)@140.211.11.27:58462
I0507 03:27:38.998700 5797 slave.cpp:2341] Executor 'default' of framework 20140507-032738-453759884-58462-5758-0000 has exited with status 0
I0507 03:27:38.998814 5793 exec.cpp:338] Executor received status update acknowledgement be7346ad-e198-4b38-9252-421ff759fdee for task 0 of framework 20140507-032738-453759884-58462-5758-0000
I0507 03:27:39.000041 5797 slave.cpp:1954] Handling status update TASK_LOST (UUID: 4c8e572c-3fa7-43f3-aaf8-f82e77a70c1b) for task 0 of framework 20140507-032738-453759884-58462-5758-0000 from @0.0.0.0:0
I0507 03:27:39.000063 5797 slave.cpp:3446] Terminating task 0
I0507 03:27:39.000190 5797 status_update_manager.cpp:320] Received status update TASK_LOST (UUID: 4c8e572c-3fa7-43f3-aaf8-f82e77a70c1b) for task 0 of framework 20140507-032738-453759884-58462-5758-0000
I0507 03:27:39.000229 5779 master.cpp:2523] Executor default of framework 20140507-032738-453759884-58462-5758-0000 on slave 20140507-032738-453759884-58462-5758-0 at slave(56)@140.211.11.27:58462 (hemera.apache.org) has exited with status 0
I0507 03:27:39.000341 5797 status_update_manager.cpp:398] Received status update acknowledgement (UUID: be7346ad-e198-4b38-9252-421ff759fdee) for task 0 of framework 20140507-032738-453759884-58462-5758-0000
I0507 03:27:39.000385 5797 status_update_manager.cpp:373] Forwarding status update TASK_LOST (UUID: 4c8e572c-3fa7-43f3-aaf8-f82e77a70c1b) for task 0 of framework 20140507-032738-453759884-58462-5758-0000 to master@140.211.11.27:58462
I0507 03:27:39.000516 5791 slave.cpp:2071] Status update manager successfully handled status update TASK_LOST (UUID: 4c8e572c-3fa7-43f3-aaf8-f82e77a70c1b) for task 0 of framework 20140507-032738-453759884-58462-5758-0000
I0507 03:27:39.000686 5791 slave.cpp:1539] Status update manager successfully handled status update acknowledgement (UUID: be7346ad-e198-4b38-9252-421ff759fdee) for task 0 of framework 20140507-032738-453759884-58462-5758-0000
I0507 03:27:39.000759 5795 master.cpp:2450] Status update TASK_LOST (UUID: 4c8e572c-3fa7-43f3-aaf8-f82e77a70c1b) for task 0 of framework 20140507-032738-453759884-58462-5758-0000 from slave 20140507-032738-453759884-58462-5758-0 at slave(56)@140.211.11.27:58462 (hemera.apache.org)
I0507 03:27:39.000841 5784 sched.cpp:620] Scheduler::statusUpdate took 11418ns
I0507 03:27:39.000849 5795 master.hpp:602] Removing task 0 with resources cpus(*):2; mem(*):1024 on slave 20140507-032738-453759884-58462-5758-0 (hemera.apache.org)
I0507 03:27:39.001313 5799 hierarchical_allocator_process.hpp:636] Recovered cpus(*):2; mem(*):1024 (total allocatable: disk(*):1024; ports(*):[31000-32000]; cpus(*):2; mem(*):1024) on slave 20140507-032738-453759884-58462-5758-0 from framework 20140507-032738-453759884-58462-5758-0000
I0507 03:27:39.002792 5778 status_update_manager.cpp:398] Received status update acknowledgement (UUID: 4c8e572c-3fa7-43f3-aaf8-f82e77a70c1b) for task 0 of framework 20140507-032738-453759884-58462-5758-0000
I0507 03:27:39.002831 5778 status_update_manager.cpp:530] Cleaning up status update stream for task 0 of framework 20140507-032738-453759884-58462-5758-0000
I0507 03:27:39.002903 5778 slave.cpp:1539] Status update manager successfully handled status update acknowledgement (UUID: 4c8e572c-3fa7-43f3-aaf8-f82e77a70c1b) for task 0 of framework 20140507-032738-453759884-58462-5758-0000
I0507 03:27:39.002976 5778 slave.cpp:3470] Completing task 0
I0507 03:27:39.002991 5778 slave.cpp:2480] Cleaning up executor 'default' of framework 20140507-032738-453759884-58462-5758-0000
I0507 03:27:39.006098 5778 slave.cpp:2555] Cleaning up framework 20140507-032738-453759884-58462-5758-0000
I0507 03:27:39.006105 5800 gc.cpp:56] Scheduling '/tmp/GarbageCollectorIntegrationTest_DiskUsage_A9Pxks/slaves/20140507-032738-453759884-58462-5758-0/frameworks/20140507-032738-453759884-58462-5758-0000/executors/default/runs/de776bec-2822-4bbc-befc-eec40eb5f674' for gc 1.00000000231788weeks in the future
I0507 03:27:39.006146 5800 gc.cpp:56] Scheduling '/tmp/GarbageCollectorIntegrationTest_DiskUsage_A9Pxks/slaves/20140507-032738-453759884-58462-5758-0/frameworks/20140507-032738-453759884-58462-5758-0000/executors/default' for gc 1.00000000231788weeks in the future
I0507 03:27:39.006211 5786 status_update_manager.cpp:282] Closing status update streams for framework 20140507-032738-453759884-58462-5758-0000
I0507 03:27:39.006299 5786 gc.cpp:56] Scheduling '/tmp/GarbageCollectorIntegrationTest_DiskUsage_A9Pxks/slaves/20140507-032738-453759884-58462-5758-0/frameworks/20140507-032738-453759884-58462-5758-0000' for gc 1.00000000231788weeks in the future
I0507 03:27:39.010058 5777 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 15.533184ms
I0507 03:27:39.010144 5777 leveldb.cpp:399] Deleting ~2 keys from leveldb took 64787ns
I0507 03:27:39.010154 5777 replica.cpp:676] Persisted action at 4
I0507 03:27:39.010160 5777 replica.cpp:661] Replica learned TRUNCATE action at position 4
I0507 03:27:39.029413 5789 slave.cpp:2801] Current usage 90.00%. Max allowed age: 0ns
../../src/tests/gc_tests.cpp:658: Failure
Value of: os::exists(executorDir)
Actual: true
Expected: false
Build timed out (after 120 minutes). Marking the build as failed.
Build was aborted
make[1]: *** [check-recursive] Terminated
make: *** [distcheck] Terminated
Jenkins build is back to normal : Mesos-Ubuntu-distcheck #82
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/Mesos-Ubuntu-distcheck/82/changes>
Build failed in Jenkins: Mesos-Ubuntu-distcheck #80
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/Mesos-Ubuntu-distcheck/80/changes>
Changes:
[dlester] Adds Singularity to Mesos Frameworks page.
[bmahler] Cleaned up the logging level configuration.
[bmahler] Documented Clock::settle.
[bmahler] MESOS-1310: Changed 'reply' to 'send' in slave registration.
------------------------------------------
[...truncated 11500 lines...]
I0508 02:37:07.984302 28416 contender.cpp:127] Joining the ZK group
2014-05-08 02:37:07,984:28305(0x2b822dffe700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
2014-05-08 02:37:07,984:28305(0x2b822dffe700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
2014-05-08 02:37:07,984:28305(0x2b822dffe700):ZOO_INFO@log_env@753: Client environment:user.dir=/x1/jenkins/jenkins-slave/workspace/Mesos-Ubuntu-distcheck/build/mesos-0.19.0/_build/src
2014-05-08 02:37:07,984:28305(0x2b822dffe700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:57654 sessionTimeout=10000 watcher=0x2b822b50fe60 sessionId=0 sessionPasswd=<null> context=0x2b825001bc70 flags=0
2014-05-08 02:37:07,984:28305(0x2b84a5a51700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:57654]
2014-05-08 02:37:08,036:28305(0x2b84a5a51700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:57654], sessionId=0x145d9b0f0820000, negotiated timeout=10000
I0508 02:37:08.036310 28409 group.cpp:310] Group process ((557)@140.211.11.27:38066) connected to ZooKeeper
I0508 02:37:08.036425 28409 group.cpp:784] Syncing group operations: queue size (joins, cancels, datas) = (1, 0, 0)
I0508 02:37:08.036437 28409 group.cpp:382] Trying to create path '/mesos' in ZooKeeper
I0508 02:37:08.049660 28395 contender.cpp:243] New candidate (id='0') has entered the contest for leadership
2014-05-08 02:37:08,050:28305(0x2b822e802700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-05-08 02:37:08,050:28305(0x2b822e802700):ZOO_INFO@log_env@716: Client environment:host.name=hemera
2014-05-08 02:37:08,050:28305(0x2b822e802700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
2014-05-08 02:37:08,050:28305(0x2b822e802700):ZOO_INFO@log_env@724: Client environment:os.arch=3.2.0-57-generic
2014-05-08 02:37:08,050:28305(0x2b822e802700):ZOO_INFO@log_env@725: Client environment:os.version=#87-Ubuntu SMP Tue Nov 12 21:35:10 UTC 2013
2014-05-08 02:37:08,050:28305(0x2b822e802700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
2014-05-08 02:37:08,051:28305(0x2b822e802700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
2014-05-08 02:37:08,051:28305(0x2b822e802700):ZOO_INFO@log_env@753: Client environment:user.dir=/x1/jenkins/jenkins-slave/workspace/Mesos-Ubuntu-distcheck/build/mesos-0.19.0/_build/src
2014-05-08 02:37:08,051:28305(0x2b822e802700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:57654 sessionTimeout=10000 watcher=0x2b822b50fe60 sessionId=0 sessionPasswd=<null> context=0x2b8248004960 flags=0
2014-05-08 02:37:08,051:28305(0x2b84d8201700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:57654]
2014-05-08 02:37:08,057:28305(0x2b84d8201700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:57654], sessionId=0x145d9b0f0820001, negotiated timeout=10000
I0508 02:37:08.057857 28401 group.cpp:310] Group process ((559)@140.211.11.27:38066) connected to ZooKeeper
I0508 02:37:08.057881 28401 group.cpp:784] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
I0508 02:37:08.057889 28401 group.cpp:382] Trying to create path '/mesos' in ZooKeeper
I0508 02:37:08.060474 28401 detector.cpp:135] Detected a new leader: (id='0')
I0508 02:37:08.060912 28395 group.cpp:655] Trying to get '/mesos/info_0000000000' in ZooKeeper
I0508 02:37:08.062326 28395 detector.cpp:377] A new leading master (UPID=@128.150.152.0:10000) is detected
I0508 02:37:08.063225 28305 jvm.cpp:567] Looking up method closeSession(J)V
2014-05-08 02:37:08,065:28305(0x2b84d8201700):ZOO_ERROR@handle_socket_error_msg@1721: Socket [127.0.0.1:57654] zk retcode=-4, errno=112(Host is down): failed while receiving a server response
I0508 02:37:08.065991 28414 group.cpp:415] Lost connection to ZooKeeper, attempting to reconnect ...
2014-05-08 02:37:11,402:28305(0x2b84d8201700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:57654]
2014-05-08 02:37:11,403:28305(0x2b84d8201700):ZOO_ERROR@handle_socket_error_msg@1739: Socket [127.0.0.1:57654] zk retcode=-112, errno=116(Stale NFS file handle): sessionId=0x145d9b0f0820001 has expired.
I0508 02:37:11.403323 28410 group.cpp:469] ZooKeeper session expired
I0508 02:37:11.403497 28416 detector.cpp:123] The current leader (id=0) is lost
I0508 02:37:11.403517 28416 detector.cpp:135] Detected a new leader: None
2014-05-08 02:37:11,403:28305(0x2b822fe0d700):ZOO_INFO@zookeeper_close@2522: Freeing zookeeper resources for sessionId=0x145d9b0f0820001
2014-05-08 02:37:11,403:28305(0x2b822fe0d700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-05-08 02:37:11,403:28305(0x2b822fe0d700):ZOO_INFO@log_env@716: Client environment:host.name=hemera
2014-05-08 02:37:11,403:28305(0x2b822fe0d700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
2014-05-08 02:37:11,404:28305(0x2b822fe0d700):ZOO_INFO@log_env@724: Client environment:os.arch=3.2.0-57-generic
2014-05-08 02:37:11,404:28305(0x2b822fe0d700):ZOO_INFO@log_env@725: Client environment:os.version=#87-Ubuntu SMP Tue Nov 12 21:35:10 UTC 2013
2014-05-08 02:37:11,405:28305(0x2b822fe0d700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
2014-05-08 02:37:11,405:28305(0x2b822fe0d700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
2014-05-08 02:37:11,405:28305(0x2b822fe0d700):ZOO_INFO@log_env@753: Client environment:user.dir=/x1/jenkins/jenkins-slave/workspace/Mesos-Ubuntu-distcheck/build/mesos-0.19.0/_build/src
2014-05-08 02:37:11,405:28305(0x2b822fe0d700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:57654 sessionTimeout=10000 watcher=0x2b822b50fe60 sessionId=0 sessionPasswd=<null> context=0x2b829000b140 flags=0
2014-05-08 02:37:11,405:28305(0x2b84a5850700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:57654]
2014-05-08 02:37:11,413:28305(0x2b84a5850700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:57654], sessionId=0x145d9b0f0820002, negotiated timeout=10000
I0508 02:37:11.413812 28411 group.cpp:310] Group process ((559)@140.211.11.27:38066) connected to ZooKeeper
I0508 02:37:11.413837 28411 group.cpp:784] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
I0508 02:37:11.413847 28411 group.cpp:382] Trying to create path '/mesos' in ZooKeeper
I0508 02:37:11.416388 28411 detector.cpp:135] Detected a new leader: (id='0')
I0508 02:37:11.417093 28395 group.cpp:655] Trying to get '/mesos/info_0000000000' in ZooKeeper
I0508 02:37:11.418534 28395 detector.cpp:377] A new leading master (UPID=@128.150.152.0:10000) is detected
2014-05-08 02:37:11,419:28305(0x2b822dbf7f80):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x145d9b0f0820002 to [127.0.0.1:57654]
I0508 02:37:11.420389 28413 contender.cpp:182] Now cancelling the membership: 0
2014-05-08 02:37:11,421:28305(0x2b822dbf7f80):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x145d9b0f0820000 to [127.0.0.1:57654]
I0508 02:37:11.425384 28305 zookeeper_test_server.cpp:122] Shutdown ZooKeeperTestServer on port 57654
[ OK ] ZooKeeperMasterContenderDetectorTest.MasterDetectorExpireSlaveZKSession (8449 ms)
[ RUN ] ZooKeeperMasterContenderDetectorTest.MasterDetectorTimedoutSession
I0508 02:37:11.428973 28305 zookeeper_test_server.cpp:158] Started ZooKeeperTestServer on port 49976
2014-05-08 02:37:11,429:28305(0x2b8230c14700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-05-08 02:37:11,429:28305(0x2b8230c14700):ZOO_INFO@log_env@716: Client environment:host.name=hemera
2014-05-08 02:37:11,429:28305(0x2b8230c14700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
2014-05-08 02:37:11,429:28305(0x2b8230c14700):ZOO_INFO@log_env@724: Client environment:os.arch=3.2.0-57-generic
2014-05-08 02:37:11,429:28305(0x2b8230c14700):ZOO_INFO@log_env@725: Client environment:os.version=#87-Ubuntu SMP Tue Nov 12 21:35:10 UTC 2013
2014-05-08 02:37:11,429:28305(0x2b8230c14700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
2014-05-08 02:37:11,429:28305(0x2b8230c14700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
2014-05-08 02:37:11,429:28305(0x2b8230c14700):ZOO_INFO@log_env@753: Client environment:user.dir=/x1/jenkins/jenkins-slave/workspace/Mesos-Ubuntu-distcheck/build/mesos-0.19.0/_build/src
2014-05-08 02:37:11,429:28305(0x2b8230c14700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:49976 sessionTimeout=5000 watcher=0x2b822b50fe60 sessionId=0 sessionPasswd=<null> context=0x2b8278003e00 flags=0
2014-05-08 02:37:11,429:28305(0x2b84d8603700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:49976]
2014-05-08 02:37:11,452:28305(0x2b84d8603700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:49976], sessionId=0x145d9b111830000, negotiated timeout=6000
I0508 02:37:11.453105 28396 group.cpp:310] Group process ((562)@140.211.11.27:38066) connected to ZooKeeper
I0508 02:37:11.453135 28396 group.cpp:784] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
I0508 02:37:11.453145 28396 group.cpp:382] Trying to create path '/mesos' in ZooKeeper
I0508 02:37:16.434799 28409 contender.cpp:127] Joining the ZK group
I0508 02:37:16.444753 28403 contender.cpp:243] New candidate (id='0') has entered the contest for leadership
I0508 02:37:16.446918 28417 detector.cpp:135] Detected a new leader: (id='0')
I0508 02:37:16.448513 28412 group.cpp:655] Trying to get '/mesos/info_0000000000' in ZooKeeper
I0508 02:37:16.449906 28412 detector.cpp:377] A new leading master (UPID=@128.150.152.0:10000) is detected
2014-05-08 02:37:16,450:28305(0x2b822f80a700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-05-08 02:37:16,450:28305(0x2b822f80a700):ZOO_INFO@log_env@716: Client environment:host.name=hemera
2014-05-08 02:37:16,450:28305(0x2b822f80a700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
2014-05-08 02:37:16,451:28305(0x2b822f80a700):ZOO_INFO@log_env@724: Client environment:os.arch=3.2.0-57-generic
2014-05-08 02:37:16,451:28305(0x2b822f80a700):ZOO_INFO@log_env@725: Client environment:os.version=#87-Ubuntu SMP Tue Nov 12 21:35:10 UTC 2013
2014-05-08 02:37:16,451:28305(0x2b822f80a700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
2014-05-08 02:37:16,451:28305(0x2b822f80a700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
2014-05-08 02:37:16,451:28305(0x2b822f80a700):ZOO_INFO@log_env@753: Client environment:user.dir=/x1/jenkins/jenkins-slave/workspace/Mesos-Ubuntu-distcheck/build/mesos-0.19.0/_build/src
2014-05-08 02:37:16,451:28305(0x2b822f80a700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:49976 sessionTimeout=5000 watcher=0x2b822b50fe60 sessionId=0 sessionPasswd=<null> context=0x2b82a4014bb0 flags=0
2014-05-08 02:37:16,452:28305(0x2b84d8201700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:49976]
2014-05-08 02:37:16,456:28305(0x2b84d8201700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:49976], sessionId=0x145d9b111830001, negotiated timeout=6000
I0508 02:37:16.456507 28404 group.cpp:310] Group process ((567)@140.211.11.27:38066) connected to ZooKeeper
I0508 02:37:16.456536 28404 group.cpp:784] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
I0508 02:37:16.456552 28404 group.cpp:382] Trying to create path '/mesos' in ZooKeeper
I0508 02:37:21.456471 28405 contender.cpp:127] Joining the ZK group
I0508 02:37:21.468878 28394 contender.cpp:243] New candidate (id='1') has entered the contest for leadership
I0508 02:37:21.470072 28411 detector.cpp:135] Detected a new leader: (id='0')
I0508 02:37:21.470492 28405 group.cpp:655] Trying to get '/mesos/info_0000000000' in ZooKeeper
I0508 02:37:21.471637 28408 detector.cpp:377] A new leading master (UPID=@128.150.152.0:10000) is detected
2014-05-08 02:37:21,472:28305(0x2b822e802700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-05-08 02:37:21,472:28305(0x2b822e802700):ZOO_INFO@log_env@716: Client environment:host.name=hemera
2014-05-08 02:37:21,472:28305(0x2b822e802700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
2014-05-08 02:37:21,472:28305(0x2b822e802700):ZOO_INFO@log_env@724: Client environment:os.arch=3.2.0-57-generic
2014-05-08 02:37:21,472:28305(0x2b822e802700):ZOO_INFO@log_env@725: Client environment:os.version=#87-Ubuntu SMP Tue Nov 12 21:35:10 UTC 2013
2014-05-08 02:37:21,472:28305(0x2b822e802700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
2014-05-08 02:37:21,472:28305(0x2b822e802700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
2014-05-08 02:37:21,472:28305(0x2b822e802700):ZOO_INFO@log_env@753: Client environment:user.dir=/x1/jenkins/jenkins-slave/workspace/Mesos-Ubuntu-distcheck/build/mesos-0.19.0/_build/src
2014-05-08 02:37:21,472:28305(0x2b822e802700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:49976 sessionTimeout=5000 watcher=0x2b822b50fe60 sessionId=0 sessionPasswd=<null> context=0x2b82480132a0 flags=0
2014-05-08 02:37:21,472:28305(0x2b84a544c700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:49976]
2014-05-08 02:37:21,476:28305(0x2b84a544c700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:49976], sessionId=0x145d9b111830002, negotiated timeout=6000
I0508 02:37:21.476357 28415 group.cpp:310] Group process ((572)@140.211.11.27:38066) connected to ZooKeeper
I0508 02:37:21.476374 28415 group.cpp:784] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
I0508 02:37:21.476383 28415 group.cpp:382] Trying to create path '/mesos' in ZooKeeper
I0508 02:37:21.478430 28415 detector.cpp:135] Detected a new leader: (id='0')
I0508 02:37:21.478888 28400 group.cpp:655] Trying to get '/mesos/info_0000000000' in ZooKeeper
I0508 02:37:21.479691 28400 detector.cpp:377] A new leading master (UPID=@128.150.152.0:10000) is detected
2014-05-08 02:37:21,481:28305(0x2b84d8201700):ZOO_ERROR@handle_socket_error_msg@1721: Socket [127.0.0.1:49976] zk retcode=-4, errno=112(Host is down): failed while receiving a server response
2014-05-08 02:37:21,481:28305(0x2b84d8603700):ZOO_ERROR@handle_socket_error_msg@1721: Socket [127.0.0.1:49976] zk retcode=-4, errno=112(Host is down): failed while receiving a server response
I0508 02:37:21.481569 28409 group.cpp:415] Lost connection to ZooKeeper, attempting to reconnect ...
2014-05-08 02:37:21,481:28305(0x2b84a544c700):ZOO_ERROR@handle_socket_error_msg@1721: Socket [127.0.0.1:49976] zk retcode=-4, errno=112(Host is down): failed while receiving a server response
I0508 02:37:21.481709 28402 group.cpp:415] Lost connection to ZooKeeper, attempting to reconnect ...
I0508 02:37:21.481869 28401 group.cpp:415] Lost connection to ZooKeeper, attempting to reconnect ...
I0508 02:37:21.482792 28305 zookeeper_test_server.cpp:122] Shutdown ZooKeeperTestServer on port 49976
W0508 02:37:21.493088 28416 group.cpp:453] Timed out waiting to reconnect to ZooKeeper. Forcing ZooKeeper session (sessionId=145d9b111830001) expiration
W0508 02:37:21.493105 28402 group.cpp:453] Timed out waiting to reconnect to ZooKeeper. Forcing ZooKeeper session (sessionId=145d9b111830000) expiration
I0508 02:37:21.493105 28416 group.cpp:469] ZooKeeper session expired
I0508 02:37:21.493259 28402 group.cpp:469] ZooKeeper session expired
W0508 02:37:21.493196 28408 group.cpp:453] Timed out waiting to reconnect to ZooKeeper. Forcing ZooKeeper session (sessionId=145d9b111830002) expiration
I0508 02:37:21.493499 28408 group.cpp:469] ZooKeeper session expired
I0508 02:37:21.493656 28404 detector.cpp:123] The current leader (id=0) is lost
I0508 02:37:21.493669 28404 detector.cpp:135] Detected a new leader: None
I0508 02:37:21.493677 28397 detector.cpp:123] The current leader (id=0) is lost
I0508 02:37:21.493686 28397 detector.cpp:135] Detected a new leader: None
2014-05-08 02:37:21,493:28305(0x2b822fa0b700):ZOO_INFO@zookeeper_close@2522: Freeing zookeeper resources for sessionId=0x145d9b111830002
2014-05-08 02:37:21,493:28305(0x2b822fa0b700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-05-08 02:37:21,493:28305(0x2b822fa0b700):ZOO_INFO@log_env@716: Client environment:host.name=hemera
2014-05-08 02:37:21,493:28305(0x2b822fa0b700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
2014-05-08 02:37:21,493:28305(0x2b822fa0b700):ZOO_INFO@log_env@724: Client environment:os.arch=3.2.0-57-generic
2014-05-08 02:37:21,493:28305(0x2b822fa0b700):ZOO_INFO@log_env@725: Client environment:os.version=#87-Ubuntu SMP Tue Nov 12 21:35:10 UTC 2013
I0508 02:37:21.493801 28406 detector.cpp:123] The current leader (id=0) is lost
2014-05-08 02:37:21,493:28305(0x2b822ee05700):ZOO_INFO@zookeeper_close@2522: Freeing zookeeper resources for sessionId=0x145d9b111830000
2014-05-08 02:37:21,493:28305(0x2b8230a13700):ZOO_INFO@zookeeper_close@2522: Freeing zookeeper resources for sessionId=0x145d9b111830001
I0508 02:37:21.493826 28398 contender.cpp:192] Membership cancelled: 0
2014-05-08 02:37:21,493:28305(0x2b8230a13700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-05-08 02:37:21,493:28305(0x2b8230a13700):ZOO_INFO@log_env@716: Client environment:host.name=hemera
2014-05-08 02:37:21,493:28305(0x2b8230a13700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
2014-05-08 02:37:21,494:28305(0x2b8230a13700):ZOO_INFO@log_env@724: Client environment:os.arch=3.2.0-57-generic
2014-05-08 02:37:21,494:28305(0x2b8230a13700):ZOO_INFO@log_env@725: Client environment:os.version=#87-Ubuntu SMP Tue Nov 12 21:35:10 UTC 2013
I0508 02:37:21.493897 28401 contender.cpp:192] Membership cancelled: 1
2014-05-08 02:37:21,493:28305(0x2b822fa0b700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
I0508 02:37:21.493914 28406 detector.cpp:135] Detected a new leader: None
2014-05-08 02:37:21,493:28305(0x2b822ee05700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-05-08 02:37:21,494:28305(0x2b822ee05700):ZOO_INFO@log_env@716: Client environment:host.name=hemera
2014-05-08 02:37:21,494:28305(0x2b822ee05700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
2014-05-08 02:37:21,494:28305(0x2b822ee05700):ZOO_INFO@log_env@724: Client environment:os.arch=3.2.0-57-generic
2014-05-08 02:37:21,494:28305(0x2b822ee05700):ZOO_INFO@log_env@725: Client environment:os.version=#87-Ubuntu SMP Tue Nov 12 21:35:10 UTC 2013
2014-05-08 02:37:21,494:28305(0x2b8230a13700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
2014-05-08 02:37:21,494:28305(0x2b822fa0b700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
2014-05-08 02:37:21,494:28305(0x2b822fa0b700):ZOO_INFO@log_env@753: Client environment:user.dir=/x1/jenkins/jenkins-slave/workspace/Mesos-Ubuntu-distcheck/build/mesos-0.19.0/_build/src
2014-05-08 02:37:21,494:28305(0x2b822fa0b700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:49976 sessionTimeout=5000 watcher=0x2b822b50fe60 sessionId=0 sessionPasswd=<null> context=0x2b827002c8f0 flags=0
2014-05-08 02:37:21,494:28305(0x2b8230a13700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
2014-05-08 02:37:21,494:28305(0x2b8230a13700):ZOO_INFO@log_env@753: Client environment:user.dir=/x1/jenkins/jenkins-slave/workspace/Mesos-Ubuntu-distcheck/build/mesos-0.19.0/_build/src
2014-05-08 02:37:21,494:28305(0x2b8230a13700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:49976 sessionTimeout=5000 watcher=0x2b822b50fe60 sessionId=0 sessionPasswd=<null> context=0x2b82800009f0 flags=0
2014-05-08 02:37:21,494:28305(0x2b822ee05700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
2014-05-08 02:37:21,494:28305(0x2b822ee05700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
2014-05-08 02:37:21,494:28305(0x2b822ee05700):ZOO_INFO@log_env@753: Client environment:user.dir=/x1/jenkins/jenkins-slave/workspace/Mesos-Ubuntu-distcheck/build/mesos-0.19.0/_build/src
2014-05-08 02:37:21,494:28305(0x2b822ee05700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:49976 sessionTimeout=5000 watcher=0x2b822b50fe60 sessionId=0 sessionPasswd=<null> context=0x2b82ac011180 flags=0
2014-05-08 02:37:21,494:28305(0x2b84d8201700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:49976] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
2014-05-08 02:37:21,495:28305(0x2b84a564d700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:49976] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
2014-05-08 02:37:21,495:28305(0x2b84a5850700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:49976] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
2014-05-08 02:37:21,503:28305(0x2b822dbf7f80):ZOO_INFO@zookeeper_close@2522: Freeing zookeeper resources for sessionId=0
I0508 02:37:21.503423 28305 contender.cpp:182] Now cancelling the membership: 1
2014-05-08 02:37:21,503:28305(0x2b822dbf7f80):ZOO_INFO@zookeeper_close@2522: Freeing zookeeper resources for sessionId=0
I0508 02:37:21.504681 28406 contender.cpp:182] Now cancelling the membership: 0
2014-05-08 02:37:21,504:28305(0x2b822dbf7f80):ZOO_INFO@zookeeper_close@2522: Freeing zookeeper resources for sessionId=0
[ OK ] ZooKeeperMasterContenderDetectorTest.MasterDetectorTimedoutSession (10079 ms)
[ RUN ] ZooKeeperMasterContenderDetectorTest.MasterContender
I0508 02:37:21.507156 28305 zookeeper_test_server.cpp:158] Started ZooKeeperTestServer on port 45497
2014-05-08 02:37:21,507:28305(0x2b822f80a700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-05-08 02:37:21,507:28305(0x2b822f80a700):ZOO_INFO@log_env@716: Client environment:host.name=hemera
2014-05-08 02:37:21,507:28305(0x2b822f80a700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
2014-05-08 02:37:21,507:28305(0x2b822f80a700):ZOO_INFO@log_env@724: Client environment:os.arch=3.2.0-57-generic
2014-05-08 02:37:21,507:28305(0x2b822f80a700):ZOO_INFO@log_env@725: Client environment:os.version=#87-Ubuntu SMP Tue Nov 12 21:35:10 UTC 2013
2014-05-08 02:37:21,507:28305(0x2b822f80a700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
2014-05-08 02:37:21,507:28305(0x2b822f80a700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
2014-05-08 02:37:21,507:28305(0x2b822f80a700):ZOO_INFO@log_env@753: Client environment:user.dir=/x1/jenkins/jenkins-slave/workspace/Mesos-Ubuntu-distcheck/build/mesos-0.19.0/_build/src
2014-05-08 02:37:21,507:28305(0x2b822f80a700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:45497 sessionTimeout=10000 watcher=0x2b822b50fe60 sessionId=0 sessionPasswd=<null> context=0x2b82a4014bb0 flags=0
2014-05-08 02:37:21,507:28305(0x2b84a564d700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:45497]
2014-05-08 02:37:21,526:28305(0x2b84a564d700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:45497], sessionId=0x145d9b138e20000, negotiated timeout=10000
I0508 02:37:21.526255 28417 group.cpp:310] Group process ((575)@140.211.11.27:38066) connected to ZooKeeper
I0508 02:37:21.526283 28417 group.cpp:784] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
I0508 02:37:21.526289 28417 group.cpp:382] Trying to create path '/mesos' in ZooKeeper
I0508 02:37:26.512538 28395 contender.cpp:127] Joining the ZK group
I0508 02:37:26.519099 28415 contender.cpp:243] New candidate (id='0') has entered the contest for leadership
2014-05-08 02:37:26,520:28305(0x2b822f80a700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-05-08 02:37:26,520:28305(0x2b822f80a700):ZOO_INFO@log_env@716: Client environment:host.name=hemera
2014-05-08 02:37:26,520:28305(0x2b822f80a700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
2014-05-08 02:37:26,520:28305(0x2b822f80a700):ZOO_INFO@log_env@724: Client environment:os.arch=3.2.0-57-generic
2014-05-08 02:37:26,520:28305(0x2b822f80a700):ZOO_INFO@log_env@725: Client environment:os.version=#87-Ubuntu SMP Tue Nov 12 21:35:10 UTC 2013
2014-05-08 02:37:26,520:28305(0x2b822f80a700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
2014-05-08 02:37:26,520:28305(0x2b822f80a700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
2014-05-08 02:37:26,520:28305(0x2b822f80a700):ZOO_INFO@log_env@753: Client environment:user.dir=/x1/jenkins/jenkins-slave/workspace/Mesos-Ubuntu-distcheck/build/mesos-0.19.0/_build/src
2014-05-08 02:37:26,520:28305(0x2b822f80a700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:45497 sessionTimeout=10000 watcher=0x2b822b50fe60 sessionId=0 sessionPasswd=<null> context=0x2b82a4014e10 flags=0
2014-05-08 02:37:26,521:28305(0x2b84d8201700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:45497]
2014-05-08 02:37:26,526:28305(0x2b84d8201700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:45497], sessionId=0x145d9b138e20001, negotiated timeout=10000
I0508 02:37:26.527005 28413 group.cpp:310] Group process ((579)@140.211.11.27:38066) connected to ZooKeeper
I0508 02:37:26.527050 28413 group.cpp:784] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
I0508 02:37:26.527060 28413 group.cpp:382] Trying to create path '/mesos' in ZooKeeper
I0508 02:37:26.529702 28413 detector.cpp:135] Detected a new leader: (id='0')
I0508 02:37:26.529975 28403 group.cpp:655] Trying to get '/mesos/info_0000000000' in ZooKeeper
I0508 02:37:26.531194 28403 detector.cpp:377] A new leading master (UPID=@128.150.152.0:10000) is detected
2014-05-08 02:37:26,539:28305(0x2b84a564d700):ZOO_ERROR@handle_socket_error_msg@1721: Socket [127.0.0.1:45497] zk retcode=-4, errno=112(Host is down): failed while receiving a server response
I0508 02:37:26.539973 28406 group.cpp:415] Lost connection to ZooKeeper, attempting to reconnect ...
I0508 02:37:26.540971 28412 detector.cpp:123] The current leader (id=0) is lost
I0508 02:37:26.540994 28412 detector.cpp:135] Detected a new leader: None
2014-05-08 02:37:29,876:28305(0x2b84a564d700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:45497]
2014-05-08 02:37:29,877:28305(0x2b84a564d700):ZOO_ERROR@handle_socket_error_msg@1739: Socket [127.0.0.1:45497] zk retcode=-112, errno=116(Stale NFS file handle): sessionId=0x145d9b138e20000 has expired.
I0508 02:37:29.877440 28414 group.cpp:469] ZooKeeper session expired
I0508 02:37:29.877610 28398 contender.cpp:192] Membership cancelled: 0
2014-05-08 02:37:29,878:28305(0x2b8230611700):ZOO_INFO@zookeeper_close@2522: Freeing zookeeper resources for sessionId=0x145d9b138e20000
2014-05-08 02:37:29,878:28305(0x2b8230611700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-05-08 02:37:29,878:28305(0x2b8230611700):ZOO_INFO@log_env@716: Client environment:host.name=hemera
2014-05-08 02:37:29,878:28305(0x2b8230611700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
2014-05-08 02:37:29,878:28305(0x2b8230611700):ZOO_INFO@log_env@724: Client environment:os.arch=3.2.0-57-generic
2014-05-08 02:37:29,878:28305(0x2b8230611700):ZOO_INFO@log_env@725: Client environment:os.version=#87-Ubuntu SMP Tue Nov 12 21:35:10 UTC 2013
2014-05-08 02:37:29,878:28305(0x2b8230611700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
2014-05-08 02:37:29,879:28305(0x2b8230611700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
2014-05-08 02:37:29,879:28305(0x2b8230611700):ZOO_INFO@log_env@753: Client environment:user.dir=/x1/jenkins/jenkins-slave/workspace/Mesos-Ubuntu-distcheck/build/mesos-0.19.0/_build/src
2014-05-08 02:37:29,879:28305(0x2b8230611700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:45497 sessionTimeout=10000 watcher=0x2b822b50fe60 sessionId=0 sessionPasswd=<null> context=0x2b826400af80 flags=0
2014-05-08 02:37:29,879:28305(0x2b84d8603700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:45497]
2014-05-08 02:37:29,879:28305(0x2b822dbf7f80):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x145d9b138e20001 to [127.0.0.1:45497]
2014-05-08 02:37:29,880:28305(0x2b84d8603700):ZOO_ERROR@handle_socket_error_msg@1721: Socket [127.0.0.1:45497] zk retcode=-4, errno=112(Host is down): failed while receiving a server response
I0508 02:37:29.881788 28305 zookeeper_test_server.cpp:122] Shutdown ZooKeeperTestServer on port 45497
[ OK ] ZooKeeperMasterContenderDetectorTest.MasterContender (8376 ms)
[ RUN ] ZooKeeperMasterContenderDetectorTest.MasterDetectorExpireMasterZKSession
I0508 02:37:29.885385 28305 zookeeper_test_server.cpp:158] Started ZooKeeperTestServer on port 54198
Build timed out (after 120 minutes). Marking the build as failed.
Build was aborted
Re: Build failed in Jenkins: Mesos-Ubuntu-distcheck #79
Posted by Benjamin Mahler <be...@gmail.com>.
Filed https://issues.apache.org/jira/browse/MESOS-1347
On Tue, May 6, 2014 at 9:37 PM, Apache Jenkins Server <
jenkins@builds.apache.org> wrote:
> See <https://builds.apache.org/job/Mesos-Ubuntu-distcheck/79/changes>
>
> Changes:
>
> [benjamin.hindman] Enabled unbundled usage of http-parser.
>
> ------------------------------------------
> [...truncated 19388 lines...]
> I0507 03:27:38.676010 5798 gc.cpp:56] Scheduling
> '/tmp/GarbageCollectorIntegrationTest_ExitedFramework_fAc62M/slaves/20140507-032738-453759884-58462-5758-0/frameworks/20140507-032738-453759884-58462-5758-0000'
> for gc 6.99999254958222days in the future
> I0507 03:27:38.704622 5786 hierarchical_allocator_process.hpp:687]
> Performed allocation for 1 slaves in 11228ns
> I0507 03:27:38.704907 5791 slave.cpp:2717] Framework
> 20140507-032738-453759884-58462-5758-0000 seems to have exited. Ignoring
> registration timeout for executor 'default'
> I0507 03:27:38.704932 5794 master.cpp:104] No whitelist given.
> Advertising offers for all slaves
> I0507 03:27:38.705431 5791 slave.cpp:2801] Current usage 67.66%. Max
> allowed age: 1.563618673822245days
> I0507 03:27:38.705549 5780 gc.cpp:134] Deleting
> /tmp/GarbageCollectorIntegrationTest_ExitedFramework_fAc62M/slaves/20140507-032738-453759884-58462-5758-0/frameworks/20140507-032738-453759884-58462-5758-0000/executors/default/runs/4879ef58-5529-4ba8-9f96-2ed505d57e17
> I0507 03:27:38.705714 5780 gc.cpp:143] Deleted
> '/tmp/GarbageCollectorIntegrationTest_ExitedFramework_fAc62M/slaves/20140507-032738-453759884-58462-5758-0/frameworks/20140507-032738-453759884-58462-5758-0000/executors/default/runs/4879ef58-5529-4ba8-9f96-2ed505d57e17'
> I0507 03:27:38.705773 5780 gc.cpp:134] Deleting
> /tmp/GarbageCollectorIntegrationTest_ExitedFramework_fAc62M/slaves/20140507-032738-453759884-58462-5758-0/frameworks/20140507-032738-453759884-58462-5758-0000/executors/default
> I0507 03:27:38.705937 5780 gc.cpp:143] Deleted
> '/tmp/GarbageCollectorIntegrationTest_ExitedFramework_fAc62M/slaves/20140507-032738-453759884-58462-5758-0/frameworks/20140507-032738-453759884-58462-5758-0000/executors/default'
> I0507 03:27:38.705953 5780 gc.cpp:134] Deleting
> /tmp/GarbageCollectorIntegrationTest_ExitedFramework_fAc62M/slaves/20140507-032738-453759884-58462-5758-0/frameworks/20140507-032738-453759884-58462-5758-0000
> I0507 03:27:38.706040 5780 gc.cpp:143] Deleted
> '/tmp/GarbageCollectorIntegrationTest_ExitedFramework_fAc62M/slaves/20140507-032738-453759884-58462-5758-0/frameworks/20140507-032738-453759884-58462-5758-0000'
> I0507 03:27:38.714886 5782 process.cpp:3335] Handling HTTP event for
> process 'files' with path: '/files/browse.json'
> I0507 03:27:38.715406 5801 process.cpp:1037] Socket closed while receiving
> I0507 03:27:38.724931 5758 master.cpp:552] Master terminating
> I0507 03:27:38.725226 5782 slave.cpp:2152] master@140.211.11.27:58462exited
> W0507 03:27:38.725289 5782 slave.cpp:2155] Master disconnected! Waiting
> for a new master to be elected
> I0507 03:27:38.727746 5758 slave.cpp:415] Slave terminating
> [ OK ] GarbageCollectorIntegrationTest.ExitedFramework (371 ms)
> [ RUN ] GarbageCollectorIntegrationTest.DiskUsage
> Using temporary directory
> '/tmp/GarbageCollectorIntegrationTest_DiskUsage_pU3Ym7'
> I0507 03:27:38.775058 5758 leveldb.cpp:174] Opened db in 44.343989ms
> I0507 03:27:38.787498 5758 leveldb.cpp:181] Compacted db in 12.411065ms
> I0507 03:27:38.787533 5758 leveldb.cpp:196] Created db iterator in 4008ns
> I0507 03:27:38.787545 5758 leveldb.cpp:202] Seeked to beginning of db in
> 598ns
> I0507 03:27:38.787552 5758 leveldb.cpp:271] Iterated through 0 keys in
> the db in 173ns
> I0507 03:27:38.787564 5758 replica.cpp:741] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0507 03:27:38.787858 5777 recover.cpp:425] Starting replica recovery
> I0507 03:27:38.788352 5793 master.cpp:267] Master
> 20140507-032738-453759884-58462-5758 (hemera.apache.org) started on
> 140.211.11.27:58462
> I0507 03:27:38.788377 5793 master.cpp:304] Master only allowing
> authenticated frameworks to register
> I0507 03:27:38.788383 5793 master.cpp:309] Master only allowing
> authenticated slaves to register
> I0507 03:27:38.788389 5793 credentials.hpp:35] Loading credentials for
> authentication
> I0507 03:27:38.789064 5779 recover.cpp:451] Replica is in EMPTY status
> W0507 03:27:38.789115 5793 credentials.hpp:48] Failed to stat credentials
> file
> 'file:///tmp/GarbageCollectorIntegrationTest_DiskUsage_pU3Ym7/credentials':
> No such file or directory
> I0507 03:27:38.789489 5779 master.cpp:104] No whitelist given.
> Advertising offers for all slaves
> I0507 03:27:38.789531 5778 hierarchical_allocator_process.hpp:301]
> Initializing hierarchical allocator process with master :
> master@140.211.11.27:58462
> I0507 03:27:38.791007 5788 replica.cpp:638] Replica in EMPTY status
> received a broadcasted recover request
> I0507 03:27:38.791177 5780 master.cpp:921] The newly elected leader is
> master@140.211.11.27:58462 with id 20140507-032738-453759884-58462-5758
> I0507 03:27:38.791198 5780 master.cpp:931] Elected as the leading master!
> I0507 03:27:38.791205 5780 master.cpp:752] Recovering from registrar
> I0507 03:27:38.791251 5796 recover.cpp:188] Received a recover response
> from a replica in EMPTY status
> I0507 03:27:38.791323 5797 registrar.cpp:313] Recovering registrar
> I0507 03:27:38.792137 5795 recover.cpp:542] Updating replica status to
> STARTING
> I0507 03:27:38.807531 5781 leveldb.cpp:304] Persisting metadata (8 bytes)
> to leveldb took 15.124092ms
> I0507 03:27:38.807559 5781 replica.cpp:320] Persisted replica status to
> STARTING
> I0507 03:27:38.807621 5781 recover.cpp:451] Replica is in STARTING status
> I0507 03:27:38.809319 5799 replica.cpp:638] Replica in STARTING status
> received a broadcasted recover request
> I0507 03:27:38.809983 5795 recover.cpp:188] Received a recover response
> from a replica in STARTING status
> I0507 03:27:38.811204 5778 recover.cpp:542] Updating replica status to
> VOTING
> I0507 03:27:38.827595 5795 leveldb.cpp:304] Persisting metadata (8 bytes)
> to leveldb took 16.011355ms
> I0507 03:27:38.827627 5795 replica.cpp:320] Persisted replica status to
> VOTING
> I0507 03:27:38.827683 5795 recover.cpp:556] Successfully joined the Paxos
> group
> I0507 03:27:38.827775 5795 recover.cpp:440] Recover process terminated
> I0507 03:27:38.828966 5780 log.cpp:656] Attempting to start the writer
> I0507 03:27:38.831114 5782 replica.cpp:474] Replica received implicit
> promise request with proposal 1
> I0507 03:27:38.847708 5782 leveldb.cpp:304] Persisting metadata (8 bytes)
> to leveldb took 16.573137ms
> I0507 03:27:38.847739 5782 replica.cpp:342] Persisted promised to 1
> I0507 03:27:38.848141 5797 coordinator.cpp:230] Coordinator attemping to
> fill missing position
> I0507 03:27:38.849684 5790 replica.cpp:375] Replica received explicit
> promise request for position 0 with proposal 2
> I0507 03:27:38.863777 5790 leveldb.cpp:341] Persisting action (8 bytes)
> to leveldb took 14.076775ms
> I0507 03:27:38.863801 5790 replica.cpp:676] Persisted action at 0
> I0507 03:27:38.864915 5798 replica.cpp:508] Replica received write
> request for position 0
> I0507 03:27:38.864949 5798 leveldb.cpp:436] Reading position from leveldb
> took 11807ns
> I0507 03:27:38.879945 5798 leveldb.cpp:341] Persisting action (14 bytes)
> to leveldb took 14.978446ms
> I0507 03:27:38.879976 5798 replica.cpp:676] Persisted action at 0
> I0507 03:27:38.880491 5797 replica.cpp:655] Replica received learned
> notice for position 0
> I0507 03:27:38.895969 5797 leveldb.cpp:341] Persisting action (16 bytes)
> to leveldb took 15.459949ms
> I0507 03:27:38.895992 5797 replica.cpp:676] Persisted action at 0
> I0507 03:27:38.896003 5797 replica.cpp:661] Replica learned NOP action at
> position 0
> I0507 03:27:38.896411 5783 log.cpp:672] Writer started with ending
> position 0
> I0507 03:27:38.898058 5798 leveldb.cpp:436] Reading position from leveldb
> took 11910ns
> I0507 03:27:38.899749 5777 registrar.cpp:346] Successfully fetched the
> registry (0B)
> I0507 03:27:38.899766 5777 registrar.cpp:422] Attempting to update the
> 'registry'
> I0507 03:27:38.901458 5791 log.cpp:680] Attempting to append 137 bytes to
> the log
> I0507 03:27:38.901666 5780 coordinator.cpp:340] Coordinator attempting to
> write APPEND action at position 1
> I0507 03:27:38.902773 5783 replica.cpp:508] Replica received write
> request for position 1
> I0507 03:27:38.916127 5783 leveldb.cpp:341] Persisting action (156 bytes)
> to leveldb took 13.225715ms
> I0507 03:27:38.916152 5783 replica.cpp:676] Persisted action at 1
> I0507 03:27:38.916534 5790 replica.cpp:655] Replica received learned
> notice for position 1
> I0507 03:27:38.928203 5790 leveldb.cpp:341] Persisting action (158 bytes)
> to leveldb took 11.652434ms
> I0507 03:27:38.928225 5790 replica.cpp:676] Persisted action at 1
> I0507 03:27:38.928236 5790 replica.cpp:661] Replica learned APPEND action
> at position 1
> I0507 03:27:38.928546 5790 registrar.cpp:479] Successfully updated
> 'registry'
> I0507 03:27:38.928642 5790 registrar.cpp:372] Successfully recovered
> registrar
> I0507 03:27:38.929044 5783 master.cpp:779] Recovered 0 slaves from the
> Registry (99B) ; allowing 10mins for slaves to re-register
> I0507 03:27:38.929502 5799 log.cpp:699] Attempting to truncate the log to
> 1
> I0507 03:27:38.929888 5797 coordinator.cpp:340] Coordinator attempting to
> write TRUNCATE action at position 2
> I0507 03:27:38.930161 5781 replica.cpp:508] Replica received write
> request for position 2
> I0507 03:27:38.932977 5789 slave.cpp:140] Slave started on 56)@
> 140.211.11.27:58462
> I0507 03:27:38.932991 5789 credentials.hpp:35] Loading credentials for
> authentication
> W0507 03:27:38.933567 5789 credentials.hpp:48] Failed to stat credentials
> file
> 'file:///tmp/GarbageCollectorIntegrationTest_DiskUsage_A9Pxks/credential':
> No such file or directory
> I0507 03:27:38.933585 5789 slave.cpp:230] Slave using credential for:
> test-principal
> I0507 03:27:38.933765 5789 slave.cpp:243] Slave resources: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0507 03:27:38.933854 5789 slave.cpp:271] Slave hostname:
> hemera.apache.org
> I0507 03:27:38.933863 5789 slave.cpp:272] Slave checkpoint: false
> I0507 03:27:38.934239 5778 state.cpp:33] Recovering state from
> '/tmp/GarbageCollectorIntegrationTest_DiskUsage_A9Pxks/meta'
> I0507 03:27:38.934960 5792 status_update_manager.cpp:193] Recovering
> status update manager
> I0507 03:27:38.935123 5779 slave.cpp:2945] Finished recovery
> I0507 03:27:38.936998 5779 slave.cpp:526] New master detected at
> master@140.211.11.27:58462
> I0507 03:27:38.937021 5779 slave.cpp:586] Authenticating with master
> master@140.211.11.27:58462
> I0507 03:27:38.937077 5798 status_update_manager.cpp:167] New master
> detected at master@140.211.11.27:58462
> I0507 03:27:38.937306 5779 slave.cpp:559] Detecting new master
> I0507 03:27:38.937335 5800 authenticatee.hpp:128] Creating new client
> SASL connection
> I0507 03:27:38.938030 5778 master.cpp:2798] Authenticating slave(56)@
> 140.211.11.27:58462
> I0507 03:27:38.938742 5783 authenticator.hpp:148] Creating new server
> SASL connection
> I0507 03:27:38.939312 5786 authenticatee.hpp:219] Received SASL
> authentication mechanisms: CRAM-MD5
> I0507 03:27:38.939340 5786 authenticatee.hpp:245] Attempting to
> authenticate with mechanism 'CRAM-MD5'
> I0507 03:27:38.939390 5786 authenticator.hpp:254] Received SASL
> authentication start
> I0507 03:27:38.939553 5786 authenticator.hpp:342] Authentication requires
> more steps
> I0507 03:27:38.939592 5786 authenticatee.hpp:265] Received SASL
> authentication step
> I0507 03:27:38.939715 5786 authenticator.hpp:282] Received SASL
> authentication step
> I0507 03:27:38.939803 5786 auxprop.cpp:81] Request to lookup properties
> for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: '
> hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0507 03:27:38.939821 5786 auxprop.cpp:153] Looking up auxiliary property
> '*userPassword'
> I0507 03:27:38.939831 5786 auxprop.cpp:153] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0507 03:27:38.939841 5786 auxprop.cpp:81] Request to lookup properties
> for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: '
> hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0507 03:27:38.939851 5786 auxprop.cpp:103] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0507 03:27:38.939857 5786 auxprop.cpp:103] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0507 03:27:38.939870 5786 authenticator.hpp:334] Authentication success
> I0507 03:27:38.939937 5786 authenticatee.hpp:305] Authentication success
> I0507 03:27:38.940016 5778 master.cpp:2838] Successfully authenticated
> slave(56)@140.211.11.27:58462
> I0507 03:27:38.940449 5799 slave.cpp:643] Successfully authenticated with
> master master@140.211.11.27:58462
> I0507 03:27:38.940513 5799 slave.cpp:872] Will retry registration in
> 5.176207635secs if necessary
> I0507 03:27:38.940625 5794 master.cpp:2134] Registering slave at
> slave(56)@140.211.11.27:58462 (hemera.apache.org) with id
> 20140507-032738-453759884-58462-5758-0
> I0507 03:27:38.940800 5796 registrar.cpp:422] Attempting to update the
> 'registry'
> I0507 03:27:38.940850 5781 leveldb.cpp:341] Persisting action (16 bytes)
> to leveldb took 10.659152ms
> I0507 03:27:38.940871 5781 replica.cpp:676] Persisted action at 2
> I0507 03:27:38.941843 5788 replica.cpp:655] Replica received learned
> notice for position 2
> I0507 03:27:38.953193 5788 leveldb.cpp:341] Persisting action (18 bytes)
> to leveldb took 11.291343ms
> I0507 03:27:38.953258 5788 leveldb.cpp:399] Deleting ~1 keys from leveldb
> took 33725ns
> I0507 03:27:38.953274 5788 replica.cpp:676] Persisted action at 2
> I0507 03:27:38.953282 5788 replica.cpp:661] Replica learned TRUNCATE
> action at position 2
> I0507 03:27:38.953541 5797 log.cpp:680] Attempting to append 330 bytes to
> the log
> I0507 03:27:38.953614 5797 coordinator.cpp:340] Coordinator attempting to
> write APPEND action at position 3
> I0507 03:27:38.954731 5789 replica.cpp:508] Replica received write
> request for position 3
> I0507 03:27:38.965240 5789 leveldb.cpp:341] Persisting action (349 bytes)
> to leveldb took 10.489719ms
> I0507 03:27:38.965261 5789 replica.cpp:676] Persisted action at 3
> I0507 03:27:38.966253 5780 replica.cpp:655] Replica received learned
> notice for position 3
> I0507 03:27:38.977375 5780 leveldb.cpp:341] Persisting action (351 bytes)
> to leveldb took 11.098798ms
> I0507 03:27:38.977408 5780 replica.cpp:676] Persisted action at 3
> I0507 03:27:38.977421 5780 replica.cpp:661] Replica learned APPEND action
> at position 3
> I0507 03:27:38.977859 5792 registrar.cpp:479] Successfully updated
> 'registry'
> I0507 03:27:38.977926 5780 log.cpp:699] Attempting to truncate the log to
> 3
> I0507 03:27:38.978060 5792 master.cpp:2174] Registered slave
> 20140507-032738-453759884-58462-5758-0 at slave(56)@140.211.11.27:58462 (
> hemera.apache.org)
> I0507 03:27:38.978112 5792 master.cpp:3283] Adding slave
> 20140507-032738-453759884-58462-5758-0 at slave(56)@140.211.11.27:58462 (
> hemera.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000]
> I0507 03:27:38.978134 5784 coordinator.cpp:340] Coordinator attempting to
> write TRUNCATE action at position 4
> I0507 03:27:38.978508 5785 slave.cpp:676] Registered with master
> master@140.211.11.27:58462; given slave ID
> 20140507-032738-453759884-58462-5758-0
> I0507 03:27:38.978631 5786 hierarchical_allocator_process.hpp:444] Added
> slave 20140507-032738-453759884-58462-5758-0 (hemera.apache.org) with
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
> I0507 03:27:38.978677 5786 hierarchical_allocator_process.hpp:707]
> Performed allocation for slave 20140507-032738-453759884-58462-5758-0 in
> 5421ns
> I0507 03:27:38.979872 5796 replica.cpp:508] Replica received write
> request for position 4
> I0507 03:27:38.982084 5758 sched.cpp:121] Version: 0.19.0
> I0507 03:27:38.982213 5789 sched.cpp:217] New master detected at
> master@140.211.11.27:58462
> I0507 03:27:38.982228 5789 sched.cpp:268] Authenticating with master
> master@140.211.11.27:58462
> I0507 03:27:38.982347 5788 authenticatee.hpp:128] Creating new client
> SASL connection
> I0507 03:27:38.982676 5788 master.cpp:2798] Authenticating scheduler(59)@
> 140.211.11.27:58462
> I0507 03:27:38.983100 5788 authenticator.hpp:148] Creating new server
> SASL connection
> I0507 03:27:38.983294 5788 authenticatee.hpp:219] Received SASL
> authentication mechanisms: CRAM-MD5
> I0507 03:27:38.983312 5788 authenticatee.hpp:245] Attempting to
> authenticate with mechanism 'CRAM-MD5'
> I0507 03:27:38.983360 5788 authenticator.hpp:254] Received SASL
> authentication start
> I0507 03:27:38.983505 5788 authenticator.hpp:342] Authentication requires
> more steps
> I0507 03:27:38.984220 5782 authenticatee.hpp:265] Received SASL
> authentication step
> I0507 03:27:38.984275 5782 authenticator.hpp:282] Received SASL
> authentication step
> I0507 03:27:38.984315 5782 auxprop.cpp:81] Request to lookup properties
> for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: '
> hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0507 03:27:38.984347 5782 auxprop.cpp:153] Looking up auxiliary property
> '*userPassword'
> I0507 03:27:38.984359 5782 auxprop.cpp:153] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0507 03:27:38.984370 5782 auxprop.cpp:81] Request to lookup properties
> for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: '
> hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0507 03:27:38.984377 5782 auxprop.cpp:103] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0507 03:27:38.984383 5782 auxprop.cpp:103] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0507 03:27:38.984397 5782 authenticator.hpp:334] Authentication success
> I0507 03:27:38.984429 5782 authenticatee.hpp:305] Authentication success
> I0507 03:27:38.984469 5795 master.cpp:2838] Successfully authenticated
> scheduler(59)@140.211.11.27:58462
> I0507 03:27:38.985110 5782 sched.cpp:342] Successfully authenticated with
> master master@140.211.11.27:58462
> I0507 03:27:38.985133 5782 sched.cpp:461] Sending registration request to
> master@140.211.11.27:58462
> I0507 03:27:38.985326 5795 master.cpp:980] Received registration request
> from scheduler(59)@140.211.11.27:58462
> I0507 03:27:38.985357 5795 master.cpp:998] Registering framework
> 20140507-032738-453759884-58462-5758-0000 at scheduler(59)@
> 140.211.11.27:58462
> I0507 03:27:38.985424 5795 sched.cpp:392] Framework registered with
> 20140507-032738-453759884-58462-5758-0000
> I0507 03:27:38.985471 5792 hierarchical_allocator_process.hpp:331] Added
> framework 20140507-032738-453759884-58462-5758-0000
> I0507 03:27:38.985610 5795 sched.cpp:406] Scheduler::registered took
> 36702ns
> I0507 03:27:38.985646 5792 hierarchical_allocator_process.hpp:751]
> Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on
> slave 20140507-032738-453759884-58462-5758-0 to framework
> 20140507-032738-453759884-58462-5758-0000
> I0507 03:27:38.985954 5792 hierarchical_allocator_process.hpp:687]
> Performed allocation for 1 slaves in 330895ns
> I0507 03:27:38.986001 5789 master.hpp:612] Adding offer
> 20140507-032738-453759884-58462-5758-0 with resources cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
> 20140507-032738-453759884-58462-5758-0 (hemera.apache.org)
> I0507 03:27:38.986090 5789 master.cpp:2747] Sending 1 offers to framework
> 20140507-032738-453759884-58462-5758-0000
> I0507 03:27:38.986548 5792 sched.cpp:529] Scheduler::resourceOffers took
> 162873ns
> I0507 03:27:38.986721 5792 master.hpp:622] Removing offer
> 20140507-032738-453759884-58462-5758-0 with resources cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
> 20140507-032738-453759884-58462-5758-0 (hemera.apache.org)
> I0507 03:27:38.986781 5792 master.cpp:1812] Processing reply for offers:
> [ 20140507-032738-453759884-58462-5758-0 ] on slave
> 20140507-032738-453759884-58462-5758-0 at slave(56)@140.211.11.27:58462 (
> hemera.apache.org) for framework 20140507-032738-453759884-58462-5758-0000
> I0507 03:27:38.986843 5792 master.hpp:584] Adding task 0 with resources
> cpus(*):2; mem(*):1024 on slave 20140507-032738-453759884-58462-5758-0 (
> hemera.apache.org)
> I0507 03:27:38.986876 5792 master.cpp:2922] Launching task 0 of framework
> 20140507-032738-453759884-58462-5758-0000 with resources cpus(*):2;
> mem(*):1024 on slave 20140507-032738-453759884-58462-5758-0 at slave(56)@
> 140.211.11.27:58462 (hemera.apache.org)
> I0507 03:27:38.986981 5795 slave.cpp:906] Got assigned task 0 for
> framework 20140507-032738-453759884-58462-5758-0000
> I0507 03:27:38.987180 5795 slave.cpp:1016] Launching task 0 for framework
> 20140507-032738-453759884-58462-5758-0000
> I0507 03:27:38.987203 5787 hierarchical_allocator_process.hpp:546]
> Framework 20140507-032738-453759884-58462-5758-0000 left disk(*):1024;
> ports(*):[31000-32000] unused on slave
> 20140507-032738-453759884-58462-5758-0
> I0507 03:27:38.987287 5787 hierarchical_allocator_process.hpp:589]
> Framework 20140507-032738-453759884-58462-5758-0000 filtered slave
> 20140507-032738-453759884-58462-5758-0 for 5secs
> I0507 03:27:38.991395 5795 exec.cpp:131] Version: 0.19.0
> I0507 03:27:38.991497 5779 exec.cpp:181] Executor started at:
> executor(27)@140.211.11.27:58462 with pid 5758
> I0507 03:27:38.991510 5795 slave.cpp:1126] Queuing task '0' for executor
> default of framework '20140507-032738-453759884-58462-5758-0000
> I0507 03:27:38.991566 5795 slave.cpp:487] Successfully attached file
> '/tmp/GarbageCollectorIntegrationTest_DiskUsage_A9Pxks/slaves/20140507-032738-453759884-58462-5758-0/frameworks/20140507-032738-453759884-58462-5758-0000/executors/default/runs/de776bec-2822-4bbc-befc-eec40eb5f674'
> I0507 03:27:38.991595 5795 slave.cpp:2283] Monitoring executor 'default'
> of framework '20140507-032738-453759884-58462-5758-0000' in container
> 'de776bec-2822-4bbc-befc-eec40eb5f674'
> I0507 03:27:38.991778 5795 slave.cpp:1599] Got registration for executor
> 'default' of framework 20140507-032738-453759884-58462-5758-0000
> I0507 03:27:38.991874 5795 slave.cpp:1718] Flushing queued task 0 for
> executor 'default' of framework 20140507-032738-453759884-58462-5758-0000
> I0507 03:27:38.991935 5780 exec.cpp:205] Executor registered on slave
> 20140507-032738-453759884-58462-5758-0
> I0507 03:27:38.993419 5796 leveldb.cpp:341] Persisting action (16 bytes)
> to leveldb took 13.489998ms
> I0507 03:27:38.993449 5796 replica.cpp:676] Persisted action at 4
> I0507 03:27:38.994510 5777 replica.cpp:655] Replica received learned
> notice for position 4
> I0507 03:27:38.994753 5780 exec.cpp:217] Executor::registered took 14516ns
> I0507 03:27:38.994818 5780 exec.cpp:292] Executor asked to run task '0'
> I0507 03:27:38.994849 5780 exec.cpp:301] Executor::launchTask took 18872ns
> I0507 03:27:38.996703 5780 exec.cpp:524] Executor sending status update
> TASK_RUNNING (UUID: be7346ad-e198-4b38-9252-421ff759fdee) for task 0 of
> framework 20140507-032738-453759884-58462-5758-0000
> I0507 03:27:38.996793 5780 slave.cpp:1954] Handling status update
> TASK_RUNNING (UUID: be7346ad-e198-4b38-9252-421ff759fdee) for task 0 of
> framework 20140507-032738-453759884-58462-5758-0000 from executor(27)@
> 140.211.11.27:58462
> I0507 03:27:38.996888 5780 status_update_manager.cpp:320] Received status
> update TASK_RUNNING (UUID: be7346ad-e198-4b38-9252-421ff759fdee) for task 0
> of framework 20140507-032738-453759884-58462-5758-0000
> I0507 03:27:38.996920 5780 status_update_manager.cpp:499] Creating
> StatusUpdate stream for task 0 of framework
> 20140507-032738-453759884-58462-5758-0000
> I0507 03:27:38.996968 5780 status_update_manager.cpp:373] Forwarding
> status update TASK_RUNNING (UUID: be7346ad-e198-4b38-9252-421ff759fdee) for
> task 0 of framework 20140507-032738-453759884-58462-5758-0000 to
> master@140.211.11.27:58462
> I0507 03:27:38.997189 5790 master.cpp:2450] Status update TASK_RUNNING
> (UUID: be7346ad-e198-4b38-9252-421ff759fdee) for task 0 of framework
> 20140507-032738-453759884-58462-5758-0000 from slave
> 20140507-032738-453759884-58462-5758-0 at slave(56)@140.211.11.27:58462 (
> hemera.apache.org)
> I0507 03:27:38.997268 5780 slave.cpp:2071] Status update manager
> successfully handled status update TASK_RUNNING (UUID:
> be7346ad-e198-4b38-9252-421ff759fdee) for task 0 of framework
> 20140507-032738-453759884-58462-5758-0000
> I0507 03:27:38.997321 5797 sched.cpp:620] Scheduler::statusUpdate took
> 77906ns
> I0507 03:27:38.997336 5780 slave.cpp:2077] Sending acknowledgement for
> status update TASK_RUNNING (UUID: be7346ad-e198-4b38-9252-421ff759fdee) for
> task 0 of framework 20140507-032738-453759884-58462-5758-0000 to
> executor(27)@140.211.11.27:58462
> I0507 03:27:38.998700 5797 slave.cpp:2341] Executor 'default' of
> framework 20140507-032738-453759884-58462-5758-0000 has exited with status 0
> I0507 03:27:38.998814 5793 exec.cpp:338] Executor received status update
> acknowledgement be7346ad-e198-4b38-9252-421ff759fdee for task 0 of
> framework 20140507-032738-453759884-58462-5758-0000
> I0507 03:27:39.000041 5797 slave.cpp:1954] Handling status update
> TASK_LOST (UUID: 4c8e572c-3fa7-43f3-aaf8-f82e77a70c1b) for task 0 of
> framework 20140507-032738-453759884-58462-5758-0000 from @0.0.0.0:0
> I0507 03:27:39.000063 5797 slave.cpp:3446] Terminating task 0
> I0507 03:27:39.000190 5797 status_update_manager.cpp:320] Received status
> update TASK_LOST (UUID: 4c8e572c-3fa7-43f3-aaf8-f82e77a70c1b) for task 0 of
> framework 20140507-032738-453759884-58462-5758-0000
> I0507 03:27:39.000229 5779 master.cpp:2523] Executor default of framework
> 20140507-032738-453759884-58462-5758-0000 on slave
> 20140507-032738-453759884-58462-5758-0 at slave(56)@140.211.11.27:58462 (
> hemera.apache.org) has exited with status 0
> I0507 03:27:39.000341 5797 status_update_manager.cpp:398] Received status
> update acknowledgement (UUID: be7346ad-e198-4b38-9252-421ff759fdee) for
> task 0 of framework 20140507-032738-453759884-58462-5758-0000
> I0507 03:27:39.000385 5797 status_update_manager.cpp:373] Forwarding
> status update TASK_LOST (UUID: 4c8e572c-3fa7-43f3-aaf8-f82e77a70c1b) for
> task 0 of framework 20140507-032738-453759884-58462-5758-0000 to
> master@140.211.11.27:58462
> I0507 03:27:39.000516 5791 slave.cpp:2071] Status update manager
> successfully handled status update TASK_LOST (UUID:
> 4c8e572c-3fa7-43f3-aaf8-f82e77a70c1b) for task 0 of framework
> 20140507-032738-453759884-58462-5758-0000
> I0507 03:27:39.000686 5791 slave.cpp:1539] Status update manager
> successfully handled status update acknowledgement (UUID:
> be7346ad-e198-4b38-9252-421ff759fdee) for task 0 of framework
> 20140507-032738-453759884-58462-5758-0000
> I0507 03:27:39.000759 5795 master.cpp:2450] Status update TASK_LOST
> (UUID: 4c8e572c-3fa7-43f3-aaf8-f82e77a70c1b) for task 0 of framework
> 20140507-032738-453759884-58462-5758-0000 from slave
> 20140507-032738-453759884-58462-5758-0 at slave(56)@140.211.11.27:58462 (
> hemera.apache.org)
> I0507 03:27:39.000841 5784 sched.cpp:620] Scheduler::statusUpdate took
> 11418ns
> I0507 03:27:39.000849 5795 master.hpp:602] Removing task 0 with resources
> cpus(*):2; mem(*):1024 on slave 20140507-032738-453759884-58462-5758-0 (
> hemera.apache.org)
> I0507 03:27:39.001313 5799 hierarchical_allocator_process.hpp:636]
> Recovered cpus(*):2; mem(*):1024 (total allocatable: disk(*):1024;
> ports(*):[31000-32000]; cpus(*):2; mem(*):1024) on slave
> 20140507-032738-453759884-58462-5758-0 from framework
> 20140507-032738-453759884-58462-5758-0000
> I0507 03:27:39.002792 5778 status_update_manager.cpp:398] Received status
> update acknowledgement (UUID: 4c8e572c-3fa7-43f3-aaf8-f82e77a70c1b) for
> task 0 of framework 20140507-032738-453759884-58462-5758-0000
> I0507 03:27:39.002831 5778 status_update_manager.cpp:530] Cleaning up
> status update stream for task 0 of framework
> 20140507-032738-453759884-58462-5758-0000
> I0507 03:27:39.002903 5778 slave.cpp:1539] Status update manager
> successfully handled status update acknowledgement (UUID:
> 4c8e572c-3fa7-43f3-aaf8-f82e77a70c1b) for task 0 of framework
> 20140507-032738-453759884-58462-5758-0000
> I0507 03:27:39.002976 5778 slave.cpp:3470] Completing task 0
> I0507 03:27:39.002991 5778 slave.cpp:2480] Cleaning up executor 'default'
> of framework 20140507-032738-453759884-58462-5758-0000
> I0507 03:27:39.006098 5778 slave.cpp:2555] Cleaning up framework
> 20140507-032738-453759884-58462-5758-0000
> I0507 03:27:39.006105 5800 gc.cpp:56] Scheduling
> '/tmp/GarbageCollectorIntegrationTest_DiskUsage_A9Pxks/slaves/20140507-032738-453759884-58462-5758-0/frameworks/20140507-032738-453759884-58462-5758-0000/executors/default/runs/de776bec-2822-4bbc-befc-eec40eb5f674'
> for gc 1.00000000231788weeks in the future
> I0507 03:27:39.006146 5800 gc.cpp:56] Scheduling
> '/tmp/GarbageCollectorIntegrationTest_DiskUsage_A9Pxks/slaves/20140507-032738-453759884-58462-5758-0/frameworks/20140507-032738-453759884-58462-5758-0000/executors/default'
> for gc 1.00000000231788weeks in the future
> I0507 03:27:39.006211 5786 status_update_manager.cpp:282] Closing status
> update streams for framework 20140507-032738-453759884-58462-5758-0000
> I0507 03:27:39.006299 5786 gc.cpp:56] Scheduling
> '/tmp/GarbageCollectorIntegrationTest_DiskUsage_A9Pxks/slaves/20140507-032738-453759884-58462-5758-0/frameworks/20140507-032738-453759884-58462-5758-0000'
> for gc 1.00000000231788weeks in the future
> I0507 03:27:39.010058 5777 leveldb.cpp:341] Persisting action (18 bytes)
> to leveldb took 15.533184ms
> I0507 03:27:39.010144 5777 leveldb.cpp:399] Deleting ~2 keys from leveldb
> took 64787ns
> I0507 03:27:39.010154 5777 replica.cpp:676] Persisted action at 4
> I0507 03:27:39.010160 5777 replica.cpp:661] Replica learned TRUNCATE
> action at position 4
> I0507 03:27:39.029413 5789 slave.cpp:2801] Current usage 90.00%. Max
> allowed age: 0ns
> ../../src/tests/gc_tests.cpp:658: Failure
> Value of: os::exists(executorDir)
> Actual: true
> Expected: false
> Build timed out (after 120 minutes). Marking the build as failed.
> Build was aborted
> make[1]: *** [check-recursive] Terminated
> make: *** [distcheck] Terminated
>