You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "Benjamin Mahler (JIRA)" <ji...@apache.org> on 2015/01/28 04:07:34 UTC
[jira] [Commented] (MESOS-2283) SlaveRecoveryTest.ReconcileKillTask
is flaky.
[ https://issues.apache.org/jira/browse/MESOS-2283?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14294641#comment-14294641 ]
Benjamin Mahler commented on MESOS-2283:
----------------------------------------
https://reviews.apache.org/r/30352/
https://reviews.apache.org/r/30353/
> SlaveRecoveryTest.ReconcileKillTask is flaky.
> ---------------------------------------------
>
> Key: MESOS-2283
> URL: https://issues.apache.org/jira/browse/MESOS-2283
> Project: Mesos
> Issue Type: Bug
> Components: test
> Reporter: Benjamin Mahler
> Assignee: Benjamin Mahler
> Labels: flaky-test, twitter
>
> Saw this on an internal CI:
> {noformat}
> [ RUN ] SlaveRecoveryTest/0.ReconcileKillTask
> Using temporary directory '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_D5wSwg'
> I0126 19:10:52.005317 13291 leveldb.cpp:176] Opened db in 978670ns
> I0126 19:10:52.006155 13291 leveldb.cpp:183] Compacted db in 541346ns
> I0126 19:10:52.006494 13291 leveldb.cpp:198] Created db iterator in 24562ns
> I0126 19:10:52.006798 13291 leveldb.cpp:204] Seeked to beginning of db in 3254ns
> I0126 19:10:52.007036 13291 leveldb.cpp:273] Iterated through 0 keys in the db in 949ns
> I0126 19:10:52.007369 13291 replica.cpp:744] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> I0126 19:10:52.008362 13308 recover.cpp:449] Starting replica recovery
> I0126 19:10:52.009141 13308 recover.cpp:475] Replica is in EMPTY status
> I0126 19:10:52.016494 13308 replica.cpp:641] Replica in EMPTY status received a broadcasted recover request
> I0126 19:10:52.017333 13309 recover.cpp:195] Received a recover response from a replica in EMPTY status
> I0126 19:10:52.018244 13309 recover.cpp:566] Updating replica status to STARTING
> I0126 19:10:52.019064 13305 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 113577ns
> I0126 19:10:52.019487 13305 replica.cpp:323] Persisted replica status to STARTING
> I0126 19:10:52.019937 13309 recover.cpp:475] Replica is in STARTING status
> I0126 19:10:52.021492 13307 replica.cpp:641] Replica in STARTING status received a broadcasted recover request
> I0126 19:10:52.022665 13309 recover.cpp:195] Received a recover response from a replica in STARTING status
> I0126 19:10:52.027971 13312 recover.cpp:566] Updating replica status to VOTING
> I0126 19:10:52.028590 13312 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 78452ns
> I0126 19:10:52.028869 13312 replica.cpp:323] Persisted replica status to VOTING
> I0126 19:10:52.029252 13312 recover.cpp:580] Successfully joined the Paxos group
> I0126 19:10:52.030828 13307 recover.cpp:464] Recover process terminated
> I0126 19:10:52.049947 13306 master.cpp:262] Master 20150126-191052-2272962752-35545-13291 (fedora-19) started on 192.168.122.135:35545
> I0126 19:10:52.050499 13306 master.cpp:308] Master only allowing authenticated frameworks to register
> I0126 19:10:52.050765 13306 master.cpp:313] Master only allowing authenticated slaves to register
> I0126 19:10:52.051048 13306 credentials.hpp:36] Loading credentials for authentication from '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_D5wSwg/credentials'
> I0126 19:10:52.051589 13306 master.cpp:357] Authorization enabled
> I0126 19:10:52.052531 13305 hierarchical_allocator_process.hpp:285] Initialized hierarchical allocator process
> I0126 19:10:52.052881 13311 whitelist_watcher.cpp:65] No whitelist given
> I0126 19:10:52.055524 13306 master.cpp:1219] The newly elected leader is master@192.168.122.135:35545 with id 20150126-191052-2272962752-35545-13291
> I0126 19:10:52.056226 13306 master.cpp:1232] Elected as the leading master!
> I0126 19:10:52.056639 13306 master.cpp:1050] Recovering from registrar
> I0126 19:10:52.057045 13307 registrar.cpp:313] Recovering registrar
> I0126 19:10:52.058554 13312 log.cpp:660] Attempting to start the writer
> I0126 19:10:52.060868 13309 replica.cpp:477] Replica received implicit promise request with proposal 1
> I0126 19:10:52.061691 13309 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 91680ns
> I0126 19:10:52.062261 13309 replica.cpp:345] Persisted promised to 1
> I0126 19:10:52.064559 13310 coordinator.cpp:230] Coordinator attemping to fill missing position
> I0126 19:10:52.069105 13311 replica.cpp:378] Replica received explicit promise request for position 0 with proposal 2
> I0126 19:10:52.069860 13311 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 94858ns
> I0126 19:10:52.070350 13311 replica.cpp:679] Persisted action at 0
> I0126 19:10:52.080348 13305 replica.cpp:511] Replica received write request for position 0
> I0126 19:10:52.081153 13305 leveldb.cpp:438] Reading position from leveldb took 62247ns
> I0126 19:10:52.081676 13305 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 81487ns
> I0126 19:10:52.082053 13305 replica.cpp:679] Persisted action at 0
> I0126 19:10:52.083566 13309 replica.cpp:658] Replica received learned notice for position 0
> I0126 19:10:52.085734 13309 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 283144ns
> I0126 19:10:52.086067 13309 replica.cpp:679] Persisted action at 0
> I0126 19:10:52.086448 13309 replica.cpp:664] Replica learned NOP action at position 0
> I0126 19:10:52.089784 13306 log.cpp:676] Writer started with ending position 0
> I0126 19:10:52.093415 13309 leveldb.cpp:438] Reading position from leveldb took 66744ns
> I0126 19:10:52.104814 13306 registrar.cpp:346] Successfully fetched the registry (0B) in 47.451136ms
> I0126 19:10:52.105731 13306 registrar.cpp:445] Applied 1 operations in 42124ns; attempting to update the 'registry'
> I0126 19:10:52.111935 13305 log.cpp:684] Attempting to append 131 bytes to the log
> I0126 19:10:52.112754 13305 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
> I0126 19:10:52.114297 13308 replica.cpp:511] Replica received write request for position 1
> I0126 19:10:52.114908 13308 leveldb.cpp:343] Persisting action (150 bytes) to leveldb took 98332ns
> I0126 19:10:52.115387 13308 replica.cpp:679] Persisted action at 1
> I0126 19:10:52.117277 13305 replica.cpp:658] Replica received learned notice for position 1
> I0126 19:10:52.118142 13305 leveldb.cpp:343] Persisting action (152 bytes) to leveldb took 227799ns
> I0126 19:10:52.118621 13305 replica.cpp:679] Persisted action at 1
> I0126 19:10:52.118979 13305 replica.cpp:664] Replica learned APPEND action at position 1
> I0126 19:10:52.121311 13305 registrar.cpp:490] Successfully updated the 'registry' in 15.161088ms
> I0126 19:10:52.121548 13311 log.cpp:703] Attempting to truncate the log to 1
> I0126 19:10:52.122697 13311 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
> I0126 19:10:52.124316 13307 replica.cpp:511] Replica received write request for position 2
> I0126 19:10:52.124913 13307 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 87281ns
> I0126 19:10:52.125334 13307 replica.cpp:679] Persisted action at 2
> I0126 19:10:52.127018 13311 replica.cpp:658] Replica received learned notice for position 2
> I0126 19:10:52.127835 13311 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 201050ns
> I0126 19:10:52.128232 13311 leveldb.cpp:401] Deleting ~1 keys from leveldb took 78012ns
> I0126 19:10:52.128835 13305 registrar.cpp:376] Successfully recovered registrar
> I0126 19:10:52.128551 13311 replica.cpp:679] Persisted action at 2
> I0126 19:10:52.130105 13311 replica.cpp:664] Replica learned TRUNCATE action at position 2
> I0126 19:10:52.131479 13312 master.cpp:1077] Recovered 0 slaves from the Registry (95B) ; allowing 10mins for slaves to re-register
> I0126 19:10:52.143465 13291 containerizer.cpp:103] Using isolation: posix/cpu,posix/mem
> I0126 19:10:52.170471 13309 slave.cpp:173] Slave started on 101)@192.168.122.135:35545
> I0126 19:10:52.171723 13309 credentials.hpp:84] Loading credential for authentication from '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_qbguuM/credential'
> I0126 19:10:52.172286 13309 slave.cpp:282] Slave using credential for: test-principal
> I0126 19:10:52.172821 13309 slave.cpp:300] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0126 19:10:52.173982 13309 slave.cpp:329] Slave hostname: fedora-19
> I0126 19:10:52.174505 13309 slave.cpp:330] Slave checkpoint: true
> I0126 19:10:52.179308 13309 state.cpp:33] Recovering state from '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_qbguuM/meta'
> I0126 19:10:52.180075 13308 status_update_manager.cpp:197] Recovering status update manager
> I0126 19:10:52.180611 13308 containerizer.cpp:300] Recovering containerizer
> I0126 19:10:52.182473 13309 slave.cpp:3519] Finished recovery
> I0126 19:10:52.184403 13312 slave.cpp:613] New master detected at master@192.168.122.135:35545
> I0126 19:10:52.184916 13312 slave.cpp:676] Authenticating with master master@192.168.122.135:35545
> I0126 19:10:52.185230 13312 slave.cpp:681] Using default CRAM-MD5 authenticatee
> I0126 19:10:52.185715 13312 slave.cpp:649] Detecting new master
> I0126 19:10:52.186420 13312 authenticatee.hpp:138] Creating new client SASL connection
> I0126 19:10:52.186002 13311 status_update_manager.cpp:171] Pausing sending status updates
> I0126 19:10:52.188293 13312 master.cpp:4129] Authenticating slave(101)@192.168.122.135:35545
> I0126 19:10:52.188748 13312 master.cpp:4140] Using default CRAM-MD5 authenticator
> I0126 19:10:52.189525 13312 authenticator.hpp:170] Creating new server SASL connection
> I0126 19:10:52.191082 13305 authenticatee.hpp:229] Received SASL authentication mechanisms: CRAM-MD5
> I0126 19:10:52.191550 13305 authenticatee.hpp:255] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0126 19:10:52.191990 13312 authenticator.hpp:276] Received SASL authentication start
> I0126 19:10:52.192365 13312 authenticator.hpp:398] Authentication requires more steps
> I0126 19:10:52.192800 13311 authenticatee.hpp:275] Received SASL authentication step
> I0126 19:10:52.193244 13312 authenticator.hpp:304] Received SASL authentication step
> I0126 19:10:52.193565 13312 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'fedora-19' server FQDN: 'fedora-19' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0126 19:10:52.193902 13312 auxprop.cpp:171] Looking up auxiliary property '*userPassword'
> I0126 19:10:52.194301 13312 auxprop.cpp:171] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0126 19:10:52.195669 13312 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'fedora-19' server FQDN: 'fedora-19' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0126 19:10:52.196048 13312 auxprop.cpp:121] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0126 19:10:52.196395 13312 auxprop.cpp:121] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0126 19:10:52.196723 13312 authenticator.hpp:390] Authentication success
> I0126 19:10:52.197206 13305 authenticatee.hpp:315] Authentication success
> I0126 19:10:52.204121 13305 slave.cpp:747] Successfully authenticated with master master@192.168.122.135:35545
> I0126 19:10:52.204676 13310 master.cpp:4187] Successfully authenticated principal 'test-principal' at slave(101)@192.168.122.135:35545
> I0126 19:10:52.205729 13305 slave.cpp:1075] Will retry registration in 5.608661ms if necessary
> I0126 19:10:52.206451 13310 master.cpp:3275] Registering slave at slave(101)@192.168.122.135:35545 (fedora-19) with id 20150126-191052-2272962752-35545-13291-S0
> I0126 19:10:52.210019 13310 registrar.cpp:445] Applied 1 operations in 235087ns; attempting to update the 'registry'
> I0126 19:10:52.220736 13308 slave.cpp:1075] Will retry registration in 9.28397ms if necessary
> I0126 19:10:52.221309 13311 master.cpp:3263] Ignoring register slave message from slave(101)@192.168.122.135:35545 (fedora-19) as admission is already in progress
> I0126 19:10:52.224818 13307 log.cpp:684] Attempting to append 302 bytes to the log
> I0126 19:10:52.225554 13307 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
> I0126 19:10:52.227422 13305 replica.cpp:511] Replica received write request for position 3
> I0126 19:10:52.227969 13305 leveldb.cpp:343] Persisting action (321 bytes) to leveldb took 100350ns
> I0126 19:10:52.228276 13305 replica.cpp:679] Persisted action at 3
> I0126 19:10:52.232475 13312 replica.cpp:658] Replica received learned notice for position 3
> I0126 19:10:52.233280 13312 leveldb.cpp:343] Persisting action (323 bytes) to leveldb took 546567ns
> I0126 19:10:52.233726 13312 replica.cpp:679] Persisted action at 3
> I0126 19:10:52.234035 13312 replica.cpp:664] Replica learned APPEND action at position 3
> I0126 19:10:52.236556 13310 registrar.cpp:490] Successfully updated the 'registry' in 26.040064ms
> I0126 19:10:52.237330 13305 log.cpp:703] Attempting to truncate the log to 3
> I0126 19:10:52.238056 13311 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
> I0126 19:10:52.239594 13311 replica.cpp:511] Replica received write request for position 4
> I0126 19:10:52.240129 13311 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 92868ns
> I0126 19:10:52.240458 13311 replica.cpp:679] Persisted action at 4
> I0126 19:10:52.241976 13308 replica.cpp:658] Replica received learned notice for position 4
> I0126 19:10:52.242645 13308 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 95635ns
> I0126 19:10:52.242990 13308 leveldb.cpp:401] Deleting ~2 keys from leveldb took 58066ns
> I0126 19:10:52.243337 13308 replica.cpp:679] Persisted action at 4
> I0126 19:10:52.243695 13308 replica.cpp:664] Replica learned TRUNCATE action at position 4
> I0126 19:10:52.245657 13291 sched.cpp:151] Version: 0.22.0
> I0126 19:10:52.247625 13305 master.cpp:3329] Registered slave 20150126-191052-2272962752-35545-13291-S0 at slave(101)@192.168.122.135:35545 (fedora-19) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0126 19:10:52.248942 13307 slave.cpp:781] Registered with master master@192.168.122.135:35545; given slave ID 20150126-191052-2272962752-35545-13291-S0
> I0126 19:10:52.250396 13307 slave.cpp:797] Checkpointing SlaveInfo to '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_qbguuM/meta/slaves/20150126-191052-2272962752-35545-13291-S0/slave.info'
> I0126 19:10:52.250731 13309 status_update_manager.cpp:178] Resuming sending status updates
> I0126 19:10:52.251765 13307 slave.cpp:2588] Received ping from slave-observer(99)@192.168.122.135:35545
> I0126 19:10:52.247951 13310 hierarchical_allocator_process.hpp:453] Added slave 20150126-191052-2272962752-35545-13291-S0 (fedora-19) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
> I0126 19:10:52.252810 13310 hierarchical_allocator_process.hpp:831] No resources available to allocate!
> I0126 19:10:52.254365 13310 hierarchical_allocator_process.hpp:756] Performed allocation for slave 20150126-191052-2272962752-35545-13291-S0 in 1.732701ms
> I0126 19:10:52.254137 13307 sched.cpp:248] New master detected at master@192.168.122.135:35545
> I0126 19:10:52.257863 13307 sched.cpp:304] Authenticating with master master@192.168.122.135:35545
> I0126 19:10:52.258249 13307 sched.cpp:311] Using default CRAM-MD5 authenticatee
> I0126 19:10:52.258908 13306 authenticatee.hpp:138] Creating new client SASL connection
> I0126 19:10:52.261397 13309 master.cpp:4129] Authenticating scheduler-6da85b48-b57f-4202-b630-c45f8f652321@192.168.122.135:35545
> I0126 19:10:52.261776 13309 master.cpp:4140] Using default CRAM-MD5 authenticator
> I0126 19:10:52.264528 13309 authenticator.hpp:170] Creating new server SASL connection
> I0126 19:10:52.266248 13312 authenticatee.hpp:229] Received SASL authentication mechanisms: CRAM-MD5
> I0126 19:10:52.266749 13312 authenticatee.hpp:255] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0126 19:10:52.267143 13312 authenticator.hpp:276] Received SASL authentication start
> I0126 19:10:52.267525 13312 authenticator.hpp:398] Authentication requires more steps
> I0126 19:10:52.267917 13312 authenticatee.hpp:275] Received SASL authentication step
> I0126 19:10:52.268404 13312 authenticator.hpp:304] Received SASL authentication step
> I0126 19:10:52.268725 13312 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'fedora-19' server FQDN: 'fedora-19' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0126 19:10:52.269078 13312 auxprop.cpp:171] Looking up auxiliary property '*userPassword'
> I0126 19:10:52.269498 13312 auxprop.cpp:171] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0126 19:10:52.269881 13312 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'fedora-19' server FQDN: 'fedora-19' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0126 19:10:52.270385 13312 auxprop.cpp:121] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0126 19:10:52.271015 13312 auxprop.cpp:121] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0126 19:10:52.271599 13312 authenticator.hpp:390] Authentication success
> I0126 19:10:52.272126 13312 authenticatee.hpp:315] Authentication success
> I0126 19:10:52.272415 13305 master.cpp:4187] Successfully authenticated principal 'test-principal' at scheduler-6da85b48-b57f-4202-b630-c45f8f652321@192.168.122.135:35545
> I0126 19:10:52.273998 13307 sched.cpp:392] Successfully authenticated with master master@192.168.122.135:35545
> I0126 19:10:52.274415 13307 sched.cpp:515] Sending registration request to master@192.168.122.135:35545
> I0126 19:10:52.274842 13307 sched.cpp:548] Will retry registration in 674.656506ms if necessary
> I0126 19:10:52.275235 13305 master.cpp:1420] Received registration request for framework 'default' at scheduler-6da85b48-b57f-4202-b630-c45f8f652321@192.168.122.135:35545
> I0126 19:10:52.276017 13305 master.cpp:1298] Authorizing framework principal 'test-principal' to receive offers for role '*'
> I0126 19:10:52.277027 13305 master.cpp:1484] Registering framework 20150126-191052-2272962752-35545-13291-0000 (default) at scheduler-6da85b48-b57f-4202-b630-c45f8f652321@192.168.122.135:35545
> I0126 19:10:52.278285 13308 hierarchical_allocator_process.hpp:319] Added framework 20150126-191052-2272962752-35545-13291-0000
> I0126 19:10:52.279575 13308 hierarchical_allocator_process.hpp:738] Performed allocation for 1 slaves in 697902ns
> I0126 19:10:52.287966 13305 master.cpp:4071] Sending 1 offers to framework 20150126-191052-2272962752-35545-13291-0000 (default) at scheduler-6da85b48-b57f-4202-b630-c45f8f652321@192.168.122.135:35545
> I0126 19:10:52.288776 13307 sched.cpp:442] Framework registered with 20150126-191052-2272962752-35545-13291-0000
> I0126 19:10:52.289373 13307 sched.cpp:456] Scheduler::registered took 21674ns
> I0126 19:10:52.289932 13307 sched.cpp:605] Scheduler::resourceOffers took 76147ns
> I0126 19:10:52.293220 13311 master.cpp:2677] Processing ACCEPT call for offers: [ 20150126-191052-2272962752-35545-13291-O0 ] on slave 20150126-191052-2272962752-35545-13291-S0 at slave(101)@192.168.122.135:35545 (fedora-19) for framework 20150126-191052-2272962752-35545-13291-0000 (default) at scheduler-6da85b48-b57f-4202-b630-c45f8f652321@192.168.122.135:35545
> I0126 19:10:52.293586 13311 master.cpp:2513] Authorizing framework principal 'test-principal' to launch task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e as user 'jenkins'
> I0126 19:10:52.295825 13311 master.hpp:782] Adding task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20150126-191052-2272962752-35545-13291-S0 (fedora-19)
> I0126 19:10:52.296272 13311 master.cpp:2885] Launching task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework 20150126-191052-2272962752-35545-13291-0000 (default) at scheduler-6da85b48-b57f-4202-b630-c45f8f652321@192.168.122.135:35545 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20150126-191052-2272962752-35545-13291-S0 at slave(101)@192.168.122.135:35545 (fedora-19)
> I0126 19:10:52.296886 13309 slave.cpp:1130] Got assigned task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e for framework 20150126-191052-2272962752-35545-13291-0000
> I0126 19:10:52.297324 13309 slave.cpp:3846] Checkpointing FrameworkInfo to '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_qbguuM/meta/slaves/20150126-191052-2272962752-35545-13291-S0/frameworks/20150126-191052-2272962752-35545-13291-0000/framework.info'
> I0126 19:10:52.297919 13309 slave.cpp:3853] Checkpointing framework pid 'scheduler-6da85b48-b57f-4202-b630-c45f8f652321@192.168.122.135:35545' to '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_qbguuM/meta/slaves/20150126-191052-2272962752-35545-13291-S0/frameworks/20150126-191052-2272962752-35545-13291-0000/framework.pid'
> I0126 19:10:52.299072 13309 slave.cpp:1245] Launching task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e for framework 20150126-191052-2272962752-35545-13291-0000
> I0126 19:10:52.308050 13309 slave.cpp:4289] Checkpointing ExecutorInfo to '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_qbguuM/meta/slaves/20150126-191052-2272962752-35545-13291-S0/frameworks/20150126-191052-2272962752-35545-13291-0000/executors/61eaeec3-e8ca-4e15-82d6-284c05c3bb6e/executor.info'
> I0126 19:10:52.310894 13309 slave.cpp:3921] Launching executor 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework 20150126-191052-2272962752-35545-13291-0000 in work directory '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_qbguuM/slaves/20150126-191052-2272962752-35545-13291-S0/frameworks/20150126-191052-2272962752-35545-13291-0000/executors/61eaeec3-e8ca-4e15-82d6-284c05c3bb6e/runs/960eca2c-9e2c-415a-b6a5-159efca1f1b0'
> I0126 19:10:52.311957 13308 containerizer.cpp:445] Starting container '960eca2c-9e2c-415a-b6a5-159efca1f1b0' for executor '61eaeec3-e8ca-4e15-82d6-284c05c3bb6e' of framework '20150126-191052-2272962752-35545-13291-0000'
> W0126 19:10:52.313951 13307 containerizer.cpp:296] CommandInfo.grace_period flag is not set, using default value: 3secs
> I0126 19:10:52.330166 13309 slave.cpp:4312] Checkpointing TaskInfo to '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_qbguuM/meta/slaves/20150126-191052-2272962752-35545-13291-S0/frameworks/20150126-191052-2272962752-35545-13291-0000/executors/61eaeec3-e8ca-4e15-82d6-284c05c3bb6e/runs/960eca2c-9e2c-415a-b6a5-159efca1f1b0/tasks/61eaeec3-e8ca-4e15-82d6-284c05c3bb6e/task.info'
> I0126 19:10:52.333307 13309 slave.cpp:1368] Queuing task '61eaeec3-e8ca-4e15-82d6-284c05c3bb6e' for executor 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework '20150126-191052-2272962752-35545-13291-0000
> I0126 19:10:52.332506 13307 launcher.cpp:137] Forked child with pid '15795' for container '960eca2c-9e2c-415a-b6a5-159efca1f1b0'
> I0126 19:10:52.334852 13307 containerizer.cpp:655] Checkpointing executor's forked pid 15795 to '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_qbguuM/meta/slaves/20150126-191052-2272962752-35545-13291-S0/frameworks/20150126-191052-2272962752-35545-13291-0000/executors/61eaeec3-e8ca-4e15-82d6-284c05c3bb6e/runs/960eca2c-9e2c-415a-b6a5-159efca1f1b0/pids/forked.pid'
> I0126 19:10:52.339607 13309 slave.cpp:566] Successfully attached file '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_qbguuM/slaves/20150126-191052-2272962752-35545-13291-S0/frameworks/20150126-191052-2272962752-35545-13291-0000/executors/61eaeec3-e8ca-4e15-82d6-284c05c3bb6e/runs/960eca2c-9e2c-415a-b6a5-159efca1f1b0'
> I0126 19:10:52.341423 13309 slave.cpp:2890] Monitoring executor '61eaeec3-e8ca-4e15-82d6-284c05c3bb6e' of framework '20150126-191052-2272962752-35545-13291-0000' in container '960eca2c-9e2c-415a-b6a5-159efca1f1b0'
> WARNING: Logging before InitGoogleLogging() is written to STDERR
> I0126 19:10:52.584766 15795 process.cpp:958] libprocess is initialized on 192.168.122.135:41245 for 8 cpus
> I0126 19:10:52.597306 15795 logging.cpp:177] Logging to STDERR
> I0126 19:10:52.606741 15795 exec.cpp:147] Version: 0.22.0
> I0126 19:10:52.617653 15825 exec.cpp:197] Executor started at: executor(1)@192.168.122.135:41245 with pid 15795
> I0126 19:10:52.643771 13309 slave.cpp:1912] Got registration for executor '61eaeec3-e8ca-4e15-82d6-284c05c3bb6e' of framework 20150126-191052-2272962752-35545-13291-0000 from executor(1)@192.168.122.135:41245
> I0126 19:10:52.644484 13309 slave.cpp:1998] Checkpointing executor pid 'executor(1)@192.168.122.135:41245' to '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_qbguuM/meta/slaves/20150126-191052-2272962752-35545-13291-S0/frameworks/20150126-191052-2272962752-35545-13291-0000/executors/61eaeec3-e8ca-4e15-82d6-284c05c3bb6e/runs/960eca2c-9e2c-415a-b6a5-159efca1f1b0/pids/libprocess.pid'
> I0126 19:10:52.648509 13309 slave.cpp:2031] Flushing queued task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e for executor '61eaeec3-e8ca-4e15-82d6-284c05c3bb6e' of framework 20150126-191052-2272962752-35545-13291-0000
> I0126 19:10:52.701879 15830 exec.cpp:221] Executor registered on slave 20150126-191052-2272962752-35545-13291-S0
> Shutdown timeout is set to 3secsRegistered executor on fedora-19
> I0126 19:10:52.706497 15830 exec.cpp:233] Executor::registered took 2.369798ms
> I0126 19:10:52.710708 15830 exec.cpp:308] Executor asked to run task '61eaeec3-e8ca-4e15-82d6-284c05c3bb6e'
> Starting task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e
> I0126 19:10:52.713075 15830 exec.cpp:317] Executor::launchTask took 1.248631ms
> sh -c 'sleep 1000'
> Forked command at 15832
> I0126 19:10:52.720675 15824 exec.cpp:540] Executor sending status update TASK_RUNNING (UUID: 9577ef79-7e59-4be6-a892-5a20baa13647) for task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework 20150126-191052-2272962752-35545-13291-0000
> I0126 19:10:52.722925 13308 slave.cpp:2265] Handling status update TASK_RUNNING (UUID: 9577ef79-7e59-4be6-a892-5a20baa13647) for task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework 20150126-191052-2272962752-35545-13291-0000 from executor(1)@192.168.122.135:41245
> I0126 19:10:52.723328 13308 status_update_manager.cpp:317] Received status update TASK_RUNNING (UUID: 9577ef79-7e59-4be6-a892-5a20baa13647) for task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework 20150126-191052-2272962752-35545-13291-0000
> I0126 19:10:52.723371 13308 status_update_manager.cpp:494] Creating StatusUpdate stream for task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework 20150126-191052-2272962752-35545-13291-0000
> I0126 19:10:52.723803 13308 status_update_manager.hpp:346] Checkpointing UPDATE for status update TASK_RUNNING (UUID: 9577ef79-7e59-4be6-a892-5a20baa13647) for task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework 20150126-191052-2272962752-35545-13291-0000
> I0126 19:10:52.723963 13308 status_update_manager.cpp:371] Forwarding update TASK_RUNNING (UUID: 9577ef79-7e59-4be6-a892-5a20baa13647) for task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework 20150126-191052-2272962752-35545-13291-0000 to the slave
> I0126 19:10:52.724717 13312 slave.cpp:2508] Forwarding the update TASK_RUNNING (UUID: 9577ef79-7e59-4be6-a892-5a20baa13647) for task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework 20150126-191052-2272962752-35545-13291-0000 to master@192.168.122.135:35545
> I0126 19:10:52.725385 13305 master.cpp:3652] Forwarding status update TASK_RUNNING (UUID: 9577ef79-7e59-4be6-a892-5a20baa13647) for task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework 20150126-191052-2272962752-35545-13291-0000
> I0126 19:10:52.725857 13305 master.cpp:3624] Status update TASK_RUNNING (UUID: 9577ef79-7e59-4be6-a892-5a20baa13647) for task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework 20150126-191052-2272962752-35545-13291-0000 from slave 20150126-191052-2272962752-35545-13291-S0 at slave(101)@192.168.122.135:35545 (fedora-19)
> I0126 19:10:52.726471 13305 master.cpp:4934] Updating the latest state of task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework 20150126-191052-2272962752-35545-13291-0000 to TASK_RUNNING
> I0126 19:10:52.726269 13311 sched.cpp:696] Scheduler::statusUpdate took 22534ns
> I0126 19:10:52.727679 13311 master.cpp:3125] Forwarding status update acknowledgement 9577ef79-7e59-4be6-a892-5a20baa13647 for task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework 20150126-191052-2272962752-35545-13291-0000 (default) at scheduler-6da85b48-b57f-4202-b630-c45f8f652321@192.168.122.135:35545 to slave 20150126-191052-2272962752-35545-13291-S0 at slave(101)@192.168.122.135:35545 (fedora-19)
> I0126 19:10:52.728380 13308 status_update_manager.cpp:389] Received status update acknowledgement (UUID: 9577ef79-7e59-4be6-a892-5a20baa13647) for task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework 20150126-191052-2272962752-35545-13291-0000
> I0126 19:10:52.728579 13311 slave.cpp:2435] Status update manager successfully handled status update TASK_RUNNING (UUID: 9577ef79-7e59-4be6-a892-5a20baa13647) for task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework 20150126-191052-2272962752-35545-13291-0000
> I0126 19:10:52.729403 13311 slave.cpp:2441] Sending acknowledgement for status update TASK_RUNNING (UUID: 9577ef79-7e59-4be6-a892-5a20baa13647) for task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework 20150126-191052-2272962752-35545-13291-0000 to executor(1)@192.168.122.135:41245
> I0126 19:10:52.728869 13308 status_update_manager.hpp:346] Checkpointing ACK for status update TASK_RUNNING (UUID: 9577ef79-7e59-4be6-a892-5a20baa13647) for task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework 20150126-191052-2272962752-35545-13291-0000
> I0126 19:10:52.731828 13307 slave.cpp:1852] Status update manager successfully handled status update acknowledgement (UUID: 9577ef79-7e59-4be6-a892-5a20baa13647) for task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework 20150126-191052-2272962752-35545-13291-0000
> I0126 19:10:52.732923 13307 slave.cpp:495] Slave terminating
> I0126 19:10:52.739572 15827 exec.cpp:354] Executor received status update acknowledgement 9577ef79-7e59-4be6-a892-5a20baa13647 for task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework 20150126-191052-2272962752-35545-13291-0000
> I0126 19:10:52.743466 13306 master.cpp:795] Slave 20150126-191052-2272962752-35545-13291-S0 at slave(101)@192.168.122.135:35545 (fedora-19) disconnected
> I0126 19:10:52.743948 13306 master.cpp:1826] Disconnecting slave 20150126-191052-2272962752-35545-13291-S0 at slave(101)@192.168.122.135:35545 (fedora-19)
> I0126 19:10:52.744940 13306 master.cpp:1845] Deactivating slave 20150126-191052-2272962752-35545-13291-S0 at slave(101)@192.168.122.135:35545 (fedora-19)
> I0126 19:10:52.752821 13306 hierarchical_allocator_process.hpp:512] Slave 20150126-191052-2272962752-35545-13291-S0 deactivated
> I0126 19:10:52.765900 13291 containerizer.cpp:103] Using isolation: posix/cpu,posix/mem
> I0126 19:10:52.766723 13309 master.cpp:2961] Asked to kill task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework 20150126-191052-2272962752-35545-13291-0000
> W0126 19:10:52.767549 13309 master.cpp:3030] Cannot kill task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework 20150126-191052-2272962752-35545-13291-0000 (default) at scheduler-6da85b48-b57f-4202-b630-c45f8f652321@192.168.122.135:35545 because the slave 20150126-191052-2272962752-35545-13291-S0 at slave(101)@192.168.122.135:35545 (fedora-19) is disconnected. Kill will be retried if the slave re-registers
> I0126 19:10:52.789048 13307 slave.cpp:173] Slave started on 102)@192.168.122.135:35545
> I0126 19:10:52.790671 13307 credentials.hpp:84] Loading credential for authentication from '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_qbguuM/credential'
> I0126 19:10:52.791497 13307 slave.cpp:282] Slave using credential for: test-principal
> I0126 19:10:52.792064 13307 slave.cpp:300] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0126 19:10:52.793090 13307 slave.cpp:329] Slave hostname: fedora-19
> I0126 19:10:52.793556 13307 slave.cpp:330] Slave checkpoint: true
> I0126 19:10:52.795727 13311 state.cpp:33] Recovering state from '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_qbguuM/meta'
> I0126 19:10:52.796282 13311 state.cpp:668] Failed to find resources file '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_qbguuM/meta/resources/resources.info'
> I0126 19:10:52.804524 13309 slave.cpp:3601] Recovering framework 20150126-191052-2272962752-35545-13291-0000
> I0126 19:10:52.805106 13309 slave.cpp:4040] Recovering executor '61eaeec3-e8ca-4e15-82d6-284c05c3bb6e' of framework 20150126-191052-2272962752-35545-13291-0000
> I0126 19:10:52.807494 13309 slave.cpp:566] Successfully attached file '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_qbguuM/slaves/20150126-191052-2272962752-35545-13291-S0/frameworks/20150126-191052-2272962752-35545-13291-0000/executors/61eaeec3-e8ca-4e15-82d6-284c05c3bb6e/runs/960eca2c-9e2c-415a-b6a5-159efca1f1b0'
> I0126 19:10:52.807888 13310 status_update_manager.cpp:197] Recovering status update manager
> I0126 19:10:52.808390 13310 status_update_manager.cpp:205] Recovering executor '61eaeec3-e8ca-4e15-82d6-284c05c3bb6e' of framework 20150126-191052-2272962752-35545-13291-0000
> I0126 19:10:52.808830 13310 status_update_manager.cpp:494] Creating StatusUpdate stream for task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework 20150126-191052-2272962752-35545-13291-0000
> I0126 19:10:52.809484 13310 status_update_manager.hpp:310] Replaying status update stream for task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e
> I0126 19:10:52.810966 13308 containerizer.cpp:300] Recovering containerizer
> I0126 19:10:52.811550 13308 containerizer.cpp:342] Recovering container '960eca2c-9e2c-415a-b6a5-159efca1f1b0' for executor '61eaeec3-e8ca-4e15-82d6-284c05c3bb6e' of framework 20150126-191052-2272962752-35545-13291-0000
> I0126 19:10:52.816074 13305 slave.cpp:3460] Sending reconnect request to executor 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework 20150126-191052-2272962752-35545-13291-0000 at executor(1)@192.168.122.135:41245
> I0126 19:10:52.929554 15827 exec.cpp:267] Received reconnect request from slave 20150126-191052-2272962752-35545-13291-S0
> I0126 19:10:52.946156 13305 slave.cpp:2089] Re-registering executor 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework 20150126-191052-2272962752-35545-13291-0000
> I0126 19:10:53.010731 15829 exec.cpp:244] Executor re-registered on slave 20150126-191052-2272962752-35545-13291-S0
> Re-registered executor on fedora-19
> I0126 19:10:53.012980 15829 exec.cpp:256] Executor::reregistered took 313096ns
> I0126 19:10:53.054590 13309 hierarchical_allocator_process.hpp:831] No resources available to allocate!
> I0126 19:10:53.054930 13309 hierarchical_allocator_process.hpp:738] Performed allocation for 1 slaves in 388184ns
> I0126 19:10:54.055598 13312 hierarchical_allocator_process.hpp:831] No resources available to allocate!
> I0126 19:10:54.058614 13312 hierarchical_allocator_process.hpp:738] Performed allocation for 1 slaves in 3.086403ms
> I0126 19:10:54.818248 13310 slave.cpp:2214] Cleaning up un-reregistered executors
> I0126 19:10:54.821072 13310 slave.cpp:3519] Finished recovery
> I0126 19:10:54.823081 13312 status_update_manager.cpp:171] Pausing sending status updates
> I0126 19:10:54.823719 13310 slave.cpp:613] New master detected at master@192.168.122.135:35545
> I0126 19:10:54.824260 13310 slave.cpp:676] Authenticating with master master@192.168.122.135:35545
> I0126 19:10:54.824583 13310 slave.cpp:681] Using default CRAM-MD5 authenticatee
> I0126 19:10:54.825479 13307 authenticatee.hpp:138] Creating new client SASL connection
> I0126 19:10:54.826686 13310 slave.cpp:649] Detecting new master
> I0126 19:10:54.827214 13307 master.cpp:4129] Authenticating slave(102)@192.168.122.135:35545
> I0126 19:10:54.827747 13307 master.cpp:4140] Using default CRAM-MD5 authenticator
> I0126 19:10:54.828635 13307 authenticator.hpp:170] Creating new server SASL connection
> I0126 19:10:54.830049 13306 authenticatee.hpp:229] Received SASL authentication mechanisms: CRAM-MD5
> I0126 19:10:54.830447 13306 authenticatee.hpp:255] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0126 19:10:54.830934 13307 authenticator.hpp:276] Received SASL authentication start
> I0126 19:10:54.831362 13307 authenticator.hpp:398] Authentication requires more steps
> I0126 19:10:54.831837 13309 authenticatee.hpp:275] Received SASL authentication step
> I0126 19:10:54.832283 13307 authenticator.hpp:304] Received SASL authentication step
> I0126 19:10:54.832615 13307 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'fedora-19' server FQDN: 'fedora-19' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0126 19:10:54.833143 13307 auxprop.cpp:171] Looking up auxiliary property '*userPassword'
> I0126 19:10:54.833549 13307 auxprop.cpp:171] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0126 19:10:54.833904 13307 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'fedora-19' server FQDN: 'fedora-19' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0126 19:10:54.834241 13307 auxprop.cpp:121] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0126 19:10:54.834539 13307 auxprop.cpp:121] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0126 19:10:54.834869 13307 authenticator.hpp:390] Authentication success
> I0126 19:10:54.836004 13311 authenticatee.hpp:315] Authentication success
> I0126 19:10:54.842200 13311 slave.cpp:747] Successfully authenticated with master master@192.168.122.135:35545
> I0126 19:10:54.842851 13308 master.cpp:4187] Successfully authenticated principal 'test-principal' at slave(102)@192.168.122.135:35545
> I0126 19:10:54.844679 13309 master.cpp:3401] Re-registering slave 20150126-191052-2272962752-35545-13291-S0 at slave(101)@192.168.122.135:35545 (fedora-19)
> W0126 19:10:54.845654 13309 master.cpp:4347] Slave 20150126-191052-2272962752-35545-13291-S0 at slave(102)@192.168.122.135:35545 (fedora-19) has non-terminal task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e that is supposed to be killed. Killing it now!
> I0126 19:10:54.846365 13308 hierarchical_allocator_process.hpp:498] Slave 20150126-191052-2272962752-35545-13291-S0 reactivated
> I0126 19:10:54.846976 13311 slave.cpp:1075] Will retry registration in 10.72364ms if necessary
> I0126 19:10:54.847618 13311 slave.cpp:849] Re-registered with master master@192.168.122.135:35545
> I0126 19:10:54.848054 13309 status_update_manager.cpp:178] Resuming sending status updates
> I0126 19:10:54.848565 13311 slave.cpp:1424] Asked to kill task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework 20150126-191052-2272962752-35545-13291-0000
> I0126 19:10:54.850329 13311 slave.cpp:1762] Updating framework 20150126-191052-2272962752-35545-13291-0000 pid to scheduler-6da85b48-b57f-4202-b630-c45f8f652321@192.168.122.135:35545
> I0126 19:10:54.853868 13311 slave.cpp:1770] Checkpointing framework pid 'scheduler-6da85b48-b57f-4202-b630-c45f8f652321@192.168.122.135:35545' to '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_qbguuM/meta/slaves/20150126-191052-2272962752-35545-13291-S0/frameworks/20150126-191052-2272962752-35545-13291-0000/framework.pid'
> I0126 19:10:54.854627 13312 status_update_manager.cpp:178] Resuming sending status updates
> I0126 19:10:54.920938 15824 exec.cpp:328] Executor asked to kill task '61eaeec3-e8ca-4e15-82d6-284c05c3bb6e'
> I0126 19:10:54.921044 15824 exec.cpp:337] Executor::killTask took 56676ns
> Shutting down
> Sending SIGTERM to process tree at pid 15832
> Killing the following process trees:
> [
> --- 15832 sleep 1000
> ]
> Command terminated with signal Terminated (pid: 15832)
> I0126 19:10:55.045547 15825 exec.cpp:540] Executor sending status update TASK_KILLED (UUID: 2c2ef52e-8c0d-4a83-be36-e6433316989e) for task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework 20150126-191052-2272962752-35545-13291-0000
> I0126 19:10:55.059789 13312 hierarchical_allocator_process.hpp:831] No resources available to allocate!
> I0126 19:10:55.060405 13312 hierarchical_allocator_process.hpp:738] Performed allocation for 1 slaves in 918365ns
> I0126 19:10:55.115810 13309 slave.cpp:2265] Handling status update TASK_KILLED (UUID: 2c2ef52e-8c0d-4a83-be36-e6433316989e) for task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework 20150126-191052-2272962752-35545-13291-0000 from executor(1)@192.168.122.135:41245
> I0126 19:10:55.116387 13309 slave.cpp:4229] Terminating task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e
> I0126 19:10:55.119729 13305 status_update_manager.cpp:317] Received status update TASK_KILLED (UUID: 2c2ef52e-8c0d-4a83-be36-e6433316989e) for task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework 20150126-191052-2272962752-35545-13291-0000
> I0126 19:10:55.120384 13305 status_update_manager.hpp:346] Checkpointing UPDATE for status update TASK_KILLED (UUID: 2c2ef52e-8c0d-4a83-be36-e6433316989e) for task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework 20150126-191052-2272962752-35545-13291-0000
> I0126 19:10:55.120900 13305 status_update_manager.cpp:371] Forwarding update TASK_KILLED (UUID: 2c2ef52e-8c0d-4a83-be36-e6433316989e) for task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework 20150126-191052-2272962752-35545-13291-0000 to the slave
> I0126 19:10:55.121579 13305 slave.cpp:2508] Forwarding the update TASK_KILLED (UUID: 2c2ef52e-8c0d-4a83-be36-e6433316989e) for task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework 20150126-191052-2272962752-35545-13291-0000 to master@192.168.122.135:35545
> I0126 19:10:55.122256 13310 master.cpp:3652] Forwarding status update TASK_KILLED (UUID: 2c2ef52e-8c0d-4a83-be36-e6433316989e) for task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework 20150126-191052-2272962752-35545-13291-0000
> I0126 19:10:55.122685 13310 master.cpp:3624] Status update TASK_KILLED (UUID: 2c2ef52e-8c0d-4a83-be36-e6433316989e) for task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework 20150126-191052-2272962752-35545-13291-0000 from slave 20150126-191052-2272962752-35545-13291-S0 at slave(102)@192.168.122.135:35545 (fedora-19)
> I0126 19:10:55.123086 13308 sched.cpp:696] Scheduler::statusUpdate took 79719ns
> I0126 19:10:55.124562 13310 master.cpp:4934] Updating the latest state of task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework 20150126-191052-2272962752-35545-13291-0000 to TASK_KILLED
> I0126 19:10:55.125345 13310 master.cpp:4993] Removing task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework 20150126-191052-2272962752-35545-13291-0000 on slave 20150126-191052-2272962752-35545-13291-S0 at slave(102)@192.168.122.135:35545 (fedora-19)
> I0126 19:10:55.125810 13306 hierarchical_allocator_process.hpp:645] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total allocatable: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on slave 20150126-191052-2272962752-35545-13291-S0 from framework 20150126-191052-2272962752-35545-13291-0000
> I0126 19:10:55.126552 13310 master.cpp:3125] Forwarding status update acknowledgement 2c2ef52e-8c0d-4a83-be36-e6433316989e for task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework 20150126-191052-2272962752-35545-13291-0000 (default) at scheduler-6da85b48-b57f-4202-b630-c45f8f652321@192.168.122.135:35545 to slave 20150126-191052-2272962752-35545-13291-S0 at slave(102)@192.168.122.135:35545 (fedora-19)
> I0126 19:10:55.126843 13305 slave.cpp:2435] Status update manager successfully handled status update TASK_KILLED (UUID: 2c2ef52e-8c0d-4a83-be36-e6433316989e) for task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework 20150126-191052-2272962752-35545-13291-0000
> I0126 19:10:55.127396 13305 slave.cpp:2441] Sending acknowledgement for status update TASK_KILLED (UUID: 2c2ef52e-8c0d-4a83-be36-e6433316989e) for task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework 20150126-191052-2272962752-35545-13291-0000 to executor(1)@192.168.122.135:41245
> I0126 19:10:55.129451 13306 status_update_manager.cpp:389] Received status update acknowledgement (UUID: 2c2ef52e-8c0d-4a83-be36-e6433316989e) for task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework 20150126-191052-2272962752-35545-13291-0000
> I0126 19:10:55.129976 13306 status_update_manager.hpp:346] Checkpointing ACK for status update TASK_KILLED (UUID: 2c2ef52e-8c0d-4a83-be36-e6433316989e) for task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework 20150126-191052-2272962752-35545-13291-0000
> I0126 19:10:55.130367 13306 status_update_manager.cpp:525] Cleaning up status update stream for task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework 20150126-191052-2272962752-35545-13291-0000
> I0126 19:10:55.130980 13305 slave.cpp:1852] Status update manager successfully handled status update acknowledgement (UUID: 2c2ef52e-8c0d-4a83-be36-e6433316989e) for task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework 20150126-191052-2272962752-35545-13291-0000
> I0126 19:10:55.131376 13305 slave.cpp:4268] Completing task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e
> I0126 19:10:55.148888 15823 exec.cpp:354] Executor received status update acknowledgement 2c2ef52e-8c0d-4a83-be36-e6433316989e for task 61eaeec3-e8ca-4e15-82d6-284c05c3bb6e of framework 20150126-191052-2272962752-35545-13291-0000
> I0126 19:10:56.061642 13305 hierarchical_allocator_process.hpp:738] Performed allocation for 1 slaves in 612945ns
> I0126 19:10:56.065135 13310 master.cpp:4071] Sending 1 offers to framework 20150126-191052-2272962752-35545-13291-0000 (default) at scheduler-6da85b48-b57f-4202-b630-c45f8f652321@192.168.122.135:35545
> I0126 19:10:56.068106 13310 sched.cpp:605] Scheduler::resourceOffers took 98788ns
> I0126 19:10:56.068989 13291 sched.cpp:1471] Asked to stop the driver
> I0126 19:10:56.069831 13291 master.cpp:654] Master terminating
> I0126 19:10:56.070969 13310 sched.cpp:808] Stopping framework '20150126-191052-2272962752-35545-13291-0000'
> I0126 19:10:56.072089 13312 slave.cpp:2673] master@192.168.122.135:35545 exited
> W0126 19:10:56.072654 13312 slave.cpp:2676] Master disconnected! Waiting for a new master to be elected
> I0126 19:10:56.110337 13310 containerizer.cpp:1084] Executor for container '960eca2c-9e2c-415a-b6a5-159efca1f1b0' has exited
> I0126 19:10:56.110785 13310 containerizer.cpp:879] Destroying container '960eca2c-9e2c-415a-b6a5-159efca1f1b0'
> I./tests/cluster.hpp:451: Failure
> (wait).failure(): Unknown container: 960eca2c-9e2c-415a-b6a5-159efca1f1b0
> 0126 19:10:56.146338 13307 slave.cpp:2948] Executor '61eaeec3-e8ca-4e15-82d6-284c05c3bb6e' of framework 20150126-191052-2272962752-35545-13291-0000 exited with status 0
> W0126 19:10:56.147302 13309 containerizer.cpp:868] Ignoring destroy of unknown container: 960eca2c-9e2c-415a-b6a5-159efca1f1b0
> *** Aborted at 1422328256 (unix time) try "date -d @1422328256" if you are using GNU date ***
> I0126 19:10:56.151959 13307 slave.cpp:3057] Cleaning up executor '61eaeec3-e8ca-4e15-82d6-284c05c3bb6e' of framework 20150126-191052-2272962752-35545-13291-0000
> I0126 19:10:56.153216 13309 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_qbguuM/slaves/20150126-191052-2272962752-35545-13291-S0/frameworks/20150126-191052-2272962752-35545-13291-0000/executors/61eaeec3-e8ca-4e15-82d6-284c05c3bb6e/runs/960eca2c-9e2c-415a-b6a5-159efca1f1b0' for gc 6.99999822829926days in the future
> I0126 19:10:56.154017 13305 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_qbguuM/slaves/20150126-191052-2272962752-35545-13291-S0/frameworks/20150126-191052-2272962752-35545-13291-0000/executors/61eaeec3-e8ca-4e15-82d6-284c05c3bb6e' for gc 6.99999821866963days in the future
> I0126 19:10:56.154710 13312 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_qbguuM/meta/slaves/20150126-191052-2272962752-35545-13291-S0/frameworks/20150126-191052-2272962752-35545-13291-0000/executors/61eaeec3-e8ca-4e15-82d6-284c05c3bb6e/runs/960eca2c-9e2c-415a-b6a5-159efca1f1b0' for gc 6.99999821037037days in the future
> IPC: @ 0x8f9d48 mesos::internal::tests::Cluster::Slaves::shutdown()
> 0126 19:10:56.155350 13307 slave.cpp:3136] Cleaning up framework 20150126-191052-2272962752-35545-13291-0000
> I0126 19:10:56.155609 13310 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_qbguuM/meta/slaves/20150126-191052-2272962752-35545-13291-S0/frameworks/20150126-191052-2272962752-35545-13291-0000/executors/61eaeec3-e8ca-4e15-82d6-284c05c3bb6e' for gc 6.99999820308148days in the future
> I0126 19:10:56.158103 13310 status_update_manager.cpp:279] Closing status update streams for framework 20150126-191052-2272962752-35545-13291-0000
> I0126 19:10:56.163135 13310 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_qbguuM/slaves/20150126-191052-2272962752-35545-13291-S0/frameworks/20150126-191052-2272962752-35545-13291-0000' for gc 6.99999817088days in the future
> I0126 19:10:56.168100 13307 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_qbguuM/meta/slaves/20150126-191052-2272962752-35545-13291-S0/frameworks/20150126-191052-2272962752-35545-13291-0000' for gc 6.99999805755852days in the future
> *** SIGSEGV (@0x0) received by PID 13291 (TID 0x7fc0fdb22880) from PID 0; stack trace: ***
> @ 0x7fc0da188cbb (unknown)
> @ 0x7fc0da18d1a1 (unknown)
> @ 0x3aa2a0efa0 (unknown)
> @ 0x8f9d48 mesos::internal::tests::Cluster::Slaves::shutdown()
> @ 0xe0bfba mesos::internal::tests::MesosTest::ShutdownSlaves()
> @ 0xe0bf7e mesos::internal::tests::MesosTest::Shutdown()
> @ 0xe0981f mesos::internal::tests::MesosTest::TearDown()
> @ 0xe0f2b6 mesos::internal::tests::ContainerizerTest<>::TearDown()
> @ 0x10d8180 testing::internal::HandleSehExceptionsInMethodIfSupported<>()
> @ 0x10d3356 testing::internal::HandleExceptionsInMethodIfSupported<>()
> @ 0x10bb718 testing::Test::Run()
> @ 0x10bbdf2 testing::TestInfo::Run()
> @ 0x10bc37a testing::TestCase::Run()
> @ 0x10c10f6 testing::internal::UnitTestImpl::RunAllTests()
> @ 0x10d8ff1 testing::internal::HandleSehExceptionsInMethodIfSupported<>()
> @ 0x10d4047 testing::internal::HandleExceptionsInMethodIfSupported<>()
> @ 0x10bffa6 testing::UnitTest::Run()
> @ 0xce850d main
> @ 0x3aa2221b45 (unknown)
> @ 0x8d59f9 (unknown)
> make[3]: *** [check-local] Segmentation fault (core dumped)
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)