[ RUN ] SlaveRecoveryTest/0.ShutdownSlave
Using temporary directory '/tmp/SlaveRecoveryTest_0_ShutdownSlave_3O5epS'
I0828 21:21:46.206990 27625 leveldb.cpp:176] Opened db in 24.461837ms
I0828 21:21:46.213706 27625 leveldb.cpp:183] Compacted db in 6.021499ms
I0828 21:21:46.214047 27625 leveldb.cpp:198] Created db iterator in 5566ns
I0828 21:21:46.214313 27625 leveldb.cpp:204] Seeked to beginning of db in 1433ns
I0828 21:21:46.214515 27625 leveldb.cpp:273] Iterated through 0 keys in the db in 723ns
I0828 21:21:46.214826 27625 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0828 21:21:46.215409 27642 recover.cpp:425] Starting replica recovery
I0828 21:21:46.215718 27642 recover.cpp:451] Replica is in EMPTY status
I0828 21:21:46.216264 27642 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request
I0828 21:21:46.216557 27642 recover.cpp:188] Received a recover response from a replica in EMPTY status
I0828 21:21:46.216917 27642 recover.cpp:542] Updating replica status to STARTING
I0828 21:21:46.221271 27645 master.cpp:286] Master 20140828-212146-16842879-45613-27625 (saucy) started on 127.0.1.1:45613
I0828 21:21:46.221812 27645 master.cpp:332] Master only allowing authenticated frameworks to register
I0828 21:21:46.222038 27645 master.cpp:337] Master only allowing authenticated slaves to register
I0828 21:21:46.222250 27645 credentials.hpp:36] Loading credentials for authentication from '/tmp/SlaveRecoveryTest_0_ShutdownSlave_3O5epS/credentials'
I0828 21:21:46.222585 27645 master.cpp:366] Authorization enabled
I0828 21:21:46.222885 27642 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 5.596969ms
I0828 21:21:46.223085 27642 replica.cpp:320] Persisted replica status to STARTING
I0828 21:21:46.223424 27642 recover.cpp:451] Replica is in STARTING status
I0828 21:21:46.223933 27642 replica.cpp:638] Replica in STARTING status received a broadcasted recover request
I0828 21:21:46.224984 27642 recover.cpp:188] Received a recover response from a replica in STARTING status
I0828 21:21:46.225385 27642 recover.cpp:542] Updating replica status to VOTING
I0828 21:21:46.224750 27646 master.cpp:1205] The newly elected leader is master@127.0.1.1:45613 with id 20140828-212146-16842879-45613-27625
I0828 21:21:46.226132 27646 master.cpp:1218] Elected as the leading master!
I0828 21:21:46.226349 27646 master.cpp:1036] Recovering from registrar
I0828 21:21:46.226637 27646 registrar.cpp:313] Recovering registrar
I0828 21:21:46.224473 27641 master.cpp:120] No whitelist given. Advertising offers for all slaves
I0828 21:21:46.224431 27645 hierarchical_allocator_process.hpp:299] Initializing hierarchical allocator process with master : master@127.0.1.1:45613
I0828 21:21:46.240932 27642 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 15.182422ms
I0828 21:21:46.241453 27642 replica.cpp:320] Persisted replica status to VOTING
I0828 21:21:46.241926 27643 recover.cpp:556] Successfully joined the Paxos group
I0828 21:21:46.242228 27642 recover.cpp:440] Recover process terminated
I0828 21:21:46.242501 27645 log.cpp:656] Attempting to start the writer
I0828 21:21:46.243247 27645 replica.cpp:474] Replica received implicit promise request with proposal 1
I0828 21:21:46.253456 27645 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 9.95472ms
I0828 21:21:46.253955 27645 replica.cpp:342] Persisted promised to 1
I0828 21:21:46.254518 27645 coordinator.cpp:230] Coordinator attemping to fill missing position
I0828 21:21:46.255234 27641 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
I0828 21:21:46.263128 27641 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 7.484042ms
I0828 21:21:46.263536 27641 replica.cpp:676] Persisted action at 0
I0828 21:21:46.263806 27641 replica.cpp:508] Replica received write request for position 0
I0828 21:21:46.263834 27641 leveldb.cpp:438] Reading position from leveldb took 14063ns
I0828 21:21:46.276149 27641 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 12.295476ms
I0828 21:21:46.276178 27641 replica.cpp:676] Persisted action at 0
I0828 21:21:46.276319 27641 replica.cpp:655] Replica received learned notice for position 0
I0828 21:21:46.285523 27641 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 9.185244ms
I0828 21:21:46.285552 27641 replica.cpp:676] Persisted action at 0
I0828 21:21:46.285560 27641 replica.cpp:661] Replica learned NOP action at position 0
I0828 21:21:46.289685 27642 log.cpp:672] Writer started with ending position 0
I0828 21:21:46.290166 27642 leveldb.cpp:438] Reading position from leveldb took 14463ns
I0828 21:21:46.297260 27642 registrar.cpp:346] Successfully fetched the registry (0B)
I0828 21:21:46.297622 27642 registrar.cpp:422] Attempting to update the 'registry'
I0828 21:21:46.298893 27645 log.cpp:680] Attempting to append 118 bytes to the log
I0828 21:21:46.299190 27645 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
I0828 21:21:46.299643 27645 replica.cpp:508] Replica received write request for position 1
I0828 21:21:46.310351 27645 leveldb.cpp:343] Persisting action (135 bytes) to leveldb took 10.349409ms
I0828 21:21:46.310577 27645 replica.cpp:676] Persisted action at 1
I0828 21:21:46.311039 27645 replica.cpp:655] Replica received learned notice for position 1
I0828 21:21:46.322127 27645 leveldb.cpp:343] Persisting action (137 bytes) to leveldb took 10.858061ms
I0828 21:21:46.322614 27645 replica.cpp:676] Persisted action at 1
I0828 21:21:46.322875 27645 replica.cpp:661] Replica learned APPEND action at position 1
I0828 21:21:46.323480 27645 registrar.cpp:479] Successfully updated 'registry'
I0828 21:21:46.323874 27645 registrar.cpp:372] Successfully recovered registrar
I0828 21:21:46.323649 27639 log.cpp:699] Attempting to truncate the log to 1
I0828 21:21:46.324465 27644 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
I0828 21:21:46.324988 27644 replica.cpp:508] Replica received write request for position 2
I0828 21:21:46.325335 27643 master.cpp:1063] Recovered 0 slaves from the Registry (82B) ; allowing 10mins for slaves to re-register
I0828 21:21:46.335847 27644 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 10.651398ms
I0828 21:21:46.336320 27644 replica.cpp:676] Persisted action at 2
I0828 21:21:46.336896 27644 replica.cpp:655] Replica received learned notice for position 2
I0828 21:21:46.345854 27644 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 8.540555ms
I0828 21:21:46.346261 27644 leveldb.cpp:401] Deleting ~1 keys from leveldb took 30183ns
I0828 21:21:46.346282 27644 replica.cpp:676] Persisted action at 2
I0828 21:21:46.346315 27644 replica.cpp:661] Replica learned TRUNCATE action at position 2
I0828 21:21:46.356840 27625 containerizer.cpp:89] Using isolation: posix/cpu,posix/mem
I0828 21:21:46.361413 27644 slave.cpp:167] Slave started on 48)@127.0.1.1:45613
I0828 21:21:46.361753 27644 credentials.hpp:84] Loading credential for authentication from '/tmp/SlaveRecoveryTest_0_ShutdownSlave_umhraW/credential'
I0828 21:21:46.362046 27644 slave.cpp:274] Slave using credential for: test-principal
I0828 21:21:46.362810 27644 slave.cpp:287] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0828 21:21:46.363088 27644 slave.cpp:315] Slave hostname: saucy
I0828 21:21:46.363301 27644 slave.cpp:316] Slave checkpoint: true
I0828 21:21:46.363986 27644 state.cpp:33] Recovering state from '/tmp/SlaveRecoveryTest_0_ShutdownSlave_umhraW/meta'
I0828 21:21:46.364308 27644 status_update_manager.cpp:193] Recovering status update manager
I0828 21:21:46.364600 27644 containerizer.cpp:252] Recovering containerizer
I0828 21:21:46.365325 27646 slave.cpp:3204] Finished recovery
I0828 21:21:46.365839 27646 slave.cpp:598] New master detected at master@127.0.1.1:45613
I0828 21:21:46.366041 27646 slave.cpp:672] Authenticating with master master@127.0.1.1:45613
I0828 21:21:46.366317 27646 slave.cpp:645] Detecting new master
I0828 21:21:46.366569 27646 status_update_manager.cpp:167] New master detected at master@127.0.1.1:45613
I0828 21:21:46.366827 27646 authenticatee.hpp:128] Creating new client SASL connection
I0828 21:21:46.367204 27646 master.cpp:3637] Authenticating slave(48)@127.0.1.1:45613
I0828 21:21:46.367553 27646 authenticator.hpp:156] Creating new server SASL connection
I0828 21:21:46.367857 27646 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0828 21:21:46.368031 27646 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0828 21:21:46.368228 27646 authenticator.hpp:262] Received SASL authentication start
I0828 21:21:46.368444 27646 authenticator.hpp:384] Authentication requires more steps
I0828 21:21:46.368648 27646 authenticatee.hpp:265] Received SASL authentication step
I0828 21:21:46.368924 27646 authenticator.hpp:290] Received SASL authentication step
I0828 21:21:46.369120 27646 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'saucy' server FQDN: 'saucy' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0828 21:21:46.369350 27646 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I0828 21:21:46.369544 27646 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0828 21:21:46.369730 27646 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'saucy' server FQDN: 'saucy' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0828 21:21:46.369958 27646 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0828 21:21:46.370131 27646 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0828 21:21:46.370311 27646 authenticator.hpp:376] Authentication success
I0828 21:21:46.370518 27646 authenticatee.hpp:305] Authentication success
I0828 21:21:46.370637 27642 master.cpp:3677] Successfully authenticated principal 'test-principal' at slave(48)@127.0.1.1:45613
I0828 21:21:46.371772 27641 slave.cpp:729] Successfully authenticated with master master@127.0.1.1:45613
I0828 21:21:46.371984 27641 slave.cpp:980] Will retry registration in 15.311045ms if necessary
I0828 21:21:46.372643 27641 master.cpp:2836] Registering slave at slave(48)@127.0.1.1:45613 (saucy) with id 20140828-212146-16842879-45613-27625-0
I0828 21:21:46.373016 27641 registrar.cpp:422] Attempting to update the 'registry'
I0828 21:21:46.374539 27641 log.cpp:680] Attempting to append 289 bytes to the log
I0828 21:21:46.374876 27641 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
I0828 21:21:46.375296 27641 replica.cpp:508] Replica received write request for position 3
I0828 21:21:46.376046 27625 sched.cpp:137] Version: 0.21.0
I0828 21:21:46.376374 27646 sched.cpp:233] New master detected at master@127.0.1.1:45613
I0828 21:21:46.376595 27646 sched.cpp:283] Authenticating with master master@127.0.1.1:45613
I0828 21:21:46.376857 27646 authenticatee.hpp:128] Creating new client SASL connection
I0828 21:21:46.377234 27646 master.cpp:3637] Authenticating scheduler-cb5a0264-23cc-45d0-bc4c-a92fa5308158@127.0.1.1:45613
I0828 21:21:46.377496 27646 authenticator.hpp:156] Creating new server SASL connection
I0828 21:21:46.377771 27646 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0828 21:21:46.377961 27646 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0828 21:21:46.378170 27646 authenticator.hpp:262] Received SASL authentication start
I0828 21:21:46.378360 27646 authenticator.hpp:384] Authentication requires more steps
I0828 21:21:46.378588 27639 authenticatee.hpp:265] Received SASL authentication step
I0828 21:21:46.378789 27646 authenticator.hpp:290] Received SASL authentication step
I0828 21:21:46.378942 27646 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'saucy' server FQDN: 'saucy' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0828 21:21:46.379091 27646 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I0828 21:21:46.379298 27646 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0828 21:21:46.379539 27646 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'saucy' server FQDN: 'saucy' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0828 21:21:46.379720 27646 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0828 21:21:46.379935 27646 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0828 21:21:46.380089 27646 authenticator.hpp:376] Authentication success
I0828 21:21:46.380306 27642 authenticatee.hpp:305] Authentication success
I0828 21:21:46.382625 27642 sched.cpp:357] Successfully authenticated with master master@127.0.1.1:45613
I0828 21:21:46.383031 27642 sched.cpp:476] Sending registration request to master@127.0.1.1:45613
I0828 21:21:46.382928 27640 master.cpp:3677] Successfully authenticated principal 'test-principal' at scheduler-cb5a0264-23cc-45d0-bc4c-a92fa5308158@127.0.1.1:45613
I0828 21:21:46.383651 27640 master.cpp:1324] Received registration request from scheduler-cb5a0264-23cc-45d0-bc4c-a92fa5308158@127.0.1.1:45613
I0828 21:21:46.383846 27640 master.cpp:1284] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0828 21:21:46.384184 27640 master.cpp:1383] Registering framework 20140828-212146-16842879-45613-27625-0000 at scheduler-cb5a0264-23cc-45d0-bc4c-a92fa5308158@127.0.1.1:45613
I0828 21:21:46.384464 27640 sched.cpp:407] Framework registered with 20140828-212146-16842879-45613-27625-0000
I0828 21:21:46.384764 27640 sched.cpp:421] Scheduler::registered took 18266ns
I0828 21:21:46.384600 27644 hierarchical_allocator_process.hpp:329] Added framework 20140828-212146-16842879-45613-27625-0000
I0828 21:21:46.385171 27644 hierarchical_allocator_process.hpp:691] No resources available to allocate!
I0828 21:21:46.385330 27644 hierarchical_allocator_process.hpp:653] Performed allocation for 0 slaves in 160171ns
I0828 21:21:46.386292 27641 leveldb.cpp:343] Persisting action (308 bytes) to leveldb took 10.815384ms
I0828 21:21:46.386492 27641 replica.cpp:676] Persisted action at 3
I0828 21:21:46.386844 27641 replica.cpp:655] Replica received learned notice for position 3
I0828 21:21:46.387980 27643 slave.cpp:980] Will retry registration in 19.851524ms if necessary
I0828 21:21:46.388140 27639 master.cpp:2824] Ignoring register slave message from slave(48)@127.0.1.1:45613 (saucy) as admission is already in progress
I0828 21:21:46.396355 27641 leveldb.cpp:343] Persisting action (310 bytes) to leveldb took 9.275034ms
I0828 21:21:46.396641 27641 replica.cpp:676] Persisted action at 3
I0828 21:21:46.396837 27641 replica.cpp:661] Replica learned APPEND action at position 3
I0828 21:21:46.397405 27641 registrar.cpp:479] Successfully updated 'registry'
I0828 21:21:46.397528 27645 log.cpp:699] Attempting to truncate the log to 3
I0828 21:21:46.397878 27645 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
I0828 21:21:46.398239 27645 replica.cpp:508] Replica received write request for position 4
I0828 21:21:46.398597 27641 master.cpp:2876] Registered slave 20140828-212146-16842879-45613-27625-0 at slave(48)@127.0.1.1:45613 (saucy)
I0828 21:21:46.398870 27641 master.cpp:4110] Adding slave 20140828-212146-16842879-45613-27625-0 at slave(48)@127.0.1.1:45613 (saucy) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0828 21:21:46.399178 27639 slave.cpp:763] Registered with master master@127.0.1.1:45613; given slave ID 20140828-212146-16842879-45613-27625-0
I0828 21:21:46.399521 27639 slave.cpp:776] Checkpointing SlaveInfo to '/tmp/SlaveRecoveryTest_0_ShutdownSlave_umhraW/meta/slaves/20140828-212146-16842879-45613-27625-0/slave.info'
I0828 21:21:46.399961 27641 hierarchical_allocator_process.hpp:442] Added slave 20140828-212146-16842879-45613-27625-0 (saucy) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
I0828 21:21:46.400316 27641 hierarchical_allocator_process.hpp:728] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140828-212146-16842879-45613-27625-0 to framework 20140828-212146-16842879-45613-27625-0000
I0828 21:21:46.400158 27644 slave.cpp:2333] Received ping from slave-observer(45)@127.0.1.1:45613
I0828 21:21:46.400872 27639 master.hpp:857] Adding offer 20140828-212146-16842879-45613-27625-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140828-212146-16842879-45613-27625-0 (saucy)
I0828 21:21:46.401105 27639 master.cpp:3584] Sending 1 offers to framework 20140828-212146-16842879-45613-27625-0000
I0828 21:21:46.401448 27639 sched.cpp:544] Scheduler::resourceOffers took 19056ns
I0828 21:21:46.401700 27641 hierarchical_allocator_process.hpp:673] Performed allocation for slave 20140828-212146-16842879-45613-27625-0 in 1.430159ms
I0828 21:21:46.403659 27644 master.hpp:867] Removing offer 20140828-212146-16842879-45613-27625-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140828-212146-16842879-45613-27625-0 (saucy)
I0828 21:21:46.403903 27644 master.cpp:2194] Processing reply for offers: [ 20140828-212146-16842879-45613-27625-0 ] on slave 20140828-212146-16842879-45613-27625-0 at slave(48)@127.0.1.1:45613 (saucy) for framework 20140828-212146-16842879-45613-27625-0000
I0828 21:21:46.404116 27644 master.cpp:2277] Authorizing framework principal 'test-principal' to launch task cf5afc1b-c007-435b-8c36-be8aa3659d3a as user 'jenkins'
I0828 21:21:46.404578 27644 master.hpp:829] Adding task cf5afc1b-c007-435b-8c36-be8aa3659d3a with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140828-212146-16842879-45613-27625-0 (saucy)
I0828 21:21:46.404824 27644 master.cpp:2343] Launching task cf5afc1b-c007-435b-8c36-be8aa3659d3a of framework 20140828-212146-16842879-45613-27625-0000 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140828-212146-16842879-45613-27625-0 at slave(48)@127.0.1.1:45613 (saucy)
I0828 21:21:46.405206 27644 slave.cpp:1011] Got assigned task cf5afc1b-c007-435b-8c36-be8aa3659d3a for framework 20140828-212146-16842879-45613-27625-0000
I0828 21:21:46.405462 27644 slave.cpp:3542] Checkpointing FrameworkInfo to '/tmp/SlaveRecoveryTest_0_ShutdownSlave_umhraW/meta/slaves/20140828-212146-16842879-45613-27625-0/frameworks/20140828-212146-16842879-45613-27625-0000/framework.info'
I0828 21:21:46.405840 27644 slave.cpp:3549] Checkpointing framework pid 'scheduler-cb5a0264-23cc-45d0-bc4c-a92fa5308158@127.0.1.1:45613' to '/tmp/SlaveRecoveryTest_0_ShutdownSlave_umhraW/meta/slaves/20140828-212146-16842879-45613-27625-0/frameworks/20140828-212146-16842879-45613-27625-0000/framework.pid'
I0828 21:21:46.406122 27645 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 7.684731ms
I0828 21:21:46.406288 27645 replica.cpp:676] Persisted action at 4
I0828 21:21:46.406618 27645 replica.cpp:655] Replica received learned notice for position 4
I0828 21:21:46.407562 27644 slave.cpp:1121] Launching task cf5afc1b-c007-435b-8c36-be8aa3659d3a for framework 20140828-212146-16842879-45613-27625-0000
I0828 21:21:46.409296 27644 slave.cpp:3858] Checkpointing ExecutorInfo to '/tmp/SlaveRecoveryTest_0_ShutdownSlave_umhraW/meta/slaves/20140828-212146-16842879-45613-27625-0/frameworks/20140828-212146-16842879-45613-27625-0000/executors/cf5afc1b-c007-435b-8c36-be8aa3659d3a/executor.info'
I0828 21:21:46.410117 27641 containerizer.cpp:394] Starting container '1faf33b5-7b06-4384-8b17-cdf0db68e400' for executor 'cf5afc1b-c007-435b-8c36-be8aa3659d3a' of framework '20140828-212146-16842879-45613-27625-0000'
I0828 21:21:46.413606 27641 launcher.cpp:137] Forked child with pid '28309' for container '1faf33b5-7b06-4384-8b17-cdf0db68e400'
I0828 21:21:46.414163 27641 containerizer.cpp:678] Checkpointing executor's forked pid 28309 to '/tmp/SlaveRecoveryTest_0_ShutdownSlave_umhraW/meta/slaves/20140828-212146-16842879-45613-27625-0/frameworks/20140828-212146-16842879-45613-27625-0000/executors/cf5afc1b-c007-435b-8c36-be8aa3659d3a/runs/1faf33b5-7b06-4384-8b17-cdf0db68e400/pids/forked.pid'
I0828 21:21:46.415959 27641 containerizer.cpp:510] Fetching URIs for container '1faf33b5-7b06-4384-8b17-cdf0db68e400' using command '/var/jenkins/workspace/mesos-ubuntu-13.10-gcc/src/mesos-fetcher'
I0828 21:21:46.416506 27644 slave.cpp:3973] Checkpointing TaskInfo to '/tmp/SlaveRecoveryTest_0_ShutdownSlave_umhraW/meta/slaves/20140828-212146-16842879-45613-27625-0/frameworks/20140828-212146-16842879-45613-27625-0000/executors/cf5afc1b-c007-435b-8c36-be8aa3659d3a/runs/1faf33b5-7b06-4384-8b17-cdf0db68e400/tasks/cf5afc1b-c007-435b-8c36-be8aa3659d3a/task.info'
I0828 21:21:46.419023 27644 slave.cpp:1231] Queuing task 'cf5afc1b-c007-435b-8c36-be8aa3659d3a' for executor cf5afc1b-c007-435b-8c36-be8aa3659d3a of framework '20140828-212146-16842879-45613-27625-0000
I0828 21:21:46.419585 27644 slave.cpp:552] Successfully attached file '/tmp/SlaveRecoveryTest_0_ShutdownSlave_umhraW/slaves/20140828-212146-16842879-45613-27625-0/frameworks/20140828-212146-16842879-45613-27625-0000/executors/cf5afc1b-c007-435b-8c36-be8aa3659d3a/runs/1faf33b5-7b06-4384-8b17-cdf0db68e400'
I0828 21:21:46.420091 27645 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 13.201889ms
I0828 21:21:46.420384 27645 leveldb.cpp:401] Deleting ~2 keys from leveldb took 103379ns
I0828 21:21:46.420572 27645 replica.cpp:676] Persisted action at 4
I0828 21:21:46.420763 27645 replica.cpp:661] Replica learned TRUNCATE action at position 4
I0828 21:21:47.172636 27640 slave.cpp:2544] Monitoring executor 'cf5afc1b-c007-435b-8c36-be8aa3659d3a' of framework '20140828-212146-16842879-45613-27625-0000' in container '1faf33b5-7b06-4384-8b17-cdf0db68e400'
WARNING: Logging before InitGoogleLogging() is written to STDERR
I0828 21:21:47.204005 28344 process.cpp:1771] libprocess is initialized on 127.0.1.1:58796 for 8 cpus
I0828 21:21:47.205031 28344 logging.cpp:177] Logging to STDERR
I0828 21:21:47.207900 28344 exec.cpp:132] Version: 0.21.0
I0828 21:21:47.208281 28358 exec.cpp:182] Executor started at: executor(1)@127.0.1.1:58796 with pid 28344
I0828 21:21:47.209727 27640 slave.cpp:1742] Got registration for executor 'cf5afc1b-c007-435b-8c36-be8aa3659d3a' of framework 20140828-212146-16842879-45613-27625-0000
I0828 21:21:47.209794 27640 slave.cpp:1827] Checkpointing executor pid 'executor(1)@127.0.1.1:58796' to '/tmp/SlaveRecoveryTest_0_ShutdownSlave_umhraW/meta/slaves/20140828-212146-16842879-45613-27625-0/frameworks/20140828-212146-16842879-45613-27625-0000/executors/cf5afc1b-c007-435b-8c36-be8aa3659d3a/runs/1faf33b5-7b06-4384-8b17-cdf0db68e400/pids/libprocess.pid'
I0828 21:21:47.210197 27640 slave.cpp:1861] Flushing queued task cf5afc1b-c007-435b-8c36-be8aa3659d3a for executor 'cf5afc1b-c007-435b-8c36-be8aa3659d3a' of framework 20140828-212146-16842879-45613-27625-0000
I0828 21:21:47.211431 28358 exec.cpp:206] Executor registered on slave 20140828-212146-16842879-45613-27625-0
Registered executor on saucy
I0828 21:21:47.212602 28358 exec.cpp:218] Executor::registered took 280603ns
I0828 21:21:47.212889 28358 exec.cpp:293] Executor asked to run task 'cf5afc1b-c007-435b-8c36-be8aa3659d3a'
Starting task cf5afc1b-c007-435b-8c36-be8aa3659d3a
I0828 21:21:47.213672 28358 exec.cpp:302] Executor::launchTask took 551047ns
sh -c 'sleep 1000'
Forked command at 28367
I0828 21:21:47.216408 28361 exec.cpp:525] Executor sending status update TASK_RUNNING (UUID: c0d5bd02-475c-4183-bcfd-8e1a43763e7e) for task cf5afc1b-c007-435b-8c36-be8aa3659d3a of framework 20140828-212146-16842879-45613-27625-0000
I0828 21:21:47.216979 27643 slave.cpp:2096] Handling status update TASK_RUNNING (UUID: c0d5bd02-475c-4183-bcfd-8e1a43763e7e) for task cf5afc1b-c007-435b-8c36-be8aa3659d3a of framework 20140828-212146-16842879-45613-27625-0000 from executor(1)@127.0.1.1:58796
I0828 21:21:47.217106 27643 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: c0d5bd02-475c-4183-bcfd-8e1a43763e7e) for task cf5afc1b-c007-435b-8c36-be8aa3659d3a of framework 20140828-212146-16842879-45613-27625-0000
I0828 21:21:47.217121 27643 status_update_manager.cpp:499] Creating StatusUpdate stream for task cf5afc1b-c007-435b-8c36-be8aa3659d3a of framework 20140828-212146-16842879-45613-27625-0000
I0828 21:21:47.217356 27643 status_update_manager.hpp:342] Checkpointing UPDATE for status update TASK_RUNNING (UUID: c0d5bd02-475c-4183-bcfd-8e1a43763e7e) for task cf5afc1b-c007-435b-8c36-be8aa3659d3a of framework 20140828-212146-16842879-45613-27625-0000
I0828 21:21:47.228610 27639 hierarchical_allocator_process.hpp:653] Performed allocation for 1 slaves in 31882ns
2014-08-28 21:21:48,334:27625(0x2ad7b36ba700):ZOO_WARN@zookeeper_interest@1557: Exceeded deadline by 642ms
2014-08-28 21:21:48,335:27625(0x2ad7b36ba700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:33940] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
I0828 21:21:48.336568 27639 hierarchical_allocator_process.hpp:653] Performed allocation for 1 slaves in 27650ns
I0828 21:21:48.345005 27643 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: c0d5bd02-475c-4183-bcfd-8e1a43763e7e) for task cf5afc1b-c007-435b-8c36-be8aa3659d3a of framework 20140828-212146-16842879-45613-27625-0000 to master@127.0.1.1:45613
I0828 21:21:48.345942 27644 master.cpp:3205] Forwarding status update TASK_RUNNING (UUID: c0d5bd02-475c-4183-bcfd-8e1a43763e7e) for task cf5afc1b-c007-435b-8c36-be8aa3659d3a of framework 20140828-212146-16842879-45613-27625-0000
I0828 21:21:48.346225 27644 master.cpp:3171] Status update TASK_RUNNING (UUID: c0d5bd02-475c-4183-bcfd-8e1a43763e7e) for task cf5afc1b-c007-435b-8c36-be8aa3659d3a of framework 20140828-212146-16842879-45613-27625-0000 from slave 20140828-212146-16842879-45613-27625-0 at slave(48)@127.0.1.1:45613 (saucy)
I0828 21:21:48.346660 27642 sched.cpp:635] Scheduler::statusUpdate took 86992ns
I0828 21:21:48.347705 27642 master.cpp:2686] Forwarding status update acknowledgement c0d5bd02-475c-4183-bcfd-8e1a43763e7e for task cf5afc1b-c007-435b-8c36-be8aa3659d3a of framework 20140828-212146-16842879-45613-27625-0000 to slave 20140828-212146-16842879-45613-27625-0 at slave(48)@127.0.1.1:45613 (saucy)
I0828 21:21:48.348397 28360 exec.cpp:379] Executor asked to shutdown
I0828 21:21:48.348461 28360 exec.cpp:394] Executor::shutdown took 5608ns
I0828 21:21:48.348575 28360 exec.cpp:78] Scheduling shutdown of the executor
Shutting down
Sending SIGTERM to process tree at pid 28367
I0828 21:21:48.352062 27642 hierarchical_allocator_process.hpp:653] Performed allocation for 1 slaves in 38217ns
I0828 21:21:48.353659 27646 slave.cpp:2254] Status update manager successfully handled status update TASK_RUNNING (UUID: c0d5bd02-475c-4183-bcfd-8e1a43763e7e) for task cf5afc1b-c007-435b-8c36-be8aa3659d3a of framework 20140828-212146-16842879-45613-27625-0000
I0828 21:21:48.353884 27646 slave.cpp:2260] Sending acknowledgement for status update TASK_RUNNING (UUID: c0d5bd02-475c-4183-bcfd-8e1a43763e7e) for task cf5afc1b-c007-435b-8c36-be8aa3659d3a of framework 20140828-212146-16842879-45613-27625-0000 to executor(1)@127.0.1.1:58796
I0828 21:21:48.354588 27643 status_update_manager.cpp:398] Received status update acknowledgement (UUID: c0d5bd02-475c-4183-bcfd-8e1a43763e7e) for task cf5afc1b-c007-435b-8c36-be8aa3659d3a of framework 20140828-212146-16842879-45613-27625-0000
II0828 21:21:48.354921 27643 status_update_manager.hpp:342] Checkpointing ACK for status update TASK_RUNNING (UUID: c0d5bd02-475c-4183-bcfd-8e1a43763e7e) for task cf5afc1b-c007-435b-8c36-be8aa3659d3a of framework 20140828-212146-16842879-45613-27625-0000
0828 21:21:48.355509 28365 exec.cpp:332] Ignoring status update acknowledgement c0d5bd02-475c-4183-bcfd-8e1a43763e7e for task cf5afc1b-c007-435b-8c36-be8aa3659d3a of framework 20140828-212146-16842879-45613-27625-0000 because the driver is aborted!
I0828 21:21:48.373334 27643 slave.cpp:1682] Status update manager successfully handled status update acknowledgement (UUID: c0d5bd02-475c-4183-bcfd-8e1a43763e7e) for task cf5afc1b-c007-435b-8c36-be8aa3659d3a of framework 20140828-212146-16842879-45613-27625-0000
Killing the following process trees:
[
-+- 28367 sh -c sleep 1000
\--- 28368 sleep 1000
]
I0828 21:21:50.095928 27642 hierarchical_allocator_process.hpp:653] Performed allocation for 1 slaves in 28759ns
I0828 21:21:50.136400 27640 master.cpp:120] No whitelist given. Advertising offers for all slaves
I0828 21:21:50.138304 27645 hierarchical_allocator_process.hpp:653] Performed allocation for 1 slaves in 29426ns
I0828 21:21:50.177014 27644 hierarchical_allocator_process.hpp:653] Performed allocation for 1 slaves in 28454ns
I0828 21:21:50.218552 27640 hierarchical_allocator_process.hpp:653] Performed allocation for 1 slaves in 27554ns
I0828 21:21:50.257881 27641 hierarchical_allocator_process.hpp:653] Performed allocation for 1 slaves in 27998ns
I0828 21:21:50.298316 27643 hierarchical_allocator_process.hpp:653] Performed allocation for 1 slaves in 27308ns
I0828 21:21:50.338696 27644 master.cpp:120] No whitelist given. Advertising offers for all slaves
I0828 21:21:50.338999 27645 hierarchical_allocator_process.hpp:653] Performed allocation for 1 slaves in 27084ns
I0828 21:21:50.379153 27646 hierarchical_allocator_process.hpp:653] Performed allocation for 1 slaves in 27156ns
I0828 21:21:50.419615 27644 hierarchical_allocator_process.hpp:653] Performed allocation for 1 slaves in 24254ns
I0828 21:21:50.449911 27639 hierarchical_allocator_process.hpp:653] Performed allocation for 1 slaves in 20276ns
I0828 21:21:50.490430 27640 hierarchical_allocator_process.hpp:653] Performed allocation for 1 slaves in 28566ns
I0828 21:21:50.530827 27642 master.cpp:120] No whitelist given. Advertising offers for all slaves
I0828 21:21:50.531673 27639 hierarchical_allocator_process.hpp:653] Performed allocation for 1 slaves in 28146ns
I0828 21:21:50.571229 27641 hierarchical_allocator_process.hpp:653] Performed allocation for 1 slaves in 26113ns
I0828 21:21:50.572326 27645 slave.cpp:2333] Received ping from slave-observer(45)@127.0.1.1:45613
I0828 21:21:50.611567 27642 hierarchical_allocator_process.hpp:653] Performed allocation for 1 slaves in 25396ns
I0828 21:21:50.651984 27641 hierarchical_allocator_process.hpp:653] Performed allocation for 1 slaves in 26641ns
ICommand terminated with signal Terminated (pid: 28367)
I0828 21:21:52.145009 28363 exec.cpp:525] Executor sending status update TASK_KILLED (UUID: b9a0bfa5-658e-4e40-9aff-c6c3023c06fb) for task cf5afc1b-c007-435b-8c36-be8aa3659d3a of framework 20140828-212146-16842879-45613-27625-0000
0828 21:21:50.692332 27642 hierarchical_allocator_process.hpp:653] Performed allocation for 1 slaves in 25882ns
2014-08-28 21:21:52,150:27625(0x2ad7b36ba700):ZOO_WARN@zookeeper_interest@1557: Exceeded deadline by 483ms
2014-08-28 21:21:52,155:27625(0x2ad7b36ba700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:33940] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
I0828 21:21:52.154714 27642 slave.cpp:2096] Handling status update TASK_KILLED (UUID: b9a0bfa5-658e-4e40-9aff-c6c3023c06fb) for task cf5afc1b-c007-435b-8c36-be8aa3659d3a of framework 20140828-212146-16842879-45613-27625-0000 from executor(1)@127.0.1.1:58796
I0828 21:21:52.156853 27642 slave.cpp:3906] Terminating task cf5afc1b-c007-435b-8c36-be8aa3659d3a
I0828 21:21:52.214007 27640 status_update_manager.cpp:320] Received status update TASK_KILLED (UUID: b9a0bfa5-658e-4e40-9aff-c6c3023c06fb) for task cf5afc1b-c007-435b-8c36-be8aa3659d3a of framework 20140828-212146-16842879-45613-27625-0000
I0828 21:21:52.214354 27640 status_update_manager.hpp:342] Checkpointing UPDATE for status update TASK_KILLED (UUID: b9a0bfa5-658e-4e40-9aff-c6c3023c06fb) for task cf5afc1b-c007-435b-8c36-be8aa3659d3a of framework 20140828-212146-16842879-45613-27625-0000
I0828 21:21:52.236850 27640 status_update_manager.cpp:373] Forwarding status update TASK_KILLED (UUID: b9a0bfa5-658e-4e40-9aff-c6c3023c06fb) for task cf5afc1b-c007-435b-8c36-be8aa3659d3a of framework 20140828-212146-16842879-45613-27625-0000 to master@127.0.1.1:45613
I0828 21:21:52.238040 27640 master.cpp:3205] Forwarding status update TASK_KILLED (UUID: b9a0bfa5-658e-4e40-9aff-c6c3023c06fb) for task cf5afc1b-c007-435b-8c36-be8aa3659d3a of framework 20140828-212146-16842879-45613-27625-0000
I0828 21:21:52.238370 27645 slave.cpp:2254] Status update manager successfully handled status update TASK_KILLED (UUID: b9a0bfa5-658e-4e40-9aff-c6c3023c06fb) for task cf5afc1b-c007-435b-8c36-be8aa3659d3a of framework 20140828-212146-16842879-45613-27625-0000
I0828 21:21:52.239017 27645 slave.cpp:2260] Sending acknowledgement for status update TASK_KILLED (UUID: b9a0bfa5-658e-4e40-9aff-c6c3023c06fb) for task cf5afc1b-c007-435b-8c36-be8aa3659d3a of framework 20140828-212146-16842879-45613-27625-0000 to executor(1)@127.0.1.1:58796
I0828 21:21:52.239811 28363 exec.cpp:332] Ignoring status update acknowledgement b9a0bfa5-658e-4e40-9aff-c6c3023c06fb for task cf5afc1b-c007-435b-8c36-be8aa3659d3a of framework 20140828-212146-16842879-45613-27625-0000 because the driver is aborted!
I0828 21:21:52.241734 27640 master.cpp:3171] Status update TASK_KILLED (UUID: b9a0bfa5-658e-4e40-9aff-c6c3023c06fb) for task cf5afc1b-c007-435b-8c36-be8aa3659d3a of framework 20140828-212146-16842879-45613-27625-0000 from slave 20140828-212146-16842879-45613-27625-0 at slave(48)@127.0.1.1:45613 (saucy)
I0828 21:21:52.242620 27640 master.hpp:847] Removing task cf5afc1b-c007-435b-8c36-be8aa3659d3a with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140828-212146-16842879-45613-27625-0 (saucy)
I0828 21:21:52.242277 27645 sched.cpp:635] Scheduler::statusUpdate took 17112ns
I0828 21:21:52.243813 27640 master.cpp:2686] Forwarding status update acknowledgement b9a0bfa5-658e-4e40-9aff-c6c3023c06fb for task cf5afc1b-c007-435b-8c36-be8aa3659d3a of framework 20140828-212146-16842879-45613-27625-0000 to slave 20140828-212146-16842879-45613-27625-0 at slave(48)@127.0.1.1:45613 (saucy)
I0828 21:21:52.244935 27640 status_update_manager.cpp:398] Received status update acknowledgement (UUID: b9a0bfa5-658e-4e40-9aff-c6c3023c06fb) for task cf5afc1b-c007-435b-8c36-be8aa3659d3a of framework 20140828-212146-16842879-45613-27625-0000
I0828 21:21:52.245440 27640 status_update_manager.hpp:342] Checkpointing ACK for status update TASK_KILLED (UUID: b9a0bfa5-658e-4e40-9aff-c6c3023c06fb) for task cf5afc1b-c007-435b-8c36-be8aa3659d3a of framework 20140828-212146-16842879-45613-27625-0000
I0828 21:21:52.244264 27645 hierarchical_allocator_process.hpp:563] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total allocatable: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on slave 20140828-212146-16842879-45613-27625-0 from framework 20140828-212146-16842879-45613-27625-0000
I0828 21:21:52.246511 27645 hierarchical_allocator_process.hpp:594] Framework 20140828-212146-16842879-45613-27625-0000 filtered slave 20140828-212146-16842879-45613-27625-0 for 5secs
I0828 21:21:52.267685 27640 status_update_manager.cpp:530] Cleaning up status update stream for task cf5afc1b-c007-435b-8c36-be8aa3659d3a of framework 20140828-212146-16842879-45613-27625-0000
I0828 21:21:52.268086 27644 slave.cpp:1682] Status update manager successfully handled status update acknowledgement (UUID: b9a0bfa5-658e-4e40-9aff-c6c3023c06fb) for task cf5afc1b-c007-435b-8c36-be8aa3659d3a of framework 20140828-212146-16842879-45613-27625-0000
I0828 21:21:52.268123 27644 slave.cpp:3948] Completing task cf5afc1b-c007-435b-8c36-be8aa3659d3a
I0828 21:21:52.274886 27642 master.cpp:120] No whitelist given. Advertising offers for all slaves
I0828 21:21:52.275082 27642 hierarchical_allocator_process.hpp:810] Filtered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140828-212146-16842879-45613-27625-0 for framework 20140828-212146-16842879-45613-27625-0000
I0828 21:21:52.275148 27642 hierarchical_allocator_process.hpp:653] Performed allocation for 1 slaves in 137935ns
I0828 21:21:52.335613 27640 hierarchical_allocator_process.hpp:810] Filtered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140828-212146-16842879-45613-27625-0 for framework 20140828-212146-16842879-45613-27625-0000
I0828 21:21:52.625263 27640 hierarchical_allocator_process.hpp:653] Performed allocation for 1 slaves in 289.725737ms
I0828 21:21:53.916736 27643 hierarchical_allocator_process.hpp:810] Filtered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140828-212146-16842879-45613-27625-0 for framework 20140828-212146-16842879-45613-27625-0000
I0828 21:21:53.916975 27643 hierarchical_allocator_process.hpp:653] Performed allocation for 1 slaves in 412406ns
I0828 21:21:53.957610 27639 hierarchical_allocator_process.hpp:810] Filtered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140828-212146-16842879-45613-27625-0 for framework 20140828-212146-16842879-45613-27625-0000
I0828 21:21:53.961427 27639 hierarchical_allocator_process.hpp:653] Performed allocation for 1 slaves in 3.958428ms
I0828 21:21:53.961259 27643 containerizer.cpp:998] Executor for container '1faf33b5-7b06-4384-8b17-cdf0db68e400' has exited
I0828 21:21:53.963449 27643 containerizer.cpp:882] Destroying container '1faf33b5-7b06-4384-8b17-cdf0db68e400'
W0828 21:21:54.005010 27640 containerizer.cpp:824] Skipping resource statistic for container 1faf33b5-7b06-4384-8b17-cdf0db68e400 because: Failed to get usage: No process found at 28309
W0828 21:21:54.005357 27640 containerizer.cpp:824] Skipping resource statistic for container 1faf33b5-7b06-4384-8b17-cdf0db68e400 because: Failed to get usage: No process found at 28309
I0828 21:21:54.013495 27645 slave.cpp:2602] Executor 'cf5afc1b-c007-435b-8c36-be8aa3659d3a' of framework 20140828-212146-16842879-45613-27625-0000 exited with status 0
I0828 21:21:54.013799 27645 slave.cpp:2738] Cleaning up executor 'cf5afc1b-c007-435b-8c36-be8aa3659d3a' of framework 20140828-212146-16842879-45613-27625-0000
I0828 21:21:54.014480 27645 slave.cpp:2813] Cleaning up framework 20140828-212146-16842879-45613-27625-0000
I0828 21:21:54.014824 27645 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_ShutdownSlave_umhraW/slaves/20140828-212146-16842879-45613-27625-0/frameworks/20140828-212146-16842879-45613-27625-0000/executors/cf5afc1b-c007-435b-8c36-be8aa3659d3a/runs/1faf33b5-7b06-4384-8b17-cdf0db68e400' for gc 1.0000093467509weeks in the future
I0828 21:21:54.015060 27645 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_ShutdownSlave_umhraW/slaves/20140828-212146-16842879-45613-27625-0/frameworks/20140828-212146-16842879-45613-27625-0000/executors/cf5afc1b-c007-435b-8c36-be8aa3659d3a' for gc 1.0000093467509weeks in the future
I0828 21:21:54.015277 27645 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_ShutdownSlave_umhraW/meta/slaves/20140828-212146-16842879-45613-27625-0/frameworks/20140828-212146-16842879-45613-27625-0000/executors/cf5afc1b-c007-435b-8c36-be8aa3659d3a/runs/1faf33b5-7b06-4384-8b17-cdf0db68e400' for gc 1.0000093467509weeks in the future
I0828 21:21:54.015537 27645 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_ShutdownSlave_umhraW/meta/slaves/20140828-212146-16842879-45613-27625-0/frameworks/20140828-212146-16842879-45613-27625-0000/executors/cf5afc1b-c007-435b-8c36-be8aa3659d3a' for gc 1.0000093467509weeks in the future
I0828 21:21:54.015779 27645 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_ShutdownSlave_umhraW/slaves/20140828-212146-16842879-45613-27625-0/frameworks/20140828-212146-16842879-45613-27625-0000' for gc 1.0000093467509weeks in the future
I0828 21:21:54.015985 27645 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_ShutdownSlave_umhraW/meta/slaves/20140828-212146-16842879-45613-27625-0/frameworks/20140828-212146-16842879-45613-27625-0000' for gc 1.0000093467509weeks in the future
I0828 21:21:54.016201 27645 status_update_manager.cpp:282] Closing status update streams for framework 20140828-212146-16842879-45613-27625-0000
2014-08-28 21:21:55,491:27625(0x2ad7b36ba700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:33940] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
2014-08-28 21:21:58,826:27625(0x2ad7b36ba700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:33940] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
2014-08-28 21:22:02,162:27625(0x2ad7b36ba700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:33940] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
tests/slave_recovery_tests.cpp:1747: Failure
Failed to wait 10secs for offers2
I0828 21:22:04.043253 27641 master.cpp:734] Framework 20140828-212146-16842879-45613-27625-0000 disconnected
I0828 21:22:04.043427 27641 master.cpp:1680] Deactivating framework 20140828-212146-16842879-45613-27625-0000
I0828 21:22:04.043665 27641 master.cpp:756] Giving framework 20140828-212146-16842879-45613-27625-0000 0ns to failover
I0828 21:22:04.044415 27644 master.cpp:3464] Framework failover timeout, removing framework 20140828-212146-16842879-45613-27625-0000
I0828 21:22:04.044675 27644 master.cpp:3960] Removing framework 20140828-212146-16842879-45613-27625-0000
I0828 21:22:04.045117 27644 slave.cpp:1415] Asked to shut down framework 20140828-212146-16842879-45613-27625-0000 by master@127.0.1.1:45613
W0828 21:22:04.045548 27644 slave.cpp:1430] Cannot shut down unknown framework 20140828-212146-16842879-45613-27625-0000
I0828 21:22:04.043968 27639 hierarchical_allocator_process.hpp:405] Deactivated framework 20140828-212146-16842879-45613-27625-0000
I0828 21:22:04.046103 27639 hierarchical_allocator_process.hpp:360] Removed framework 20140828-212146-16842879-45613-27625-0000
tests/slave_recovery_tests.cpp:1698: Failure
Actual function call count doesn't match EXPECT_CALL(sched, resourceOffers(_, _))...
Expected: to be called twice
Actual: called once - unsatisfied and active
I0828 21:22:04.051811 27644 master.cpp:643] Master terminating
I0828 21:22:04.056529 27640 slave.cpp:2365] master@127.0.1.1:45613 exited
W0828 21:22:04.056694 27640 slave.cpp:2368] Master disconnected! Waiting for a new master to be elected
I0828 21:22:04.079474 27625 slave.cpp:475] Slave terminating
[ FAILED ] SlaveRecoveryTest/0.ShutdownSlave, where TypeParam = mesos::internal::slave::MesosContainerizer (17900 ms)
Major