[ https://issues.apache.org/jira/browse/MESOS-1347?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Benjamin Mahler reopened MESOS-1347: ------------------------------------ Re-opening as it appears to still be flaky: https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/2137/consoleFull {noformat} [ RUN ] GarbageCollectorIntegrationTest.DiskUsage Using temporary directory '/tmp/GarbageCollectorIntegrationTest_DiskUsage_tjpfEc' I1001 03:47:36.653859 9413 leveldb.cpp:176] Opened db in 2.065433ms I1001 03:47:36.654671 9413 leveldb.cpp:183] Compacted db in 784728ns I1001 03:47:36.654695 9413 leveldb.cpp:198] Created db iterator in 3540ns I1001 03:47:36.654711 9413 leveldb.cpp:204] Seeked to beginning of db in 683ns I1001 03:47:36.654722 9413 leveldb.cpp:273] Iterated through 0 keys in the db in 208ns I1001 03:47:36.654742 9413 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I1001 03:47:36.654906 9433 recover.cpp:425] Starting replica recovery I1001 03:47:36.654992 9433 recover.cpp:451] Replica is in EMPTY status I1001 03:47:36.655396 9429 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request I1001 03:47:36.655482 9437 recover.cpp:188] Received a recover response from a replica in EMPTY status I1001 03:47:36.655678 9428 recover.cpp:542] Updating replica status to STARTING I1001 03:47:36.656245 9434 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 494048ns I1001 03:47:36.656272 9434 replica.cpp:320] Persisted replica status to STARTING I1001 03:47:36.656352 9429 master.cpp:312] Master 20141001-034736-3176252227-46678-9413 (proserpina.apache.org) started on 67.195.81.189:46678 I1001 03:47:36.656388 9429 master.cpp:358] Master only allowing authenticated frameworks to register I1001 03:47:36.656404 9429 master.cpp:363] Master only allowing authenticated slaves to register I1001 03:47:36.656421 9429 credentials.hpp:36] Loading credentials for authentication from '/tmp/GarbageCollectorIntegrationTest_DiskUsage_tjpfEc/credentials' I1001 03:47:36.656436 9442 recover.cpp:451] Replica is in STARTING status I1001 03:47:36.656574 9429 master.cpp:392] Authorization enabled I1001 03:47:36.656782 9431 master.cpp:120] No whitelist given. Advertising offers for all slaves I1001 03:47:36.656842 9442 replica.cpp:638] Replica in STARTING status received a broadcasted recover request I1001 03:47:36.656867 9438 hierarchical_allocator_process.hpp:299] Initializing hierarchical allocator process with master : master@67.195.81.189:46678 I1001 03:47:36.657053 9437 recover.cpp:188] Received a recover response from a replica in STARTING status I1001 03:47:36.657254 9441 master.cpp:1241] The newly elected leader is master@67.195.81.189:46678 with id 20141001-034736-3176252227-46678-9413 I1001 03:47:36.657279 9441 master.cpp:1254] Elected as the leading master! I1001 03:47:36.657292 9441 master.cpp:1072] Recovering from registrar I1001 03:47:36.657311 9440 recover.cpp:542] Updating replica status to VOTING I1001 03:47:36.657403 9436 registrar.cpp:312] Recovering registrar I1001 03:47:36.657766 9437 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 295743ns I1001 03:47:36.657793 9437 replica.cpp:320] Persisted replica status to VOTING I1001 03:47:36.657863 9433 recover.cpp:556] Successfully joined the Paxos group I1001 03:47:36.657943 9433 recover.cpp:440] Recover process terminated I1001 03:47:36.658114 9432 log.cpp:656] Attempting to start the writer I1001 03:47:36.658612 9438 replica.cpp:474] Replica received implicit promise request with proposal 1 I1001 03:47:36.658779 9438 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 141800ns I1001 03:47:36.658797 9438 replica.cpp:342] Persisted promised to 1 I1001 03:47:36.659145 9432 coordinator.cpp:230] Coordinator attemping to fill missing position I1001 03:47:36.659880 9437 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2 I1001 03:47:36.769940 9437 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 516875ns I1001 03:47:36.769964 9437 replica.cpp:676] Persisted action at 0 I1001 03:47:36.770449 9437 replica.cpp:508] Replica received write request for position 0 I1001 03:47:36.770480 9437 leveldb.cpp:438] Reading position from leveldb took 12227ns I1001 03:47:36.770740 9437 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 237752ns I1001 03:47:36.770764 9437 replica.cpp:676] Persisted action at 0 I1001 03:47:36.771070 9435 replica.cpp:655] Replica received learned notice for position 0 I1001 03:47:36.771237 9435 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 145713ns I1001 03:47:36.771257 9435 replica.cpp:676] Persisted action at 0 I1001 03:47:36.771268 9435 replica.cpp:661] Replica learned NOP action at position 0 I1001 03:47:36.771442 9442 log.cpp:672] Writer started with ending position 0 I1001 03:47:36.772145 9437 leveldb.cpp:438] Reading position from leveldb took 12340ns I1001 03:47:36.773732 9428 registrar.cpp:345] Successfully fetched the registry (0B) I1001 03:47:36.773766 9428 registrar.cpp:421] Attempting to update the 'registry' I1001 03:47:36.775279 9436 log.cpp:680] Attempting to append 142 bytes to the log I1001 03:47:36.775357 9438 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1 I1001 03:47:36.775722 9438 replica.cpp:508] Replica received write request for position 1 I1001 03:47:36.776036 9438 leveldb.cpp:343] Persisting action (161 bytes) to leveldb took 288035ns I1001 03:47:36.776054 9438 replica.cpp:676] Persisted action at 1 I1001 03:47:36.776386 9442 replica.cpp:655] Replica received learned notice for position 1 I1001 03:47:36.776558 9442 leveldb.cpp:343] Persisting action (163 bytes) to leveldb took 149245ns I1001 03:47:36.776577 9442 replica.cpp:676] Persisted action at 1 I1001 03:47:36.776588 9442 replica.cpp:661] Replica learned APPEND action at position 1 I1001 03:47:36.776929 9428 registrar.cpp:478] Successfully updated 'registry' I1001 03:47:36.777048 9428 registrar.cpp:371] Successfully recovered registrar I1001 03:47:36.777078 9427 log.cpp:699] Attempting to truncate the log to 1 I1001 03:47:36.777173 9434 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2 I1001 03:47:36.777166 9428 master.cpp:1099] Recovered 0 slaves from the Registry (104B) ; allowing 10mins for slaves to re-register I1001 03:47:36.777612 9429 replica.cpp:508] Replica received write request for position 2 I1001 03:47:36.777926 9429 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 290035ns I1001 03:47:36.777945 9429 replica.cpp:676] Persisted action at 2 I1001 03:47:36.778380 9432 replica.cpp:655] Replica received learned notice for position 2 I1001 03:47:36.778542 9432 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 140867ns I1001 03:47:36.778574 9432 leveldb.cpp:401] Deleting ~1 keys from leveldb took 14792ns I1001 03:47:36.778587 9432 replica.cpp:676] Persisted action at 2 I1001 03:47:36.778599 9432 replica.cpp:661] Replica learned TRUNCATE action at position 2 I1001 03:47:36.790099 9431 slave.cpp:169] Slave started on 80)@67.195.81.189:46678 I1001 03:47:36.790130 9431 credentials.hpp:84] Loading credential for authentication from '/tmp/GarbageCollectorIntegrationTest_DiskUsage_YNTHJN/credential' I1001 03:47:36.790243 9431 slave.cpp:276] Slave using credential for: test-principal I1001 03:47:36.790345 9431 slave.cpp:289] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I1001 03:47:36.790429 9431 slave.cpp:317] Slave hostname: proserpina.apache.org I1001 03:47:36.790444 9431 slave.cpp:318] Slave checkpoint: false I1001 03:47:36.790887 9434 state.cpp:33] Recovering state from '/tmp/GarbageCollectorIntegrationTest_DiskUsage_YNTHJN/meta' I1001 03:47:36.791020 9441 status_update_manager.cpp:193] Recovering status update manager I1001 03:47:36.791182 9436 slave.cpp:3271] Finished recovery I1001 03:47:36.791498 9438 slave.cpp:598] New master detected at master@67.195.81.189:46678 I1001 03:47:36.791534 9438 slave.cpp:672] Authenticating with master master@67.195.81.189:46678 I1001 03:47:36.791556 9436 status_update_manager.cpp:167] New master detected at master@67.195.81.189:46678 I1001 03:47:36.791595 9438 slave.cpp:645] Detecting new master I1001 03:47:36.791604 9432 authenticatee.hpp:128] Creating new client SASL connection I1001 03:47:36.791746 9441 master.cpp:3737] Authenticating slave(80)@67.195.81.189:46678 I1001 03:47:36.791833 9429 authenticator.hpp:156] Creating new server SASL connection I1001 03:47:36.791950 9431 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5 I1001 03:47:36.791980 9431 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5' I1001 03:47:36.792038 9431 authenticator.hpp:262] Received SASL authentication start I1001 03:47:36.792093 9431 authenticator.hpp:384] Authentication requires more steps I1001 03:47:36.792143 9431 authenticatee.hpp:265] Received SASL authentication step I1001 03:47:36.792201 9431 authenticator.hpp:290] Received SASL authentication step I1001 03:47:36.792220 9431 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 I1001 03:47:36.792237 9431 auxprop.cpp:153] Looking up auxiliary property '*userPassword' I1001 03:47:36.792253 9431 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I1001 03:47:36.792266 9431 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 I1001 03:47:36.792276 9431 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I1001 03:47:36.792284 9431 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I1001 03:47:36.792299 9431 authenticator.hpp:376] Authentication success I1001 03:47:36.792356 9429 authenticatee.hpp:305] Authentication success I1001 03:47:36.792376 9431 master.cpp:3777] Successfully authenticated principal 'test-principal' at slave(80)@67.195.81.189:46678 I1001 03:47:36.792521 9429 slave.cpp:729] Successfully authenticated with master master@67.195.81.189:46678 I1001 03:47:36.792570 9429 slave.cpp:992] Will retry registration in 3.961757ms if necessary I1001 03:47:36.792639 9435 master.cpp:2930] Registering slave at slave(80)@67.195.81.189:46678 (proserpina.apache.org) with id 20141001-034736-3176252227-46678-9413-0 I1001 03:47:36.792791 9430 registrar.cpp:421] Attempting to update the 'registry' I1001 03:47:36.794385 9432 log.cpp:680] Attempting to append 321 bytes to the log I1001 03:47:36.794448 9442 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3 I1001 03:47:36.794879 9432 replica.cpp:508] Replica received write request for position 3 I1001 03:47:36.795069 9432 leveldb.cpp:343] Persisting action (340 bytes) to leveldb took 168022ns I1001 03:47:36.795089 9432 replica.cpp:676] Persisted action at 3 I1001 03:47:36.795445 9435 replica.cpp:655] Replica received learned notice for position 3 I1001 03:47:36.795871 9435 leveldb.cpp:343] Persisting action (342 bytes) to leveldb took 399601ns I1001 03:47:36.795892 9435 replica.cpp:676] Persisted action at 3 I1001 03:47:36.795902 9435 replica.cpp:661] Replica learned APPEND action at position 3 I1001 03:47:36.796242 9440 registrar.cpp:478] Successfully updated 'registry' I1001 03:47:36.796334 9434 master.cpp:2970] Registered slave 20141001-034736-3176252227-46678-9413-0 at slave(80)@67.195.81.189:46678 (proserpina.apache.org) I1001 03:47:36.796357 9431 log.cpp:699] Attempting to truncate the log to 3 I1001 03:47:36.796362 9434 master.cpp:4180] Adding slave 20141001-034736-3176252227-46678-9413-0 at slave(80)@67.195.81.189:46678 (proserpina.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I1001 03:47:36.796418 9436 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4 I1001 03:47:36.796800 9431 slave.cpp:992] Will retry registration in 21.067958ms if necessary I1001 03:47:36.871445 9431 slave.cpp:763] Registered with master master@67.195.81.189:46678; given slave ID 20141001-034736-3176252227-46678-9413-0 I1001 03:47:36.871557 9431 slave.cpp:2345] Received ping from slave-observer(80)@67.195.81.189:46678 I1001 03:47:36.871706 9434 master.cpp:2906] Slave 20141001-034736-3176252227-46678-9413-0 at slave(80)@67.195.81.189:46678 (proserpina.apache.org) already registered, resending acknowledgement I1001 03:47:36.871831 9431 hierarchical_allocator_process.hpp:442] Added slave 20141001-034736-3176252227-46678-9413-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) I1001 03:47:36.871876 9440 replica.cpp:508] Replica received write request for position 4 I1001 03:47:36.871886 9431 hierarchical_allocator_process.hpp:679] Performed allocation for slave 20141001-034736-3176252227-46678-9413-0 in 10017ns W1001 03:47:36.871920 9430 slave.cpp:800] Already registered with master master@67.195.81.189:46678 I1001 03:47:36.872323 9440 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 422038ns I1001 03:47:36.872346 9440 replica.cpp:676] Persisted action at 4 I1001 03:47:36.872623 9442 replica.cpp:655] Replica received learned notice for position 4 I1001 03:47:36.872745 9442 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 98969ns I1001 03:47:36.872781 9442 leveldb.cpp:401] Deleting ~2 keys from leveldb took 18039ns I1001 03:47:36.872795 9442 replica.cpp:676] Persisted action at 4 I1001 03:47:36.872807 9442 replica.cpp:661] Replica learned TRUNCATE action at position 4 I1001 03:47:36.875334 9413 sched.cpp:137] Version: 0.21.0 I1001 03:47:36.875529 9438 sched.cpp:233] New master detected at master@67.195.81.189:46678 I1001 03:47:36.875552 9438 sched.cpp:283] Authenticating with master master@67.195.81.189:46678 I1001 03:47:36.875627 9441 authenticatee.hpp:128] Creating new client SASL connection I1001 03:47:36.875756 9439 master.cpp:3737] Authenticating scheduler-61ff7896-3433-44f2-9bba-6912813fbb48@67.195.81.189:46678 I1001 03:47:36.875836 9438 authenticator.hpp:156] Creating new server SASL connection I1001 03:47:36.875934 9437 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5 I1001 03:47:36.875962 9437 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5' I1001 03:47:36.876003 9437 authenticator.hpp:262] Received SASL authentication start I1001 03:47:36.876049 9437 authenticator.hpp:384] Authentication requires more steps I1001 03:47:36.876093 9437 authenticatee.hpp:265] Received SASL authentication step I1001 03:47:36.876180 9434 authenticator.hpp:290] Received SASL authentication step I1001 03:47:36.876205 9434 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 I1001 03:47:36.876216 9434 auxprop.cpp:153] Looking up auxiliary property '*userPassword' I1001 03:47:36.876230 9434 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I1001 03:47:36.876241 9434 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 I1001 03:47:36.876250 9434 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I1001 03:47:36.876258 9434 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I1001 03:47:36.876276 9434 authenticator.hpp:376] Authentication success I1001 03:47:36.876327 9433 authenticatee.hpp:305] Authentication success I1001 03:47:36.876344 9434 master.cpp:3777] Successfully authenticated principal 'test-principal' at scheduler-61ff7896-3433-44f2-9bba-6912813fbb48@67.195.81.189:46678 I1001 03:47:36.876502 9433 sched.cpp:357] Successfully authenticated with master master@67.195.81.189:46678 I1001 03:47:36.876531 9433 sched.cpp:476] Sending registration request to master@67.195.81.189:46678 I1001 03:47:36.876612 9427 master.cpp:1360] Received registration request from scheduler-61ff7896-3433-44f2-9bba-6912813fbb48@67.195.81.189:46678 I1001 03:47:36.876642 9427 master.cpp:1320] Authorizing framework principal 'test-principal' to receive offers for role '*' I1001 03:47:36.876834 9441 master.cpp:1419] Registering framework 20141001-034736-3176252227-46678-9413-0000 at scheduler-61ff7896-3433-44f2-9bba-6912813fbb48@67.195.81.189:46678 I1001 03:47:36.876929 9432 sched.cpp:407] Framework registered with 20141001-034736-3176252227-46678-9413-0000 I1001 03:47:36.876955 9437 hierarchical_allocator_process.hpp:329] Added framework 20141001-034736-3176252227-46678-9413-0000 I1001 03:47:36.877030 9432 sched.cpp:421] Scheduler::registered took 75424ns I1001 03:47:36.877038 9437 hierarchical_allocator_process.hpp:734] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20141001-034736-3176252227-46678-9413-0 to framework 20141001-034736-3176252227-46678-9413-0000 I1001 03:47:36.877174 9437 hierarchical_allocator_process.hpp:659] Performed allocation for 1 slaves in 194213ns I1001 03:47:36.877241 9439 master.hpp:868] Adding offer 20141001-034736-3176252227-46678-9413-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20141001-034736-3176252227-46678-9413-0 (proserpina.apache.org) I1001 03:47:36.877300 9439 master.cpp:3679] Sending 1 offers to framework 20141001-034736-3176252227-46678-9413-0000 I1001 03:47:36.877568 9427 sched.cpp:544] Scheduler::resourceOffers took 147352ns I1001 03:47:36.877751 9439 master.hpp:877] Removing offer 20141001-034736-3176252227-46678-9413-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20141001-034736-3176252227-46678-9413-0 (proserpina.apache.org) I1001 03:47:36.877799 9439 master.cpp:2274] Processing reply for offers: [ 20141001-034736-3176252227-46678-9413-0 ] on slave 20141001-034736-3176252227-46678-9413-0 at slave(80)@67.195.81.189:46678 (proserpina.apache.org) for framework 20141001-034736-3176252227-46678-9413-0000 W1001 03:47:36.877830 9439 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. W1001 03:47:36.877849 9439 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. I1001 03:47:36.877864 9439 master.cpp:2357] Authorizing framework principal 'test-principal' to launch task 0 as user 'jenkins' I1001 03:47:36.878176 9434 master.hpp:845] Adding task 0 with resources cpus(*):2; mem(*):1024 on slave 20141001-034736-3176252227-46678-9413-0 (proserpina.apache.org) I1001 03:47:36.878219 9434 master.cpp:2423] Launching task 0 of framework 20141001-034736-3176252227-46678-9413-0000 with resources cpus(*):2; mem(*):1024 on slave 20141001-034736-3176252227-46678-9413-0 at slave(80)@67.195.81.189:46678 (proserpina.apache.org) I1001 03:47:36.878320 9429 slave.cpp:1023] Got assigned task 0 for framework 20141001-034736-3176252227-46678-9413-0000 I1001 03:47:36.878429 9432 hierarchical_allocator_process.hpp:563] Recovered disk(*):1024; ports(*):[31000-32000] (total allocatable: disk(*):1024; ports(*):[31000-32000]) on slave 20141001-034736-3176252227-46678-9413-0 from framework 20141001-034736-3176252227-46678-9413-0000 I1001 03:47:36.878540 9429 slave.cpp:1133] Launching task 0 for framework 20141001-034736-3176252227-46678-9413-0000 I1001 03:47:36.958345 9432 hierarchical_allocator_process.hpp:599] Framework 20141001-034736-3176252227-46678-9413-0000 filtered slave 20141001-034736-3176252227-46678-9413-0 for 5secs I1001 03:47:36.961282 9429 exec.cpp:132] Version: 0.21.0 I1001 03:47:36.961365 9429 slave.cpp:1246] Queuing task '0' for executor default of framework '20141001-034736-3176252227-46678-9413-0000 I1001 03:47:36.961370 9440 exec.cpp:182] Executor started at: executor(22)@67.195.81.189:46678 with pid 9413 I1001 03:47:36.961405 9429 slave.cpp:554] Successfully attached file '/tmp/GarbageCollectorIntegrationTest_DiskUsage_YNTHJN/slaves/20141001-034736-3176252227-46678-9413-0/frameworks/20141001-034736-3176252227-46678-9413-0000/executors/default/runs/c36ff4ea-dca5-44e1-b528-455450b56beb' I1001 03:47:36.961436 9429 slave.cpp:2611] Monitoring executor 'default' of framework '20141001-034736-3176252227-46678-9413-0000' in container 'c36ff4ea-dca5-44e1-b528-455450b56beb' I1001 03:47:36.961498 9429 slave.cpp:1756] Got registration for executor 'default' of framework 20141001-034736-3176252227-46678-9413-0000 from executor(22)@67.195.81.189:46678 I1001 03:47:36.961591 9429 slave.cpp:1875] Flushing queued task 0 for executor 'default' of framework 20141001-034736-3176252227-46678-9413-0000 I1001 03:47:36.961628 9433 exec.cpp:206] Executor registered on slave 20141001-034736-3176252227-46678-9413-0 I1001 03:47:36.962927 9433 exec.cpp:218] Executor::registered took 14929ns I1001 03:47:36.962990 9433 exec.cpp:293] Executor asked to run task '0' I1001 03:47:36.963026 9433 exec.cpp:302] Executor::launchTask took 20934ns I1001 03:47:36.964328 9433 exec.cpp:525] Executor sending status update TASK_RUNNING (UUID: a8cbd148-ccc6-4d05-9501-391570d7c885) for task 0 of framework 20141001-034736-3176252227-46678-9413-0000 I1001 03:47:36.964419 9433 slave.cpp:2109] Handling status update TASK_RUNNING (UUID: a8cbd148-ccc6-4d05-9501-391570d7c885) for task 0 of framework 20141001-034736-3176252227-46678-9413-0000 from executor(22)@67.195.81.189:46678 I1001 03:47:36.964521 9431 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: a8cbd148-ccc6-4d05-9501-391570d7c885) for task 0 of framework 20141001-034736-3176252227-46678-9413-0000 I1001 03:47:36.964547 9431 status_update_manager.cpp:499] Creating StatusUpdate stream for task 0 of framework 20141001-034736-3176252227-46678-9413-0000 I1001 03:47:36.964613 9431 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: a8cbd148-ccc6-4d05-9501-391570d7c885) for task 0 of framework 20141001-034736-3176252227-46678-9413-0000 to master@67.195.81.189:46678 I1001 03:47:36.964725 9430 master.cpp:3301] Forwarding status update TASK_RUNNING (UUID: a8cbd148-ccc6-4d05-9501-391570d7c885) for task 0 of framework 20141001-034736-3176252227-46678-9413-0000 I1001 03:47:36.964737 9433 slave.cpp:2266] Status update manager successfully handled status update TASK_RUNNING (UUID: a8cbd148-ccc6-4d05-9501-391570d7c885) for task 0 of framework 20141001-034736-3176252227-46678-9413-0000 I1001 03:47:36.964758 9433 slave.cpp:2272] Sending acknowledgement for status update TASK_RUNNING (UUID: a8cbd148-ccc6-4d05-9501-391570d7c885) for task 0 of framework 20141001-034736-3176252227-46678-9413-0000 to executor(22)@67.195.81.189:46678 I1001 03:47:36.964802 9430 master.cpp:3273] Status update TASK_RUNNING (UUID: a8cbd148-ccc6-4d05-9501-391570d7c885) for task 0 of framework 20141001-034736-3176252227-46678-9413-0000 from slave 20141001-034736-3176252227-46678-9413-0 at slave(80)@67.195.81.189:46678 (proserpina.apache.org) I1001 03:47:36.964870 9435 exec.cpp:339] Executor received status update acknowledgement a8cbd148-ccc6-4d05-9501-391570d7c885 for task 0 of framework 20141001-034736-3176252227-46678-9413-0000 I1001 03:47:36.964907 9438 sched.cpp:635] Scheduler::statusUpdate took 33619ns I1001 03:47:36.965086 9430 master.cpp:2777] Forwarding status update acknowledgement a8cbd148-ccc6-4d05-9501-391570d7c885 for task 0 of framework 20141001-034736-3176252227-46678-9413-0000 to slave 20141001-034736-3176252227-46678-9413-0 at slave(80)@67.195.81.189:46678 (proserpina.apache.org) I1001 03:47:36.965242 9430 slave.cpp:2669] Executor 'default' of framework 20141001-034736-3176252227-46678-9413-0000 exited with status 0 I1001 03:47:36.965286 9436 status_update_manager.cpp:398] Received status update acknowledgement (UUID: a8cbd148-ccc6-4d05-9501-391570d7c885) for task 0 of framework 20141001-034736-3176252227-46678-9413-0000 I1001 03:47:36.966593 9430 slave.cpp:2109] Handling status update TASK_LOST (UUID: ee90feaa-ae64-4773-a8e3-fe161724f5c6) for task 0 of framework 20141001-034736-3176252227-46678-9413-0000 from @0.0.0.0:0 I1001 03:47:36.966621 9430 slave.cpp:3989] Terminating task 0 I1001 03:47:36.966749 9430 slave.cpp:1696] Status update manager successfully handled status update acknowledgement (UUID: a8cbd148-ccc6-4d05-9501-391570d7c885) for task 0 of framework 20141001-034736-3176252227-46678-9413-0000 I1001 03:47:36.966814 9439 master.cpp:3353] Executor default of framework 20141001-034736-3176252227-46678-9413-0000 on slave 20141001-034736-3176252227-46678-9413-0 at slave(80)@67.195.81.189:46678 (proserpina.apache.org) exited with status 0 I1001 03:47:36.966853 9439 master.cpp:4514] Removing executor 'default' with resources of framework 20141001-034736-3176252227-46678-9413-0000 on slave 20141001-034736-3176252227-46678-9413-0 at slave(80)@67.195.81.189:46678 (proserpina.apache.org) I1001 03:47:36.966905 9427 status_update_manager.cpp:320] Received status update TASK_LOST (UUID: ee90feaa-ae64-4773-a8e3-fe161724f5c6) for task 0 of framework 20141001-034736-3176252227-46678-9413-0000 I1001 03:47:36.966963 9427 status_update_manager.cpp:373] Forwarding status update TASK_LOST (UUID: ee90feaa-ae64-4773-a8e3-fe161724f5c6) for task 0 of framework 20141001-034736-3176252227-46678-9413-0000 to master@67.195.81.189:46678 I1001 03:47:36.967103 9438 master.cpp:3301] Forwarding status update TASK_LOST (UUID: ee90feaa-ae64-4773-a8e3-fe161724f5c6) for task 0 of framework 20141001-034736-3176252227-46678-9413-0000 I1001 03:47:36.967121 9432 slave.cpp:2266] Status update manager successfully handled status update TASK_LOST (UUID: ee90feaa-ae64-4773-a8e3-fe161724f5c6) for task 0 of framework 20141001-034736-3176252227-46678-9413-0000 I1001 03:47:36.967178 9438 master.cpp:3273] Status update TASK_LOST (UUID: ee90feaa-ae64-4773-a8e3-fe161724f5c6) for task 0 of framework 20141001-034736-3176252227-46678-9413-0000 from slave 20141001-034736-3176252227-46678-9413-0 at slave(80)@67.195.81.189:46678 (proserpina.apache.org) I1001 03:47:36.967262 9432 sched.cpp:635] Scheduler::statusUpdate took 20007ns I1001 03:47:36.967309 9436 hierarchical_allocator_process.hpp:563] Recovered cpus(*):2; mem(*):1024 (total allocatable: disk(*):1024; ports(*):[31000-32000]; cpus(*):2; mem(*):1024) on slave 20141001-034736-3176252227-46678-9413-0 from framework 20141001-034736-3176252227-46678-9413-0000 I1001 03:47:36.967345 9432 master.cpp:4485] Removing task 0 with resources cpus(*):2; mem(*):1024 of framework 20141001-034736-3176252227-46678-9413-0000 on slave 20141001-034736-3176252227-46678-9413-0 at slave(80)@67.195.81.189:46678 (proserpina.apache.org) I1001 03:47:36.967407 9432 master.cpp:2777] Forwarding status update acknowledgement ee90feaa-ae64-4773-a8e3-fe161724f5c6 for task 0 of framework 20141001-034736-3176252227-46678-9413-0000 to slave 20141001-034736-3176252227-46678-9413-0 at slave(80)@67.195.81.189:46678 (proserpina.apache.org) I1001 03:47:36.967563 9430 status_update_manager.cpp:398] Received status update acknowledgement (UUID: ee90feaa-ae64-4773-a8e3-fe161724f5c6) for task 0 of framework 20141001-034736-3176252227-46678-9413-0000 I1001 03:47:39.236191 9430 status_update_manager.cpp:530] Cleaning up status update stream for task 0 of framework 20141001-034736-3176252227-46678-9413-0000 I1001 03:47:39.236281 9430 slave.cpp:1696] Status update manager successfully handled status update acknowledgement (UUID: ee90feaa-ae64-4773-a8e3-fe161724f5c6) for task 0 of framework 20141001-034736-3176252227-46678-9413-0000 I1001 03:47:39.236301 9430 slave.cpp:4028] Completing task 0 I1001 03:47:39.236313 9430 slave.cpp:2805] Cleaning up executor 'default' of framework 20141001-034736-3176252227-46678-9413-0000 I1001 03:47:39.236425 9430 slave.cpp:2880] Cleaning up framework 20141001-034736-3176252227-46678-9413-0000 I1001 03:47:39.236428 9433 gc.cpp:56] Scheduling '/tmp/GarbageCollectorIntegrationTest_DiskUsage_YNTHJN/slaves/20141001-034736-3176252227-46678-9413-0/frameworks/20141001-034736-3176252227-46678-9413-0000/executors/default/runs/c36ff4ea-dca5-44e1-b528-455450b56beb' for gc 1.00000336462772weeks in the future I1001 03:47:39.236502 9432 status_update_manager.cpp:282] Closing status update streams for framework 20141001-034736-3176252227-46678-9413-0000 I1001 03:47:39.236526 9433 gc.cpp:56] Scheduling '/tmp/GarbageCollectorIntegrationTest_DiskUsage_YNTHJN/slaves/20141001-034736-3176252227-46678-9413-0/frameworks/20141001-034736-3176252227-46678-9413-0000/executors/default' for gc 1.00000336462772weeks in the future I1001 03:47:39.236568 9433 gc.cpp:56] Scheduling '/tmp/GarbageCollectorIntegrationTest_DiskUsage_YNTHJN/slaves/20141001-034736-3176252227-46678-9413-0/frameworks/20141001-034736-3176252227-46678-9413-0000' for gc 1.00000336462772weeks in the future I1001 03:47:39.253628 9438 slave.cpp:3126] Current usage 90.00%. Max allowed age: 0ns I1001 03:47:39.253835 9435 hierarchical_allocator_process.hpp:734] Offering disk(*):1024; ports(*):[31000-32000]; cpus(*):2; mem(*):1024 on slave 20141001-034736-3176252227-46678-9413-0 to framework 20141001-034736-3176252227-46678-9413-0000 I1001 03:47:39.253962 9435 hierarchical_allocator_process.hpp:659] Performed allocation for 1 slaves in 178393ns I1001 03:47:39.254017 9431 master.hpp:868] Adding offer 20141001-034736-3176252227-46678-9413-1 with resources disk(*):1024; ports(*):[31000-32000]; cpus(*):2; mem(*):1024 on slave 20141001-034736-3176252227-46678-9413-0 (proserpina.apache.org) I1001 03:47:39.254076 9431 master.cpp:3679] Sending 1 offers to framework 20141001-034736-3176252227-46678-9413-0000 I1001 03:47:39.254214 9435 sched.cpp:544] Scheduler::resourceOffers took 10750ns tests/gc_tests.cpp:675: Failure Value of: os::exists(executorDir) Actual: true Expected: false I1001 03:47:39.273896 9431 master.cpp:767] Framework 20141001-034736-3176252227-46678-9413-0000 disconnected I1001 03:47:39.273916 9431 master.cpp:1705] Disconnecting framework 20141001-034736-3176252227-46678-9413-0000 I1001 03:47:39.273927 9431 master.cpp:1721] Deactivating framework 20141001-034736-3176252227-46678-9413-0000 I1001 03:47:39.273983 9431 master.hpp:877] Removing offer 20141001-034736-3176252227-46678-9413-1 with resources disk(*):1024; ports(*):[31000-32000]; cpus(*):2; mem(*):1024 on slave 20141001-034736-3176252227-46678-9413-0 (proserpina.apache.org) I1001 03:47:39.274027 9428 hierarchical_allocator_process.hpp:405] Deactivated framework 20141001-034736-3176252227-46678-9413-0000 I1001 03:47:39.274044 9431 master.cpp:789] Giving framework 20141001-034736-3176252227-46678-9413-0000 0ns to failover I1001 03:47:39.274149 9432 master.cpp:3549] Framework failover timeout, removing framework 20141001-034736-3176252227-46678-9413-0000 I1001 03:47:39.274171 9432 master.cpp:4041] Removing framework 20141001-034736-3176252227-46678-9413-0000 I1001 03:47:39.274166 9428 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 20141001-034736-3176252227-46678-9413-0 from framework 20141001-034736-3176252227-46678-9413-0000 I1001 03:47:39.274261 9435 slave.cpp:1429] Asked to shut down framework 20141001-034736-3176252227-46678-9413-0000 by master@67.195.81.189:46678 W1001 03:47:39.274288 9435 slave.cpp:1444] Cannot shut down unknown framework 20141001-034736-3176252227-46678-9413-0000 I1001 03:47:39.274303 9432 master.cpp:676] Master terminating I1001 03:47:39.274348 9439 hierarchical_allocator_process.hpp:360] Removed framework 20141001-034736-3176252227-46678-9413-0000 I1001 03:47:39.274453 9435 slave.cpp:2430] master@67.195.81.189:46678 exited W1001 03:47:39.274478 9435 slave.cpp:2433] Master disconnected! Waiting for a new master to be elected F1001 03:47:39.274478 9413 logging.cpp:57] RAW: Pure virtual method called @ 0x2af2a4894f6d google::LogMessage::Fail() @ 0x2af2a489c666 google::RawLog__() @ 0x506c16 mesos::internal::tests::Cluster::Slaves::shutdown() @ 0x7b28f4 mesos::internal::tests::MesosTest::ShutdownSlaves() @ 0x9a4de3 testing::internal::HandleExceptionsInMethodIfSupported<>() @ 0x99bf80 testing::Test::Run() @ 0x99c05e testing::TestInfo::Run() @ 0x99c165 testing::TestCase::Run() @ 0x99c408 testing::internal::UnitTestImpl::RunAllTests() @ 0x99c6a7 testing::UnitTest::Run() @ 0x492c63 main @ 0x2af2a65baec5 (unknown) @ 0x4a1bb8 (unknown) make[3]: *** [check-local] Aborted {noformat} This stack trace appears only in *failing* tests, when a TestContainerizer lives in the test's scope, but MesosTest::Shutdown was not called until the test exception is being handled. > 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)