[
https://issues.apache.org/jira/browse/MESOS-1749?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14117718#comment-14117718
]
Jie Yu commented on MESOS-1749:
-------------------------------
https://reviews.apache.org/r/25207/
> SlaveRecoveryTest.ShutdownSlave is flaky
> ----------------------------------------
>
> Key: MESOS-1749
> URL: https://issues.apache.org/jira/browse/MESOS-1749
> Project: Mesos
> Issue Type: Bug
> Affects Versions: 0.20.0
> Environment: ubuntu-13.10-gcc
> Reporter: Jie Yu
> Assignee: Jie Yu
>
> {noformat}
> [ 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
> [email protected]: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 :
> [email protected]: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
> [email protected]:45613
> I0828 21:21:46.366041 27646 slave.cpp:672] Authenticating with master
> [email protected]: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 [email protected]: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 [email protected]: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
> [email protected]:45613
> I0828 21:21:46.376595 27646 sched.cpp:283] Authenticating with master
> [email protected]: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
> [email protected]: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 [email protected]:45613
> I0828 21:21:46.383031 27642 sched.cpp:476] Sending registration request to
> [email protected]:45613
> I0828 21:21:46.382928 27640 master.cpp:3677] Successfully authenticated
> principal 'test-principal' at
> [email protected]:45613
> I0828 21:21:46.383651 27640 master.cpp:1324] Received registration request
> from [email protected]: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
> [email protected]: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
> [email protected]: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
> '[email protected]: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 [email protected]: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 [email protected]: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 [email protected]: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] [email protected]: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)
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
