[
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 :
> [email protected]: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
> [email protected]: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
> [email protected]:36514
> I0715 18:16:03.436039 5875 slave.cpp:679] Authenticating with master
> [email protected]: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 [email protected]: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 [email protected]: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
> [email protected]:36514
> I0715 18:16:03.439963 5878 sched.cpp:285] Authenticating with master
> [email protected]: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
> [email protected]: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
> [email protected]:36514
> I0715 18:16:03.440747 5878 sched.cpp:359] Successfully authenticated with
> master [email protected]:36514
> I0715 18:16:03.440762 5878 sched.cpp:478] Sending registration request to
> [email protected]:36514
> I0715 18:16:03.440819 5878 master.cpp:1247] Received registration request
> from [email protected]: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
> [email protected]: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
> [email protected]: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
> [email protected]: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
> [email protected]:36514
> I0715 18:16:03.479853 5882 slave.cpp:679] Authenticating with master
> [email protected]:36514
> I0715 18:16:03.480185 5879 status_update_manager.cpp:167] New master
> detected at [email protected]: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 [email protected]: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)
