Benjamin Mahler created MESOS-1603:
--------------------------------------
Summary: SlaveTest.TerminatingSlaveDoesNotReregister is flaky.
Key: MESOS-1603
URL: https://issues.apache.org/jira/browse/MESOS-1603
Project: Mesos
Issue Type: Bug
Components: test
Reporter: Benjamin Mahler
Assignee: Benjamin Mahler
{noformat}
[ RUN ] SlaveTest.TerminatingSlaveDoesNotReregister
Using temporary directory
'/tmp/SlaveTest_TerminatingSlaveDoesNotReregister_6OCQiU'
I0715 18:16:03.231495 5857 leveldb.cpp:176] Opened db in 27.552259ms
I0715 18:16:03.240953 5857 leveldb.cpp:183] Compacted db in 8.801497ms
I0715 18:16:03.241580 5857 leveldb.cpp:198] Created db iterator in 39823ns
I0715 18:16:03.241945 5857 leveldb.cpp:204] Seeked to beginning of db in
15498ns
I0715 18:16:03.242385 5857 leveldb.cpp:273] Iterated through 0 keys in the db
in 15153ns
I0715 18:16:03.242780 5857 replica.cpp:741] Replica recovered with log
positions 0 -> 0 with 1 holes and 0 unlearned
I0715 18:16:03.243475 5882 recover.cpp:425] Starting replica recovery
I0715 18:16:03.243540 5882 recover.cpp:451] Replica is in EMPTY status
I0715 18:16:03.243862 5882 replica.cpp:638] Replica in EMPTY status received a
broadcasted recover request
I0715 18:16:03.243919 5882 recover.cpp:188] Received a recover response from a
replica in EMPTY status
I0715 18:16:03.244112 5875 recover.cpp:542] Updating replica status to STARTING
I0715 18:16:03.249405 5880 master.cpp:288] Master
20140715-181603-16842879-36514-5857 (trusty) started on 127.0.1.1:36514
I0715 18:16:03.249445 5880 master.cpp:325] Master only allowing authenticated
frameworks to register
I0715 18:16:03.249454 5880 master.cpp:330] Master only allowing authenticated
slaves to register
I0715 18:16:03.249480 5880 credentials.hpp:36] Loading credentials for
authentication from
'/tmp/SlaveTest_TerminatingSlaveDoesNotReregister_6OCQiU/credentials'
I0715 18:16:03.250130 5880 master.cpp:359] Authorization enabled
I0715 18:16:03.250900 5880 hierarchical_allocator_process.hpp:301]
Initializing hierarchical allocator process with master : master@127.0.1.1:36514
I0715 18:16:03.250951 5880 master.cpp:122] No whitelist given. Advertising
offers for all slaves
I0715 18:16:03.251145 5880 master.cpp:1128] The newly elected leader is
master@127.0.1.1:36514 with id 20140715-181603-16842879-36514-5857
I0715 18:16:03.251164 5880 master.cpp:1141] Elected as the leading master!
I0715 18:16:03.251173 5880 master.cpp:959] Recovering from registrar
I0715 18:16:03.251225 5880 registrar.cpp:313] Recovering registrar
I0715 18:16:03.254640 5875 leveldb.cpp:306] Persisting metadata (8 bytes) to
leveldb took 10.421369ms
I0715 18:16:03.254683 5875 replica.cpp:320] Persisted replica status to
STARTING
I0715 18:16:03.254770 5875 recover.cpp:451] Replica is in STARTING status
I0715 18:16:03.255097 5875 replica.cpp:638] Replica in STARTING status
received a broadcasted recover request
I0715 18:16:03.255166 5875 recover.cpp:188] Received a recover response from a
replica in STARTING status
I0715 18:16:03.255280 5875 recover.cpp:542] Updating replica status to VOTING
I0715 18:16:03.263897 5875 leveldb.cpp:306] Persisting metadata (8 bytes) to
leveldb took 8.581313ms
I0715 18:16:03.263944 5875 replica.cpp:320] Persisted replica status to VOTING
I0715 18:16:03.264010 5875 recover.cpp:556] Successfully joined the Paxos group
I0715 18:16:03.264085 5875 recover.cpp:440] Recover process terminated
I0715 18:16:03.264227 5875 log.cpp:656] Attempting to start the writer
I0715 18:16:03.264570 5875 replica.cpp:474] Replica received implicit promise
request with proposal 1
I0715 18:16:03.322881 5875 leveldb.cpp:306] Persisting metadata (8 bytes) to
leveldb took 58.31469ms
I0715 18:16:03.323349 5875 replica.cpp:342] Persisted promised to 1
I0715 18:16:03.328495 5876 coordinator.cpp:230] Coordinator attemping to fill
missing position
I0715 18:16:03.328910 5876 replica.cpp:375] Replica received explicit promise
request for position 0 with proposal 2
I0715 18:16:03.338655 5876 leveldb.cpp:343] Persisting action (8 bytes) to
leveldb took 9.73834ms
I0715 18:16:03.338693 5876 replica.cpp:676] Persisted action at 0
I0715 18:16:03.338964 5876 replica.cpp:508] Replica received write request for
position 0
I0715 18:16:03.338997 5876 leveldb.cpp:438] Reading position from leveldb took
21691ns
I0715 18:16:03.349257 5876 leveldb.cpp:343] Persisting action (14 bytes) to
leveldb took 10.25515ms
I0715 18:16:03.349551 5876 replica.cpp:676] Persisted action at 0
I0715 18:16:03.354379 5877 replica.cpp:655] Replica received learned notice
for position 0
I0715 18:16:03.367383 5877 leveldb.cpp:343] Persisting action (16 bytes) to
leveldb took 12.99789ms
I0715 18:16:03.367434 5877 replica.cpp:676] Persisted action at 0
I0715 18:16:03.367444 5877 replica.cpp:661] Replica learned NOP action at
position 0
I0715 18:16:03.367688 5877 log.cpp:672] Writer started with ending position 0
I0715 18:16:03.367974 5877 leveldb.cpp:438] Reading position from leveldb took
29424ns
I0715 18:16:03.372969 5879 registrar.cpp:346] Successfully fetched the
registry (0B)
I0715 18:16:03.373006 5879 registrar.cpp:422] Attempting to update the
'registry'
I0715 18:16:03.374577 5878 log.cpp:680] Attempting to append 118 bytes to the
log
I0715 18:16:03.374641 5878 coordinator.cpp:340] Coordinator attempting to
write APPEND action at position 1
I0715 18:16:03.374858 5878 replica.cpp:508] Replica received write request for
position 1
I0715 18:16:03.385396 5878 leveldb.cpp:343] Persisting action (135 bytes) to
leveldb took 10.542293ms
I0715 18:16:03.385468 5878 replica.cpp:676] Persisted action at 1
I0715 18:16:03.385762 5878 replica.cpp:655] Replica received learned notice
for position 1
I0715 18:16:03.396587 5878 leveldb.cpp:343] Persisting action (137 bytes) to
leveldb took 10.837685ms
I0715 18:16:03.396683 5878 replica.cpp:676] Persisted action at 1
I0715 18:16:03.396697 5878 replica.cpp:661] Replica learned APPEND action at
position 1
I0715 18:16:03.397517 5878 registrar.cpp:479] Successfully updated 'registry'
I0715 18:16:03.397564 5878 registrar.cpp:372] Successfully recovered registrar
I0715 18:16:03.397626 5878 log.cpp:699] Attempting to truncate the log to 1
I0715 18:16:03.397745 5878 master.cpp:986] Recovered 0 slaves from the
Registry (82B) ; allowing 10mins for slaves to re-register
I0715 18:16:03.397802 5878 coordinator.cpp:340] Coordinator attempting to
write TRUNCATE action at position 2
I0715 18:16:03.398658 5879 replica.cpp:508] Replica received write request for
position 2
I0715 18:16:03.409629 5879 leveldb.cpp:343] Persisting action (16 bytes) to
leveldb took 10.960842ms
I0715 18:16:03.409679 5879 replica.cpp:676] Persisted action at 2
I0715 18:16:03.414571 5881 replica.cpp:655] Replica received learned notice
for position 2
I0715 18:16:03.424715 5881 leveldb.cpp:343] Persisting action (18 bytes) to
leveldb took 10.135639ms
I0715 18:16:03.424793 5881 leveldb.cpp:401] Deleting ~1 keys from leveldb took
40641ns
I0715 18:16:03.424810 5881 replica.cpp:676] Persisted action at 2
I0715 18:16:03.424820 5881 replica.cpp:661] Replica learned TRUNCATE action at
position 2
I0715 18:16:03.433630 5857 sched.cpp:139] Version: 0.20.0
I0715 18:16:03.434007 5875 slave.cpp:168] Slave started on 108)@127.0.1.1:36514
I0715 18:16:03.434711 5875 credentials.hpp:84] Loading credential for
authentication from
'/tmp/SlaveTest_TerminatingSlaveDoesNotReregister_h7Rohl/credential'
I0715 18:16:03.434808 5875 slave.cpp:266] Slave using credential for:
test-principal
I0715 18:16:03.434921 5875 slave.cpp:279] Slave resources: cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0715 18:16:03.434994 5875 slave.cpp:324] Slave hostname: trusty
I0715 18:16:03.435008 5875 slave.cpp:325] Slave checkpoint: false
I0715 18:16:03.435442 5875 state.cpp:33] Recovering state from
'/tmp/SlaveTest_TerminatingSlaveDoesNotReregister_h7Rohl/meta'
I0715 18:16:03.435578 5875 status_update_manager.cpp:193] Recovering status
update manager
I0715 18:16:03.435683 5875 slave.cpp:3130] Finished recovery
I0715 18:16:03.436012 5875 slave.cpp:603] New master detected at
master@127.0.1.1:36514
I0715 18:16:03.436039 5875 slave.cpp:679] Authenticating with master
master@127.0.1.1:36514
I0715 18:16:03.436105 5875 slave.cpp:652] Detecting new master
I0715 18:16:03.436143 5875 status_update_manager.cpp:167] New master detected
at master@127.0.1.1:36514
I0715 18:16:03.436187 5875 authenticatee.hpp:128] Creating new client SASL
connection
I0715 18:16:03.436374 5875 master.cpp:3512] Authenticating
slave(108)@127.0.1.1:36514
I0715 18:16:03.436499 5875 authenticator.hpp:156] Creating new server SASL
connection
I0715 18:16:03.436643 5875 authenticatee.hpp:219] Received SASL authentication
mechanisms: CRAM-MD5
I0715 18:16:03.436667 5875 authenticatee.hpp:245] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0715 18:16:03.436699 5875 authenticator.hpp:262] Received SASL authentication
start
I0715 18:16:03.436739 5875 authenticator.hpp:384] Authentication requires more
steps
I0715 18:16:03.436766 5875 authenticatee.hpp:265] Received SASL authentication
step
I0715 18:16:03.436801 5875 authenticator.hpp:290] Received SASL authentication
step
I0715 18:16:03.436818 5875 auxprop.cpp:81] Request to lookup properties for
user: 'test-principal' realm: 'trusty' server FQDN: 'trusty'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
I0715 18:16:03.436828 5875 auxprop.cpp:153] Looking up auxiliary property
'*userPassword'
I0715 18:16:03.436841 5875 auxprop.cpp:153] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0715 18:16:03.436853 5875 auxprop.cpp:81] Request to lookup properties for
user: 'test-principal' realm: 'trusty' server FQDN: 'trusty'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
I0715 18:16:03.436861 5875 auxprop.cpp:103] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0715 18:16:03.436868 5875 auxprop.cpp:103] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0715 18:16:03.436882 5875 authenticator.hpp:376] Authentication success
I0715 18:16:03.436908 5875 authenticatee.hpp:305] Authentication success
I0715 18:16:03.436929 5875 master.cpp:3552] Successfully authenticated
principal 'test-principal' at slave(108)@127.0.1.1:36514
I0715 18:16:03.437002 5875 slave.cpp:736] Successfully authenticated with
master master@127.0.1.1:36514
I0715 18:16:03.437039 5875 slave.cpp:974] Will retry registration in
18.234305ms if necessary
I0715 18:16:03.437165 5881 master.cpp:2789] Registering slave at
slave(108)@127.0.1.1:36514 (trusty) with id
20140715-181603-16842879-36514-5857-0
I0715 18:16:03.437278 5881 registrar.cpp:422] Attempting to update the
'registry'
I0715 18:16:03.438777 5879 log.cpp:680] Attempting to append 290 bytes to the
log
I0715 18:16:03.438833 5879 coordinator.cpp:340] Coordinator attempting to
write APPEND action at position 3
I0715 18:16:03.439064 5879 replica.cpp:508] Replica received write request for
position 3
I0715 18:16:03.439939 5878 sched.cpp:235] New master detected at
master@127.0.1.1:36514
I0715 18:16:03.439963 5878 sched.cpp:285] Authenticating with master
master@127.0.1.1:36514
I0715 18:16:03.440035 5878 authenticatee.hpp:128] Creating new client SASL
connection
I0715 18:16:03.440206 5878 master.cpp:3512] Authenticating
scheduler-7bee978f-e866-4187-aceb-50f0796f2ff7@127.0.1.1:36514
I0715 18:16:03.440282 5878 authenticator.hpp:156] Creating new server SASL
connection
I0715 18:16:03.440405 5878 authenticatee.hpp:219] Received SASL authentication
mechanisms: CRAM-MD5
I0715 18:16:03.440428 5878 authenticatee.hpp:245] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0715 18:16:03.440451 5878 authenticator.hpp:262] Received SASL authentication
start
I0715 18:16:03.440498 5878 authenticator.hpp:384] Authentication requires more
steps
I0715 18:16:03.440526 5878 authenticatee.hpp:265] Received SASL authentication
step
I0715 18:16:03.440557 5878 authenticator.hpp:290] Received SASL authentication
step
I0715 18:16:03.440573 5878 auxprop.cpp:81] Request to lookup properties for
user: 'test-principal' realm: 'trusty' server FQDN: 'trusty'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
I0715 18:16:03.440582 5878 auxprop.cpp:153] Looking up auxiliary property
'*userPassword'
I0715 18:16:03.440593 5878 auxprop.cpp:153] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0715 18:16:03.440604 5878 auxprop.cpp:81] Request to lookup properties for
user: 'test-principal' realm: 'trusty' server FQDN: 'trusty'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
I0715 18:16:03.440611 5878 auxprop.cpp:103] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0715 18:16:03.440618 5878 auxprop.cpp:103] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0715 18:16:03.440630 5878 authenticator.hpp:376] Authentication success
I0715 18:16:03.440656 5878 authenticatee.hpp:305] Authentication success
I0715 18:16:03.440678 5878 master.cpp:3552] Successfully authenticated
principal 'test-principal' at
scheduler-7bee978f-e866-4187-aceb-50f0796f2ff7@127.0.1.1:36514
I0715 18:16:03.440747 5878 sched.cpp:359] Successfully authenticated with
master master@127.0.1.1:36514
I0715 18:16:03.440762 5878 sched.cpp:478] Sending registration request to
master@127.0.1.1:36514
I0715 18:16:03.440819 5878 master.cpp:1247] Received registration request from
scheduler-7bee978f-e866-4187-aceb-50f0796f2ff7@127.0.1.1:36514
I0715 18:16:03.440836 5878 master.cpp:1207] Authorizing framework principal
'test-principal' to receive offers for role '*'
I0715 18:16:03.440964 5878 master.cpp:1306] Registering framework
20140715-181603-16842879-36514-5857-0000 at
scheduler-7bee978f-e866-4187-aceb-50f0796f2ff7@127.0.1.1:36514
I0715 18:16:03.441062 5878 sched.cpp:409] Framework registered with
20140715-181603-16842879-36514-5857-0000
I0715 18:16:03.441087 5878 sched.cpp:423] Scheduler::registered took 13975ns
I0715 18:16:03.441141 5878 hierarchical_allocator_process.hpp:331] Added
framework 20140715-181603-16842879-36514-5857-0000
I0715 18:16:03.441155 5878 hierarchical_allocator_process.hpp:724] No
resources available to allocate!
I0715 18:16:03.441162 5878 hierarchical_allocator_process.hpp:686] Performed
allocation for 0 slaves in 12893ns
I0715 18:16:03.448935 5879 leveldb.cpp:343] Persisting action (309 bytes) to
leveldb took 9.863974ms
I0715 18:16:03.448974 5879 replica.cpp:676] Persisted action at 3
I0715 18:16:03.449188 5879 replica.cpp:655] Replica received learned notice
for position 3
I0715 18:16:03.456302 5877 slave.cpp:974] Will retry registration in
33.136278ms if necessary
I0715 18:16:03.456385 5877 master.cpp:2777] Ignoring register slave message
from slave(108)@127.0.1.1:36514 (trusty) as admission is already in progress
I0715 18:16:03.460172 5879 leveldb.cpp:343] Persisting action (311 bytes) to
leveldb took 10.979854ms
I0715 18:16:03.460209 5879 replica.cpp:676] Persisted action at 3
I0715 18:16:03.460222 5879 replica.cpp:661] Replica learned APPEND action at
position 3
I0715 18:16:03.460597 5879 registrar.cpp:479] Successfully updated 'registry'
I0715 18:16:03.460685 5879 log.cpp:699] Attempting to truncate the log to 3
I0715 18:16:03.460747 5879 master.cpp:2829] Registered slave
20140715-181603-16842879-36514-5857-0 at slave(108)@127.0.1.1:36514 (trusty)
I0715 18:16:03.460764 5879 master.cpp:3980] Adding slave
20140715-181603-16842879-36514-5857-0 at slave(108)@127.0.1.1:36514 (trusty)
with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0715 18:16:03.460901 5879 coordinator.cpp:340] Coordinator attempting to
write TRUNCATE action at position 4
I0715 18:16:03.460975 5879 slave.cpp:770] Registered with master
master@127.0.1.1:36514; given slave ID 20140715-181603-16842879-36514-5857-0
I0715 18:16:03.461045 5879 hierarchical_allocator_process.hpp:444] Added slave
20140715-181603-16842879-36514-5857-0 (trusty) with cpus(*):2; mem(*):1024;
disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000] available)
I0715 18:16:03.461103 5879 hierarchical_allocator_process.hpp:750] Offering
cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
20140715-181603-16842879-36514-5857-0 to framework
20140715-181603-16842879-36514-5857-0000
I0715 18:16:03.461186 5879 hierarchical_allocator_process.hpp:706] Performed
allocation for slave 20140715-181603-16842879-36514-5857-0 in 119665ns
I0715 18:16:03.461241 5879 slave.cpp:2327] Received ping from
slave-observer(95)@127.0.1.1:36514
I0715 18:16:03.461310 5879 master.hpp:802] Adding offer
20140715-181603-16842879-36514-5857-0 with resources cpus(*):2; mem(*):1024;
disk(*):1024; ports(*):[31000-32000] on slave
20140715-181603-16842879-36514-5857-0 (trusty)
I0715 18:16:03.461354 5879 master.cpp:3459] Sending 1 offers to framework
20140715-181603-16842879-36514-5857-0000
I0715 18:16:03.461612 5879 sched.cpp:546] Scheduler::resourceOffers took
124246ns
I0715 18:16:03.461832 5879 master.hpp:812] Removing offer
20140715-181603-16842879-36514-5857-0 with resources cpus(*):2; mem(*):1024;
disk(*):1024; ports(*):[31000-32000] on slave
20140715-181603-16842879-36514-5857-0 (trusty)
I0715 18:16:03.461879 5879 master.cpp:2133] Processing reply for offers: [
20140715-181603-16842879-36514-5857-0 ] on slave
20140715-181603-16842879-36514-5857-0 at slave(108)@127.0.1.1:36514 (trusty)
for framework 20140715-181603-16842879-36514-5857-0000
I0715 18:16:03.461910 5879 master.cpp:2219] Authorizing framework principal
'test-principal' to launch task 0 as user 'jenkins'
I0715 18:16:03.462636 5877 replica.cpp:508] Replica received write request for
position 4
I0715 18:16:03.463337 5882 master.hpp:774] Adding task 0 with resources
cpus(*):1; mem(*):64 on slave 20140715-181603-16842879-36514-5857-0 (trusty)
I0715 18:16:03.463378 5882 master.cpp:2285] Launching task 0 of framework
20140715-181603-16842879-36514-5857-0000 with resources cpus(*):1; mem(*):64 on
slave 20140715-181603-16842879-36514-5857-0 at slave(108)@127.0.1.1:36514
(trusty)
I0715 18:16:03.463506 5882 slave.cpp:1005] Got assigned task 0 for framework
20140715-181603-16842879-36514-5857-0000
I0715 18:16:03.463758 5882 slave.cpp:1115] Launching task 0 for framework
20140715-181603-16842879-36514-5857-0000
I0715 18:16:03.465001 5876 hierarchical_allocator_process.hpp:546] Framework
20140715-181603-16842879-36514-5857-0000 left cpus(*):1; mem(*):960;
disk(*):1024; ports(*):[31000-32000] unused on slave
20140715-181603-16842879-36514-5857-0
I0715 18:16:03.465104 5876 hierarchical_allocator_process.hpp:588] Framework
20140715-181603-16842879-36514-5857-0000 filtered slave
20140715-181603-16842879-36514-5857-0 for 5secs
I0715 18:16:03.467053 5882 exec.cpp:131] Version: 0.20.0
I0715 18:16:03.467799 5880 exec.cpp:181] Executor started at:
executor(40)@127.0.1.1:36514 with pid 5857
I0715 18:16:03.468108 5882 slave.cpp:1225] Queuing task '0' for executor
default of framework '20140715-181603-16842879-36514-5857-0000
I0715 18:16:03.468487 5882 slave.cpp:564] Successfully attached file
'/tmp/SlaveTest_TerminatingSlaveDoesNotReregister_h7Rohl/slaves/20140715-181603-16842879-36514-5857-0/frameworks/20140715-181603-16842879-36514-5857-0000/executors/default/runs/b4458ecf-c062-4e6e-b7bb-25b0b6d16be7'
I0715 18:16:03.468945 5882 slave.cpp:1736] Got registration for executor
'default' of framework 20140715-181603-16842879-36514-5857-0000
I0715 18:16:03.469445 5876 exec.cpp:205] Executor registered on slave
20140715-181603-16842879-36514-5857-0
I0715 18:16:03.470674 5876 exec.cpp:217] Executor::registered took 34094ns
I0715 18:16:03.471213 5882 slave.cpp:1855] Flushing queued task 0 for executor
'default' of framework 20140715-181603-16842879-36514-5857-0000
I0715 18:16:03.471658 5881 exec.cpp:292] Executor asked to run task '0'
I0715 18:16:03.471715 5881 exec.cpp:301] Executor::launchTask took 44871ns
I0715 18:16:03.472210 5877 leveldb.cpp:343] Persisting action (16 bytes) to
leveldb took 9.561532ms
I0715 18:16:03.472239 5877 replica.cpp:676] Persisted action at 4
I0715 18:16:03.472455 5877 replica.cpp:655] Replica received learned notice
for position 4
I0715 18:16:03.473673 5881 exec.cpp:524] Executor sending status update
TASK_RUNNING (UUID: be5d205a-5d5f-4a3c-b4ae-f9eba8d45de1) for task 0 of
framework 20140715-181603-16842879-36514-5857-0000
I0715 18:16:03.474225 5882 slave.cpp:2472] Monitoring executor 'default' of
framework '20140715-181603-16842879-36514-5857-0000' in container
'b4458ecf-c062-4e6e-b7bb-25b0b6d16be7'
I0715 18:16:03.474766 5882 slave.cpp:2090] Handling status update TASK_RUNNING
(UUID: be5d205a-5d5f-4a3c-b4ae-f9eba8d45de1) for task 0 of framework
20140715-181603-16842879-36514-5857-0000 from executor(40)@127.0.1.1:36514
I0715 18:16:03.475308 5879 status_update_manager.cpp:320] Received status
update TASK_RUNNING (UUID: be5d205a-5d5f-4a3c-b4ae-f9eba8d45de1) for task 0 of
framework 20140715-181603-16842879-36514-5857-0000
I0715 18:16:03.475735 5879 status_update_manager.cpp:499] Creating
StatusUpdate stream for task 0 of framework
20140715-181603-16842879-36514-5857-0000
I0715 18:16:03.476150 5879 status_update_manager.cpp:373] Forwarding status
update TASK_RUNNING (UUID: be5d205a-5d5f-4a3c-b4ae-f9eba8d45de1) for task 0 of
framework 20140715-181603-16842879-36514-5857-0000 to master@127.0.1.1:36514
I0715 18:16:03.476629 5879 master.cpp:3120] Status update TASK_RUNNING (UUID:
be5d205a-5d5f-4a3c-b4ae-f9eba8d45de1) for task 0 of framework
20140715-181603-16842879-36514-5857-0000 from slave
20140715-181603-16842879-36514-5857-0 at slave(108)@127.0.1.1:36514 (trusty)
I0715 18:16:03.476893 5876 sched.cpp:637] Scheduler::statusUpdate took 30446ns
I0715 18:16:03.478320 5876 master.cpp:2639] Forwarding status update
acknowledgement be5d205a-5d5f-4a3c-b4ae-f9eba8d45de1 for task 0 of framework
20140715-181603-16842879-36514-5857-0000 to slave
20140715-181603-16842879-36514-5857-0 at slave(108)@127.0.1.1:36514 (trusty)
I0715 18:16:03.479068 5880 status_update_manager.cpp:398] Received status
update acknowledgement (UUID: be5d205a-5d5f-4a3c-b4ae-f9eba8d45de1) for task 0
of framework 20140715-181603-16842879-36514-5857-0000
I0715 18:16:03.479437 5882 slave.cpp:603] New master detected at
master@127.0.1.1:36514
I0715 18:16:03.479853 5882 slave.cpp:679] Authenticating with master
master@127.0.1.1:36514
I0715 18:16:03.480185 5879 status_update_manager.cpp:167] New master detected
at master@127.0.1.1:36514
I0715 18:16:03.480821 5878 authenticatee.hpp:128] Creating new client SASL
connection
I0715 18:16:03.480984 5878 master.cpp:1608] Disconnecting slave
20140715-181603-16842879-36514-5857-0
I0715 18:16:03.481015 5878 master.cpp:3512] Authenticating
slave(108)@127.0.1.1:36514
I0715 18:16:03.481096 5878 hierarchical_allocator_process.hpp:483] Slave
20140715-181603-16842879-36514-5857-0 disconnected
I0715 18:16:03.481127 5878 authenticator.hpp:156] Creating new server SASL
connection
I0715 18:16:03.481238 5878 authenticatee.hpp:219] Received SASL authentication
mechanisms: CRAM-MD5
I0715 18:16:03.481262 5878 authenticatee.hpp:245] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0715 18:16:03.481288 5878 authenticator.hpp:262] Received SASL authentication
start
I0715 18:16:03.481326 5878 authenticator.hpp:384] Authentication requires more
steps
I0715 18:16:03.481355 5878 authenticatee.hpp:265] Received SASL authentication
step
I0715 18:16:03.481392 5878 authenticator.hpp:290] Received SASL authentication
step
I0715 18:16:03.481410 5878 auxprop.cpp:81] Request to lookup properties for
user: 'test-principal' realm: 'trusty' server FQDN: 'trusty'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
I0715 18:16:03.481420 5878 auxprop.cpp:153] Looking up auxiliary property
'*userPassword'
I0715 18:16:03.481434 5878 auxprop.cpp:153] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0715 18:16:03.481446 5878 auxprop.cpp:81] Request to lookup properties for
user: 'test-principal' realm: 'trusty' server FQDN: 'trusty'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
I0715 18:16:03.481453 5878 auxprop.cpp:103] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0715 18:16:03.481461 5878 auxprop.cpp:103] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0715 18:16:03.481473 5878 authenticator.hpp:376] Authentication success
I0715 18:16:03.481501 5878 authenticatee.hpp:305] Authentication success
I0715 18:16:03.481520 5878 master.cpp:3552] Successfully authenticated
principal 'test-principal' at slave(108)@127.0.1.1:36514
I0715 18:16:03.481658 5877 leveldb.cpp:343] Persisting action (18 bytes) to
leveldb took 9.197034ms
I0715 18:16:03.481720 5877 leveldb.cpp:401] Deleting ~2 keys from leveldb took
42269ns
I0715 18:16:03.481736 5877 replica.cpp:676] Persisted action at 4
I0715 18:16:03.481746 5877 replica.cpp:661] Replica learned TRUNCATE action at
position 4
I0715 18:16:03.482575 5882 slave.cpp:652] Detecting new master
I0715 18:16:03.483158 5882 slave.cpp:2248] Status update manager successfully
handled status update TASK_RUNNING (UUID: be5d205a-5d5f-4a3c-b4ae-f9eba8d45de1)
for task 0 of framework 20140715-181603-16842879-36514-5857-0000
I0715 18:16:03.483580 5882 slave.cpp:2254] Sending acknowledgement for status
update TASK_RUNNING (UUID: be5d205a-5d5f-4a3c-b4ae-f9eba8d45de1) for task 0 of
framework 20140715-181603-16842879-36514-5857-0000 to
executor(40)@127.0.1.1:36514
I0715 18:16:03.484143 5880 exec.cpp:338] Executor received status update
acknowledgement be5d205a-5d5f-4a3c-b4ae-f9eba8d45de1 for task 0 of framework
20140715-181603-16842879-36514-5857-0000
I0715 18:16:03.484455 5882 slave.cpp:1676] Status update manager successfully
handled status update acknowledgement (UUID:
be5d205a-5d5f-4a3c-b4ae-f9eba8d45de1) for task 0 of framework
20140715-181603-16842879-36514-5857-0000
I0715 18:16:03.489369 5882 slave.cpp:736] Successfully authenticated with
master master@127.0.1.1:36514
W0715 18:16:03.490160 5878 master.cpp:2904] Slave at
slave(108)@127.0.1.1:36514 (trusty) is being allowed to re-register with an
already in use id (20140715-181603-16842879-36514-5857-0)
I0715 18:16:03.490360 5878 hierarchical_allocator_process.hpp:497] Slave
20140715-181603-16842879-36514-5857-0 reconnected
I0715 18:16:03.490674 5882 slave.cpp:974] Will retry registration in
5.578672ms if necessary
W0715 18:16:03.491215 5882 slave.cpp:1566] Dropping updateFramework message
for 20140715-181603-16842879-36514-5857-0000 because the slave is in
DISCONNECTED state
I0715 18:16:03.499841 5875 slave.cpp:532] ; unregistering and shutting down
I0715 18:16:03.499899 5875 slave.cpp:1409] Asked to shut down framework
20140715-181603-16842879-36514-5857-0000 by @0.0.0.0:0
I0715 18:16:03.499917 5875 slave.cpp:1434] Shutting down framework
20140715-181603-16842879-36514-5857-0000
I0715 18:16:03.499934 5875 slave.cpp:2810] Shutting down executor 'default' of
framework 20140715-181603-16842879-36514-5857-0000
I0715 18:16:03.499994 5875 master.cpp:3047] Asked to unregister slave
20140715-181603-16842879-36514-5857-0
I0715 18:16:03.500015 5875 master.cpp:4113] Removing slave
20140715-181603-16842879-36514-5857-0 at slave(108)@127.0.1.1:36514 (trusty)
I0715 18:16:03.500768 5876 hierarchical_allocator_process.hpp:469] Removed
slave 20140715-181603-16842879-36514-5857-0
I0715 18:16:03.501397 5875 master.hpp:792] Removing task 0 with resources
cpus(*):1; mem(*):64 on slave 20140715-181603-16842879-36514-5857-0 (trusty)
I0715 18:16:03.501669 5875 registrar.cpp:422] Attempting to update the
'registry'
I0715 18:16:03.503196 5876 slave.cpp:871] Skipping registration because slave
is terminating
I0715 18:16:03.503226 5876 slave.cpp:871] Skipping registration because slave
is terminating
I0715 18:16:03.503293 5876 slave.cpp:2912] Ignoring registration timeout for
executor 'default' because the framework
20140715-181603-16842879-36514-5857-0000 is terminating
I0715 18:16:03.503314 5876 slave.cpp:2880] Killing executor 'default' of
framework 20140715-181603-16842879-36514-5857-0000
I0715 18:16:03.503376 5876 slave.cpp:2985] Current usage 63.03%. Max allowed
age: 1.887698625683276days
I0715 18:16:03.503427 5876 slave.cpp:2530] Executor 'default' of framework
20140715-181603-16842879-36514-5857-0000 exited with status 0
I0715 18:16:03.503484 5876 slave.cpp:2664] Cleaning up executor 'default' of
framework 20140715-181603-16842879-36514-5857-0000
I0715 18:16:03.503592 5876 slave.cpp:2739] Cleaning up framework
20140715-181603-16842879-36514-5857-0000
I0715 18:16:03.503648 5876 slave.cpp:484] Slave terminating
I0715 18:16:03.503777 5876 hierarchical_allocator_process.hpp:724] No
resources available to allocate!
I0715 18:16:03.503789 5876 hierarchical_allocator_process.hpp:686] Performed
allocation for 0 slaves in 22130ns
W0715 18:16:03.503911 5876 master.cpp:3170] Ignoring exited executor 'default'
of framework 20140715-181603-16842879-36514-5857-0000 on deactivated slave
20140715-181603-16842879-36514-5857-0 ; asking slave to shutdown
I0715 18:16:03.503952 5876 master.cpp:122] No whitelist given. Advertising
offers for all slaves
I0715 18:16:03.503980 5876 status_update_manager.cpp:282] Closing status
update streams for framework 20140715-181603-16842879-36514-5857-0000
I0715 18:16:03.503994 5876 status_update_manager.cpp:530] Cleaning up status
update stream for task 0 of framework 20140715-181603-16842879-36514-5857-0000
I0715 18:16:03.504065 5876 gc.cpp:56] Scheduling
'/tmp/SlaveTest_TerminatingSlaveDoesNotReregister_h7Rohl/slaves/20140715-181603-16842879-36514-5857-0/frameworks/20140715-181603-16842879-36514-5857-0000/executors/default/runs/b4458ecf-c062-4e6e-b7bb-25b0b6d16be7'
for gc 6.99999447943111days in the future
I0715 18:16:03.504107 5876 gc.cpp:56] Scheduling
'/tmp/SlaveTest_TerminatingSlaveDoesNotReregister_h7Rohl/slaves/20140715-181603-16842879-36514-5857-0/frameworks/20140715-181603-16842879-36514-5857-0000/executors/default'
for gc 6.99999447943111days in the future
I0715 18:16:03.504134 5876 gc.cpp:56] Scheduling
'/tmp/SlaveTest_TerminatingSlaveDoesNotReregister_h7Rohl/slaves/20140715-181603-16842879-36514-5857-0/frameworks/20140715-181603-16842879-36514-5857-0000'
for gc 6.99999447943111days in the future
I0715 18:16:03.505105 5878 log.cpp:680] Attempting to append 120 bytes to the
log
I0715 18:16:03.505167 5878 coordinator.cpp:340] Coordinator attempting to
write APPEND action at position 5
I0715 18:16:03.505393 5878 replica.cpp:508] Replica received write request for
position 5
F0715 18:16:03.506721 5881 master.cpp:4206] Failed to remove slave
20140715-181603-16842879-36514-5857-0 (trusty) from the registrar: Failed to
update 'registry': Failed to perform store within 25secs
*** Check failure stack trace: ***
E0715 18:16:03.507683 5875 registrar.cpp:500] Registrar aborting: Failed to
update 'registry': Failed to perform store within 25secs
I0715 18:16:03.523195 5878 leveldb.cpp:343] Persisting action (137 bytes) to
leveldb took 17.799819ms
I0715 18:16:03.534334 5878 replica.cpp:676] Persisted action at 5
@ 0x2b61ece43db9 google::LogMessage::SendToLog()
@ 0x2b61ece4421f google::LogMessage::Flush()
@ 0x2b61ece47aac google::LogMessageFatal::~LogMessageFatal()
@ 0x2b61ec74680a mesos::internal::master::Master::_removeSlave()
@ 0x2b61ecd47400 process::ProcessManager::resume()
@ 0x2b61ecd46eef process::schedule()
@ 0x2b61eed4a182 start_thread
@ 0x2b61ef05b30d (unknown)
{noformat}
--
This message was sent by Atlassian JIRA
(v6.2#6252)
