[ https://issues.apache.org/jira/browse/MESOS-1603?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14063058#comment-14063058 ]
Benjamin Mahler commented on MESOS-1603: ---------------------------------------- Review: https://reviews.apache.org/r/23543/ > 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)