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/11/20 03:22:33 UTC
[jira] [Created] (MESOS-2143) 'gc' process is leaked in tests
Vinod Kone created MESOS-2143:
---------------------------------
Summary: 'gc' process is leaked in tests
Key: MESOS-2143
URL: https://issues.apache.org/jira/browse/MESOS-2143
Project: Mesos
Issue Type: Bug
Components: test
Reporter: Vinod Kone
Observed this on Apache CI.
The 'gc' process from a failed test (GarbageCollectorIntegrationTest.DiskUsage) is still active when the next test (GarbageCollectorIntegrationTest.Restart) is being run causing it to SEGFAULT. It is not yet clear, why the old 'gc' is still active.
{code}
[ RUN ] GarbageCollectorIntegrationTest.DiskUsage
Using temporary directory '/tmp/GarbageCollectorIntegrationTest_DiskUsage_2vU5Cz'
I1119 20:55:49.040068 25120 leveldb.cpp:176] Opened db in 2.493217ms
I1119 20:55:49.041033 25120 leveldb.cpp:183] Compacted db in 936066ns
I1119 20:55:49.041086 25120 leveldb.cpp:198] Created db iterator in 19935ns
I1119 20:55:49.041106 25120 leveldb.cpp:204] Seeked to beginning of db in 2060ns
I1119 20:55:49.041117 25120 leveldb.cpp:273] Iterated through 0 keys in the db in 338ns
I1119 20:55:49.041156 25120 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I1119 20:55:49.041666 25137 recover.cpp:437] Starting replica recovery
I1119 20:55:49.042052 25137 recover.cpp:463] Replica is in EMPTY status
I1119 20:55:49.043650 25137 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request
I1119 20:55:49.044262 25136 recover.cpp:188] Received a recover response from a replica in EMPTY status
I1119 20:55:49.044724 25147 recover.cpp:554] Updating replica status to STARTING
I1119 20:55:49.045310 25143 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 452241ns
I1119 20:55:49.045328 25143 replica.cpp:320] Persisted replica status to STARTING
I1119 20:55:49.045667 25147 recover.cpp:463] Replica is in STARTING status
I1119 20:55:49.046681 25149 replica.cpp:638] Replica in STARTING status received a broadcasted recover request
I1119 20:55:49.047066 25139 recover.cpp:188] Received a recover response from a replica in STARTING status
I1119 20:55:49.047394 25148 recover.cpp:554] Updating replica status to VOTING
I1119 20:55:49.047874 25142 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 391070ns
I1119 20:55:49.047899 25142 replica.cpp:320] Persisted replica status to VOTING
I1119 20:55:49.047991 25135 recover.cpp:568] Successfully joined the Paxos group
I1119 20:55:49.048159 25135 recover.cpp:452] Recover process terminated
I1119 20:55:49.053148 25142 master.cpp:318] Master 20141119-205549-3125920579-57639-25120 (penates.apache.org) started on 67.195.81.186:57639
I1119 20:55:49.053186 25142 master.cpp:364] Master only allowing authenticated frameworks to register
I1119 20:55:49.053196 25142 master.cpp:369] Master only allowing authenticated slaves to register
I1119 20:55:49.053215 25142 credentials.hpp:36] Loading credentials for authentication from '/tmp/GarbageCollectorIntegrationTest_DiskUsage_2vU5Cz/credentials'
I1119 20:55:49.053413 25142 master.cpp:413] Authorization enabled
I1119 20:55:49.053772 25134 master.cpp:126] No whitelist given. Advertising offers for all slaves
I1119 20:55:49.053874 25141 hierarchical_allocator_process.hpp:299] Initializing hierarchical allocator process with master : master@67.195.81.186:57639
I1119 20:55:49.054661 25148 master.cpp:1263] The newly elected leader is master@67.195.81.186:57639 with id 20141119-205549-3125920579-57639-25120
I1119 20:55:49.054682 25148 master.cpp:1276] Elected as the leading master!
I1119 20:55:49.054695 25148 master.cpp:1094] Recovering from registrar
I1119 20:55:49.054811 25140 registrar.cpp:313] Recovering registrar
I1119 20:55:49.055305 25148 log.cpp:656] Attempting to start the writer
I1119 20:55:49.056386 25140 replica.cpp:474] Replica received implicit promise request with proposal 1
I1119 20:55:49.056764 25140 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 357088ns
I1119 20:55:49.056782 25140 replica.cpp:342] Persisted promised to 1
I1119 20:55:49.057235 25140 coordinator.cpp:230] Coordinator attemping to fill missing position
I1119 20:55:49.058406 25148 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
I1119 20:55:49.058948 25148 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 509833ns
I1119 20:55:49.058970 25148 replica.cpp:676] Persisted action at 0
I1119 20:55:49.060003 25136 replica.cpp:508] Replica received write request for position 0
I1119 20:55:49.060070 25136 leveldb.cpp:438] Reading position from leveldb took 33920ns
I1119 20:55:49.060590 25136 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 478048ns
I1119 20:55:49.060621 25136 replica.cpp:676] Persisted action at 0
I1119 20:55:49.061161 25141 replica.cpp:655] Replica received learned notice for position 0
I1119 20:55:49.061653 25141 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 465965ns
I1119 20:55:49.061676 25141 replica.cpp:676] Persisted action at 0
I1119 20:55:49.061694 25141 replica.cpp:661] Replica learned NOP action at position 0
I1119 20:55:49.062234 25147 log.cpp:672] Writer started with ending position 0
I1119 20:55:49.063383 25146 leveldb.cpp:438] Reading position from leveldb took 31010ns
I1119 20:55:49.066402 25142 registrar.cpp:346] Successfully fetched the registry (0B) in 11.53408ms
I1119 20:55:49.066534 25142 registrar.cpp:445] Applied 1 operations in 18377ns; attempting to update the 'registry'
I1119 20:55:49.069085 25144 log.cpp:680] Attempting to append 140 bytes to the log
I1119 20:55:49.069246 25149 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
I1119 20:55:49.070111 25140 replica.cpp:508] Replica received write request for position 1
I1119 20:55:49.070607 25140 leveldb.cpp:343] Persisting action (159 bytes) to leveldb took 463861ns
I1119 20:55:49.070633 25140 replica.cpp:676] Persisted action at 1
I1119 20:55:49.071202 25149 replica.cpp:655] Replica received learned notice for position 1
I1119 20:55:49.071861 25149 leveldb.cpp:343] Persisting action (161 bytes) to leveldb took 631323ns
I1119 20:55:49.071887 25149 replica.cpp:676] Persisted action at 1
I1119 20:55:49.071907 25149 replica.cpp:661] Replica learned APPEND action at position 1
I1119 20:55:49.072870 25149 registrar.cpp:490] Successfully updated the 'registry' in 6.285824ms
I1119 20:55:49.072996 25149 registrar.cpp:376] Successfully recovered registrar
I1119 20:55:49.073214 25145 log.cpp:699] Attempting to truncate the log to 1
I1119 20:55:49.073396 25147 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
I1119 20:55:49.073580 25139 master.cpp:1121] Recovered 0 slaves from the Registry (102B) ; allowing 10mins for slaves to re-register
I1119 20:55:49.074381 25143 replica.cpp:508] Replica received write request for position 2
I1119 20:55:49.074913 25143 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 496612ns
I1119 20:55:49.074937 25143 replica.cpp:676] Persisted action at 2
I1119 20:55:49.075544 25146 replica.cpp:655] Replica received learned notice for position 2
I1119 20:55:49.076230 25146 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 658082ns
I1119 20:55:49.076287 25146 leveldb.cpp:401] Deleting ~1 keys from leveldb took 32149ns
I1119 20:55:49.076306 25146 replica.cpp:676] Persisted action at 2
I1119 20:55:49.076328 25146 replica.cpp:661] Replica learned TRUNCATE action at position 2
I1119 20:55:49.091895 25145 slave.cpp:170] Slave started on 169)@67.195.81.186:57639
I1119 20:55:49.091929 25145 credentials.hpp:84] Loading credential for authentication from '/tmp/GarbageCollectorIntegrationTest_DiskUsage_4kBMA9/credential'
I1119 20:55:49.092043 25145 slave.cpp:279] Slave using credential for: test-principal
I1119 20:55:49.092212 25145 slave.cpp:292] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I1119 20:55:49.092283 25145 slave.cpp:321] Slave hostname: penates.apache.org
I1119 20:55:49.092293 25145 slave.cpp:322] Slave checkpoint: false
W1119 20:55:49.092299 25145 slave.cpp:324] Disabling checkpointing is deprecated and the --checkpoint flag will be removed in a future release. Please avoid using this flag
I1119 20:55:49.092885 25134 state.cpp:33] Recovering state from '/tmp/GarbageCollectorIntegrationTest_DiskUsage_4kBMA9/meta'
I1119 20:55:49.093101 25145 status_update_manager.cpp:197] Recovering status update manager
I1119 20:55:49.093340 25141 slave.cpp:3481] Finished recovery
I1119 20:55:49.093741 25147 status_update_manager.cpp:171] Pausing sending status updates
I1119 20:55:49.093757 25148 slave.cpp:605] New master detected at master@67.195.81.186:57639
I1119 20:55:49.093794 25148 slave.cpp:668] Authenticating with master master@67.195.81.186:57639
I1119 20:55:49.093806 25148 slave.cpp:673] Using default CRAM-MD5 authenticatee
I1119 20:55:49.093911 25148 slave.cpp:641] Detecting new master
I1119 20:55:49.094045 25134 authenticatee.hpp:138] Creating new client SASL connection
I1119 20:55:49.094220 25136 master.cpp:3902] Authenticating slave(169)@67.195.81.186:57639
I1119 20:55:49.094251 25136 master.cpp:3913] Using default CRAM-MD5 authenticator
I1119 20:55:49.094429 25148 authenticator.hpp:170] Creating new server SASL connection
I1119 20:55:49.094601 25138 authenticatee.hpp:229] Received SASL authentication mechanisms: CRAM-MD5
I1119 20:55:49.094624 25138 authenticatee.hpp:255] Attempting to authenticate with mechanism 'CRAM-MD5'
I1119 20:55:49.094698 25147 authenticator.hpp:276] Received SASL authentication start
I1119 20:55:49.094741 25147 authenticator.hpp:398] Authentication requires more steps
I1119 20:55:49.094805 25147 authenticatee.hpp:275] Received SASL authentication step
I1119 20:55:49.094903 25135 authenticator.hpp:304] Received SASL authentication step
I1119 20:55:49.094933 25135 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'penates.apache.org' server FQDN: 'penates.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1119 20:55:49.094944 25135 auxprop.cpp:171] Looking up auxiliary property '*userPassword'
I1119 20:55:49.094976 25135 auxprop.cpp:171] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1119 20:55:49.094993 25135 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'penates.apache.org' server FQDN: 'penates.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1119 20:55:49.095002 25135 auxprop.cpp:121] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1119 20:55:49.095007 25135 auxprop.cpp:121] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1119 20:55:49.095021 25135 authenticator.hpp:390] Authentication success
I1119 20:55:49.095093 25142 authenticatee.hpp:315] Authentication success
I1119 20:55:49.095103 25148 master.cpp:3960] Successfully authenticated principal 'test-principal' at slave(169)@67.195.81.186:57639
I1119 20:55:49.095281 25134 slave.cpp:739] Successfully authenticated with master master@67.195.81.186:57639
I1119 20:55:49.095383 25134 slave.cpp:1067] Will retry registration in 13.24833ms if necessary
I1119 20:55:49.095536 25141 master.cpp:3069] Registering slave at slave(169)@67.195.81.186:57639 (penates.apache.org) with id 20141119-205549-3125920579-57639-25120-S0
I1119 20:55:49.095870 25135 registrar.cpp:445] Applied 1 operations in 43881ns; attempting to update the 'registry'
I1119 20:55:49.097861 25137 log.cpp:680] Attempting to append 318 bytes to the log
I1119 20:55:49.108901 25144 slave.cpp:1067] Will retry registration in 30.742385ms if necessary
I1119 20:55:49.108978 25136 master.cpp:3057] Ignoring register slave message from slave(169)@67.195.81.186:57639 (penates.apache.org) as admission is already in progress
I1119 20:55:49.152987 25136 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
I1119 20:55:49.154022 25142 replica.cpp:508] Replica received write request for position 3
I1119 20:55:49.154422 25142 leveldb.cpp:343] Persisting action (337 bytes) to leveldb took 349495ns
I1119 20:55:49.154446 25142 replica.cpp:676] Persisted action at 3
I1119 20:55:49.155174 25141 replica.cpp:655] Replica received learned notice for position 3
I1119 20:55:49.156018 25141 leveldb.cpp:343] Persisting action (339 bytes) to leveldb took 821758ns
I1119 20:55:49.156040 25141 replica.cpp:676] Persisted action at 3
I1119 20:55:49.156061 25141 replica.cpp:661] Replica learned APPEND action at position 3
I1119 20:55:49.157196 25145 registrar.cpp:490] Successfully updated the 'registry' in 61.261824ms
I1119 20:55:49.157443 25145 log.cpp:699] Attempting to truncate the log to 3
I1119 20:55:49.157655 25135 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
I1119 20:55:49.157799 25148 slave.cpp:2553] Received ping from slave-observer(151)@67.195.81.186:57639
I1119 20:55:49.157845 25139 master.cpp:3123] Registered slave 20141119-205549-3125920579-57639-25120-S0 at slave(169)@67.195.81.186:57639 (penates.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I1119 20:55:49.158033 25148 slave.cpp:773] Registered with master master@67.195.81.186:57639; given slave ID 20141119-205549-3125920579-57639-25120-S0
I1119 20:55:49.158133 25148 status_update_manager.cpp:178] Resuming sending status updates
I1119 20:55:49.158140 25135 hierarchical_allocator_process.hpp:442] Added slave 20141119-205549-3125920579-57639-25120-S0 (penates.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
I1119 20:55:49.158278 25135 hierarchical_allocator_process.hpp:679] Performed allocation for slave 20141119-205549-3125920579-57639-25120-S0 in 67181ns
I1119 20:55:49.158942 25136 replica.cpp:508] Replica received write request for position 4
I1119 20:55:49.159543 25136 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 576036ns
I1119 20:55:49.159561 25136 replica.cpp:676] Persisted action at 4
I1119 20:55:49.160084 25138 replica.cpp:655] Replica received learned notice for position 4
I1119 20:55:49.160580 25138 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 477822ns
I1119 20:55:49.160632 25138 leveldb.cpp:401] Deleting ~2 keys from leveldb took 32974ns
I1119 20:55:49.160648 25138 replica.cpp:676] Persisted action at 4
I1119 20:55:49.160665 25138 replica.cpp:661] Replica learned TRUNCATE action at position 4
I1119 20:55:49.165117 25120 sched.cpp:148] Version: 0.22.0
I1119 20:55:49.165639 25145 sched.cpp:245] New master detected at master@67.195.81.186:57639
I1119 20:55:49.165673 25145 sched.cpp:301] Authenticating with master master@67.195.81.186:57639
I1119 20:55:49.165684 25145 sched.cpp:308] Using default CRAM-MD5 authenticatee
I1119 20:55:49.165923 25144 authenticatee.hpp:138] Creating new client SASL connection
I1119 20:55:49.166106 25147 master.cpp:3902] Authenticating scheduler-fb71f060-bf75-47b8-8c3a-f22138e23e88@67.195.81.186:57639
I1119 20:55:49.166136 25147 master.cpp:3913] Using default CRAM-MD5 authenticator
I1119 20:55:49.166327 25141 authenticator.hpp:170] Creating new server SASL connection
I1119 20:55:49.166455 25139 authenticatee.hpp:229] Received SASL authentication mechanisms: CRAM-MD5
I1119 20:55:49.166474 25139 authenticatee.hpp:255] Attempting to authenticate with mechanism 'CRAM-MD5'
I1119 20:55:49.166558 25134 authenticator.hpp:276] Received SASL authentication start
I1119 20:55:49.166600 25134 authenticator.hpp:398] Authentication requires more steps
I1119 20:55:49.166672 25138 authenticatee.hpp:275] Received SASL authentication step
I1119 20:55:49.166764 25134 authenticator.hpp:304] Received SASL authentication step
I1119 20:55:49.166785 25134 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'penates.apache.org' server FQDN: 'penates.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1119 20:55:49.166795 25134 auxprop.cpp:171] Looking up auxiliary property '*userPassword'
I1119 20:55:49.166829 25134 auxprop.cpp:171] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1119 20:55:49.166846 25134 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'penates.apache.org' server FQDN: 'penates.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1119 20:55:49.166853 25134 auxprop.cpp:121] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1119 20:55:49.166859 25134 auxprop.cpp:121] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1119 20:55:49.166872 25134 authenticator.hpp:390] Authentication success
I1119 20:55:49.166929 25138 authenticatee.hpp:315] Authentication success
I1119 20:55:49.166960 25141 master.cpp:3960] Successfully authenticated principal 'test-principal' at scheduler-fb71f060-bf75-47b8-8c3a-f22138e23e88@67.195.81.186:57639
I1119 20:55:49.167121 25142 sched.cpp:389] Successfully authenticated with master master@67.195.81.186:57639
I1119 20:55:49.167145 25142 sched.cpp:512] Sending registration request to master@67.195.81.186:57639
I1119 20:55:49.167202 25142 sched.cpp:545] Will retry registration in 1.96517529secs if necessary
I1119 20:55:49.167269 25147 master.cpp:1383] Received registration request for framework 'default' at scheduler-fb71f060-bf75-47b8-8c3a-f22138e23e88@67.195.81.186:57639
I1119 20:55:49.167330 25147 master.cpp:1342] Authorizing framework principal 'test-principal' to receive offers for role '*'
I1119 20:55:49.167688 25147 master.cpp:1447] Registering framework 20141119-205549-3125920579-57639-25120-0000 (default) at scheduler-fb71f060-bf75-47b8-8c3a-f22138e23e88@67.195.81.186:57639
I1119 20:55:49.167909 25138 hierarchical_allocator_process.hpp:329] Added framework 20141119-205549-3125920579-57639-25120-0000
I1119 20:55:49.168056 25138 hierarchical_allocator_process.hpp:734] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20141119-205549-3125920579-57639-25120-S0 to framework 20141119-205549-3125920579-57639-25120-0000
I1119 20:55:49.168164 25134 sched.cpp:439] Framework registered with 20141119-205549-3125920579-57639-25120-0000
I1119 20:55:49.168226 25134 sched.cpp:453] Scheduler::registered took 40742ns
I1119 20:55:49.168339 25138 hierarchical_allocator_process.hpp:659] Performed allocation for 1 slaves in 408585ns
I1119 20:55:49.168596 25145 master.cpp:3844] Sending 1 offers to framework 20141119-205549-3125920579-57639-25120-0000 (default) at scheduler-fb71f060-bf75-47b8-8c3a-f22138e23e88@67.195.81.186:57639
I1119 20:55:49.169258 25135 sched.cpp:602] Scheduler::resourceOffers took 418669ns
I1119 20:55:49.169837 25144 master.cpp:2363] Processing reply for offers: [ 20141119-205549-3125920579-57639-25120-O0 ] on slave 20141119-205549-3125920579-57639-25120-S0 at slave(169)@67.195.81.186:57639 (penates.apache.org) for framework 20141119-205549-3125920579-57639-25120-0000 (default) at scheduler-fb71f060-bf75-47b8-8c3a-f22138e23e88@67.195.81.186:57639
I1119 20:55:49.169862 25144 master.cpp:2461] Authorizing framework principal 'test-principal' to launch task 0 as user 'jenkins'
W1119 20:55:49.170433 25135 master.cpp:1998] 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.
W1119 20:55:49.170461 25135 master.cpp:2010] 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.
I1119 20:55:49.329773 25135 master.hpp:753] Adding task 0 with resources cpus(*):2; mem(*):1024 on slave 20141119-205549-3125920579-57639-25120-S0 (penates.apache.org)
I1119 20:55:49.329857 25135 master.cpp:2531] Launching task 0 of framework 20141119-205549-3125920579-57639-25120-0000 (default) at scheduler-fb71f060-bf75-47b8-8c3a-f22138e23e88@67.195.81.186:57639 with resources cpus(*):2; mem(*):1024 on slave 20141119-205549-3125920579-57639-25120-S0 at slave(169)@67.195.81.186:57639 (penates.apache.org)
I1119 20:55:49.330288 25134 slave.cpp:1098] Got assigned task 0 for framework 20141119-205549-3125920579-57639-25120-0000
I1119 20:55:49.330353 25149 hierarchical_allocator_process.hpp:563] Recovered disk(*):1024; ports(*):[31000-32000] (total allocatable: disk(*):1024; ports(*):[31000-32000]) on slave 20141119-205549-3125920579-57639-25120-S0 from framework 20141119-205549-3125920579-57639-25120-0000
I1119 20:55:49.330399 25149 hierarchical_allocator_process.hpp:599] Framework 20141119-205549-3125920579-57639-25120-0000 filtered slave 20141119-205549-3125920579-57639-25120-S0 for 5secs
I1119 20:55:49.330909 25134 slave.cpp:1208] Launching task 0 for framework 20141119-205549-3125920579-57639-25120-0000
I1119 20:55:49.332845 25134 slave.cpp:3863] Launching executor default of framework 20141119-205549-3125920579-57639-25120-0000 in work directory '/tmp/GarbageCollectorIntegrationTest_DiskUsage_4kBMA9/slaves/20141119-205549-3125920579-57639-25120-S0/frameworks/20141119-205549-3125920579-57639-25120-0000/executors/default/runs/938f4723-ba7b-4738-89db-ac755f638e08'
I1119 20:55:49.335047 25134 exec.cpp:132] Version: 0.22.0
I1119 20:55:49.335381 25140 exec.cpp:182] Executor started at: executor(53)@67.195.81.186:57639 with pid 25120
I1119 20:55:49.335450 25134 slave.cpp:1331] Queuing task '0' for executor default of framework '20141119-205549-3125920579-57639-25120-0000
I1119 20:55:49.335566 25134 slave.cpp:558] Successfully attached file '/tmp/GarbageCollectorIntegrationTest_DiskUsage_4kBMA9/slaves/20141119-205549-3125920579-57639-25120-S0/frameworks/20141119-205549-3125920579-57639-25120-0000/executors/default/runs/938f4723-ba7b-4738-89db-ac755f638e08'
I1119 20:55:49.335675 25134 slave.cpp:2855] Monitoring executor 'default' of framework '20141119-205549-3125920579-57639-25120-0000' in container '938f4723-ba7b-4738-89db-ac755f638e08'
I1119 20:55:49.335852 25134 slave.cpp:1875] Got registration for executor 'default' of framework 20141119-205549-3125920579-57639-25120-0000 from executor(53)@67.195.81.186:57639
I1119 20:55:49.336175 25134 slave.cpp:1994] Flushing queued task 0 for executor 'default' of framework 20141119-205549-3125920579-57639-25120-0000
I1119 20:55:49.336323 25137 exec.cpp:206] Executor registered on slave 20141119-205549-3125920579-57639-25120-S0
I1119 20:55:49.337741 25137 exec.cpp:218] Executor::registered took 24206ns
I1119 20:55:49.337864 25137 exec.cpp:293] Executor asked to run task '0'
I1119 20:55:49.337927 25137 exec.cpp:302] Executor::launchTask took 47470ns
I1119 20:55:49.339380 25137 exec.cpp:525] Executor sending status update TASK_RUNNING (UUID: 649b71d8-7571-4782-989a-df503a990445) for task 0 of framework 20141119-205549-3125920579-57639-25120-0000
I1119 20:55:49.339615 25141 slave.cpp:2230] Handling status update TASK_RUNNING (UUID: 649b71d8-7571-4782-989a-df503a990445) for task 0 of framework 20141119-205549-3125920579-57639-25120-0000 from executor(53)@67.195.81.186:57639
I1119 20:55:49.339812 25137 status_update_manager.cpp:317] Received status update TASK_RUNNING (UUID: 649b71d8-7571-4782-989a-df503a990445) for task 0 of framework 20141119-205549-3125920579-57639-25120-0000
I1119 20:55:49.339848 25137 status_update_manager.cpp:494] Creating StatusUpdate stream for task 0 of framework 20141119-205549-3125920579-57639-25120-0000
I1119 20:55:49.340045 25137 status_update_manager.cpp:371] Forwarding update TASK_RUNNING (UUID: 649b71d8-7571-4782-989a-df503a990445) for task 0 of framework 20141119-205549-3125920579-57639-25120-0000 to the slave
I1119 20:55:49.340286 25143 slave.cpp:2473] Forwarding the update TASK_RUNNING (UUID: 649b71d8-7571-4782-989a-df503a990445) for task 0 of framework 20141119-205549-3125920579-57639-25120-0000 to master@67.195.81.186:57639
I1119 20:55:49.340430 25143 slave.cpp:2400] Status update manager successfully handled status update TASK_RUNNING (UUID: 649b71d8-7571-4782-989a-df503a990445) for task 0 of framework 20141119-205549-3125920579-57639-25120-0000
I1119 20:55:49.340452 25143 slave.cpp:2406] Sending acknowledgement for status update TASK_RUNNING (UUID: 649b71d8-7571-4782-989a-df503a990445) for task 0 of framework 20141119-205549-3125920579-57639-25120-0000 to executor(53)@67.195.81.186:57639
I1119 20:55:49.340545 25147 master.cpp:3447] Forwarding status update TASK_RUNNING (UUID: 649b71d8-7571-4782-989a-df503a990445) for task 0 of framework 20141119-205549-3125920579-57639-25120-0000
I1119 20:55:49.340601 25145 exec.cpp:339] Executor received status update acknowledgement 649b71d8-7571-4782-989a-df503a990445 for task 0 of framework 20141119-205549-3125920579-57639-25120-0000
I1119 20:55:49.340667 25147 master.cpp:3419] Status update TASK_RUNNING (UUID: 649b71d8-7571-4782-989a-df503a990445) for task 0 of framework 20141119-205549-3125920579-57639-25120-0000 from slave 20141119-205549-3125920579-57639-25120-S0 at slave(169)@67.195.81.186:57639 (penates.apache.org)
I1119 20:55:49.340716 25147 master.cpp:4694] Updating the latest state of task 0 of framework 20141119-205549-3125920579-57639-25120-0000 to TASK_RUNNING
I1119 20:55:49.340798 25145 sched.cpp:693] Scheduler::statusUpdate took 53658ns
I1119 20:55:49.340991 25138 master.cpp:2919] Forwarding status update acknowledgement 649b71d8-7571-4782-989a-df503a990445 for task 0 of framework 20141119-205549-3125920579-57639-25120-0000 (default) at scheduler-fb71f060-bf75-47b8-8c3a-f22138e23e88@67.195.81.186:57639 to slave 20141119-205549-3125920579-57639-25120-S0 at slave(169)@67.195.81.186:57639 (penates.apache.org)
I1119 20:55:49.341287 25138 status_update_manager.cpp:389] Received status update acknowledgement (UUID: 649b71d8-7571-4782-989a-df503a990445) for task 0 of framework 20141119-205549-3125920579-57639-25120-0000
I1119 20:55:49.341460 25142 slave.cpp:2913] Executor 'default' of framework 20141119-205549-3125920579-57639-25120-0000 exited with status 0
I1119 20:55:49.343101 25142 slave.cpp:2230] Handling status update TASK_LOST (UUID: 7801987a-dbe6-49b8-9fb0-7134c2a08749) for task 0 of framework 20141119-205549-3125920579-57639-25120-0000 from @0.0.0.0:0
I1119 20:55:49.343176 25142 slave.cpp:4171] Terminating task 0
I1119 20:55:49.343468 25142 slave.cpp:1815] Status update manager successfully handled status update acknowledgement (UUID: 649b71d8-7571-4782-989a-df503a990445) for task 0 of framework 20141119-205549-3125920579-57639-25120-0000
I1119 20:55:49.343667 25147 master.cpp:3499] Executor default of framework 20141119-205549-3125920579-57639-25120-0000 on slave 20141119-205549-3125920579-57639-25120-S0 at slave(169)@67.195.81.186:57639 (penates.apache.org) exited with status 0
I1119 20:55:49.343745 25147 master.cpp:4782] Removing executor 'default' with resources of framework 20141119-205549-3125920579-57639-25120-0000 on slave 20141119-205549-3125920579-57639-25120-S0 at slave(169)@67.195.81.186:57639 (penates.apache.org)
I1119 20:55:49.343765 25134 status_update_manager.cpp:317] Received status update TASK_LOST (UUID: 7801987a-dbe6-49b8-9fb0-7134c2a08749) for task 0 of framework 20141119-205549-3125920579-57639-25120-0000
I1119 20:55:49.343832 25134 status_update_manager.cpp:371] Forwarding update TASK_LOST (UUID: 7801987a-dbe6-49b8-9fb0-7134c2a08749) for task 0 of framework 20141119-205549-3125920579-57639-25120-0000 to the slave
I1119 20:55:49.344089 25141 slave.cpp:2473] Forwarding the update TASK_LOST (UUID: 7801987a-dbe6-49b8-9fb0-7134c2a08749) for task 0 of framework 20141119-205549-3125920579-57639-25120-0000 to master@67.195.81.186:57639
I1119 20:55:51.425735 25141 slave.cpp:2400] Status update manager successfully handled status update TASK_LOST (UUID: 7801987a-dbe6-49b8-9fb0-7134c2a08749) for task 0 of framework 20141119-205549-3125920579-57639-25120-0000
I1119 20:55:51.425897 25147 master.cpp:3447] Forwarding status update TASK_LOST (UUID: 7801987a-dbe6-49b8-9fb0-7134c2a08749) for task 0 of framework 20141119-205549-3125920579-57639-25120-0000
I1119 20:55:51.426041 25147 master.cpp:3419] Status update TASK_LOST (UUID: 7801987a-dbe6-49b8-9fb0-7134c2a08749) for task 0 of framework 20141119-205549-3125920579-57639-25120-0000 from slave 20141119-205549-3125920579-57639-25120-S0 at slave(169)@67.195.81.186:57639 (penates.apache.org)
I1119 20:55:51.426093 25147 master.cpp:4694] Updating the latest state of task 0 of framework 20141119-205549-3125920579-57639-25120-0000 to TASK_LOST
I1119 20:55:51.426151 25140 sched.cpp:693] Scheduler::statusUpdate took 18305ns
I1119 20:55:51.426308 25141 hierarchical_allocator_process.hpp:563] Recovered cpus(*):2; mem(*):1024 (total allocatable: disk(*):1024; ports(*):[31000-32000]; cpus(*):2; mem(*):1024) on slave 20141119-205549-3125920579-57639-25120-S0 from framework 20141119-205549-3125920579-57639-25120-0000
I1119 20:55:51.426398 25147 master.cpp:4753] Removing task 0 with resources cpus(*):2; mem(*):1024 of framework 20141119-205549-3125920579-57639-25120-0000 on slave 20141119-205549-3125920579-57639-25120-S0 at slave(169)@67.195.81.186:57639 (penates.apache.org)
I1119 20:55:51.426585 25147 master.cpp:2919] Forwarding status update acknowledgement 7801987a-dbe6-49b8-9fb0-7134c2a08749 for task 0 of framework 20141119-205549-3125920579-57639-25120-0000 (default) at scheduler-fb71f060-bf75-47b8-8c3a-f22138e23e88@67.195.81.186:57639 to slave 20141119-205549-3125920579-57639-25120-S0 at slave(169)@67.195.81.186:57639 (penates.apache.org)
I1119 20:55:51.426861 25146 status_update_manager.cpp:389] Received status update acknowledgement (UUID: 7801987a-dbe6-49b8-9fb0-7134c2a08749) for task 0 of framework 20141119-205549-3125920579-57639-25120-0000
I1119 20:55:51.426949 25146 status_update_manager.cpp:525] Cleaning up status update stream for task 0 of framework 20141119-205549-3125920579-57639-25120-0000
I1119 20:55:51.427199 25137 slave.cpp:1815] Status update manager successfully handled status update acknowledgement (UUID: 7801987a-dbe6-49b8-9fb0-7134c2a08749) for task 0 of framework 20141119-205549-3125920579-57639-25120-0000
I1119 20:55:51.427253 25137 slave.cpp:4210] Completing task 0
I1119 20:55:51.427296 25137 slave.cpp:3022] Cleaning up executor 'default' of framework 20141119-205549-3125920579-57639-25120-0000
I1119 20:55:51.427497 25135 gc.cpp:56] Scheduling '/tmp/GarbageCollectorIntegrationTest_DiskUsage_4kBMA9/slaves/20141119-205549-3125920579-57639-25120-S0/frameworks/20141119-205549-3125920579-57639-25120-0000/executors/default/runs/938f4723-ba7b-4738-89db-ac755f638e08' for gc 1.00000274279746weeks in the future
I1119 20:55:51.427686 25137 slave.cpp:3099] Cleaning up framework 20141119-205549-3125920579-57639-25120-0000
I1119 20:55:51.427769 25135 gc.cpp:56] Scheduling '/tmp/GarbageCollectorIntegrationTest_DiskUsage_4kBMA9/slaves/20141119-205549-3125920579-57639-25120-S0/frameworks/20141119-205549-3125920579-57639-25120-0000/executors/default' for gc 1.00000274279746weeks in the future
I1119 20:55:51.427855 25141 status_update_manager.cpp:279] Closing status update streams for framework 20141119-205549-3125920579-57639-25120-0000
I1119 20:55:51.427916 25135 gc.cpp:56] Scheduling '/tmp/GarbageCollectorIntegrationTest_DiskUsage_4kBMA9/slaves/20141119-205549-3125920579-57639-25120-S0/frameworks/20141119-205549-3125920579-57639-25120-0000' for gc 1.00000274279746weeks in the future
I1119 20:55:51.448726 25135 slave.cpp:3336] Current usage 90.00%. Max allowed age: 0ns
I1119 20:55:51.448741 25149 hierarchical_allocator_process.hpp:734] Offering disk(*):1024; ports(*):[31000-32000]; cpus(*):2; mem(*):1024 on slave 20141119-205549-3125920579-57639-25120-S0 to framework 20141119-205549-3125920579-57639-25120-0000
I1119 20:55:51.449023 25149 hierarchical_allocator_process.hpp:659] Performed allocation for 1 slaves in 571425ns
I1119 20:55:51.449374 25142 master.cpp:3844] Sending 1 offers to framework 20141119-205549-3125920579-57639-25120-0000 (default) at scheduler-fb71f060-bf75-47b8-8c3a-f22138e23e88@67.195.81.186:57639
I1119 20:55:51.449745 25142 sched.cpp:602] Scheduler::resourceOffers took 21934ns
../../src/tests/gc_tests.cpp:675: Failure
Value of: os::exists(executorDir)
Actual: true
Expected: false
I1119 20:55:51.468889 25141 master.cpp:789] Framework 20141119-205549-3125920579-57639-25120-0000 (default) at scheduler-fb71f060-bf75-47b8-8c3a-f22138e23e88@67.195.81.186:57639 disconnected
I1119 20:55:51.468924 25141 master.cpp:1752] Disconnecting framework 20141119-205549-3125920579-57639-25120-0000 (default) at scheduler-fb71f060-bf75-47b8-8c3a-f22138e23e88@67.195.81.186:57639
I1119 20:55:51.468962 25141 master.cpp:1768] Deactivating framework 20141119-205549-3125920579-57639-25120-0000 (default) at scheduler-fb71f060-bf75-47b8-8c3a-f22138e23e88@67.195.81.186:57639
I1119 20:55:51.469161 25147 hierarchical_allocator_process.hpp:405] Deactivated framework 20141119-205549-3125920579-57639-25120-0000
I1119 20:55:51.469455 25147 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 20141119-205549-3125920579-57639-25120-S0 from framework 20141119-205549-3125920579-57639-25120-0000
I1119 20:55:51.469553 25141 master.cpp:811] Giving framework 20141119-205549-3125920579-57639-25120-0000 (default) at scheduler-fb71f060-bf75-47b8-8c3a-f22138e23e88@67.195.81.186:57639 0ns to failover
I1119 20:55:51.469797 25139 master.cpp:3714] Framework failover timeout, removing framework 20141119-205549-3125920579-57639-25120-0000 (default) at scheduler-fb71f060-bf75-47b8-8c3a-f22138e23e88@67.195.81.186:57639
I1119 20:55:51.469832 25139 master.cpp:4272] Removing framework 20141119-205549-3125920579-57639-25120-0000 (default) at scheduler-fb71f060-bf75-47b8-8c3a-f22138e23e88@67.195.81.186:57639
I1119 20:55:51.470029 25146 slave.cpp:1548] Asked to shut down framework 20141119-205549-3125920579-57639-25120-0000 by master@67.195.81.186:57639
W1119 20:55:51.470060 25146 slave.cpp:1563] Cannot shut down unknown framework 20141119-205549-3125920579-57639-25120-0000
I1119 20:55:51.470623 25139 master.cpp:698] Master terminating
I1119 20:55:51.470702 25135 hierarchical_allocator_process.hpp:360] Removed framework 20141119-205549-3125920579-57639-25120-0000
I1119 20:55:51.471101 25135 slave.cpp:2638] master@67.195.81.186:57639 exited
W1119 20:55:51.471127 25135 slave.cpp:2641] Master disconnected! Waiting for a new master to be elected
[ FAILED ] GarbageCollectorIntegrationTest.DiskUsage (2451 ms)
[ RUN ] GarbageCollectorIntegrationTest.Restart
Using temporary directory '/tmp/GarbageCollectorIntegrationTest_Restart_UKwPQP'
I1119 20:55:51.492524 25120 leveldb.cpp:176] Opened db in 3.210523ms
I1119 20:55:51.493749 25120 leveldb.cpp:183] Compacted db in 1.191343ms
I1119 20:55:51.493800 25120 leveldb.cpp:198] Created db iterator in 15941ns
I1119 20:55:51.493820 25120 leveldb.cpp:204] Seeked to beginning of db in 1870ns
I1119 20:55:51.493831 25120 leveldb.cpp:273] Iterated through 0 keys in the db in 280ns
I1119 20:55:51.493865 25120 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I1119 20:55:51.494324 25136 recover.cpp:437] Starting replica recovery
I1119 20:55:51.494657 25136 recover.cpp:463] Replica is in EMPTY status
I1119 20:55:51.495916 25149 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request
I1119 20:55:51.496414 25137 recover.cpp:188] Received a recover response from a replica in EMPTY status
I1119 20:55:51.496856 25143 recover.cpp:554] Updating replica status to STARTING
I1119 20:55:51.497649 25140 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 609652ns
I1119 20:55:51.497681 25140 replica.cpp:320] Persisted replica status to STARTING
I1119 20:55:51.497987 25137 recover.cpp:463] Replica is in STARTING status
I1119 20:55:51.499169 25143 replica.cpp:638] Replica in STARTING status received a broadcasted recover request
I1119 20:55:51.499657 25137 recover.cpp:188] Received a recover response from a replica in STARTING status
I1119 20:55:51.500144 25145 recover.cpp:554] Updating replica status to VOTING
I1119 20:55:51.500725 25138 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 445751ns
I1119 20:55:51.500759 25138 replica.cpp:320] Persisted replica status to VOTING
I1119 20:55:51.500888 25142 recover.cpp:568] Successfully joined the Paxos group
I1119 20:55:51.501169 25142 recover.cpp:452] Recover process terminated
I1119 20:55:51.509845 25139 master.cpp:318] Master 20141119-205551-3125920579-57639-25120 (penates.apache.org) started on 67.195.81.186:57639
I1119 20:55:51.509887 25139 master.cpp:364] Master only allowing authenticated frameworks to register
I1119 20:55:51.509906 25139 master.cpp:369] Master only allowing authenticated slaves to register
I1119 20:55:51.509933 25139 credentials.hpp:36] Loading credentials for authentication from '/tmp/GarbageCollectorIntegrationTest_Restart_UKwPQP/credentials'
I1119 20:55:51.510176 25139 master.cpp:413] Authorization enabled
I1119 20:55:51.510640 25148 master.cpp:126] No whitelist given. Advertising offers for all slaves
I1119 20:55:51.510710 25135 hierarchical_allocator_process.hpp:299] Initializing hierarchical allocator process with master : master@67.195.81.186:57639
I1119 20:55:51.511772 25141 master.cpp:1263] The newly elected leader is master@67.195.81.186:57639 with id 20141119-205551-3125920579-57639-25120
I1119 20:55:51.511803 25141 master.cpp:1276] Elected as the leading master!
I1119 20:55:51.511819 25141 master.cpp:1094] Recovering from registrar
I1119 20:55:51.511951 25136 registrar.cpp:313] Recovering registrar
I1119 20:55:51.512557 25145 log.cpp:656] Attempting to start the writer
I1119 20:55:51.513921 25146 replica.cpp:474] Replica received implicit promise request with proposal 1
I1119 20:55:51.514410 25146 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 460395ns
I1119 20:55:51.514436 25146 replica.cpp:342] Persisted promised to 1
I1119 20:55:51.515111 25134 coordinator.cpp:230] Coordinator attemping to fill missing position
I1119 20:55:51.516425 25145 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
I1119 20:55:51.517081 25145 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 623344ns
I1119 20:55:51.517107 25145 replica.cpp:676] Persisted action at 0
I1119 20:55:51.518228 25139 replica.cpp:508] Replica received write request for position 0
I1119 20:55:51.518280 25139 leveldb.cpp:438] Reading position from leveldb took 26865ns
I1119 20:55:51.518745 25139 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 432980ns
I1119 20:55:51.518769 25139 replica.cpp:676] Persisted action at 0
I1119 20:55:51.519376 25136 replica.cpp:655] Replica received learned notice for position 0
I1119 20:55:51.519873 25136 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 468114ns
I1119 20:55:51.519898 25136 replica.cpp:676] Persisted action at 0
I1119 20:55:51.519917 25136 replica.cpp:661] Replica learned NOP action at position 0
I1119 20:55:51.520426 25145 log.cpp:672] Writer started with ending position 0
I1119 20:55:51.521723 25148 leveldb.cpp:438] Reading position from leveldb took 35783ns
I1119 20:55:51.524723 25147 registrar.cpp:346] Successfully fetched the registry (0B) in 12.72704ms
I1119 20:55:51.524830 25147 registrar.cpp:445] Applied 1 operations in 21127ns; attempting to update the 'registry'
I1119 20:55:51.527822 25136 log.cpp:680] Attempting to append 140 bytes to the log
I1119 20:55:51.527954 25139 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
I1119 20:55:51.529208 25145 replica.cpp:508] Replica received write request for position 1
I1119 20:55:51.530031 25145 leveldb.cpp:343] Persisting action (159 bytes) to leveldb took 790822ns
I1119 20:55:51.530061 25145 replica.cpp:676] Persisted action at 1
I1119 20:55:51.530709 25143 replica.cpp:655] Replica received learned notice for position 1
I1119 20:55:51.531402 25143 leveldb.cpp:343] Persisting action (161 bytes) to leveldb took 665029ns
I1119 20:55:51.531430 25143 replica.cpp:676] Persisted action at 1
I1119 20:55:51.531450 25143 replica.cpp:661] Replica learned APPEND action at position 1
I1119 20:55:51.532356 25134 registrar.cpp:490] Successfully updated the 'registry' in 7.467008ms
I1119 20:55:51.532544 25134 registrar.cpp:376] Successfully recovered registrar
I1119 20:55:51.532752 25146 log.cpp:699] Attempting to truncate the log to 1
I1119 20:55:51.532882 25145 master.cpp:1121] Recovered 0 slaves from the Registry (102B) ; allowing 10mins for slaves to re-register
I1119 20:55:51.532927 25138 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
I1119 20:55:51.533808 25134 replica.cpp:508] Replica received write request for position 2
I1119 20:55:51.534651 25134 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 813141ns
I1119 20:55:51.534680 25134 replica.cpp:676] Persisted action at 2
I1119 20:55:51.535320 25135 replica.cpp:655] Replica received learned notice for position 2
I1119 20:55:51.535979 25135 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 632705ns
I1119 20:55:51.536041 25135 leveldb.cpp:401] Deleting ~1 keys from leveldb took 37083ns
I1119 20:55:51.536059 25135 replica.cpp:676] Persisted action at 2
I1119 20:55:51.536078 25135 replica.cpp:661] Replica learned TRUNCATE action at position 2
I1119 20:55:51.551708 25142 slave.cpp:170] Slave started on 170)@67.195.81.186:57639
I1119 20:55:51.551770 25142 credentials.hpp:84] Loading credential for authentication from '/tmp/GarbageCollectorIntegrationTest_Restart_NfqYfw/credential'
I1119 20:55:51.551950 25142 slave.cpp:279] Slave using credential for: test-principal
I1119 20:55:51.552150 25142 slave.cpp:292] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I1119 20:55:51.552229 25142 slave.cpp:321] Slave hostname: penates.apache.org
I1119 20:55:51.552242 25142 slave.cpp:322] Slave checkpoint: false
W1119 20:55:51.552248 25142 slave.cpp:324] Disabling checkpointing is deprecated and the --checkpoint flag will be removed in a future release. Please avoid using this flag
I1119 20:55:51.553061 25146 state.cpp:33] Recovering state from '/tmp/GarbageCollectorIntegrationTest_Restart_NfqYfw/meta'
I1119 20:55:51.553270 25149 status_update_manager.cpp:197] Recovering status update manager
I1119 20:55:51.553563 25141 slave.cpp:3481] Finished recovery
I1119 20:55:51.554040 25147 status_update_manager.cpp:171] Pausing sending status updates
I1119 20:55:51.554039 25146 slave.cpp:605] New master detected at master@67.195.81.186:57639
I1119 20:55:51.554090 25146 slave.cpp:668] Authenticating with master master@67.195.81.186:57639
I1119 20:55:51.554102 25146 slave.cpp:673] Using default CRAM-MD5 authenticatee
I1119 20:55:51.554234 25146 slave.cpp:641] Detecting new master
I1119 20:55:51.554461 25143 authenticatee.hpp:138] Creating new client SASL connection
I1119 20:55:51.554694 25135 master.cpp:3902] Authenticating slave(170)@67.195.81.186:57639
I1119 20:55:51.554738 25135 master.cpp:3913] Using default CRAM-MD5 authenticator
I1119 20:55:51.554975 25141 authenticator.hpp:170] Creating new server SASL connection
I1119 20:55:51.555167 25144 authenticatee.hpp:229] Received SASL authentication mechanisms: CRAM-MD5
I1119 20:55:51.555191 25144 authenticatee.hpp:255] Attempting to authenticate with mechanism 'CRAM-MD5'
I1119 20:55:51.555276 25148 authenticator.hpp:276] Received SASL authentication start
I1119 20:55:51.555325 25148 authenticator.hpp:398] Authentication requires more steps
I1119 20:55:51.641027 25148 authenticatee.hpp:275] Received SASL authentication step
I1119 20:55:51.641137 25148 authenticator.hpp:304] Received SASL authentication step
I1119 20:55:51.641167 25148 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'penates.apache.org' server FQDN: 'penates.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1119 20:55:51.641180 25148 auxprop.cpp:171] Looking up auxiliary property '*userPassword'
I1119 20:55:51.641217 25148 auxprop.cpp:171] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1119 20:55:51.641245 25148 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'penates.apache.org' server FQDN: 'penates.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1119 20:55:51.641258 25148 auxprop.cpp:121] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1119 20:55:51.641266 25148 auxprop.cpp:121] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1119 20:55:51.641283 25148 authenticator.hpp:390] Authentication success
I1119 20:55:51.641396 25135 authenticatee.hpp:315] Authentication success
I1119 20:55:51.641440 25144 master.cpp:3960] Successfully authenticated principal 'test-principal' at slave(170)@67.195.81.186:57639
I1119 20:55:51.641772 25138 slave.cpp:739] Successfully authenticated with master master@67.195.81.186:57639
I1119 20:55:51.641894 25138 slave.cpp:1067] Will retry registration in 2.979033ms if necessary
I1119 20:55:51.642122 25146 master.cpp:3069] Registering slave at slave(170)@67.195.81.186:57639 (penates.apache.org) with id 20141119-205551-3125920579-57639-25120-S0
I1119 20:55:51.642619 25141 registrar.cpp:445] Applied 1 operations in 55100ns; attempting to update the 'registry'
I1119 20:55:51.645437 25148 slave.cpp:1067] Will retry registration in 17.67503ms if necessary
I1119 20:55:51.645668 25145 master.cpp:3057] Ignoring register slave message from slave(170)@67.195.81.186:57639 (penates.apache.org) as admission is already in progress
I1119 20:55:51.645871 25141 log.cpp:680] Attempting to append 318 bytes to the log
I1119 20:55:51.646059 25137 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
I1119 20:55:51.646967 25148 replica.cpp:508] Replica received write request for position 3
I1119 20:55:51.647927 25148 leveldb.cpp:343] Persisting action (337 bytes) to leveldb took 926863ns
I1119 20:55:51.647958 25148 replica.cpp:676] Persisted action at 3
I1119 20:55:51.648717 25143 replica.cpp:655] Replica received learned notice for position 3
I1119 20:55:51.649287 25143 leveldb.cpp:343] Persisting action (339 bytes) to leveldb took 543567ns
I1119 20:55:51.649318 25143 replica.cpp:676] Persisted action at 3
I1119 20:55:51.649343 25143 replica.cpp:661] Replica learned APPEND action at position 3
I1119 20:55:51.650802 25148 registrar.cpp:490] Successfully updated the 'registry' in 8.130048ms
I1119 20:55:51.651131 25145 log.cpp:699] Attempting to truncate the log to 3
I1119 20:55:51.651309 25136 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
I1119 20:55:51.651494 25146 slave.cpp:2553] Received ping from slave-observer(152)@67.195.81.186:57639
I1119 20:55:51.651527 25142 master.cpp:3123] Registered slave 20141119-205551-3125920579-57639-25120-S0 at slave(170)@67.195.81.186:57639 (penates.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I1119 20:55:51.651711 25149 hierarchical_allocator_process.hpp:442] Added slave 20141119-205551-3125920579-57639-25120-S0 (penates.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
I1119 20:55:51.651835 25149 hierarchical_allocator_process.hpp:679] Performed allocation for slave 20141119-205551-3125920579-57639-25120-S0 in 47598ns
I1119 20:55:51.651877 25146 slave.cpp:773] Registered with master master@67.195.81.186:57639; given slave ID 20141119-205551-3125920579-57639-25120-S0
I1119 20:55:51.651989 25146 status_update_manager.cpp:178] Resuming sending status updates
I1119 20:55:51.652350 25145 replica.cpp:508] Replica received write request for position 4
I1119 20:55:51.652925 25145 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 544604ns
I1119 20:55:51.652951 25145 replica.cpp:676] Persisted action at 4
I1119 20:55:51.653673 25142 replica.cpp:655] Replica received learned notice for position 4
I1119 20:55:51.654456 25142 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 753589ns
I1119 20:55:51.654567 25142 leveldb.cpp:401] Deleting ~2 keys from leveldb took 80063ns
I1119 20:55:51.654654 25142 replica.cpp:676] Persisted action at 4
I1119 20:55:51.654681 25142 replica.cpp:661] Replica learned TRUNCATE action at position 4
I1119 20:55:51.657250 25120 sched.cpp:148] Version: 0.22.0
I1119 20:55:51.658082 25138 sched.cpp:245] New master detected at master@67.195.81.186:57639
I1119 20:55:51.658125 25138 sched.cpp:301] Authenticating with master master@67.195.81.186:57639
I1119 20:55:51.658141 25138 sched.cpp:308] Using default CRAM-MD5 authenticatee
I1119 20:55:51.658354 25142 authenticatee.hpp:138] Creating new client SASL connection
I1119 20:55:51.658622 25142 master.cpp:3902] Authenticating scheduler-71d4de3d-d16a-443e-888c-3ad984c2993e@67.195.81.186:57639
I1119 20:55:51.658658 25142 master.cpp:3913] Using default CRAM-MD5 authenticator
I1119 20:55:51.658959 25149 authenticator.hpp:170] Creating new server SASL connection
I1119 20:55:51.659235 25146 authenticatee.hpp:229] Received SASL authentication mechanisms: CRAM-MD5
I1119 20:55:51.659298 25146 authenticatee.hpp:255] Attempting to authenticate with mechanism 'CRAM-MD5'
I1119 20:55:51.659373 25146 authenticator.hpp:276] Received SASL authentication start
I1119 20:55:51.659409 25146 authenticator.hpp:398] Authentication requires more steps
I1119 20:55:51.659548 25148 authenticatee.hpp:275] Received SASL authentication step
I1119 20:55:51.659634 25148 authenticator.hpp:304] Received SASL authentication step
I1119 20:55:51.659656 25148 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'penates.apache.org' server FQDN: 'penates.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1119 20:55:51.659664 25148 auxprop.cpp:171] Looking up auxiliary property '*userPassword'
I1119 20:55:51.659699 25148 auxprop.cpp:171] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1119 20:55:51.659721 25148 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'penates.apache.org' server FQDN: 'penates.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1119 20:55:51.659736 25148 auxprop.cpp:121] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1119 20:55:51.659742 25148 auxprop.cpp:121] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1119 20:55:51.659754 25148 authenticator.hpp:390] Authentication success
I1119 20:55:51.659847 25148 authenticatee.hpp:315] Authentication success
I1119 20:55:51.659881 25139 master.cpp:3960] Successfully authenticated principal 'test-principal' at scheduler-71d4de3d-d16a-443e-888c-3ad984c2993e@67.195.81.186:57639
I1119 20:55:51.660011 25143 sched.cpp:389] Successfully authenticated with master master@67.195.81.186:57639
I1119 20:55:51.660035 25143 sched.cpp:512] Sending registration request to master@67.195.81.186:57639
I1119 20:55:51.660159 25143 sched.cpp:545] Will retry registration in 944.513209ms if necessary
I1119 20:55:51.660300 25139 master.cpp:1383] Received registration request for framework 'default' at scheduler-71d4de3d-d16a-443e-888c-3ad984c2993e@67.195.81.186:57639
I1119 20:55:51.838100 25139 master.cpp:1342] Authorizing framework principal 'test-principal' to receive offers for role '*'
I1119 20:55:51.838531 25141 master.cpp:1447] Registering framework 20141119-205551-3125920579-57639-25120-0000 (default) at scheduler-71d4de3d-d16a-443e-888c-3ad984c2993e@67.195.81.186:57639
I1119 20:55:51.838961 25138 hierarchical_allocator_process.hpp:329] Added framework 20141119-205551-3125920579-57639-25120-0000
I1119 20:55:51.839155 25138 hierarchical_allocator_process.hpp:734] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20141119-205551-3125920579-57639-25120-S0 to framework 20141119-205551-3125920579-57639-25120-0000
I1119 20:55:51.839249 25149 sched.cpp:439] Framework registered with 20141119-205551-3125920579-57639-25120-0000
I1119 20:55:51.839293 25149 sched.cpp:453] Scheduler::registered took 17715ns
I1119 20:55:51.839381 25138 hierarchical_allocator_process.hpp:659] Performed allocation for 1 slaves in 370594ns
I1119 20:55:51.839718 25142 master.cpp:3844] Sending 1 offers to framework 20141119-205551-3125920579-57639-25120-0000 (default) at scheduler-71d4de3d-d16a-443e-888c-3ad984c2993e@67.195.81.186:57639
I1119 20:55:51.840572 25142 sched.cpp:602] Scheduler::resourceOffers took 575156ns
I1119 20:55:51.841292 25142 master.cpp:2363] Processing reply for offers: [ 20141119-205551-3125920579-57639-25120-O0 ] on slave 20141119-205551-3125920579-57639-25120-S0 at slave(170)@67.195.81.186:57639 (penates.apache.org) for framework 20141119-205551-3125920579-57639-25120-0000 (default) at scheduler-71d4de3d-d16a-443e-888c-3ad984c2993e@67.195.81.186:57639
I1119 20:55:51.841332 25142 master.cpp:2461] Authorizing framework principal 'test-principal' to launch task 0 as user 'jenkins'
W1119 20:55:51.842247 25136 master.cpp:1998] 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.
W1119 20:55:51.842288 25136 master.cpp:2010] 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.
I1119 20:55:51.842574 25136 master.hpp:753] Adding task 0 with resources cpus(*):2; mem(*):1024 on slave 20141119-205551-3125920579-57639-25120-S0 (penates.apache.org)
I1119 20:55:51.842655 25136 master.cpp:2531] Launching task 0 of framework 20141119-205551-3125920579-57639-25120-0000 (default) at scheduler-71d4de3d-d16a-443e-888c-3ad984c2993e@67.195.81.186:57639 with resources cpus(*):2; mem(*):1024 on slave 20141119-205551-3125920579-57639-25120-S0 at slave(170)@67.195.81.186:57639 (penates.apache.org)
I1119 20:55:51.842952 25137 slave.cpp:1098] Got assigned task 0 for framework 20141119-205551-3125920579-57639-25120-0000
I1119 20:55:51.843076 25140 hierarchical_allocator_process.hpp:563] Recovered disk(*):1024; ports(*):[31000-32000] (total allocatable: disk(*):1024; ports(*):[31000-32000]) on slave 20141119-205551-3125920579-57639-25120-S0 from framework 20141119-205551-3125920579-57639-25120-0000
I1119 20:55:51.843169 25140 hierarchical_allocator_process.hpp:599] Framework 20141119-205551-3125920579-57639-25120-0000 filtered slave 20141119-205551-3125920579-57639-25120-S0 for 5secs
I1119 20:55:51.843490 25137 slave.cpp:1208] Launching task 0 for framework 20141119-205551-3125920579-57639-25120-0000
I1119 20:55:51.846076 25137 slave.cpp:3863] Launching executor default of framework 20141119-205551-3125920579-57639-25120-0000 in work directory '/tmp/GarbageCollectorIntegrationTest_Restart_NfqYfw/slaves/20141119-205551-3125920579-57639-25120-S0/frameworks/20141119-205551-3125920579-57639-25120-0000/executors/default/runs/c5990ed1-f83f-4860-87d8-eccb146bc79b'
I1119 20:55:51.848954 25137 exec.cpp:132] Version: 0.22.0
I1119 20:55:51.849208 25145 exec.cpp:182] Executor started at: executor(54)@67.195.81.186:57639 with pid 25120
I1119 20:55:51.849371 25137 slave.cpp:1331] Queuing task '0' for executor default of framework '20141119-205551-3125920579-57639-25120-0000
I1119 20:55:51.849491 25137 slave.cpp:558] Successfully attached file '/tmp/GarbageCollectorIntegrationTest_Restart_NfqYfw/slaves/20141119-205551-3125920579-57639-25120-S0/frameworks/20141119-205551-3125920579-57639-25120-0000/executors/default/runs/c5990ed1-f83f-4860-87d8-eccb146bc79b'
I1119 20:55:51.849593 25137 slave.cpp:1875] Got registration for executor 'default' of framework 20141119-205551-3125920579-57639-25120-0000 from executor(54)@67.195.81.186:57639
I1119 20:55:51.849922 25137 slave.cpp:1994] Flushing queued task 0 for executor 'default' of framework 20141119-205551-3125920579-57639-25120-0000
I1119 20:55:51.849998 25149 exec.cpp:206] Executor registered on slave 20141119-205551-3125920579-57639-25120-S0
I1119 20:55:51.850167 25137 slave.cpp:2855] Monitoring executor 'default' of framework '20141119-205551-3125920579-57639-25120-0000' in container 'c5990ed1-f83f-4860-87d8-eccb146bc79b'
I1119 20:55:51.852202 25149 exec.cpp:218] Executor::registered took 24230ns
I1119 20:55:51.852372 25149 exec.cpp:293] Executor asked to run task '0'
I1119 20:55:51.852447 25149 exec.cpp:302] Executor::launchTask took 51403ns
I1119 20:55:51.854575 25149 exec.cpp:525] Executor sending status update TASK_RUNNING (UUID: 2ca01883-21c2-4dbc-8ac4-d249c616db57) for task 0 of framework 20141119-205551-3125920579-57639-25120-0000
I1119 20:55:51.854799 25149 slave.cpp:2230] Handling status update TASK_RUNNING (UUID: 2ca01883-21c2-4dbc-8ac4-d249c616db57) for task 0 of framework 20141119-205551-3125920579-57639-25120-0000 from executor(54)@67.195.81.186:57639
I1119 20:55:51.855067 25137 status_update_manager.cpp:317] Received status update TASK_RUNNING (UUID: 2ca01883-21c2-4dbc-8ac4-d249c616db57) for task 0 of framework 20141119-205551-3125920579-57639-25120-0000
I1119 20:55:51.855108 25137 status_update_manager.cpp:494] Creating StatusUpdate stream for task 0 of framework 20141119-205551-3125920579-57639-25120-0000
I1119 20:55:51.855295 25137 status_update_manager.cpp:371] Forwarding update TASK_RUNNING (UUID: 2ca01883-21c2-4dbc-8ac4-d249c616db57) for task 0 of framework 20141119-205551-3125920579-57639-25120-0000 to the slave
I1119 20:55:51.855590 25138 slave.cpp:2473] Forwarding the update TASK_RUNNING (UUID: 2ca01883-21c2-4dbc-8ac4-d249c616db57) for task 0 of framework 20141119-205551-3125920579-57639-25120-0000 to master@67.195.81.186:57639
I1119 20:55:51.855765 25138 slave.cpp:2400] Status update manager successfully handled status update TASK_RUNNING (UUID: 2ca01883-21c2-4dbc-8ac4-d249c616db57) for task 0 of framework 20141119-205551-3125920579-57639-25120-0000
I1119 20:55:51.855788 25138 slave.cpp:2406] Sending acknowledgement for status update TASK_RUNNING (UUID: 2ca01883-21c2-4dbc-8ac4-d249c616db57) for task 0 of framework 20141119-205551-3125920579-57639-25120-0000 to executor(54)@67.195.81.186:57639
I1119 20:55:51.855937 25149 master.cpp:3447] Forwarding status update TASK_RUNNING (UUID: 2ca01883-21c2-4dbc-8ac4-d249c616db57) for task 0 of framework 20141119-205551-3125920579-57639-25120-0000
I1119 20:55:51.855962 25144 exec.cpp:339] Executor received status update acknowledgement 2ca01883-21c2-4dbc-8ac4-d249c616db57 for task 0 of framework 20141119-205551-3125920579-57639-25120-0000
I1119 20:55:51.856088 25149 master.cpp:3419] Status update TASK_RUNNING (UUID: 2ca01883-21c2-4dbc-8ac4-d249c616db57) for task 0 of framework 20141119-205551-3125920579-57639-25120-0000 from slave 20141119-205551-3125920579-57639-25120-S0 at slave(170)@67.195.81.186:57639 (penates.apache.org)
I1119 20:55:51.856142 25149 master.cpp:4694] Updating the latest state of task 0 of framework 20141119-205551-3125920579-57639-25120-0000 to TASK_RUNNING
I1119 20:55:51.856267 25134 sched.cpp:693] Scheduler::statusUpdate took 60023ns
I1119 20:55:51.856701 25141 master.cpp:2919] Forwarding status update acknowledgement 2ca01883-21c2-4dbc-8ac4-d249c616db57 for task 0 of framework 20141119-205551-3125920579-57639-25120-0000 (default) at scheduler-71d4de3d-d16a-443e-888c-3ad984c2993e@67.195.81.186:57639 to slave 20141119-205551-3125920579-57639-25120-S0 at slave(170)@67.195.81.186:57639 (penates.apache.org)
I1119 20:55:51.857004 25120 slave.cpp:487] Slave terminating
I1119 20:55:51.988471 25120 slave.cpp:1548] Asked to shut down framework 20141119-205551-3125920579-57639-25120-0000 by @0.0.0.0:0
I1119 20:55:51.988502 25120 slave.cpp:1573] Shutting down framework 20141119-205551-3125920579-57639-25120-0000
I1119 20:55:51.988595 25120 slave.cpp:3161] Shutting down executor 'default' of framework 20141119-205551-3125920579-57639-25120-0000
I1119 20:55:51.988844 25138 exec.cpp:379] Executor asked to shutdown
I1119 20:55:51.988886 25147 master.cpp:839] Slave 20141119-205551-3125920579-57639-25120-S0 at slave(170)@67.195.81.186:57639 (penates.apache.org) disconnected
I1119 20:55:51.988906 25138 exec.cpp:394] Executor::shutdown took 17627ns
I1119 20:55:51.988914 25147 master.cpp:843] Removing disconnected slave 20141119-205551-3125920579-57639-25120-S0 at slave(170)@67.195.81.186:57639 (penates.apache.org) because it is not checkpointing!
I1119 20:55:51.988924 25147 master.cpp:4510] Removing slave 20141119-205551-3125920579-57639-25120-S0 at slave(170)@67.195.81.186:57639 (penates.apache.org)
I1119 20:55:51.989198 25134 hierarchical_allocator_process.hpp:467] Removed slave 20141119-205551-3125920579-57639-25120-S0
I1119 20:55:51.990890 25147 master.cpp:4694] Updating the latest state of task 0 of framework 20141119-205551-3125920579-57639-25120-0000 to TASK_LOST
I1119 20:55:51.991261 25147 master.cpp:4753] Removing task 0 with resources cpus(*):2; mem(*):1024 of framework 20141119-205551-3125920579-57639-25120-0000 on slave 20141119-205551-3125920579-57639-25120-S0 at slave(170)@67.195.81.186:57639 (penates.apache.org)
I1119 20:55:51.991596 25147 master.cpp:4782] Removing executor 'default' with resources of framework 20141119-205551-3125920579-57639-25120-0000 on slave 20141119-205551-3125920579-57639-25120-S0 at slave(170)@67.195.81.186:57639 (penates.apache.org)
I1119 20:55:51.992651 25137 registrar.cpp:445] Applied 1 operations in 79281ns; attempting to update the 'registry'
I1119 20:55:51.994978 25135 log.cpp:680] Attempting to append 142 bytes to the log
I1119 20:55:51.995136 25147 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 5
I1119 20:55:51.995918 25142 replica.cpp:508] Replica received write request for position 5
I1119 20:55:51.996655 25142 leveldb.cpp:343] Persisting action (161 bytes) to leveldb took 710930ns
I1119 20:55:51.996675 25142 replica.cpp:676] Persisted action at 5
I1119 20:55:51.997179 25143 replica.cpp:655] Replica received learned notice for position 5
I1119 20:55:51.997761 25143 leveldb.cpp:343] Persisting action (163 bytes) to leveldb took 561213ns
I1119 20:55:51.997781 25143 replica.cpp:676] Persisted action at 5
I1119 20:55:51.997797 25143 replica.cpp:661] Replica learned APPEND action at position 5
I1119 20:55:51.998579 25140 registrar.cpp:490] Successfully updated the 'registry' in 0ns
I1119 20:55:51.998796 25145 master.cpp:4604] Removed slave 20141119-205551-3125920579-57639-25120-S0 (penates.apache.org)
I1119 20:55:51.998824 25138 log.cpp:699] Attempting to truncate the log to 5
I1119 20:55:51.998834 25145 master.cpp:3442] Sending status update TASK_LOST (UUID: df8816c7-b5f1-4148-8e3f-eb233450e9fd) for task 0 of framework 20141119-205551-3125920579-57639-25120-0000 'Slave penates.apache.org removed'
I1119 20:55:51.998934 25147 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 6
I1119 20:55:51.998945 25145 master.cpp:4622] Notifying framework 20141119-205551-3125920579-57639-25120-0000 (default) at scheduler-71d4de3d-d16a-443e-888c-3ad984c2993e@67.195.81.186:57639 of lost slave 20141119-205551-3125920579-57639-25120-S0 (penates.apache.org) after recovering
I1119 20:55:51.999068 25148 sched.cpp:693] Scheduler::statusUpdate took 16960ns
I1119 20:55:51.999125 25148 sched.cpp:745] Lost slave 20141119-205551-3125920579-57639-25120-S0
I1119 20:55:51.999171 25148 sched.cpp:756] Scheduler::slaveLost took 22586ns
I1119 20:55:51.999542 25145 replica.cpp:508] Replica received write request for position 6
I1119 20:55:51.999994 25145 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 429105ns
I1119 20:55:52.000011 25145 replica.cpp:676] Persisted action at 6
I1119 20:55:52.000478 25145 replica.cpp:655] Replica received learned notice for position 6
I1119 20:55:52.001101 25145 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 603409ns
I1119 20:55:52.001149 25145 leveldb.cpp:401] Deleting ~2 keys from leveldb took 28351ns
I1119 20:55:52.001163 25145 replica.cpp:676] Persisted action at 6
I1119 20:55:52.001178 25145 replica.cpp:661] Replica learned TRUNCATE action at position 6
I1119 20:55:52.004945 25120 containerizer.cpp:101] Using isolation: posix/cpu,posix/mem
I1119 20:55:52.011484 25134 slave.cpp:170] Slave started on 171)@67.195.81.186:57639
I1119 20:55:52.011546 25134 credentials.hpp:84] Loading credential for authentication from '/tmp/GarbageCollectorIntegrationTest_Restart_NfqYfw/credential'
I1119 20:55:52.011695 25134 slave.cpp:279] Slave using credential for: test-principal
I1119 20:55:52.011860 25134 slave.cpp:292] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I1119 20:55:52.011932 25134 slave.cpp:321] Slave hostname: penates.apache.org
I1119 20:55:52.011945 25134 slave.cpp:322] Slave checkpoint: false
W1119 20:55:52.011950 25134 slave.cpp:324] Disabling checkpointing is deprecated and the --checkpoint flag will be removed in a future release. Please avoid using this flag
I1119 20:55:52.012670 25140 state.cpp:33] Recovering state from '/tmp/GarbageCollectorIntegrationTest_Restart_NfqYfw/meta'
I1119 20:55:52.012778 25140 state.cpp:62] Failed to find the latest slave from '/tmp/GarbageCollectorIntegrationTest_Restart_NfqYfw/meta'
I1119 20:55:52.012987 25143 status_update_manager.cpp:197] Recovering status update manager
I1119 20:55:52.013170 25147 containerizer.cpp:282] Recovering containerizer
I1119 20:55:52.013921 25145 slave.cpp:3481] Finished recovery
I1119 20:55:52.014137 25145 slave.cpp:3514] Garbage collecting old slave 20141119-205551-3125920579-57639-25120-S0
I1119 20:55:52.014256 25142 gc.cpp:56] Scheduling '/tmp/GarbageCollectorIntegrationTest_Restart_NfqYfw/slaves/20141119-205551-3125920579-57639-25120-S0' for gc 1.00000023690624weeks in the future
I1119 20:55:52.014497 25145 status_update_manager.cpp:171] Pausing sending status updates
I1119 20:55:52.014499 25134 slave.cpp:605] New master detected at master@67.195.81.186:57639
I1119 20:55:52.014560 25134 slave.cpp:668] Authenticating with master master@67.195.81.186:57639
I1119 20:55:52.014572 25134 slave.cpp:673] Using default CRAM-MD5 authenticatee
I1119 20:55:52.014690 25134 slave.cpp:641] Detecting new master
I1119 20:55:52.014803 25135 authenticatee.hpp:138] Creating new client SASL connection
I1119 20:55:52.014958 25134 master.cpp:3902] Authenticating slave(171)@67.195.81.186:57639
I1119 20:55:52.014986 25134 master.cpp:3913] Using default CRAM-MD5 authenticator
I1119 20:55:52.015208 25146 authenticator.hpp:170] Creating new server SASL connection
I1119 20:55:52.015374 25137 authenticatee.hpp:229] Received SASL authentication mechanisms: CRAM-MD5
I1119 20:55:52.015396 25137 authenticatee.hpp:255] Attempting to authenticate with mechanism 'CRAM-MD5'
I1119 20:55:52.015482 25139 authenticator.hpp:276] Received SASL authentication start
I1119 20:55:52.015537 25139 authenticator.hpp:398] Authentication requires more steps
I1119 20:55:52.015626 25135 authenticatee.hpp:275] Received SASL authentication step
I1119 20:55:52.015718 25139 authenticator.hpp:304] Received SASL authentication step
I1119 20:55:52.015745 25139 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'penates.apache.org' server FQDN: 'penates.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1119 20:55:52.141175 25139 auxprop.cpp:171] Looking up auxiliary property '*userPassword'
I1119 20:55:52.141226 25139 auxprop.cpp:171] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1119 20:55:52.141263 25139 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'penates.apache.org' server FQDN: 'penates.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1119 20:55:52.141276 25139 auxprop.cpp:121] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1119 20:55:52.141284 25139 auxprop.cpp:121] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1119 20:55:52.141304 25139 authenticator.hpp:390] Authentication success
I1119 20:55:52.141443 25135 authenticatee.hpp:315] Authentication success
I1119 20:55:52.141463 25139 master.cpp:3960] Successfully authenticated principal 'test-principal' at slave(171)@67.195.81.186:57639
I1119 20:55:52.141909 25140 slave.cpp:739] Successfully authenticated with master master@67.195.81.186:57639
I1119 20:55:52.142099 25140 slave.cpp:1067] Will retry registration in 17.332436ms if necessary
I1119 20:55:52.142302 25138 master.cpp:3069] Registering slave at slave(171)@67.195.81.186:57639 (penates.apache.org) with id 20141119-205551-3125920579-57639-25120-S1
I1119 20:55:52.142891 25137 registrar.cpp:445] Applied 1 operations in 80189ns; attempting to update the 'registry'
I1119 20:55:52.145234 25140 log.cpp:680] Attempting to append 318 bytes to the log
I1119 20:55:52.145550 25146 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 7
I1119 20:55:52.146803 25147 replica.cpp:508] Replica received write request for position 7
I1119 20:55:52.147094 25147 leveldb.cpp:343] Persisting action (337 bytes) to leveldb took 254443ns
I1119 20:55:52.147125 25147 replica.cpp:676] Persisted action at 7
I1119 20:55:52.148007 25134 replica.cpp:655] Replica received learned notice for position 7
I1119 20:55:52.148839 25134 leveldb.cpp:343] Persisting action (339 bytes) to leveldb took 802036ns
I1119 20:55:52.148866 25134 replica.cpp:676] Persisted action at 7
I1119 20:55:52.148888 25134 replica.cpp:661] Replica learned APPEND action at position 7
I1119 20:55:52.150070 25149 registrar.cpp:490] Successfully updated the 'registry' in 0ns
I1119 20:55:52.150444 25149 log.cpp:699] Attempting to truncate the log to 7
I1119 20:55:52.150643 25139 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 8
I1119 20:55:52.150822 25134 slave.cpp:2553] Received ping from slave-observer(153)@67.195.81.186:57639
I1119 20:55:52.150784 25138 master.cpp:3123] Registered slave 20141119-205551-3125920579-57639-25120-S1 at slave(171)@67.195.81.186:57639 (penates.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I1119 20:55:52.151083 25144 hierarchical_allocator_process.hpp:442] Added slave 20141119-205551-3125920579-57639-25120-S1 (penates.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
I1119 20:55:52.151203 25134 slave.cpp:773] Registered with master master@67.195.81.186:57639; given slave ID 20141119-205551-3125920579-57639-25120-S1
I1119 20:55:52.151306 25140 status_update_manager.cpp:178] Resuming sending status updates
I1119 20:55:52.151396 25144 hierarchical_allocator_process.hpp:734] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20141119-205551-3125920579-57639-25120-S1 to framework 20141119-205551-3125920579-57639-25120-0000
I1119 20:55:52.151685 25144 hierarchical_allocator_process.hpp:679] Performed allocation for slave 20141119-205551-3125920579-57639-25120-S1 in 437297ns
I1119 20:55:52.151710 25135 replica.cpp:508] Replica received write request for position 8
I1119 20:55:52.152009 25137 master.cpp:3844] Sending 1 offers to framework 20141119-205551-3125920579-57639-25120-0000 (default) at scheduler-71d4de3d-d16a-443e-888c-3ad984c2993e@67.195.81.186:57639
I1119 20:55:52.152302 25135 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 560685ns
I1119 20:55:52.152309 25137 sched.cpp:602] Scheduler::resourceOffers took 18501ns
I1119 20:55:52.152333 25135 replica.cpp:676] Persisted action at 8
I1119 20:55:52.152984 25146 replica.cpp:655] Replica received learned notice for position 8
I1119 20:55:52.153604 25146 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 592552ns
I1119 20:55:52.153681 25146 leveldb.cpp:401] Deleting ~2 keys from leveldb took 48696ns
I1119 20:55:52.153704 25146 replica.cpp:676] Persisted action at 8
I1119 20:55:52.153728 25146 replica.cpp:661] Replica learned TRUNCATE action at position 8
I1119 20:55:52.174667 25145 hierarchical_allocator_process.hpp:659] Performed allocation for 1 slaves in 129261ns
I1119 20:55:52.174723 25135 master.cpp:126] No whitelist given. Advertising offers for all slaves
I1119 20:55:52.175037 25134 slave.cpp:3252] Framework 20141119-205549-3125920579-57639-25120-0000 seems to have exited. Ignoring registration timeout for executor 'default'
I1119 20:55:52.175127 25141 gc.cpp:134] Deleting /tmp/GarbageCollectorIntegrationTest_DiskUsage_4kBMA9/slaves/20141119-205549-3125920579-57639-25120-S0/frameworks/20141119-205549-3125920579-57639-25120-0000/executors/default/runs/938f4723-ba7b-4738-89db-ac755f638e08
I1119 20:55:52.175256 25141 gc.cpp:143] Deleted '/tmp/GarbageCollectorIntegrationTest_DiskUsage_4kBMA9/slaves/20141119-205549-3125920579-57639-25120-S0/frameworks/20141119-205549-3125920579-57639-25120-0000/executors/default/runs/938f4723-ba7b-4738-89db-ac755f638e08'
I1119 20:55:52.175313 25142 slave.cpp:2628] No pings from master received within 75secs
I1119 20:55:52.175366 25134 slave.cpp:2628] No pings from master received within 75secs
I1119 20:55:52.175393 25141 gc.cpp:134] Deleting /tmp/GarbageCollectorIntegrationTest_DiskUsage_4kBMA9/slaves/20141119-205549-3125920579-57639-25120-S0/frameworks/20141119-205549-3125920579-57639-25120-0000/executors/default
I1119 20:55:52.175464 25142 slave.cpp:2553] Received ping from slave-observer(153)@67.195.81.186:57639
I1119 20:55:52.175606 25134 slave.cpp:3336] Current usage 7.68%. Max allowed age: 5.762099051717870days
I1119 20:55:52.175626 25141 gc.cpp:143] Deleted '/tmp/GarbageCollectorIntegrationTest_DiskUsage_4kBMA9/slaves/20141119-205549-3125920579-57639-25120-S0/frameworks/20141119-205549-3125920579-57639-25120-0000/executors/default'
I1119 20:55:52.175667 25141 gc.cpp:134] Deleting /tmp/GarbageCollectorIntegrationTest_DiskUsage_4kBMA9/slaves/20141119-205549-3125920579-57639-25120-S0/frameworks/20141119-205549-3125920579-57639-25120-0000
I1119 20:55:52.175700 25142 slave.cpp:3336] Current usage 7.68%. Max allowed age: 5.762099051717870days
I1119 20:55:52.175768 25141 gc.cpp:143] Deleted '/tmp/GarbageCollectorIntegrationTest_DiskUsage_4kBMA9/slaves/20141119-205549-3125920579-57639-25120-S0/frameworks/20141119-205549-3125920579-57639-25120-0000'
I1119 20:55:52.175776 25134 slave.cpp:3336] Current usage 7.68%. Max allowed age: 5.762099059095440days
I1119 20:55:52.175850 25149 gc.cpp:167] Pruning directories with remaining removal time 143.280896ms
I1119 20:55:52.175886 25142 slave.cpp:594] Re-detecting master
I1119 20:55:52.175914 25142 slave.cpp:641] Detecting new master
I1119 20:55:52.175941 25135 status_update_manager.cpp:171] Pausing sending status updates
I1119 20:55:52.176003 25149 gc.cpp:134] Deleting /tmp/GarbageCollectorIntegrationTest_Restart_NfqYfw/slaves/20141119-205551-3125920579-57639-25120-S0
*** Aborted at 1416430552 (unix time) try "date -d @1416430552" if you are using GNU date ***
I1119 20:55:52.176296 25142 slave.cpp:605] New master detected at master@67.195.81.186:57639
I1119 20:55:52.176309 25143 status_update_manager.cpp:171] Pausing sending status updates
PC: @ 0x2b37874132d2 (unknown)
I1119 20:55:52.176342 25142 slave.cpp:668] Authenticating with master master@67.195.81.186:57639
I1119 20:55:52.292456 25142 slave.cpp:673] Using default CRAM-MD5 authenticatee
I1119 20:55:52.176353 25149 gc.cpp:143] Deleted '/tmp/GarbageCollectorIntegrationTest_Restart_NfqYfw/slaves/20141119-205551-3125920579-57639-25120-S0'
*** SIGSEGV (@0x1d) received by PID 25120 (TID 0x2b3789e91700) from PID 29; stack trace: ***
I1119 20:55:52.292702 25142 slave.cpp:641] Detecting new master
I1119 20:55:52.292875 25141 authenticatee.hpp:138] Creating new client SASL connection
I1119 20:55:52.293140 25148 master.cpp:3902] Authenticating slave(171)@67.195.81.186:57639
I1119 20:55:52.293181 25148 master.cpp:3913] Using default CRAM-MD5 authenticator
I1119 20:55:52.293591 25147 authenticator.hpp:170] Creating new server SASL connection
I1119 20:55:52.293779 25143 authenticatee.hpp:229] Received SASL authentication mechanisms: CRAM-MD5
I1119 20:55:52.293805 25143 authenticatee.hpp:255] Attempting to authenticate with mechanism 'CRAM-MD5'
I1119 20:55:52.293903 25148 authenticator.hpp:276] Received SASL authentication start
I1119 20:55:52.293957 25148 authenticator.hpp:398] Authentication requires more steps
I1119 20:55:52.294081 25137 authenticatee.hpp:275] Received SASL authentication step
I1119 20:55:52.294214 25146 authenticator.hpp:304] Received SASL authentication step
I1119 20:55:52.294245 25146 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'penates.apache.org' server FQDN: 'penates.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1119 20:55:52.294256 25146 auxprop.cpp:171] Looking up auxiliary property '*userPassword'
I1119 20:55:52.294288 25146 auxprop.cpp:171] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1119 20:55:52.294312 25146 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'penates.apache.org' server FQDN: 'penates.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1119 20:55:52.294323 25146 auxprop.cpp:121] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1119 20:55:52.294332 25146 auxprop.cpp:121] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1119 20:55:52.294348 25146 authenticator.hpp:390] Authentication success
I1119 20:55:52.294441 25137 authenticatee.hpp:315] Authentication success
I1119 20:55:52.294474 25146 master.cpp:3960] Successfully authenticated principal 'test-principal' at slave(171)@67.195.81.186:57639
I1119 20:55:52.294723 25137 slave.cpp:739] Successfully authenticated with master master@67.195.81.186:57639
I1119 20:55:52.294875 25137 slave.cpp:1067] Will retry registration in 4.008242ms if necessary
I1119 20:55:52.295094 25135 master.cpp:3196] Re-registering slave 20141119-205551-3125920579-57639-25120-S1 at slave(171)@67.195.81.186:57639 (penates.apache.org)
I1119 20:55:52.295258 25137 slave.cpp:841] Re-registered with master master@67.195.81.186:57639
I1119 20:55:52.295364 25138 status_update_manager.cpp:178] Resuming sending status updates
@ 0x2b3787be6340 (unknown)
@ 0x2b37874132d2 (unknown)
@ 0x2b3784ef0651 process::Process<>::self()
@ 0x2b3784eee72a process::dispatch<>()
@ 0x2b3784ee9ec6 mesos::internal::Files::detach()
@ 0x2b3785202db3 mesos::internal::slave::Slave::detachFile()
@ 0x2b3785247f26 _ZZN7process8dispatchI7NothingN5mesos8internal5slave5SlaveERKSsSsEENS_6FutureIT_EERKNS_3PIDIT0_EEMSC_FS9_T1_ET2_ENKUlPNS_11ProcessBaseEE_clESL_
@ 0x2b378526bb07 _ZNSt17_Function_handlerIFvPN7process11ProcessBaseEEZNS0_8dispatchI7NothingN5mesos8internal5slave5SlaveERKSsSsEENS0_6FutureIT_EERKNS0_3PIDIT0_EEMSG_FSD_T1_ET2_EUlS2_E_E9_M_invokeERKSt9_Any_dataS2_
@ 0x2b378587a78f std::function<>::operator()()
@ 0x2b3785861b0d process::ProcessBase::visit()
@ 0x2b3785866338 process::DispatchEvent::visit()
@ 0x8fb972 process::ProcessBase::serve()
@ 0x2b378585e5a6 process::ProcessManager::resume()
@ 0x2b3785852d65 process::schedule()
@ 0x2b3787bde182 start_thread
@ 0x2b3787eeefbd (unknown)
make[3]: *** [check-local] Segmentation fault
{code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)