You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "Vinod Kone (JIRA)" <ji...@apache.org> on 2014/09/30 01:58:34 UTC
[jira] [Commented] (MESOS-1347)
GarbageCollectorIntegrationTest.DiskUsage is flaky.
[ https://issues.apache.org/jira/browse/MESOS-1347?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14152556#comment-14152556 ]
Vinod Kone commented on MESOS-1347:
-----------------------------------
Seen a similar issue on the CI. https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/2131/consoleText
[~dhamon] mind taking a look since you last touched this test?
{code}
[ RUN ] GarbageCollectorIntegrationTest.DiskUsage
Using temporary directory '/tmp/GarbageCollectorIntegrationTest_DiskUsage_F6Outi'
I0929 19:27:33.685165 6596 leveldb.cpp:176] Opened db in 2.183011ms
I0929 19:27:33.685974 6596 leveldb.cpp:183] Compacted db in 780668ns
I0929 19:27:33.685997 6596 leveldb.cpp:198] Created db iterator in 2917ns
I0929 19:27:33.686007 6596 leveldb.cpp:204] Seeked to beginning of db in 558ns
I0929 19:27:33.686015 6596 leveldb.cpp:273] Iterated through 0 keys in the db in 168ns
I0929 19:27:33.686030 6596 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0929 19:27:33.686216 6614 recover.cpp:425] Starting replica recovery
I0929 19:27:33.686314 6614 recover.cpp:451] Replica is in EMPTY status
I0929 19:27:33.686764 6612 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request
I0929 19:27:33.686841 6618 recover.cpp:188] Received a recover response from a replica in EMPTY status
I0929 19:27:33.687016 6620 recover.cpp:542] Updating replica status to STARTING
I0929 19:27:33.687522 6624 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 446044ns
I0929 19:27:33.687541 6624 replica.cpp:320] Persisted replica status to STARTING
I0929 19:27:33.687557 6613 master.cpp:312] Master 20140929-192733-3176252227-39093-6596 (proserpina.apache.org) started on 67.195.81.189:39093
I0929 19:27:33.687584 6613 master.cpp:358] Master only allowing authenticated frameworks to register
I0929 19:27:33.687597 6613 master.cpp:363] Master only allowing authenticated slaves to register
I0929 19:27:33.687613 6613 credentials.hpp:36] Loading credentials for authentication from '/tmp/GarbageCollectorIntegrationTest_DiskUsage_F6Outi/credentials'
I0929 19:27:33.687650 6621 recover.cpp:451] Replica is in STARTING status
I0929 19:27:33.687731 6613 master.cpp:392] Authorization enabled
I0929 19:27:33.687934 6617 master.cpp:120] No whitelist given. Advertising offers for all slaves
I0929 19:27:33.687958 6618 hierarchical_allocator_process.hpp:299] Initializing hierarchical allocator process with master : master@67.195.81.189:39093
I0929 19:27:33.688124 6620 replica.cpp:638] Replica in STARTING status received a broadcasted recover request
I0929 19:27:33.688262 6618 recover.cpp:188] Received a recover response from a replica in STARTING status
I0929 19:27:33.688426 6623 master.cpp:1241] The newly elected leader is master@67.195.81.189:39093 with id 20140929-192733-3176252227-39093-6596
I0929 19:27:33.688451 6623 master.cpp:1254] Elected as the leading master!
I0929 19:27:33.688467 6623 master.cpp:1072] Recovering from registrar
I0929 19:27:33.688633 6619 registrar.cpp:313] Recovering registrar
I0929 19:27:33.688735 6620 recover.cpp:542] Updating replica status to VOTING
I0929 19:27:33.688967 6624 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 157347ns
I0929 19:27:33.689012 6624 replica.cpp:320] Persisted replica status to VOTING
I0929 19:27:33.689074 6620 recover.cpp:556] Successfully joined the Paxos group
I0929 19:27:33.689184 6620 recover.cpp:440] Recover process terminated
I0929 19:27:33.689317 6616 log.cpp:656] Attempting to start the writer
I0929 19:27:33.689877 6617 replica.cpp:474] Replica received implicit promise request with proposal 1
I0929 19:27:33.690207 6617 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 306053ns
I0929 19:27:33.690224 6617 replica.cpp:342] Persisted promised to 1
I0929 19:27:33.690493 6614 coordinator.cpp:230] Coordinator attemping to fill missing position
I0929 19:27:33.691164 6616 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
I0929 19:27:33.691285 6616 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 101482ns
I0929 19:27:33.691304 6616 replica.cpp:676] Persisted action at 0
I0929 19:27:33.691746 6623 replica.cpp:508] Replica received write request for position 0
I0929 19:27:33.691776 6623 leveldb.cpp:438] Reading position from leveldb took 11754ns
I0929 19:27:33.691954 6623 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 154753ns
I0929 19:27:33.691972 6623 replica.cpp:676] Persisted action at 0
I0929 19:27:33.692244 6622 replica.cpp:655] Replica received learned notice for position 0
I0929 19:27:33.692389 6622 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 121120ns
I0929 19:27:33.692407 6622 replica.cpp:676] Persisted action at 0
I0929 19:27:33.692417 6622 replica.cpp:661] Replica learned NOP action at position 0
I0929 19:27:33.692615 6615 log.cpp:672] Writer started with ending position 0
I0929 19:27:33.693091 6624 leveldb.cpp:438] Reading position from leveldb took 11308ns
I0929 19:27:33.694427 6623 registrar.cpp:346] Successfully fetched the registry (0B)
I0929 19:27:33.694454 6623 registrar.cpp:422] Attempting to update the 'registry'
I0929 19:27:33.695809 6610 log.cpp:680] Attempting to append 142 bytes to the log
I0929 19:27:33.695890 6615 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
I0929 19:27:33.696285 6622 replica.cpp:508] Replica received write request for position 1
I0929 19:27:33.696734 6622 leveldb.cpp:343] Persisting action (161 bytes) to leveldb took 424360ns
I0929 19:27:33.696753 6622 replica.cpp:676] Persisted action at 1
I0929 19:27:33.697084 6613 replica.cpp:655] Replica received learned notice for position 1
I0929 19:27:33.697428 6613 leveldb.cpp:343] Persisting action (163 bytes) to leveldb took 321272ns
I0929 19:27:33.697448 6613 replica.cpp:676] Persisted action at 1
I0929 19:27:33.697458 6613 replica.cpp:661] Replica learned APPEND action at position 1
I0929 19:27:33.697747 6615 registrar.cpp:479] Successfully updated 'registry'
I0929 19:27:33.697799 6615 registrar.cpp:372] Successfully recovered registrar
I0929 19:27:33.697830 6622 log.cpp:699] Attempting to truncate the log to 1
I0929 19:27:33.697904 6611 master.cpp:1099] Recovered 0 slaves from the Registry (104B) ; allowing 10mins for slaves to re-register
I0929 19:27:33.698005 6623 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
I0929 19:27:33.698477 6624 replica.cpp:508] Replica received write request for position 2
I0929 19:27:33.698654 6624 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 155120ns
I0929 19:27:33.698671 6624 replica.cpp:676] Persisted action at 2
I0929 19:27:33.698987 6612 replica.cpp:655] Replica received learned notice for position 2
I0929 19:27:33.699115 6612 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 105299ns
I0929 19:27:33.699148 6612 leveldb.cpp:401] Deleting ~1 keys from leveldb took 15614ns
I0929 19:27:33.699162 6612 replica.cpp:676] Persisted action at 2
I0929 19:27:33.699170 6612 replica.cpp:661] Replica learned TRUNCATE action at position 2
I0929 19:27:33.710770 6615 slave.cpp:169] Slave started on 46)@67.195.81.189:39093
I0929 19:27:33.710803 6615 credentials.hpp:84] Loading credential for authentication from '/tmp/GarbageCollectorIntegrationTest_DiskUsage_5meoSi/credential'
I0929 19:27:33.710908 6615 slave.cpp:276] Slave using credential for: test-principal
I0929 19:27:33.711005 6615 slave.cpp:289] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0929 19:27:33.711081 6615 slave.cpp:317] Slave hostname: proserpina.apache.org
I0929 19:27:33.711098 6615 slave.cpp:318] Slave checkpoint: false
I0929 19:27:33.711467 6617 state.cpp:33] Recovering state from '/tmp/GarbageCollectorIntegrationTest_DiskUsage_5meoSi/meta'
I0929 19:27:33.711596 6617 status_update_manager.cpp:193] Recovering status update manager
I0929 19:27:33.711730 6622 slave.cpp:3277] Finished recovery
I0929 19:27:33.712009 6617 slave.cpp:604] New master detected at master@67.195.81.189:39093
I0929 19:27:33.712050 6617 slave.cpp:678] Authenticating with master master@67.195.81.189:39093
I0929 19:27:33.712081 6610 status_update_manager.cpp:167] New master detected at master@67.195.81.189:39093
I0929 19:27:33.712152 6617 slave.cpp:651] Detecting new master
I0929 19:27:33.712177 6625 authenticatee.hpp:128] Creating new client SASL connection
I0929 19:27:33.712275 6610 master.cpp:3737] Authenticating slave(46)@67.195.81.189:39093
I0929 19:27:33.712368 6617 authenticator.hpp:156] Creating new server SASL connection
I0929 19:27:33.712460 6619 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0929 19:27:33.712486 6619 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0929 19:27:33.712530 6619 authenticator.hpp:262] Received SASL authentication start
I0929 19:27:33.712574 6619 authenticator.hpp:384] Authentication requires more steps
I0929 19:27:33.712641 6613 authenticatee.hpp:265] Received SASL authentication step
I0929 19:27:33.712708 6613 authenticator.hpp:290] Received SASL authentication step
I0929 19:27:33.712738 6613 auxprop.cpp:81] 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
I0929 19:27:33.712749 6613 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I0929 19:27:33.712761 6613 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0929 19:27:33.712774 6613 auxprop.cpp:81] 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
I0929 19:27:33.712787 6613 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0929 19:27:33.712801 6613 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0929 19:27:33.712818 6613 authenticator.hpp:376] Authentication success
I0929 19:27:33.712877 6614 authenticatee.hpp:305] Authentication success
I0929 19:27:33.712890 6613 master.cpp:3777] Successfully authenticated principal 'test-principal' at slave(46)@67.195.81.189:39093
I0929 19:27:33.713059 6614 slave.cpp:735] Successfully authenticated with master master@67.195.81.189:39093
I0929 19:27:33.713119 6614 slave.cpp:998] Will retry registration in 19361ns if necessary
I0929 19:27:33.713223 6619 master.cpp:2930] Registering slave at slave(46)@67.195.81.189:39093 (proserpina.apache.org) with id 20140929-192733-3176252227-39093-6596-0
I0929 19:27:33.713335 6615 slave.cpp:998] Will retry registration in 4.227055ms if necessary
I0929 19:27:33.713359 6611 registrar.cpp:422] Attempting to update the 'registry'
I0929 19:27:33.713367 6619 master.cpp:2918] Ignoring register slave message from slave(46)@67.195.81.189:39093 (proserpina.apache.org) as admission is already in progress
I0929 19:27:33.714776 6615 log.cpp:680] Attempting to append 344 bytes to the log
I0929 19:27:33.714859 6618 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
I0929 19:27:33.715200 6613 replica.cpp:508] Replica received write request for position 3
I0929 19:27:33.715421 6613 leveldb.cpp:343] Persisting action (363 bytes) to leveldb took 194931ns
I0929 19:27:33.715440 6613 replica.cpp:676] Persisted action at 3
I0929 19:27:33.715760 6623 replica.cpp:655] Replica received learned notice for position 3
I0929 19:27:33.716230 6623 leveldb.cpp:343] Persisting action (365 bytes) to leveldb took 444917ns
I0929 19:27:33.716250 6623 replica.cpp:676] Persisted action at 3
I0929 19:27:33.716262 6623 replica.cpp:661] Replica learned APPEND action at position 3
I0929 19:27:33.716580 6620 registrar.cpp:479] Successfully updated 'registry'
I0929 19:27:33.716696 6618 master.cpp:2970] Registered slave 20140929-192733-3176252227-39093-6596-0 at slave(46)@67.195.81.189:39093 (proserpina.apache.org)
I0929 19:27:33.716704 6613 log.cpp:699] Attempting to truncate the log to 3
I0929 19:27:33.716725 6618 master.cpp:4180] Adding slave 20140929-192733-3176252227-39093-6596-0 at slave(46)@67.195.81.189:39093 (proserpina.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0929 19:27:33.716799 6622 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
I0929 19:27:33.716914 6611 slave.cpp:769] Registered with master master@67.195.81.189:39093; given slave ID 20140929-192733-3176252227-39093-6596-0
I0929 19:27:33.716976 6611 slave.cpp:2351] Received ping from slave-observer(48)@67.195.81.189:39093
I0929 19:27:33.717036 6623 hierarchical_allocator_process.hpp:442] Added slave 20140929-192733-3176252227-39093-6596-0 (proserpina.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
I0929 19:27:33.717105 6623 hierarchical_allocator_process.hpp:679] Performed allocation for slave 20140929-192733-3176252227-39093-6596-0 in 9692ns
I0929 19:27:33.717315 6612 replica.cpp:508] Replica received write request for position 4
I0929 19:27:33.717638 6612 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 299339ns
I0929 19:27:33.717658 6612 replica.cpp:676] Persisted action at 4
I0929 19:27:33.717993 6620 replica.cpp:655] Replica received learned notice for position 4
I0929 19:27:33.718130 6620 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 111401ns
I0929 19:27:33.718179 6620 leveldb.cpp:401] Deleting ~2 keys from leveldb took 24089ns
I0929 19:27:33.718194 6620 replica.cpp:676] Persisted action at 4
I0929 19:27:33.718205 6620 replica.cpp:661] Replica learned TRUNCATE action at position 4
I0929 19:27:33.720230 6596 sched.cpp:137] Version: 0.21.0
I0929 19:27:33.720419 6616 sched.cpp:233] New master detected at master@67.195.81.189:39093
I0929 19:27:33.720448 6616 sched.cpp:283] Authenticating with master master@67.195.81.189:39093
I0929 19:27:33.720541 6619 authenticatee.hpp:128] Creating new client SASL connection
I0929 19:27:33.720649 6616 master.cpp:3737] Authenticating scheduler-6fbb44f6-f20c-48f5-a008-c5819b25326f@67.195.81.189:39093
I0929 19:27:33.720732 6619 authenticator.hpp:156] Creating new server SASL connection
I0929 19:27:33.720816 6611 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0929 19:27:33.720844 6611 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0929 19:27:33.720909 6614 authenticator.hpp:262] Received SASL authentication start
I0929 19:27:33.720968 6614 authenticator.hpp:384] Authentication requires more steps
I0929 19:27:33.721038 6614 authenticatee.hpp:265] Received SASL authentication step
I0929 19:27:33.721110 6619 authenticator.hpp:290] Received SASL authentication step
I0929 19:27:33.721138 6619 auxprop.cpp:81] 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
I0929 19:27:33.721149 6619 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I0929 19:27:33.721161 6619 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0929 19:27:33.721174 6619 auxprop.cpp:81] 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
I0929 19:27:33.721182 6619 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0929 19:27:33.721195 6619 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0929 19:27:33.721211 6619 authenticator.hpp:376] Authentication success
I0929 19:27:33.721262 6614 authenticatee.hpp:305] Authentication success
I0929 19:27:33.721282 6619 master.cpp:3777] Successfully authenticated principal 'test-principal' at scheduler-6fbb44f6-f20c-48f5-a008-c5819b25326f@67.195.81.189:39093
I0929 19:27:33.721364 6614 sched.cpp:357] Successfully authenticated with master master@67.195.81.189:39093
I0929 19:27:33.721384 6614 sched.cpp:476] Sending registration request to master@67.195.81.189:39093
I0929 19:27:33.721452 6625 master.cpp:1360] Received registration request from scheduler-6fbb44f6-f20c-48f5-a008-c5819b25326f@67.195.81.189:39093
I0929 19:27:33.721478 6625 master.cpp:1320] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0929 19:27:33.721627 6618 master.cpp:1419] Registering framework 20140929-192733-3176252227-39093-6596-0000 at scheduler-6fbb44f6-f20c-48f5-a008-c5819b25326f@67.195.81.189:39093
I0929 19:27:33.721707 6619 sched.cpp:407] Framework registered with 20140929-192733-3176252227-39093-6596-0000
I0929 19:27:33.721742 6611 hierarchical_allocator_process.hpp:329] Added framework 20140929-192733-3176252227-39093-6596-0000
I0929 19:27:33.721784 6619 sched.cpp:421] Scheduler::registered took 55248ns
I0929 19:27:33.721801 6611 hierarchical_allocator_process.hpp:734] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140929-192733-3176252227-39093-6596-0 to framework 20140929-192733-3176252227-39093-6596-0000
I0929 19:27:33.721974 6611 hierarchical_allocator_process.hpp:659] Performed allocation for 1 slaves in 205122ns
I0929 19:27:33.722015 6621 master.hpp:868] Adding offer 20140929-192733-3176252227-39093-6596-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140929-192733-3176252227-39093-6596-0 (proserpina.apache.org)
I0929 19:27:33.722069 6621 master.cpp:3679] Sending 1 offers to framework 20140929-192733-3176252227-39093-6596-0000
I0929 19:27:33.722326 6616 sched.cpp:544] Scheduler::resourceOffers took 134808ns
I0929 19:27:33.722502 6621 master.hpp:877] Removing offer 20140929-192733-3176252227-39093-6596-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140929-192733-3176252227-39093-6596-0 (proserpina.apache.org)
I0929 19:27:33.722551 6621 master.cpp:2274] Processing reply for offers: [ 20140929-192733-3176252227-39093-6596-0 ] on slave 20140929-192733-3176252227-39093-6596-0 at slave(46)@67.195.81.189:39093 (proserpina.apache.org) for framework 20140929-192733-3176252227-39093-6596-0000
W0929 19:27:33.722581 6621 master.cpp:1944] Executor default for task 0 uses less CPUs (None) than the minimum required (0.01). Please update your executor, as this will be mandatory in future releases.
W0929 19:27:33.722601 6621 master.cpp:1955] Executor default for task 0 uses less memory (None) than the minimum required (32MB). Please update your executor, as this will be mandatory in future releases.
I0929 19:27:33.722616 6621 master.cpp:2357] Authorizing framework principal 'test-principal' to launch task 0 as user 'jenkins'
I0929 19:27:33.722928 6614 master.hpp:845] Adding task 0 with resources cpus(*):2; mem(*):1024 on slave 20140929-192733-3176252227-39093-6596-0 (proserpina.apache.org)
I0929 19:27:33.722966 6614 master.cpp:2423] Launching task 0 of framework 20140929-192733-3176252227-39093-6596-0000 with resources cpus(*):2; mem(*):1024 on slave 20140929-192733-3176252227-39093-6596-0 at slave(46)@67.195.81.189:39093 (proserpina.apache.org)
I0929 19:27:33.723063 6625 slave.cpp:1029] Got assigned task 0 for framework 20140929-192733-3176252227-39093-6596-0000
I0929 19:27:33.723165 6623 hierarchical_allocator_process.hpp:563] Recovered disk(*):1024; ports(*):[31000-32000] (total allocatable: disk(*):1024; ports(*):[31000-32000]) on slave 20140929-192733-3176252227-39093-6596-0 from framework 20140929-192733-3176252227-39093-6596-0000
I0929 19:27:33.723199 6623 hierarchical_allocator_process.hpp:599] Framework 20140929-192733-3176252227-39093-6596-0000 filtered slave 20140929-192733-3176252227-39093-6596-0 for 5secs
I0929 19:27:33.723265 6625 slave.cpp:1139] Launching task 0 for framework 20140929-192733-3176252227-39093-6596-0000
I0929 19:27:33.726184 6625 exec.cpp:132] Version: 0.21.0
I0929 19:27:33.726266 6614 exec.cpp:182] Executor started at: executor(18)@67.195.81.189:39093 with pid 6596
I0929 19:27:33.726286 6625 slave.cpp:1252] Queuing task '0' for executor default of framework '20140929-192733-3176252227-39093-6596-0000
I0929 19:27:33.726331 6625 slave.cpp:560] Successfully attached file '/tmp/GarbageCollectorIntegrationTest_DiskUsage_5meoSi/slaves/20140929-192733-3176252227-39093-6596-0/frameworks/20140929-192733-3176252227-39093-6596-0000/executors/default/runs/42edbc00-b71c-49fb-b90d-41abae736459'
I0929 19:27:33.726371 6625 slave.cpp:2617] Monitoring executor 'default' of framework '20140929-192733-3176252227-39093-6596-0000' in container '42edbc00-b71c-49fb-b90d-41abae736459'
I0929 19:27:33.726445 6625 slave.cpp:1762] Got registration for executor 'default' of framework 20140929-192733-3176252227-39093-6596-0000 from executor(18)@67.195.81.189:39093
I0929 19:27:33.726568 6625 slave.cpp:1881] Flushing queued task 0 for executor 'default' of framework 20140929-192733-3176252227-39093-6596-0000
I0929 19:27:33.726606 6615 exec.cpp:206] Executor registered on slave 20140929-192733-3176252227-39093-6596-0
I0929 19:27:33.727777 6615 exec.cpp:218] Executor::registered took 12005ns
I0929 19:27:33.727838 6615 exec.cpp:293] Executor asked to run task '0'
I0929 19:27:33.727869 6615 exec.cpp:302] Executor::launchTask took 17937ns
I0929 19:27:33.729051 6615 exec.cpp:525] Executor sending status update TASK_RUNNING (UUID: e0274dc9-b651-4034-8910-29c5d4b17f4c) for task 0 of framework 20140929-192733-3176252227-39093-6596-0000
I0929 19:27:33.729141 6615 slave.cpp:2115] Handling status update TASK_RUNNING (UUID: e0274dc9-b651-4034-8910-29c5d4b17f4c) for task 0 of framework 20140929-192733-3176252227-39093-6596-0000 from executor(18)@67.195.81.189:39093
I0929 19:27:33.729228 6615 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: e0274dc9-b651-4034-8910-29c5d4b17f4c) for task 0 of framework 20140929-192733-3176252227-39093-6596-0000
I0929 19:27:33.729244 6615 status_update_manager.cpp:499] Creating StatusUpdate stream for task 0 of framework 20140929-192733-3176252227-39093-6596-0000
I0929 19:27:33.729305 6615 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: e0274dc9-b651-4034-8910-29c5d4b17f4c) for task 0 of framework 20140929-192733-3176252227-39093-6596-0000 to master@67.195.81.189:39093
I0929 19:27:33.729485 6617 master.cpp:3301] Forwarding status update TASK_RUNNING (UUID: e0274dc9-b651-4034-8910-29c5d4b17f4c) for task 0 of framework 20140929-192733-3176252227-39093-6596-0000
I0929 19:27:33.729542 6617 master.cpp:3273] Status update TASK_RUNNING (UUID: e0274dc9-b651-4034-8910-29c5d4b17f4c) for task 0 of framework 20140929-192733-3176252227-39093-6596-0000 from slave 20140929-192733-3176252227-39093-6596-0 at slave(46)@67.195.81.189:39093 (proserpina.apache.org)
I0929 19:27:33.729639 6611 sched.cpp:635] Scheduler::statusUpdate took 30441ns
I0929 19:27:33.729758 6622 master.cpp:2777] Forwarding status update acknowledgement e0274dc9-b651-4034-8910-29c5d4b17f4c for task 0 of framework 20140929-192733-3176252227-39093-6596-0000 to slave 20140929-192733-3176252227-39093-6596-0 at slave(46)@67.195.81.189:39093 (proserpina.apache.org)
I0929 19:27:33.729779 6625 slave.cpp:2272] Status update manager successfully handled status update TASK_RUNNING (UUID: e0274dc9-b651-4034-8910-29c5d4b17f4c) for task 0 of framework 20140929-192733-3176252227-39093-6596-0000
I0929 19:27:35.410068 6625 slave.cpp:2278] Sending acknowledgement for status update TASK_RUNNING (UUID: e0274dc9-b651-4034-8910-29c5d4b17f4c) for task 0 of framework 20140929-192733-3176252227-39093-6596-0000 to executor(18)@67.195.81.189:39093
I0929 19:27:35.410200 6625 slave.cpp:2675] Executor 'default' of framework 20140929-192733-3176252227-39093-6596-0000 exited with status 0
I0929 19:27:35.410275 6623 status_update_manager.cpp:398] Received status update acknowledgement (UUID: e0274dc9-b651-4034-8910-29c5d4b17f4c) for task 0 of framework 20140929-192733-3176252227-39093-6596-0000
I0929 19:27:35.411408 6625 slave.cpp:2115] Handling status update TASK_LOST (UUID: 6faaca53-ce83-40ff-b3f5-521ea804354e) for task 0 of framework 20140929-192733-3176252227-39093-6596-0000 from @0.0.0.0:0
I0929 19:27:35.411434 6625 slave.cpp:3995] Terminating task 0
I0929 19:27:35.411547 6625 slave.cpp:1702] Status update manager successfully handled status update acknowledgement (UUID: e0274dc9-b651-4034-8910-29c5d4b17f4c) for task 0 of framework 20140929-192733-3176252227-39093-6596-0000
I0929 19:27:35.411640 6625 status_update_manager.cpp:320] Received status update TASK_LOST (UUID: 6faaca53-ce83-40ff-b3f5-521ea804354e) for task 0 of framework 20140929-192733-3176252227-39093-6596-0000
I0929 19:27:35.411648 6623 master.cpp:3353] Executor default of framework 20140929-192733-3176252227-39093-6596-0000 on slave 20140929-192733-3176252227-39093-6596-0 at slave(46)@67.195.81.189:39093 (proserpina.apache.org) exited with status 0
I0929 19:27:35.411666 6625 status_update_manager.cpp:373] Forwarding status update TASK_LOST (UUID: 6faaca53-ce83-40ff-b3f5-521ea804354e) for task 0 of framework 20140929-192733-3176252227-39093-6596-0000 to master@67.195.81.189:39093
I0929 19:27:35.411679 6623 master.cpp:4514] Removing executor 'default' with resources of framework 20140929-192733-3176252227-39093-6596-0000 on slave 20140929-192733-3176252227-39093-6596-0 at slave(46)@67.195.81.189:39093 (proserpina.apache.org)
I0929 19:27:35.411798 6621 slave.cpp:2272] Status update manager successfully handled status update TASK_LOST (UUID: 6faaca53-ce83-40ff-b3f5-521ea804354e) for task 0 of framework 20140929-192733-3176252227-39093-6596-0000
I0929 19:27:35.411867 6623 master.cpp:3301] Forwarding status update TASK_LOST (UUID: 6faaca53-ce83-40ff-b3f5-521ea804354e) for task 0 of framework 20140929-192733-3176252227-39093-6596-0000
I0929 19:27:35.411924 6623 master.cpp:3273] Status update TASK_LOST (UUID: 6faaca53-ce83-40ff-b3f5-521ea804354e) for task 0 of framework 20140929-192733-3176252227-39093-6596-0000 from slave 20140929-192733-3176252227-39093-6596-0 at slave(46)@67.195.81.189:39093 (proserpina.apache.org)
I0929 19:27:35.412044 6625 sched.cpp:635] Scheduler::statusUpdate took 12352ns
I0929 19:27:35.412045 6623 hierarchical_allocator_process.hpp:563] Recovered cpus(*):2; mem(*):1024 (total allocatable: disk(*):1024; ports(*):[31000-32000]; cpus(*):2; mem(*):1024) on slave 20140929-192733-3176252227-39093-6596-0 from framework 20140929-192733-3176252227-39093-6596-0000
I0929 19:27:35.412128 6623 master.cpp:4485] Removing task 0 with resources cpus(*):2; mem(*):1024 of framework 20140929-192733-3176252227-39093-6596-0000 on slave 20140929-192733-3176252227-39093-6596-0 at slave(46)@67.195.81.189:39093 (proserpina.apache.org)
I0929 19:27:35.412174 6623 master.cpp:2777] Forwarding status update acknowledgement 6faaca53-ce83-40ff-b3f5-521ea804354e for task 0 of framework 20140929-192733-3176252227-39093-6596-0000 to slave 20140929-192733-3176252227-39093-6596-0 at slave(46)@67.195.81.189:39093 (proserpina.apache.org)
I0929 19:27:35.412346 6616 status_update_manager.cpp:398] Received status update acknowledgement (UUID: 6faaca53-ce83-40ff-b3f5-521ea804354e) for task 0 of framework 20140929-192733-3176252227-39093-6596-0000
I0929 19:27:35.412390 6616 status_update_manager.cpp:530] Cleaning up status update stream for task 0 of framework 20140929-192733-3176252227-39093-6596-0000
I0929 19:27:35.412519 6621 slave.cpp:1702] Status update manager successfully handled status update acknowledgement (UUID: 6faaca53-ce83-40ff-b3f5-521ea804354e) for task 0 of framework 20140929-192733-3176252227-39093-6596-0000
I0929 19:27:35.412541 6621 slave.cpp:4034] Completing task 0
I0929 19:27:35.412554 6621 slave.cpp:2811] Cleaning up executor 'default' of framework 20140929-192733-3176252227-39093-6596-0000
I0929 19:27:35.412665 6616 gc.cpp:56] Scheduling '/tmp/GarbageCollectorIntegrationTest_DiskUsage_5meoSi/slaves/20140929-192733-3176252227-39093-6596-0/frameworks/20140929-192733-3176252227-39093-6596-0000/executors/default/runs/42edbc00-b71c-49fb-b90d-41abae736459' for gc 1.00000210012741weeks in the future
I0929 19:27:35.412681 6621 slave.cpp:2886] Cleaning up framework 20140929-192733-3176252227-39093-6596-0000
I0929 19:27:35.412740 6616 gc.cpp:56] Scheduling '/tmp/GarbageCollectorIntegrationTest_DiskUsage_5meoSi/slaves/20140929-192733-3176252227-39093-6596-0/frameworks/20140929-192733-3176252227-39093-6596-0000/executors/default' for gc 1.00000210012741weeks in the future
I0929 19:27:35.412782 6612 status_update_manager.cpp:282] Closing status update streams for framework 20140929-192733-3176252227-39093-6596-0000
I0929 19:27:35.412793 6616 gc.cpp:56] Scheduling '/tmp/GarbageCollectorIntegrationTest_DiskUsage_5meoSi/slaves/20140929-192733-3176252227-39093-6596-0/frameworks/20140929-192733-3176252227-39093-6596-0000' for gc 1.00000210012741weeks in the future
I0929 19:27:35.423359 6617 slave.cpp:3132] Current usage 90.00%. Max allowed age: 0ns
I0929 19:27:35.423506 6617 hierarchical_allocator_process.hpp:734] Offering disk(*):1024; ports(*):[31000-32000]; cpus(*):2; mem(*):1024 on slave 20140929-192733-3176252227-39093-6596-0 to framework 20140929-192733-3176252227-39093-6596-0000
I0929 19:27:35.423621 6617 hierarchical_allocator_process.hpp:659] Performed allocation for 1 slaves in 166404ns
I0929 19:27:35.423671 6617 master.hpp:868] Adding offer 20140929-192733-3176252227-39093-6596-1 with resources disk(*):1024; ports(*):[31000-32000]; cpus(*):2; mem(*):1024 on slave 20140929-192733-3176252227-39093-6596-0 (proserpina.apache.org)
I0929 19:27:35.423720 6617 master.cpp:3679] Sending 1 offers to framework 20140929-192733-3176252227-39093-6596-0000
I0929 19:27:35.423882 6614 sched.cpp:544] Scheduler::resourceOffers took 15465ns
tests/gc_tests.cpp:675: Failure
Value of: os::exists(executorDir)
Actual: true
Expected: false
I0929 19:27:35.443688 6617 master.cpp:767] Framework 20140929-192733-3176252227-39093-6596-0000 disconnected
I0929 19:27:35.443712 6617 master.cpp:1705] Disconnecting framework 20140929-192733-3176252227-39093-6596-0000
I0929 19:27:35.443729 6617 master.cpp:1721] Deactivating framework 20140929-192733-3176252227-39093-6596-0000
I0929 19:27:35.443822 6617 master.hpp:877] Removing offer 20140929-192733-3176252227-39093-6596-1 with resources disk(*):1024; ports(*):[31000-32000]; cpus(*):2; mem(*):1024 on slave 20140929-192733-3176252227-39093-6596-0 (proserpina.apache.org)
I0929 19:27:35.443846 6620 hierarchical_allocator_process.hpp:405] Deactivated framework 20140929-192733-3176252227-39093-6596-0000
I0929 19:27:35.443877 6617 master.cpp:789] Giving framework 20140929-192733-3176252227-39093-6596-0000 0ns to failover
I0929 19:27:35.443943 6620 hierarchical_allocator_process.hpp:563] Recovered disk(*):1024; ports(*):[31000-32000]; cpus(*):2; mem(*):1024 (total allocatable: disk(*):1024; ports(*):[31000-32000]; cpus(*):2; mem(*):1024) on slave 20140929-192733-3176252227-39093-6596-0 from framework 20140929-192733-3176252227-39093-6596-0000
I0929 19:27:35.443974 6610 master.cpp:3549] Framework failover timeout, removing framework 20140929-192733-3176252227-39093-6596-0000
I0929 19:27:35.443991 6610 master.cpp:4041] Removing framework 20140929-192733-3176252227-39093-6596-0000
I0929 19:27:35.444080 6613 slave.cpp:1435] Asked to shut down framework 20140929-192733-3176252227-39093-6596-0000 by master@67.195.81.189:39093
W0929 19:27:35.583452 6613 slave.cpp:1450] Cannot shut down unknown framework 20140929-192733-3176252227-39093-6596-0000
I0929 19:27:35.444135 6610 master.cpp:676] Master terminating
I0929 19:27:35.444231 6616 hierarchical_allocator_process.hpp:360] Removed framework 20140929-192733-3176252227-39093-6596-0000
I0929 19:27:35.583642 6616 slave.cpp:2436] master@67.195.81.189:39093 exited
W0929 19:27:35.583662 6616 slave.cpp:2439] Master disconnected! Waiting for a new master to be elected
F0929 19:27:35.583662 6596 logging.cpp:57] RAW: Pure virtual method called
@ 0x2b5deb5974ed google::LogMessage::Fail()
@ 0x2b5deb59ebe6 google::RawLog__()
@ 0x5067c6 mesos::internal::tests::Cluster::Slaves::shutdown()
@ 0x7b1da4 mesos::internal::tests::MesosTest::ShutdownSlaves()
@ 0x9a4073 testing::internal::HandleExceptionsInMethodIfSupported<>()
@ 0x99b210 testing::Test::Run()
@ 0x99b2ee testing::TestInfo::Run()
@ 0x99b3f5 testing::TestCase::Run()
@ 0x99b698 testing::internal::UnitTestImpl::RunAllTests()
@ 0x99b937 testing::UnitTest::Run()
@ 0x492683 main
@ 0x2b5ded2bdec5 (unknown)
@ 0x4a15d8 (unknown)
make[3]: *** [check-local] Aborted
{code}
> GarbageCollectorIntegrationTest.DiskUsage is flaky.
> ---------------------------------------------------
>
> Key: MESOS-1347
> URL: https://issues.apache.org/jira/browse/MESOS-1347
> Project: Mesos
> Issue Type: Bug
> Components: test
> Affects Versions: 0.19.0
> Reporter: Benjamin Mahler
> Assignee: Dominic Hamon
> Fix For: 0.19.0
>
>
> From Jenkins:
> https://builds.apache.org/job/Mesos-Ubuntu-distcheck/79/consoleFull
> {noformat}
> [ 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
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)