You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "Yan Xu (JIRA)" <ji...@apache.org> on 2015/01/23 21:09:35 UTC
[jira] [Created] (MESOS-2255) SlaveRecoveryTest/0.MasterFailover is
flaky
Yan Xu created MESOS-2255:
-----------------------------
Summary: SlaveRecoveryTest/0.MasterFailover is flaky
Key: MESOS-2255
URL: https://issues.apache.org/jira/browse/MESOS-2255
Project: Mesos
Issue Type: Bug
Components: test
Reporter: Yan Xu
{noformat:title=}
[ RUN ] SlaveRecoveryTest/0.MasterFailover
Using temporary directory '/tmp/SlaveRecoveryTest_0_MasterFailover_dtF7o0'
I0123 07:45:49.818686 17634 leveldb.cpp:176] Opened db in 31.195549ms
I0123 07:45:49.821962 17634 leveldb.cpp:183] Compacted db in 3.190936ms
I0123 07:45:49.822049 17634 leveldb.cpp:198] Created db iterator in 47324ns
I0123 07:45:49.822069 17634 leveldb.cpp:204] Seeked to beginning of db in 2038ns
I0123 07:45:49.822084 17634 leveldb.cpp:273] Iterated through 0 keys in the db in 484ns
I0123 07:45:49.822160 17634 replica.cpp:744] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0123 07:45:49.824241 17660 recover.cpp:449] Starting replica recovery
I0123 07:45:49.825217 17660 recover.cpp:475] Replica is in EMPTY status
I0123 07:45:49.827020 17660 replica.cpp:641] Replica in EMPTY status received a broadcasted recover request
I0123 07:45:49.827453 17659 recover.cpp:195] Received a recover response from a replica in EMPTY status
I0123 07:45:49.828047 17659 recover.cpp:566] Updating replica status to STARTING
I0123 07:45:49.838543 17659 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 10.24963ms
I0123 07:45:49.838580 17659 replica.cpp:323] Persisted replica status to STARTING
I0123 07:45:49.848836 17659 recover.cpp:475] Replica is in STARTING status
I0123 07:45:49.850039 17659 replica.cpp:641] Replica in STARTING status received a broadcasted recover request
I0123 07:45:49.850286 17659 recover.cpp:195] Received a recover response from a replica in STARTING status
I0123 07:45:49.850754 17659 recover.cpp:566] Updating replica status to VOTING
I0123 07:45:49.853698 17655 master.cpp:262] Master 20150123-074549-16842879-44955-17634 (utopic) started on 127.0.1.1:44955
I0123 07:45:49.853981 17655 master.cpp:308] Master only allowing authenticated frameworks to register
I0123 07:45:49.853997 17655 master.cpp:313] Master only allowing authenticated slaves to register
I0123 07:45:49.854038 17655 credentials.hpp:36] Loading credentials for authentication from '/tmp/SlaveRecoveryTest_0_MasterFailover_dtF7o0/credentials'
I0123 07:45:49.854557 17655 master.cpp:357] Authorization enabled
I0123 07:45:49.859633 17659 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 8.742923ms
I0123 07:45:49.859853 17659 replica.cpp:323] Persisted replica status to VOTING
I0123 07:45:49.860327 17658 recover.cpp:580] Successfully joined the Paxos group
I0123 07:45:49.860703 17654 recover.cpp:464] Recover process terminated
I0123 07:45:49.859591 17655 master.cpp:1219] The newly elected leader is master@127.0.1.1:44955 with id 20150123-074549-16842879-44955-17634
I0123 07:45:49.864702 17655 master.cpp:1232] Elected as the leading master!
I0123 07:45:49.864904 17655 master.cpp:1050] Recovering from registrar
I0123 07:45:49.865406 17660 registrar.cpp:313] Recovering registrar
I0123 07:45:49.866576 17660 log.cpp:660] Attempting to start the writer
I0123 07:45:49.868638 17658 replica.cpp:477] Replica received implicit promise request with proposal 1
I0123 07:45:49.872521 17658 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 3.848859ms
I0123 07:45:49.872555 17658 replica.cpp:345] Persisted promised to 1
I0123 07:45:49.873769 17661 coordinator.cpp:230] Coordinator attemping to fill missing position
I0123 07:45:49.875474 17658 replica.cpp:378] Replica received explicit promise request for position 0 with proposal 2
I0123 07:45:49.880878 17658 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 5.364021ms
I0123 07:45:49.880913 17658 replica.cpp:679] Persisted action at 0
I0123 07:45:49.882619 17657 replica.cpp:511] Replica received write request for position 0
I0123 07:45:49.882998 17657 leveldb.cpp:438] Reading position from leveldb took 150092ns
I0123 07:45:49.886488 17657 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 3.269189ms
I0123 07:45:49.886536 17657 replica.cpp:679] Persisted action at 0
I0123 07:45:49.887181 17657 replica.cpp:658] Replica received learned notice for position 0
I0123 07:45:49.892900 17657 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 5.690093ms
I0123 07:45:49.892935 17657 replica.cpp:679] Persisted action at 0
I0123 07:45:49.892956 17657 replica.cpp:664] Replica learned NOP action at position 0
I0123 07:45:49.896195 17657 log.cpp:676] Writer started with ending position 0
I0123 07:45:49.897519 17657 leveldb.cpp:438] Reading position from leveldb took 28484ns
I0123 07:45:49.907706 17657 registrar.cpp:346] Successfully fetched the registry (0B) in 42.256896ms
I0123 07:45:49.907829 17657 registrar.cpp:445] Applied 1 operations in 27858ns; attempting to update the 'registry'
I0123 07:45:49.910070 17659 log.cpp:684] Attempting to append 119 bytes to the log
I0123 07:45:49.910245 17659 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
I0123 07:45:49.911144 17659 replica.cpp:511] Replica received write request for position 1
I0123 07:45:49.913838 17659 leveldb.cpp:343] Persisting action (136 bytes) to leveldb took 2.662342ms
I0123 07:45:49.913873 17659 replica.cpp:679] Persisted action at 1
I0123 07:45:49.915096 17656 replica.cpp:658] Replica received learned notice for position 1
I0123 07:45:49.917762 17656 leveldb.cpp:343] Persisting action (138 bytes) to leveldb took 2.632749ms
I0123 07:45:49.917796 17656 replica.cpp:679] Persisted action at 1
I0123 07:45:49.917816 17656 replica.cpp:664] Replica learned APPEND action at position 1
I0123 07:45:49.923773 17656 registrar.cpp:490] Successfully updated the 'registry' in 15.85792ms
I0123 07:45:49.924000 17659 log.cpp:703] Attempting to truncate the log to 1
I0123 07:45:49.924314 17659 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
I0123 07:45:49.925415 17659 replica.cpp:511] Replica received write request for position 2
I0123 07:45:49.925743 17656 registrar.cpp:376] Successfully recovered registrar
I0123 07:45:49.926185 17661 master.cpp:1077] Recovered 0 slaves from the Registry (83B) ; allowing 10mins for slaves to re-register
I0123 07:45:49.928938 17659 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 3.489795ms
I0123 07:45:49.929078 17659 replica.cpp:679] Persisted action at 2
I0123 07:45:49.930430 17659 replica.cpp:658] Replica received learned notice for position 2
I0123 07:45:49.933015 17659 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 2.552222ms
I0123 07:45:49.933086 17659 leveldb.cpp:401] Deleting ~1 keys from leveldb took 37955ns
I0123 07:45:49.933107 17659 replica.cpp:679] Persisted action at 2
I0123 07:45:49.933130 17659 replica.cpp:664] Replica learned TRUNCATE action at position 2
I0123 07:45:49.937980 17634 containerizer.cpp:103] Using isolation: posix/cpu,posix/mem
I0123 07:45:49.959229 17657 slave.cpp:173] Slave started on 181)@127.0.1.1:44955
I0123 07:45:49.963649 17657 credentials.hpp:84] Loading credential for authentication from '/tmp/SlaveRecoveryTest_0_MasterFailover_RIevEf/credential'
I0123 07:45:49.964156 17657 slave.cpp:282] Slave using credential for: test-principal
I0123 07:45:49.965526 17657 slave.cpp:300] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0123 07:45:49.965939 17657 slave.cpp:329] Slave hostname: utopic
I0123 07:45:49.966125 17657 slave.cpp:330] Slave checkpoint: true
I0123 07:45:49.975633 17634 sched.cpp:151] Version: 0.22.0
I0123 07:45:49.977212 17657 state.cpp:33] Recovering state from '/tmp/SlaveRecoveryTest_0_MasterFailover_RIevEf/meta'
I0123 07:45:49.977771 17657 sched.cpp:248] New master detected at master@127.0.1.1:44955
I0123 07:45:49.977869 17657 sched.cpp:304] Authenticating with master master@127.0.1.1:44955
I0123 07:45:49.977891 17657 sched.cpp:311] Using default CRAM-MD5 authenticatee
I0123 07:45:49.978088 17657 status_update_manager.cpp:197] Recovering status update manager
I0123 07:45:49.978309 17657 authenticatee.hpp:138] Creating new client SASL connection
I0123 07:45:49.978911 17657 master.cpp:4129] Authenticating scheduler-a70d391c-9825-4fe6-8f73-70850700ea51@127.0.1.1:44955
I0123 07:45:49.978941 17657 master.cpp:4140] Using default CRAM-MD5 authenticator
I0123 07:45:49.979204 17657 containerizer.cpp:300] Recovering containerizer
I0123 07:45:49.979637 17654 authenticator.hpp:170] Creating new server SASL connection
I0123 07:45:49.980034 17654 authenticatee.hpp:229] Received SASL authentication mechanisms: CRAM-MD5
I0123 07:45:49.980072 17654 authenticatee.hpp:255] Attempting to authenticate with mechanism 'CRAM-MD5'
I0123 07:45:49.980188 17654 authenticator.hpp:276] Received SASL authentication start
I0123 07:45:49.980247 17654 authenticator.hpp:398] Authentication requires more steps
I0123 07:45:49.980324 17654 authenticatee.hpp:275] Received SASL authentication step
I0123 07:45:49.980411 17654 authenticator.hpp:304] Received SASL authentication step
I0123 07:45:49.980516 17654 authenticator.hpp:390] Authentication success
I0123 07:45:49.980622 17654 authenticatee.hpp:315] Authentication success
I0123 07:45:49.980692 17654 master.cpp:4187] Successfully authenticated principal 'test-principal' at scheduler-a70d391c-9825-4fe6-8f73-70850700ea51@127.0.1.1:44955
I0123 07:45:49.981005 17654 sched.cpp:392] Successfully authenticated with master master@127.0.1.1:44955
I0123 07:45:49.981215 17654 master.cpp:1420] Received registration request for framework 'default' at scheduler-a70d391c-9825-4fe6-8f73-70850700ea51@127.0.1.1:44955
I0123 07:45:49.981317 17654 master.cpp:1298] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0123 07:45:49.981838 17654 master.cpp:1484] Registering framework 20150123-074549-16842879-44955-17634-0000 (default) at scheduler-a70d391c-9825-4fe6-8f73-70850700ea51@127.0.1.1:44955
I0123 07:45:49.982498 17654 hierarchical_allocator_process.hpp:319] Added framework 20150123-074549-16842879-44955-17634-0000
I0123 07:45:49.983006 17654 sched.cpp:442] Framework registered with 20150123-074549-16842879-44955-17634-0000
I0123 07:45:49.988867 17657 slave.cpp:3519] Finished recovery
I0123 07:45:49.989565 17657 slave.cpp:613] New master detected at master@127.0.1.1:44955
I0123 07:45:49.989804 17658 status_update_manager.cpp:171] Pausing sending status updates
I0123 07:45:49.990255 17657 slave.cpp:676] Authenticating with master master@127.0.1.1:44955
I0123 07:45:49.990459 17657 slave.cpp:681] Using default CRAM-MD5 authenticatee
I0123 07:45:49.991062 17656 authenticatee.hpp:138] Creating new client SASL connection
I0123 07:45:49.993137 17661 master.cpp:4129] Authenticating slave(181)@127.0.1.1:44955
I0123 07:45:49.993167 17661 master.cpp:4140] Using default CRAM-MD5 authenticator
I0123 07:45:49.993476 17657 slave.cpp:649] Detecting new master
I0123 07:45:49.994479 17661 authenticator.hpp:170] Creating new server SASL connection
I0123 07:45:49.994830 17661 authenticatee.hpp:229] Received SASL authentication mechanisms: CRAM-MD5
I0123 07:45:49.994858 17661 authenticatee.hpp:255] Attempting to authenticate with mechanism 'CRAM-MD5'
I0123 07:45:49.994964 17661 authenticator.hpp:276] Received SASL authentication start
I0123 07:45:49.995007 17661 authenticator.hpp:398] Authentication requires more steps
I0123 07:45:49.995079 17661 authenticatee.hpp:275] Received SASL authentication step
I0123 07:45:49.995160 17661 authenticator.hpp:304] Received SASL authentication step
I0123 07:45:49.995226 17661 authenticator.hpp:390] Authentication success
I0123 07:45:49.995369 17655 authenticatee.hpp:315] Authentication success
I0123 07:45:49.995694 17660 master.cpp:4187] Successfully authenticated principal 'test-principal' at slave(181)@127.0.1.1:44955
I0123 07:45:49.996366 17657 slave.cpp:747] Successfully authenticated with master master@127.0.1.1:44955
I0123 07:45:49.997289 17657 master.cpp:3275] Registering slave at slave(181)@127.0.1.1:44955 (utopic) with id 20150123-074549-16842879-44955-17634-S0
I0123 07:45:49.998033 17658 registrar.cpp:445] Applied 1 operations in 75017ns; attempting to update the 'registry'
I0123 07:45:50.000515 17660 log.cpp:684] Attempting to append 285 bytes to the log
I0123 07:45:50.000744 17660 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
I0123 07:45:50.001775 17660 replica.cpp:511] Replica received write request for position 3
I0123 07:45:50.004446 17660 leveldb.cpp:343] Persisting action (304 bytes) to leveldb took 2.637071ms
I0123 07:45:50.004485 17660 replica.cpp:679] Persisted action at 3
I0123 07:45:50.005712 17658 replica.cpp:658] Replica received learned notice for position 3
I0123 07:45:50.008474 17658 leveldb.cpp:343] Persisting action (306 bytes) to leveldb took 2338us
I0123 07:45:50.008510 17658 replica.cpp:679] Persisted action at 3
I0123 07:45:50.008534 17658 replica.cpp:664] Replica learned APPEND action at position 3
I0123 07:45:50.009821 17658 registrar.cpp:490] Successfully updated the 'registry' in 11.714304ms
I0123 07:45:50.010036 17658 log.cpp:703] Attempting to truncate the log to 3
I0123 07:45:50.010694 17658 master.cpp:3329] Registered slave 20150123-074549-16842879-44955-17634-S0 at slave(181)@127.0.1.1:44955 (utopic) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0123 07:45:50.010804 17658 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
I0123 07:45:50.011210 17658 hierarchical_allocator_process.hpp:453] Added slave 20150123-074549-16842879-44955-17634-S0 (utopic) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
I0123 07:45:50.011428 17660 slave.cpp:781] Registered with master master@127.0.1.1:44955; given slave ID 20150123-074549-16842879-44955-17634-S0
I0123 07:45:50.012161 17659 status_update_manager.cpp:178] Resuming sending status updates
I0123 07:45:50.012707 17659 replica.cpp:511] Replica received write request for position 4
I0123 07:45:50.015665 17654 master.cpp:4071] Sending 1 offers to framework 20150123-074549-16842879-44955-17634-0000 (default) at scheduler-a70d391c-9825-4fe6-8f73-70850700ea51@127.0.1.1:44955
I0123 07:45:50.017946 17659 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 5.204664ms
I0123 07:45:50.017982 17659 replica.cpp:679] Persisted action at 4
I0123 07:45:50.018901 17659 replica.cpp:658] Replica received learned notice for position 4
I0123 07:45:50.020967 17657 master.cpp:2677] Processing ACCEPT call for offers: [ 20150123-074549-16842879-44955-17634-O0 ] on slave 20150123-074549-16842879-44955-17634-S0 at slave(181)@127.0.1.1:44955 (utopic) for framework 20150123-074549-16842879-44955-17634-0000 (default) at scheduler-a70d391c-9825-4fe6-8f73-70850700ea51@127.0.1.1:44955
I0123 07:45:50.021029 17657 master.cpp:2513] Authorizing framework principal 'test-principal' to launch task 459233e7-b3a0-4367-aaee-4d1706988b1c as user 'jenkins'
I0123 07:45:50.022380 17657 master.hpp:782] Adding task 459233e7-b3a0-4367-aaee-4d1706988b1c with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20150123-074549-16842879-44955-17634-S0 (utopic)
I0123 07:45:50.022500 17657 master.cpp:2885] Launching task 459233e7-b3a0-4367-aaee-4d1706988b1c of framework 20150123-074549-16842879-44955-17634-0000 (default) at scheduler-a70d391c-9825-4fe6-8f73-70850700ea51@127.0.1.1:44955 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20150123-074549-16842879-44955-17634-S0 at slave(181)@127.0.1.1:44955 (utopic)
I0123 07:45:50.022912 17657 slave.cpp:1130] Got assigned task 459233e7-b3a0-4367-aaee-4d1706988b1c for framework 20150123-074549-16842879-44955-17634-0000
I0123 07:45:50.024471 17657 slave.cpp:1245] Launching task 459233e7-b3a0-4367-aaee-4d1706988b1c for framework 20150123-074549-16842879-44955-17634-0000
I0123 07:45:50.025522 17659 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 6.592566ms
I0123 07:45:50.025601 17659 leveldb.cpp:401] Deleting ~2 keys from leveldb took 45510ns
I0123 07:45:50.025624 17659 replica.cpp:679] Persisted action at 4
I0123 07:45:50.025645 17659 replica.cpp:664] Replica learned TRUNCATE action at position 4
I0123 07:45:50.032011 17657 slave.cpp:3921] Launching executor 459233e7-b3a0-4367-aaee-4d1706988b1c of framework 20150123-074549-16842879-44955-17634-0000 in work directory '/tmp/SlaveRecoveryTest_0_MasterFailover_RIevEf/slaves/20150123-074549-16842879-44955-17634-S0/frameworks/20150123-074549-16842879-44955-17634-0000/executors/459233e7-b3a0-4367-aaee-4d1706988b1c/runs/852caf33-5860-488f-b8da-256908d79e64'
I0123 07:45:50.033010 17656 containerizer.cpp:445] Starting container '852caf33-5860-488f-b8da-256908d79e64' for executor '459233e7-b3a0-4367-aaee-4d1706988b1c' of framework '20150123-074549-16842879-44955-17634-0000'
W0123 07:45:50.034787 17656 containerizer.cpp:296] CommandInfo.grace_period flag is not set, using default value: 3secs
I0123 07:45:50.043774 17657 slave.cpp:1368] Queuing task '459233e7-b3a0-4367-aaee-4d1706988b1c' for executor 459233e7-b3a0-4367-aaee-4d1706988b1c of framework '20150123-074549-16842879-44955-17634-0000
I0123 07:45:50.051795 17656 launcher.cpp:137] Forked child with pid '20372' for container '852caf33-5860-488f-b8da-256908d79e64'
I0123 07:45:50.052232 17656 containerizer.cpp:655] Checkpointing executor's forked pid 20372 to '/tmp/SlaveRecoveryTest_0_MasterFailover_RIevEf/meta/slaves/20150123-074549-16842879-44955-17634-S0/frameworks/20150123-074549-16842879-44955-17634-0000/executors/459233e7-b3a0-4367-aaee-4d1706988b1c/runs/852caf33-5860-488f-b8da-256908d79e64/pids/forked.pid'
I0123 07:45:50.068331 17656 slave.cpp:2890] Monitoring executor '459233e7-b3a0-4367-aaee-4d1706988b1c' of framework '20150123-074549-16842879-44955-17634-0000' in container '852caf33-5860-488f-b8da-256908d79e64'
I0123 07:45:50.339436 20386 exec.cpp:147] Version: 0.22.0
I0123 07:45:50.472121 17659 slave.cpp:1912] Got registration for executor '459233e7-b3a0-4367-aaee-4d1706988b1c' of framework 20150123-074549-16842879-44955-17634-0000 from executor(1)@127.0.1.1:33302
I0123 07:45:50.476608 17659 slave.cpp:2031] Flushing queued task 459233e7-b3a0-4367-aaee-4d1706988b1c for executor '459233e7-b3a0-4367-aaee-4d1706988b1c' of framework 20150123-074549-16842879-44955-17634-0000
I0123 07:45:50.664320 20402 exec.cpp:221] Executor registered on slave 20150123-074549-16842879-44955-17634-S0
Shutdown timeout is set to 3secsRegistered executor on utopic
Starting task 459233e7-b3a0-4367-aaee-4d1706988b1c
Forked command at 20409
sh -c 'sleep 1000'
I0123 07:45:50.843693 17658 slave.cpp:2265] Handling status update TASK_RUNNING (UUID: 53d403ac-83f4-48d9-b62b-ff76979b7c9c) for task 459233e7-b3a0-4367-aaee-4d1706988b1c of framework 20150123-074549-16842879-44955-17634-0000 from executor(1)@127.0.1.1:33302
I0123 07:45:50.844213 17658 status_update_manager.cpp:317] Received status update TASK_RUNNING (UUID: 53d403ac-83f4-48d9-b62b-ff76979b7c9c) for task 459233e7-b3a0-4367-aaee-4d1706988b1c of framework 20150123-074549-16842879-44955-17634-0000
I0123 07:45:50.845342 17658 status_update_manager.hpp:346] Checkpointing UPDATE for status update TASK_RUNNING (UUID: 53d403ac-83f4-48d9-b62b-ff76979b7c9c) for task 459233e7-b3a0-4367-aaee-4d1706988b1c of framework 20150123-074549-16842879-44955-17634-0000
I0123 07:45:50.861532 17660 slave.cpp:2508] Forwarding the update TASK_RUNNING (UUID: 53d403ac-83f4-48d9-b62b-ff76979b7c9c) for task 459233e7-b3a0-4367-aaee-4d1706988b1c of framework 20150123-074549-16842879-44955-17634-0000 to master@127.0.1.1:44955
I0123 07:45:50.861980 17660 master.cpp:3652] Forwarding status update TASK_RUNNING (UUID: 53d403ac-83f4-48d9-b62b-ff76979b7c9c) for task 459233e7-b3a0-4367-aaee-4d1706988b1c of framework 20150123-074549-16842879-44955-17634-0000
I0123 07:45:50.862157 17660 master.cpp:3624] Status update TASK_RUNNING (UUID: 53d403ac-83f4-48d9-b62b-ff76979b7c9c) for task 459233e7-b3a0-4367-aaee-4d1706988b1c of framework 20150123-074549-16842879-44955-17634-0000 from slave 20150123-074549-16842879-44955-17634-S0 at slave(181)@127.0.1.1:44955 (utopic)
I0123 07:45:50.862231 17660 master.cpp:4934] Updating the latest state of task 459233e7-b3a0-4367-aaee-4d1706988b1c of framework 20150123-074549-16842879-44955-17634-0000 to TASK_RUNNING
I0123 07:45:50.862691 17660 master.cpp:3125] Forwarding status update acknowledgement 53d403ac-83f4-48d9-b62b-ff76979b7c9c for task 459233e7-b3a0-4367-aaee-4d1706988b1c of framework 20150123-074549-16842879-44955-17634-0000 (default) at scheduler-a70d391c-9825-4fe6-8f73-70850700ea51@127.0.1.1:44955 to slave 20150123-074549-16842879-44955-17634-S0 at slave(181)@127.0.1.1:44955 (utopic)
I0123 07:45:50.863428 17658 status_update_manager.cpp:389] Received status update acknowledgement (UUID: 53d403ac-83f4-48d9-b62b-ff76979b7c9c) for task 459233e7-b3a0-4367-aaee-4d1706988b1c of framework 20150123-074549-16842879-44955-17634-0000
I0123 07:45:50.863510 17658 status_update_manager.hpp:346] Checkpointing ACK for status update TASK_RUNNING (UUID: 53d403ac-83f4-48d9-b62b-ff76979b7c9c) for task 459233e7-b3a0-4367-aaee-4d1706988b1c of framework 20150123-074549-16842879-44955-17634-0000
I0123 07:45:50.863965 17659 slave.cpp:2441] Sending acknowledgement for status update TASK_RUNNING (UUID: 53d403ac-83f4-48d9-b62b-ff76979b7c9c) for task 459233e7-b3a0-4367-aaee-4d1706988b1c of framework 20150123-074549-16842879-44955-17634-0000 to executor(1)@127.0.1.1:33302
I0123 07:45:50.876504 17634 slave.cpp:495] Slave terminating
I0123 07:45:50.879389 17656 master.cpp:795] Slave 20150123-074549-16842879-44955-17634-S0 at slave(181)@127.0.1.1:44955 (utopic) disconnected
I0123 07:45:50.879421 17656 master.cpp:1826] Disconnecting slave 20150123-074549-16842879-44955-17634-S0 at slave(181)@127.0.1.1:44955 (utopic)
I0123 07:45:50.879508 17656 master.cpp:1845] Deactivating slave 20150123-074549-16842879-44955-17634-S0 at slave(181)@127.0.1.1:44955 (utopic)
I0123 07:45:50.887653 17654 hierarchical_allocator_process.hpp:512] Slave 20150123-074549-16842879-44955-17634-S0 deactivated
I0123 07:45:50.899884 17634 master.cpp:654] Master terminating
W0123 07:45:50.900359 17634 master.cpp:4979] Removing task 459233e7-b3a0-4367-aaee-4d1706988b1c with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework 20150123-074549-16842879-44955-17634-0000 on slave 20150123-074549-16842879-44955-17634-S0 at slave(181)@127.0.1.1:44955 (utopic) in non-terminal state TASK_RUNNING
I0123 07:45:50.901008 17658 hierarchical_allocator_process.hpp:653] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total allocatable: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on slave 20150123-074549-16842879-44955-17634-S0 from framework 20150123-074549-16842879-44955-17634-0000
I0123 07:45:50.962065 17634 leveldb.cpp:176] Opened db in 23.504748ms
I0123 07:45:50.973923 17634 leveldb.cpp:183] Compacted db in 11.818962ms
I0123 07:45:50.973990 17634 leveldb.cpp:198] Created db iterator in 33105ns
I0123 07:45:50.974026 17634 leveldb.cpp:204] Seeked to beginning of db in 18659ns
I0123 07:45:50.974165 17634 leveldb.cpp:273] Iterated through 3 keys in the db in 122434ns
I0123 07:45:50.974257 17634 replica.cpp:744] Replica recovered with log positions 3 -> 4 with 0 holes and 0 unlearned
I0123 07:45:50.976765 17656 recover.cpp:449] Starting replica recovery
I0123 07:45:50.978348 17656 recover.cpp:475] Replica is in VOTING status
I0123 07:45:51.011759 17656 recover.cpp:464] Recover process terminated
I0123 07:45:51.013435 17658 master.cpp:262] Master 20150123-074550-16842879-44955-17634 (utopic) started on 127.0.1.1:44955
I0123 07:45:51.013839 17658 master.cpp:308] Master only allowing authenticated frameworks to register
I0123 07:45:51.014076 17658 master.cpp:313] Master only allowing authenticated slaves to register
I0123 07:45:51.014349 17658 credentials.hpp:36] Loading credentials for authentication from '/tmp/SlaveRecoveryTest_0_MasterFailover_dtF7o0/credentials'
I0123 07:45:51.014860 17658 master.cpp:357] Authorization enabled
I0123 07:45:51.019244 17658 master.cpp:1219] The newly elected leader is master@127.0.1.1:44955 with id 20150123-074550-16842879-44955-17634
I0123 07:45:51.019484 17658 master.cpp:1232] Elected as the leading master!
I0123 07:45:51.019866 17658 master.cpp:1050] Recovering from registrar
I0123 07:45:51.020685 17659 registrar.cpp:313] Recovering registrar
I0123 07:45:51.021906 17659 log.cpp:660] Attempting to start the writer
I0123 07:45:51.023519 17661 replica.cpp:477] Replica received implicit promise request with proposal 2
I0123 07:45:51.031894 17661 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 8.344373ms
I0123 07:45:51.031929 17661 replica.cpp:345] Persisted promised to 2
I0123 07:45:51.033164 17655 coordinator.cpp:230] Coordinator attemping to fill missing position
I0123 07:45:51.033499 17655 log.cpp:676] Writer started with ending position 4
I0123 07:45:51.034826 17655 leveldb.cpp:438] Reading position from leveldb took 61148ns
I0123 07:45:51.034909 17655 leveldb.cpp:438] Reading position from leveldb took 36111ns
I0123 07:45:51.044178 17655 registrar.cpp:346] Successfully fetched the registry (246B) in 23.412992ms
I0123 07:45:51.044378 17655 registrar.cpp:445] Applied 1 operations in 54454ns; attempting to update the 'registry'
I0123 07:45:51.046926 17658 log.cpp:684] Attempting to append 285 bytes to the log
I0123 07:45:51.047116 17658 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 5
I0123 07:45:51.048112 17660 replica.cpp:511] Replica received write request for position 5
I0123 07:45:51.050938 17660 leveldb.cpp:343] Persisting action (304 bytes) to leveldb took 2.793074ms
I0123 07:45:51.050971 17660 replica.cpp:679] Persisted action at 5
I0123 07:45:51.052258 17657 replica.cpp:658] Replica received learned notice for position 5
I0123 07:45:51.054956 17657 leveldb.cpp:343] Persisting action (306 bytes) to leveldb took 2.666129ms
I0123 07:45:51.054990 17657 replica.cpp:679] Persisted action at 5
I0123 07:45:51.055011 17657 replica.cpp:664] Replica learned APPEND action at position 5
I0123 07:45:51.056664 17657 registrar.cpp:490] Successfully updated the 'registry' in 12.22912ms
I0123 07:45:51.056829 17660 log.cpp:703] Attempting to truncate the log to 5
I0123 07:45:51.057220 17660 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 6
I0123 07:45:51.058104 17660 replica.cpp:511] Replica received write request for position 6
I0123 07:45:51.058671 17657 registrar.cpp:376] Successfully recovered registrar
I0123 07:45:51.059358 17658 master.cpp:1077] Recovered 1 slaves from the Registry (246B) ; allowing 10mins for slaves to re-register
I0123 07:45:51.060629 17660 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 2.494841ms
I0123 07:45:51.060662 17660 replica.cpp:679] Persisted action at 6
I0123 07:45:51.061506 17660 replica.cpp:658] Replica received learned notice for position 6
I0123 07:45:51.064167 17660 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 2.63489ms
I0123 07:45:51.064240 17660 leveldb.cpp:401] Deleting ~2 keys from leveldb took 39533ns
I0123 07:45:51.064260 17660 replica.cpp:679] Persisted action at 6
I0123 07:45:51.064280 17660 replica.cpp:664] Replica learned TRUNCATE action at position 6
I0123 07:45:51.071774 17658 sched.cpp:248] New master detected at master@127.0.1.1:44955
I0123 07:45:51.071879 17658 sched.cpp:304] Authenticating with master master@127.0.1.1:44955
I0123 07:45:51.071902 17658 sched.cpp:311] Using default CRAM-MD5 authenticatee
I0123 07:45:51.072239 17658 authenticatee.hpp:138] Creating new client SASL connection
I0123 07:45:51.072758 17658 master.cpp:4129] Authenticating scheduler-a70d391c-9825-4fe6-8f73-70850700ea51@127.0.1.1:44955
I0123 07:45:51.072788 17658 master.cpp:4140] Using default CRAM-MD5 authenticator
I0123 07:45:51.073230 17658 authenticator.hpp:170] Creating new server SASL connection
I0123 07:45:51.073597 17658 authenticatee.hpp:229] Received SASL authentication mechanisms: CRAM-MD5
I0123 07:45:51.073635 17658 authenticatee.hpp:255] Attempting to authenticate with mechanism 'CRAM-MD5'
I0123 07:45:51.073745 17658 authenticator.hpp:276] Received SASL authentication start
I0123 07:45:51.073798 17658 authenticator.hpp:398] Authentication requires more steps
I0123 07:45:51.073871 17658 authenticatee.hpp:275] Received SASL authentication step
I0123 07:45:51.073969 17658 authenticator.hpp:304] Received SASL authentication step
I0123 07:45:51.074075 17658 authenticator.hpp:390] Authentication success
I0123 07:45:51.074182 17658 authenticatee.hpp:315] Authentication success
I0123 07:45:51.074259 17658 master.cpp:4187] Successfully authenticated principal 'test-principal' at scheduler-a70d391c-9825-4fe6-8f73-70850700ea51@127.0.1.1:44955
I0123 07:45:51.074595 17658 sched.cpp:392] Successfully authenticated with master master@127.0.1.1:44955
I0123 07:45:51.074815 17658 master.cpp:1557] Received re-registration request from framework 20150123-074549-16842879-44955-17634-0000 (default) at scheduler-a70d391c-9825-4fe6-8f73-70850700ea51@127.0.1.1:44955
I0123 07:45:51.074906 17658 master.cpp:1298] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0123 07:45:51.079452 17658 master.cpp:1610] Re-registering framework 20150123-074549-16842879-44955-17634-0000 (default) at scheduler-a70d391c-9825-4fe6-8f73-70850700ea51@127.0.1.1:44955
I0123 07:45:51.083551 17658 hierarchical_allocator_process.hpp:319] Added framework 20150123-074549-16842879-44955-17634-0000
I0123 07:45:51.084125 17661 sched.cpp:442] Framework registered with 20150123-074549-16842879-44955-17634-0000
I0123 07:45:51.085055 17634 containerizer.cpp:103] Using isolation: posix/cpu,posix/mem
I0123 07:45:51.104457 17656 slave.cpp:173] Slave started on 182)@127.0.1.1:44955
I0123 07:45:51.104496 17656 credentials.hpp:84] Loading credential for authentication from '/tmp/SlaveRecoveryTest_0_MasterFailover_RIevEf/credential'
I0123 07:45:51.106145 17656 slave.cpp:282] Slave using credential for: test-principal
I0123 07:45:51.106395 17656 slave.cpp:300] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0123 07:45:51.106492 17656 slave.cpp:329] Slave hostname: utopic
I0123 07:45:51.106520 17656 slave.cpp:330] Slave checkpoint: true
I0123 07:45:51.107895 17655 state.cpp:33] Recovering state from '/tmp/SlaveRecoveryTest_0_MasterFailover_RIevEf/meta'
I0123 07:45:51.107983 17655 state.cpp:668] Failed to find resources file '/tmp/SlaveRecoveryTest_0_MasterFailover_RIevEf/meta/resources/resources.info'
I0123 07:45:51.111822 17656 slave.cpp:3601] Recovering framework 20150123-074549-16842879-44955-17634-0000
I0123 07:45:51.112095 17656 slave.cpp:4040] Recovering executor '459233e7-b3a0-4367-aaee-4d1706988b1c' of framework 20150123-074549-16842879-44955-17634-0000
I0123 07:45:51.115715 17657 status_update_manager.cpp:197] Recovering status update manager
I0123 07:45:51.115749 17657 status_update_manager.cpp:205] Recovering executor '459233e7-b3a0-4367-aaee-4d1706988b1c' of framework 20150123-074549-16842879-44955-17634-0000
I0123 07:45:51.119401 17654 containerizer.cpp:300] Recovering containerizer
I0123 07:45:51.119504 17654 containerizer.cpp:342] Recovering container '852caf33-5860-488f-b8da-256908d79e64' for executor '459233e7-b3a0-4367-aaee-4d1706988b1c' of framework 20150123-074549-16842879-44955-17634-0000
I0123 07:45:51.122992 17654 slave.cpp:3460] Sending reconnect request to executor 459233e7-b3a0-4367-aaee-4d1706988b1c of framework 20150123-074549-16842879-44955-17634-0000 at executor(1)@127.0.1.1:33302
I0123 07:45:51.308917 20401 exec.cpp:267] Received reconnect request from slave 20150123-074549-16842879-44955-17634-S0
I0123 07:45:51.367311 17660 slave.cpp:2089] Re-registering executor 459233e7-b3a0-4367-aaee-4d1706988b1c of framework 20150123-074549-16842879-44955-17634-0000
I0123 07:45:51.387477 17657 slave.cpp:2214] Cleaning up un-reregistered executors
I0123 07:45:51.387569 17657 slave.cpp:3519] Finished recovery
I0123 07:45:51.388195 17657 slave.cpp:613] New master detected at master@127.0.1.1:44955
I0123 07:45:51.388283 17657 slave.cpp:676] Authenticating with master master@127.0.1.1:44955
I0123 07:45:51.388304 17657 slave.cpp:681] Using default CRAM-MD5 authenticatee
I0123 07:45:51.388430 17657 slave.cpp:649] Detecting new master
I0123 07:45:51.388536 17657 status_update_manager.cpp:171] Pausing sending status updates
I0123 07:45:51.388676 17657 authenticatee.hpp:138] Creating new client SASL connection
I0123 07:45:51.389194 17657 master.cpp:4129] Authenticating slave(182)@127.0.1.1:44955
I0123 07:45:51.389222 17657 master.cpp:4140] Using default CRAM-MD5 authenticator
I0123 07:45:51.389617 17657 authenticator.hpp:170] Creating new server SASL connection
I0123 07:45:51.389981 17657 authenticatee.hpp:229] Received SASL authentication mechanisms: CRAM-MD5
I0123 07:45:51.390010 17657 authenticatee.hpp:255] Attempting to authenticate with mechanism 'CRAM-MD5'
I0123 07:45:51.390118 17657 authenticator.hpp:276] Received SASL authentication start
I0123 07:45:51.390167 17657 authenticator.hpp:398] Authentication requires more steps
I0123 07:45:51.390239 17657 authenticatee.hpp:275] Received SASL authentication step
I0123 07:45:51.390323 17657 authenticator.hpp:304] Received SASL authentication step
I0123 07:45:51.390416 17657 authenticator.hpp:390] Authentication success
I0123 07:45:51.390532 17657 authenticatee.hpp:315] Authentication success
I0123 07:45:51.390604 17657 master.cpp:4187] Successfully authenticated principal 'test-principal' at slave(182)@127.0.1.1:44955
I0123 07:45:51.390918 17657 slave.cpp:747] Successfully authenticated with master master@127.0.1.1:44955
I0123 07:45:51.395545 17657 master.cpp:3452] Re-registering slave 20150123-074549-16842879-44955-17634-S0 at slave(182)@127.0.1.1:44955 (utopic)
I0123 07:45:51.399631 17655 registrar.cpp:445] Applied 1 operations in 83007ns; attempting to update the 'registry'
I0123 07:45:51.411895 17660 log.cpp:684] Attempting to append 285 bytes to the log
I0123 07:45:51.412127 17660 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 7
I0123 07:45:51.413163 17660 replica.cpp:511] Replica received write request for position 7
I0123 07:45:51.417855 17660 leveldb.cpp:343] Persisting action (304 bytes) to leveldb took 4.658884ms
I0123 07:45:51.418076 17660 replica.cpp:679] Persisted action at 7
I0123 07:45:51.432068 17658 replica.cpp:658] Replica received learned notice for position 7
I0123 07:45:51.432921 17655 master.cpp:3445] Ignoring re-register slave message from slave 20150123-074549-16842879-44955-17634-S0 at slave(182)@127.0.1.1:44955 (utopic) as readmission is already in progress
I0123 07:45:51.435578 17658 leveldb.cpp:343] Persisting action (306 bytes) to leveldb took 3.478084ms
I0123 07:45:51.435611 17658 replica.cpp:679] Persisted action at 7
I0123 07:45:51.435634 17658 replica.cpp:664] Replica learned APPEND action at position 7
I0123 07:45:51.437288 17658 registrar.cpp:490] Successfully updated the 'registry' in 33.895936ms
I0123 07:45:51.437456 17655 log.cpp:703] Attempting to truncate the log to 7
I0123 07:45:51.437827 17655 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 8
I0123 07:45:51.438772 17655 replica.cpp:511] Replica received write request for position 8
I0123 07:45:51.439739 17659 master.hpp:782] Adding task 459233e7-b3a0-4367-aaee-4d1706988b1c with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20150123-074549-16842879-44955-17634-S0 (utopic)
I0123 07:45:51.440281 17659 master.cpp:3520] Re-registered slave 20150123-074549-16842879-44955-17634-S0 at slave(182)@127.0.1.1:44955 (utopic) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0123 07:45:51.440722 17659 hierarchical_allocator_process.hpp:453] Added slave 20150123-074549-16842879-44955-17634-S0 (utopic) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and available)
I0123 07:45:51.441057 17659 slave.cpp:849] Re-registered with master master@127.0.1.1:44955
I0123 07:45:51.441174 17659 slave.cpp:1762] Updating framework 20150123-074549-16842879-44955-17634-0000 pid to scheduler-a70d391c-9825-4fe6-8f73-70850700ea51@127.0.1.1:44955
I0123 07:45:51.441496 17660 status_update_manager.cpp:178] Resuming sending status updates
I0123 07:45:51.442297 17657 master.cpp:2961] Asked to kill task 459233e7-b3a0-4367-aaee-4d1706988b1c of framework 20150123-074549-16842879-44955-17634-0000
I0123 07:45:51.442404 17657 master.cpp:3021] Telling slave 20150123-074549-16842879-44955-17634-S0 at slave(182)@127.0.1.1:44955 (utopic) to kill task 459233e7-b3a0-4367-aaee-4d1706988b1c of framework 20150123-074549-16842879-44955-17634-0000 (default) at scheduler-a70d391c-9825-4fe6-8f73-70850700ea51@127.0.1.1:44955
I0123 07:45:51.442643 17655 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 3.839111ms
I0123 07:45:51.442957 17655 replica.cpp:679] Persisted action at 8
I0123 07:45:51.455999 17657 replica.cpp:658] Replica received learned notice for position 8
I0123 07:45:51.456774 17659 slave.cpp:1424] Asked to kill task 459233e7-b3a0-4367-aaee-4d1706988b1c of framework 20150123-074549-16842879-44955-17634-0000
I0123 07:45:51.456926 17658 status_update_manager.cpp:178] Resuming sending status updates
I0123 07:45:51.458889 17657 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 2.856951ms
I0123 07:45:51.458959 17657 leveldb.cpp:401] Deleting ~2 keys from leveldb took 37642ns
I0123 07:45:51.458979 17657 replica.cpp:679] Persisted action at 8
I0123 07:45:51.459002 17657 replica.cpp:664] Replica learned TRUNCATE action at position 8
I0123 07:45:51.651130 20401 exec.cpp:244] Executor re-registered on slave 20150123-074549-16842879-44955-17634-S0
Re-registered executor on utopic
Shutting down
Sending SIGTERM to process tree at pid 20409
Killing the following process trees:
[
-+- 20409 sh -c sleep 1000
\--- 20410 sleep 1000
]
Command terminated with signal Terminated (pid: 20409)
I0123 07:45:51.932518 17656 slave.cpp:2265] Handling status update TASK_KILLED (UUID: 4d6711eb-8268-4a68-b226-3b7857687c18) for task 459233e7-b3a0-4367-aaee-4d1706988b1c of framework 20150123-074549-16842879-44955-17634-0000 from executor(1)@127.0.1.1:33302
I0123 07:45:51.934726 17656 status_update_manager.cpp:317] Received status update TASK_KILLED (UUID: 4d6711eb-8268-4a68-b226-3b7857687c18) for task 459233e7-b3a0-4367-aaee-4d1706988b1c of framework 20150123-074549-16842879-44955-17634-0000
I0123 07:45:51.934804 17656 status_update_manager.hpp:346] Checkpointing UPDATE for status update TASK_KILLED (UUID: 4d6711eb-8268-4a68-b226-3b7857687c18) for task 459233e7-b3a0-4367-aaee-4d1706988b1c of framework 20150123-074549-16842879-44955-17634-0000
I0123 07:45:51.947357 17658 slave.cpp:2508] Forwarding the update TASK_KILLED (UUID: 4d6711eb-8268-4a68-b226-3b7857687c18) for task 459233e7-b3a0-4367-aaee-4d1706988b1c of framework 20150123-074549-16842879-44955-17634-0000 to master@127.0.1.1:44955
I0123 07:45:51.947723 17658 master.cpp:3652] Forwarding status update TASK_KILLED (UUID: 4d6711eb-8268-4a68-b226-3b7857687c18) for task 459233e7-b3a0-4367-aaee-4d1706988b1c of framework 20150123-074549-16842879-44955-17634-0000
I0123 07:45:51.947868 17658 master.cpp:3624] Status update TASK_KILLED (UUID: 4d6711eb-8268-4a68-b226-3b7857687c18) for task 459233e7-b3a0-4367-aaee-4d1706988b1c of framework 20150123-074549-16842879-44955-17634-0000 from slave 20150123-074549-16842879-44955-17634-S0 at slave(182)@127.0.1.1:44955 (utopic)
I0123 07:45:51.947947 17658 master.cpp:4934] Updating the latest state of task 459233e7-b3a0-4367-aaee-4d1706988b1c of framework 20150123-074549-16842879-44955-17634-0000 to TASK_KILLED
I0123 07:45:51.948683 17658 hierarchical_allocator_process.hpp:653] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total allocatable: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on slave 20150123-074549-16842879-44955-17634-S0 from framework 20150123-074549-16842879-44955-17634-0000
I0123 07:45:51.949165 17654 master.cpp:4993] Removing task 459233e7-b3a0-4367-aaee-4d1706988b1c with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework 20150123-074549-16842879-44955-17634-0000 on slave 20150123-074549-16842879-44955-17634-S0 at slave(182)@127.0.1.1:44955 (utopic)
I0123 07:45:51.949414 17654 master.cpp:3125] Forwarding status update acknowledgement 4d6711eb-8268-4a68-b226-3b7857687c18 for task 459233e7-b3a0-4367-aaee-4d1706988b1c of framework 20150123-074549-16842879-44955-17634-0000 (default) at scheduler-a70d391c-9825-4fe6-8f73-70850700ea51@127.0.1.1:44955 to slave 20150123-074549-16842879-44955-17634-S0 at slave(182)@127.0.1.1:44955 (utopic)
I0123 07:45:51.950338 17656 status_update_manager.cpp:389] Received status update acknowledgement (UUID: 4d6711eb-8268-4a68-b226-3b7857687c18) for task 459233e7-b3a0-4367-aaee-4d1706988b1c of framework 20150123-074549-16842879-44955-17634-0000
I0123 07:45:51.950426 17656 status_update_manager.hpp:346] Checkpointing ACK for status update TASK_KILLED (UUID: 4d6711eb-8268-4a68-b226-3b7857687c18) for task 459233e7-b3a0-4367-aaee-4d1706988b1c of framework 20150123-074549-16842879-44955-17634-0000
I0123 07:45:51.950980 17659 slave.cpp:2441] Sending acknowledgement for status update TASK_KILLED (UUID: 4d6711eb-8268-4a68-b226-3b7857687c18) for task 459233e7-b3a0-4367-aaee-4d1706988b1c of framework 20150123-074549-16842879-44955-17634-0000 to executor(1)@127.0.1.1:33302
2015-01-23 07:45:51,987:17634(0x7f976dc4b700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:52495] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
I0123 07:45:52.379093 17659 master.cpp:4071] Sending 1 offers to framework 20150123-074549-16842879-44955-17634-0000 (default) at scheduler-a70d391c-9825-4fe6-8f73-70850700ea51@127.0.1.1:44955
2015-01-23 07:45:55,323:17634(0x7f976dc4b700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:52495] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
2015-01-23 07:45:58,663:17634(0x7f976dc4b700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:52495] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
2015-01-23 07:46:02,003:17634(0x7f976dc4b700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:52495] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
../../src/tests/slave_recovery_tests.cpp:2841: Failure
Failed to wait 10secs for executorTerminated
I0123 07:46:02.406190 17661 master.cpp:745] Framework 20150123-074549-16842879-44955-17634-0000 (default) at scheduler-a70d391c-9825-4fe6-8f73-70850700ea51@127.0.1.1:44955 disconnected
I0123 07:46:02.406302 17661 master.cpp:1789] Disconnecting framework 20150123-074549-16842879-44955-17634-0000 (default) at scheduler-a70d391c-9825-4fe6-8f73-70850700ea51@127.0.1.1:44955
I0123 07:46:02.406369 17661 master.cpp:1805] Deactivating framework 20150123-074549-16842879-44955-17634-0000 (default) at scheduler-a70d391c-9825-4fe6-8f73-70850700ea51@127.0.1.1:44955
I0123 07:46:02.407075 17661 master.cpp:767] Giving framework 20150123-074549-16842879-44955-17634-0000 (default) at scheduler-a70d391c-9825-4fe6-8f73-70850700ea51@127.0.1.1:44955 0ns to failover
I0123 07:46:02.411994 17660 hierarchical_allocator_process.hpp:398] Deactivated framework 20150123-074549-16842879-44955-17634-0000
I0123 07:46:02.412348 17660 hierarchical_allocator_process.hpp:653] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total allocatable: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on slave 20150123-074549-16842879-44955-17634-S0 from framework 20150123-074549-16842879-44955-17634-0000
I0123 07:46:02.416890 17655 master.cpp:654] Master terminating
I0123 07:46:02.419524 17654 slave.cpp:2673] master@127.0.1.1:44955 exited
W0123 07:46:02.419587 17654 slave.cpp:2676] Master disconnected! Waiting for a new master to be elected
I0123 07:46:02.469024 17657 containerizer.cpp:879] Destroying container '852caf33-5860-488f-b8da-256908d79e64'
I0123 07:46:02.584841 17654 containerizer.cpp:1084] Executor for container '852caf33-5860-488f-b8da-256908d79e64' has exited
I0123 07:46:02.590347 17656 slave.cpp:2948] Executor '459233e7-b3a0-4367-aaee-4d1706988b1c' of framework 20150123-074549-16842879-44955-17634-0000 terminated with signal Killed
I0123 07:46:02.590734 17656 slave.cpp:3057] Cleaning up executor '459233e7-b3a0-4367-aaee-4d1706988b1c' of framework 20150123-074549-16842879-44955-17634-0000
I0123 07:46:02.591828 17661 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_MasterFailover_RIevEf/slaves/20150123-074549-16842879-44955-17634-S0/frameworks/20150123-074549-16842879-44955-17634-0000/executors/459233e7-b3a0-4367-aaee-4d1706988b1c/runs/852caf33-5860-488f-b8da-256908d79e64' for gc 6.99999315785778days in the future
I0123 07:46:02.592452 17656 slave.cpp:3136] Cleaning up framework 20150123-074549-16842879-44955-17634-0000
I0123 07:46:02.592773 17656 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_MasterFailover_RIevEf/slaves/20150123-074549-16842879-44955-17634-S0/frameworks/20150123-074549-16842879-44955-17634-0000/executors/459233e7-b3a0-4367-aaee-4d1706988b1c' for gc 6.99999314576296days in the future
I0123 07:46:02.592880 17661 status_update_manager.cpp:279] Closing status update streams for framework 20150123-074549-16842879-44955-17634-0000
I0123 07:46:02.593117 17656 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_MasterFailover_RIevEf/meta/slaves/20150123-074549-16842879-44955-17634-S0/frameworks/20150123-074549-16842879-44955-17634-0000/executors/459233e7-b3a0-4367-aaee-4d1706988b1c/runs/852caf33-5860-488f-b8da-256908d79e64' for gc 6.99999314486222days in the future
I0123 07:46:02.593353 17656 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_MasterFailover_RIevEf/meta/slaves/20150123-074549-16842879-44955-17634-S0/frameworks/20150123-074549-16842879-44955-17634-0000/executors/459233e7-b3a0-4367-aaee-4d1706988b1c' for gc 6.99999314421333days in the future
I0123 07:46:02.593595 17656 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_MasterFailover_RIevEf/slaves/20150123-074549-16842879-44955-17634-S0/frameworks/20150123-074549-16842879-44955-17634-0000' for gc 6.99999314078519days in the future
I0123 07:46:02.593777 17656 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_MasterFailover_RIevEf/meta/slaves/20150123-074549-16842879-44955-17634-S0/frameworks/20150123-074549-16842879-44955-17634-0000' for gc 6.9999931401037days in the future
I0123 07:46:02.595842 17634 slave.cpp:495] Slave terminating
[ FAILED ] SlaveRecoveryTest/0.MasterFailover, where TypeParam = mesos::internal::slave::MesosContainerizer (12840 ms)
{noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)