You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@mesos.apache.org by "Dominic Hamon (JIRA)" <ji...@apache.org> on 2014/06/10 22:41:02 UTC
[jira] [Commented] (MESOS-1437)
SlaveRecoveryTest/0.RestartBeforeContainerizerLaunch is flaky
[ https://issues.apache.org/jira/browse/MESOS-1437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14026966#comment-14026966 ]
Dominic Hamon commented on MESOS-1437:
--------------------------------------
https://reviews.apache.org/r/22441/
> SlaveRecoveryTest/0.RestartBeforeContainerizerLaunch is flaky
> -------------------------------------------------------------
>
> Key: MESOS-1437
> URL: https://issues.apache.org/jira/browse/MESOS-1437
> Project: Mesos
> Issue Type: Bug
> Components: test
> Affects Versions: 0.19.0
> Environment: ubuntu-14.04-gcc
> Reporter: Yan Xu
> Assignee: Dominic Hamon
>
> {noformat}
> [ RUN ] SlaveRecoveryTest/0.RestartBeforeContainerizerLaunch
> Using temporary directory '/tmp/SlaveRecoveryTest_0_RestartBeforeContainerizerLaunch_lUbOAD'
> I0529 09:29:24.491727 18175 leveldb.cpp:176] Opened db in 3.742412ms
> I0529 09:29:24.493413 18175 leveldb.cpp:183] Compacted db in 1.183942ms
> I0529 09:29:24.493865 18175 leveldb.cpp:198] Created db iterator in 6242ns
> I0529 09:29:24.494138 18175 leveldb.cpp:204] Seeked to beginning of db in 1213ns
> I0529 09:29:24.494526 18175 leveldb.cpp:273] Iterated through 0 keys in the db in 638ns
> I0529 09:29:24.494839 18175 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> I0529 09:29:24.495407 18197 recover.cpp:425] Starting replica recovery
> I0529 09:29:24.495491 18197 recover.cpp:451] Replica is in EMPTY status
> I0529 09:29:24.495844 18197 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request
> I0529 09:29:24.495916 18197 recover.cpp:188] Received a recover response from a replica in EMPTY status
> I0529 09:29:24.496022 18197 recover.cpp:542] Updating replica status to STARTING
> I0529 09:29:24.497161 18194 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 844433ns
> I0529 09:29:24.497185 18194 replica.cpp:320] Persisted replica status to STARTING
> I0529 09:29:24.497251 18194 recover.cpp:451] Replica is in STARTING status
> I0529 09:29:24.497478 18194 replica.cpp:638] Replica in STARTING status received a broadcasted recover request
> I0529 09:29:24.497534 18194 recover.cpp:188] Received a recover response from a replica in STARTING status
> I0529 09:29:24.497622 18194 recover.cpp:542] Updating replica status to VOTING
> I0529 09:29:24.498047 18194 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 376402ns
> I0529 09:29:24.498067 18194 replica.cpp:320] Persisted replica status to VOTING
> I0529 09:29:24.498108 18194 recover.cpp:556] Successfully joined the Paxos group
> I0529 09:29:24.498159 18194 recover.cpp:440] Recover process terminated
> I0529 09:29:24.503008 18196 master.cpp:272] Master 20140529-092924-16842879-48472-18175 (trusty) started on 127.0.1.1:48472
> I0529 09:29:24.503432 18196 master.cpp:309] Master only allowing authenticated frameworks to register
> I0529 09:29:24.503765 18196 master.cpp:314] Master only allowing authenticated slaves to register
> I0529 09:29:24.504178 18196 credentials.hpp:35] Loading credentials for authentication from '/tmp/SlaveRecoveryTest_0_RestartBeforeContainerizerLaunch_lUbOAD/credentials'
> I0529 09:29:24.504432 18196 master.cpp:340] Master enabling authorization
> I0529 09:29:24.504879 18200 hierarchical_allocator_process.hpp:301] Initializing hierarchical allocator process with master : master@127.0.1.1:48472
> I0529 09:29:24.505163 18198 master.cpp:108] No whitelist given. Advertising offers for all slaves
> I0529 09:29:24.506216 18196 master.cpp:957] The newly elected leader is master@127.0.1.1:48472 with id 20140529-092924-16842879-48472-18175
> I0529 09:29:24.506657 18196 master.cpp:970] Elected as the leading master!
> I0529 09:29:24.506963 18196 master.cpp:788] Recovering from registrar
> I0529 09:29:24.507419 18201 registrar.cpp:313] Recovering registrar
> I0529 09:29:24.507659 18194 log.cpp:656] Attempting to start the writer
> I0529 09:29:24.507969 18194 replica.cpp:474] Replica received implicit promise request with proposal 1
> I0529 09:29:24.508533 18194 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 540486ns
> I0529 09:29:24.508553 18194 replica.cpp:342] Persisted promised to 1
> I0529 09:29:24.508718 18194 coordinator.cpp:230] Coordinator attemping to fill missing position
> I0529 09:29:24.509006 18194 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
> I0529 09:29:24.509305 18194 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 278308ns
> I0529 09:29:24.509552 18194 replica.cpp:676] Persisted action at 0
> I0529 09:29:24.510025 18194 replica.cpp:508] Replica received write request for position 0
> I0529 09:29:24.510303 18194 leveldb.cpp:438] Reading position from leveldb took 16831ns
> I0529 09:29:24.510577 18194 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 252132ns
> I0529 09:29:24.510615 18194 replica.cpp:676] Persisted action at 0
> I0529 09:29:24.514835 18197 replica.cpp:655] Replica received learned notice for position 0
> I0529 09:29:24.515504 18197 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 639727ns
> I0529 09:29:24.515524 18197 replica.cpp:676] Persisted action at 0
> I0529 09:29:24.515534 18197 replica.cpp:661] Replica learned NOP action at position 0
> I0529 09:29:24.515691 18197 log.cpp:672] Writer started with ending position 0
> I0529 09:29:24.516027 18198 leveldb.cpp:438] Reading position from leveldb took 11426ns
> I0529 09:29:24.517470 18198 registrar.cpp:346] Successfully fetched the registry (0B)
> I0529 09:29:24.517500 18198 registrar.cpp:422] Attempting to update the 'registry'
> I0529 09:29:24.519122 18199 log.cpp:680] Attempting to append 119 bytes to the log
> I0529 09:29:24.519177 18199 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
> I0529 09:29:24.519358 18199 replica.cpp:508] Replica received write request for position 1
> I0529 09:29:24.520508 18199 leveldb.cpp:343] Persisting action (136 bytes) to leveldb took 1.12638ms
> I0529 09:29:24.520544 18199 replica.cpp:676] Persisted action at 1
> I0529 09:29:24.520712 18199 replica.cpp:655] Replica received learned notice for position 1
> I0529 09:29:24.521198 18199 leveldb.cpp:343] Persisting action (138 bytes) to leveldb took 464062ns
> I0529 09:29:24.521219 18199 replica.cpp:676] Persisted action at 1
> I0529 09:29:24.521229 18199 replica.cpp:661] Replica learned APPEND action at position 1
> I0529 09:29:24.521467 18199 registrar.cpp:479] Successfully updated 'registry'
> I0529 09:29:24.521507 18199 registrar.cpp:372] Successfully recovered registrar
> I0529 09:29:24.521543 18199 log.cpp:699] Attempting to truncate the log to 1
> I0529 09:29:24.521605 18199 master.cpp:815] Recovered 0 slaves from the Registry (83B) ; allowing 10mins for slaves to re-register
> I0529 09:29:24.521646 18199 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
> I0529 09:29:24.521832 18199 replica.cpp:508] Replica received write request for position 2
> I0529 09:29:24.522260 18199 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 405954ns
> I0529 09:29:24.522593 18199 replica.cpp:676] Persisted action at 2
> I0529 09:29:24.522948 18199 replica.cpp:655] Replica received learned notice for position 2
> I0529 09:29:24.524375 18199 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 1.142005ms
> I0529 09:29:24.524786 18199 leveldb.cpp:401] Deleting ~1 keys from leveldb took 24473ns
> I0529 09:29:24.525178 18199 replica.cpp:676] Persisted action at 2
> I0529 09:29:24.525440 18199 replica.cpp:661] Replica learned TRUNCATE action at position 2
> I0529 09:29:24.528745 18175 sched.cpp:126] Version: 0.19.0
> I0529 09:29:24.529137 18199 slave.cpp:143] Slave started on 136)@127.0.1.1:48472
> I0529 09:29:24.529464 18199 credentials.hpp:35] Loading credentials for authentication from '/tmp/SlaveRecoveryTest_0_RestartBeforeContainerizerLaunch_q4MPqy/credential'
> I0529 09:29:24.529770 18199 slave.cpp:242] Slave using credential for: test-principal
> I0529 09:29:24.529885 18199 slave.cpp:255] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0529 09:29:24.529955 18199 slave.cpp:283] Slave hostname: trusty
> I0529 09:29:24.529968 18199 slave.cpp:284] Slave checkpoint: true
> I0529 09:29:24.530727 18199 state.cpp:33] Recovering state from '/tmp/SlaveRecoveryTest_0_RestartBeforeContainerizerLaunch_q4MPqy/meta'
> I0529 09:29:24.530822 18199 status_update_manager.cpp:193] Recovering status update manager
> I0529 09:29:24.530894 18199 slave.cpp:3018] Finished recovery
> I0529 09:29:24.531134 18199 slave.cpp:536] New master detected at master@127.0.1.1:48472
> I0529 09:29:24.531162 18199 slave.cpp:612] Authenticating with master master@127.0.1.1:48472
> I0529 09:29:24.531199 18199 slave.cpp:585] Detecting new master
> I0529 09:29:24.531229 18199 status_update_manager.cpp:167] New master detected at master@127.0.1.1:48472
> I0529 09:29:24.531265 18199 authenticatee.hpp:128] Creating new client SASL connection
> I0529 09:29:24.531412 18199 master.cpp:2986] Authenticating slave(136)@127.0.1.1:48472
> I0529 09:29:24.531489 18199 authenticator.hpp:156] Creating new server SASL connection
> I0529 09:29:24.531599 18199 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0529 09:29:24.531620 18199 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0529 09:29:24.531644 18199 authenticator.hpp:262] Received SASL authentication start
> I0529 09:29:24.531680 18199 authenticator.hpp:384] Authentication requires more steps
> I0529 09:29:24.531707 18199 authenticatee.hpp:265] Received SASL authentication step
> I0529 09:29:24.531741 18199 authenticator.hpp:290] Received SASL authentication step
> I0529 09:29:24.531759 18199 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
> I0529 09:29:24.531767 18199 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0529 09:29:24.531780 18199 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0529 09:29:24.531790 18199 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
> I0529 09:29:24.531797 18199 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0529 09:29:24.531803 18199 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0529 09:29:24.531827 18199 authenticator.hpp:376] Authentication success
> I0529 09:29:24.531857 18199 authenticatee.hpp:305] Authentication success
> I0529 09:29:24.531882 18199 master.cpp:3026] Successfully authenticated principal 'test-principal' at slave(136)@127.0.1.1:48472
> I0529 09:29:24.531945 18199 slave.cpp:669] Successfully authenticated with master master@127.0.1.1:48472
> I0529 09:29:24.531986 18199 slave.cpp:902] Will retry registration in 3.076227ms if necessary
> I0529 09:29:24.532193 18196 master.cpp:2302] Registering slave at slave(136)@127.0.1.1:48472 (trusty) with id 20140529-092924-16842879-48472-18175-0
> I0529 09:29:24.532804 18197 registrar.cpp:422] Attempting to update the 'registry'
> I0529 09:29:24.533882 18201 log.cpp:680] Attempting to append 292 bytes to the log
> I0529 09:29:24.533936 18201 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
> I0529 09:29:24.534139 18201 replica.cpp:508] Replica received write request for position 3
> I0529 09:29:24.534694 18201 leveldb.cpp:343] Persisting action (311 bytes) to leveldb took 532639ns
> I0529 09:29:24.534715 18201 replica.cpp:676] Persisted action at 3
> I0529 09:29:24.535266 18194 replica.cpp:655] Replica received learned notice for position 3
> I0529 09:29:24.536165 18196 sched.cpp:222] New master detected at master@127.0.1.1:48472
> I0529 09:29:24.536190 18196 sched.cpp:273] Authenticating with master master@127.0.1.1:48472
> I0529 09:29:24.536586 18194 leveldb.cpp:343] Persisting action (313 bytes) to leveldb took 1.293153ms
> I0529 09:29:24.536613 18194 replica.cpp:676] Persisted action at 3
> I0529 09:29:24.536623 18194 replica.cpp:661] Replica learned APPEND action at position 3
> I0529 09:29:24.536893 18194 registrar.cpp:479] Successfully updated 'registry'
> I0529 09:29:24.536964 18194 log.cpp:699] Attempting to truncate the log to 3
> I0529 09:29:24.537014 18194 master.cpp:2342] Registered slave 20140529-092924-16842879-48472-18175-0 at slave(136)@127.0.1.1:48472 (trusty)
> I0529 09:29:24.537031 18194 master.cpp:3472] Adding slave 20140529-092924-16842879-48472-18175-0 at slave(136)@127.0.1.1:48472 (trusty) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0529 09:29:24.537122 18194 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
> I0529 09:29:24.537215 18194 hierarchical_allocator_process.hpp:444] Added slave 20140529-092924-16842879-48472-18175-0 (trusty) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
> I0529 09:29:24.537257 18194 hierarchical_allocator_process.hpp:707] Performed allocation for slave 20140529-092924-16842879-48472-18175-0 in 9613ns
> I0529 09:29:24.537389 18194 replica.cpp:508] Replica received write request for position 4
> I0529 09:29:24.536259 18196 authenticatee.hpp:128] Creating new client SASL connection
> I0529 09:29:24.538015 18196 master.cpp:2986] Authenticating scheduler(130)@127.0.1.1:48472
> I0529 09:29:24.538091 18196 authenticator.hpp:156] Creating new server SASL connection
> I0529 09:29:24.538194 18196 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0529 09:29:24.538214 18196 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0529 09:29:24.538238 18196 authenticator.hpp:262] Received SASL authentication start
> I0529 09:29:24.538272 18196 authenticator.hpp:384] Authentication requires more steps
> I0529 09:29:24.538297 18196 authenticatee.hpp:265] Received SASL authentication step
> I0529 09:29:24.538331 18196 authenticator.hpp:290] Received SASL authentication step
> I0529 09:29:24.538346 18196 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
> I0529 09:29:24.538354 18196 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0529 09:29:24.538365 18196 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0529 09:29:24.538374 18196 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
> I0529 09:29:24.538383 18196 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0529 09:29:24.538388 18196 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0529 09:29:24.538399 18196 authenticator.hpp:376] Authentication success
> I0529 09:29:24.538424 18196 authenticatee.hpp:305] Authentication success
> I0529 09:29:24.538570 18195 sched.cpp:347] Successfully authenticated with master master@127.0.1.1:48472
> I0529 09:29:24.538591 18195 sched.cpp:466] Sending registration request to master@127.0.1.1:48472
> I0529 09:29:24.538947 18201 slave.cpp:902] Will retry registration in 14.852555ms if necessary
> I0529 09:29:24.539002 18201 slave.cpp:703] Registered with master master@127.0.1.1:48472; given slave ID 20140529-092924-16842879-48472-18175-0
> I0529 09:29:24.539147 18201 slave.cpp:716] Checkpointing SlaveInfo to '/tmp/SlaveRecoveryTest_0_RestartBeforeContainerizerLaunch_q4MPqy/meta/slaves/20140529-092924-16842879-48472-18175-0/slave.info'
> I0529 09:29:24.539445 18194 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 2.035571ms
> I0529 09:29:24.539471 18194 replica.cpp:676] Persisted action at 4
> I0529 09:29:24.539649 18194 replica.cpp:655] Replica received learned notice for position 4
> I0529 09:29:24.539990 18196 master.cpp:3026] Successfully authenticated principal 'test-principal' at scheduler(130)@127.0.1.1:48472
> I0529 09:29:24.540099 18196 master.cpp:1041] Received registration request from scheduler(130)@127.0.1.1:48472
> I0529 09:29:24.540127 18196 master.cpp:1059] Registering framework 20140529-092924-16842879-48472-18175-0000 at scheduler(130)@127.0.1.1:48472
> I0529 09:29:24.540189 18196 master.cpp:2278] Slave 20140529-092924-16842879-48472-18175-0 at slave(136)@127.0.1.1:48472 (trusty) already registered, resending acknowledgement
> I0529 09:29:24.540230 18196 sched.cpp:397] Framework registered with 20140529-092924-16842879-48472-18175-0000
> I0529 09:29:24.540249 18196 sched.cpp:411] Scheduler::registered took 9083ns
> I0529 09:29:24.540282 18196 hierarchical_allocator_process.hpp:331] Added framework 20140529-092924-16842879-48472-18175-0000
> I0529 09:29:24.540318 18196 hierarchical_allocator_process.hpp:751] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140529-092924-16842879-48472-18175-0 to framework 20140529-092924-16842879-48472-18175-0000
> I0529 09:29:24.540398 18196 hierarchical_allocator_process.hpp:687] Performed allocation for 1 slaves in 103378ns
> W0529 09:29:24.540426 18196 slave.cpp:728] Already registered with master master@127.0.1.1:48472
> I0529 09:29:24.540478 18196 master.hpp:683] Adding offer 20140529-092924-16842879-48472-18175-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140529-092924-16842879-48472-18175-0 (trusty)
> I0529 09:29:24.540520 18196 master.cpp:2933] Sending 1 offers to framework 20140529-092924-16842879-48472-18175-0000
> I0529 09:29:24.540613 18196 sched.cpp:534] Scheduler::resourceOffers took 13742ns
> I0529 09:29:24.541463 18194 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 1.792617ms
> I0529 09:29:24.541507 18194 leveldb.cpp:401] Deleting ~2 keys from leveldb took 19301ns
> I0529 09:29:24.541520 18194 replica.cpp:676] Persisted action at 4
> I0529 09:29:24.541529 18194 replica.cpp:661] Replica learned TRUNCATE action at position 4
> I0529 09:29:24.542551 18196 master.hpp:693] Removing offer 20140529-092924-16842879-48472-18175-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140529-092924-16842879-48472-18175-0 (trusty)
> I0529 09:29:24.542899 18196 master.cpp:1889] Processing reply for offers: [ 20140529-092924-16842879-48472-18175-0 ] on slave 20140529-092924-16842879-48472-18175-0 at slave(136)@127.0.1.1:48472 (trusty) for framework 20140529-092924-16842879-48472-18175-0000
> I0529 09:29:24.543246 18196 master.hpp:655] Adding task 24a52e8f-0b30-4970-8829-a7383f19980e with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140529-092924-16842879-48472-18175-0 (trusty)
> I0529 09:29:24.543572 18196 master.cpp:3111] Launching task 24a52e8f-0b30-4970-8829-a7383f19980e of framework 20140529-092924-16842879-48472-18175-0000 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140529-092924-16842879-48472-18175-0 at slave(136)@127.0.1.1:48472 (trusty)
> I0529 09:29:24.544034 18195 slave.cpp:933] Got assigned task 24a52e8f-0b30-4970-8829-a7383f19980e for framework 20140529-092924-16842879-48472-18175-0000
> I0529 09:29:24.544123 18195 slave.cpp:3290] Checkpointing FrameworkInfo to '/tmp/SlaveRecoveryTest_0_RestartBeforeContainerizerLaunch_q4MPqy/meta/slaves/20140529-092924-16842879-48472-18175-0/frameworks/20140529-092924-16842879-48472-18175-0000/framework.info'
> I0529 09:29:24.544325 18195 slave.cpp:3297] Checkpointing framework pid 'scheduler(130)@127.0.1.1:48472' to '/tmp/SlaveRecoveryTest_0_RestartBeforeContainerizerLaunch_q4MPqy/meta/slaves/20140529-092924-16842879-48472-18175-0/frameworks/20140529-092924-16842879-48472-18175-0000/framework.pid'
> I0529 09:29:24.544543 18195 slave.cpp:1043] Launching task 24a52e8f-0b30-4970-8829-a7383f19980e for framework 20140529-092924-16842879-48472-18175-0000
> I0529 09:29:24.545670 18195 slave.cpp:3612] Checkpointing ExecutorInfo to '/tmp/SlaveRecoveryTest_0_RestartBeforeContainerizerLaunch_q4MPqy/meta/slaves/20140529-092924-16842879-48472-18175-0/frameworks/20140529-092924-16842879-48472-18175-0000/executors/24a52e8f-0b30-4970-8829-a7383f19980e/executor.info'
> I0529 09:29:24.546325 18195 slave.cpp:3727] Checkpointing TaskInfo to '/tmp/SlaveRecoveryTest_0_RestartBeforeContainerizerLaunch_q4MPqy/meta/slaves/20140529-092924-16842879-48472-18175-0/frameworks/20140529-092924-16842879-48472-18175-0000/executors/24a52e8f-0b30-4970-8829-a7383f19980e/runs/7fbaa2b9-d41e-4d3e-897f-3d593b1308c7/tasks/24a52e8f-0b30-4970-8829-a7383f19980e/task.info'
> I0529 09:29:24.546923 18195 slave.cpp:1153] Queuing task '24a52e8f-0b30-4970-8829-a7383f19980e' for executor 24a52e8f-0b30-4970-8829-a7383f19980e of framework '20140529-092924-16842879-48472-18175-0000
> E0529 09:29:24.547292 18195 slave.cpp:2397] Termination of executor '24a52e8f-0b30-4970-8829-a7383f19980e' of framework '20140529-092924-16842879-48472-18175-0000' failed: Unknown container: 7fbaa2b9-d41e-4d3e-897f-3d593b1308c7
> E0529 09:29:24.547698 18195 slave.cpp:2686] Failed to unmonitor container for executor 24a52e8f-0b30-4970-8829-a7383f19980e of framework 20140529-092924-16842879-48472-18175-0000: Not monitored
> I0529 09:29:24.548846 18195 slave.cpp:2018] Handling status update TASK_FAILED (UUID: aee0620e-c349-42ce-8cce-7b3835adad95) for task 24a52e8f-0b30-4970-8829-a7383f19980e of framework 20140529-092924-16842879-48472-18175-0000 from @0.0.0.0:0
> I0529 09:29:24.549253 18195 slave.cpp:3660] Terminating task 24a52e8f-0b30-4970-8829-a7383f19980e
> I0529 09:29:24.549710 18194 status_update_manager.cpp:320] Received status update TASK_FAILED (UUID: aee0620e-c349-42ce-8cce-7b3835adad95) for task 24a52e8f-0b30-4970-8829-a7383f19980e of framework 20140529-092924-16842879-48472-18175-0000
> I0529 09:29:24.549733 18194 status_update_manager.cpp:499] Creating StatusUpdate stream for task 24a52e8f-0b30-4970-8829-a7383f19980e of framework 20140529-092924-16842879-48472-18175-0000
> I0529 09:29:24.549865 18194 status_update_manager.hpp:342] Checkpointing UPDATE for status update TASK_FAILED (UUID: aee0620e-c349-42ce-8cce-7b3835adad95) for task 24a52e8f-0b30-4970-8829-a7383f19980e of framework 20140529-092924-16842879-48472-18175-0000
> I0529 09:29:24.550242 18195 slave.cpp:425] Slave terminating
> I0529 09:29:24.550930 18198 master.cpp:712] Slave 20140529-092924-16842879-48472-18175-0 at slave(136)@127.0.1.1:48472 (trusty) disconnected
> I0529 09:29:24.550952 18198 master.cpp:1344] Disconnecting slave 20140529-092924-16842879-48472-18175-0
> I0529 09:29:24.551013 18194 status_update_manager.cpp:373] Forwarding status update TASK_FAILED (UUID: aee0620e-c349-42ce-8cce-7b3835adad95) for task 24a52e8f-0b30-4970-8829-a7383f19980e of framework 20140529-092924-16842879-48472-18175-0000 to master@127.0.1.1:48472
> I0529 09:29:24.551261 18198 hierarchical_allocator_process.hpp:483] Slave 20140529-092924-16842879-48472-18175-0 disconnected
> I0529 09:29:24.551419 18194 master.cpp:2628] Status update TASK_FAILED (UUID: aee0620e-c349-42ce-8cce-7b3835adad95) for task 24a52e8f-0b30-4970-8829-a7383f19980e of framework 20140529-092924-16842879-48472-18175-0000 from slave 20140529-092924-16842879-48472-18175-0 at slave(136)@127.0.1.1:48472 (trusty)
> I0529 09:29:24.551475 18194 master.hpp:673] Removing task 24a52e8f-0b30-4970-8829-a7383f19980e with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140529-092924-16842879-48472-18175-0 (trusty)
> GMOCK WARNING:
> Uninteresting mock function call - returning directly.
> Function call: statusUpdate(0x7fff69ebf410, @0x2ad9c80de320 72-byte object <30-17 18-A5 D9-2A 00-00 00-00 00-00 00-00 00-00 D0-6B 0E-C8 D9-2A 00-00 50-4A 0E-C8 D9-2A 00-00 38-30 D1-00 00-00 00-00 90-F1 0D-C8 D9-2A 00-00 1B-13 63-6B 13-EB D4-41 03-00 00-00 00-00 00-00 37-00 00-00 00-00 00-00>)
> Stack trace:
> I0529 09:29:24.551668 18194 sched.cpp:625] Scheduler::statusUpdate took 87069ns
> I0529 09:29:24.552121 18194 hierarchical_allocator_process.hpp:636] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total allocatable: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on slave 20140529-092924-16842879-48472-18175-0 from framework 20140529-092924-16842879-48472-18175-0000
> I0529 09:29:24.560880 18197 slave.cpp:143] Slave started on 137)@127.0.1.1:48472
> I0529 09:29:24.560909 18197 credentials.hpp:35] Loading credentials for authentication from '/tmp/SlaveRecoveryTest_0_RestartBeforeContainerizerLaunch_q4MPqy/credential'
> I0529 09:29:24.560972 18197 slave.cpp:242] Slave using credential for: test-principal
> I0529 09:29:24.561058 18197 slave.cpp:255] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0529 09:29:24.561120 18197 slave.cpp:283] Slave hostname: trusty
> I0529 09:29:24.561133 18197 slave.cpp:284] Slave checkpoint: true
> I0529 09:29:24.561491 18197 state.cpp:33] Recovering state from '/tmp/SlaveRecoveryTest_0_RestartBeforeContainerizerLaunch_q4MPqy/meta'
> W0529 09:29:24.562824 18197 state.cpp:426] Failed to find executor forked pid file '/tmp/SlaveRecoveryTest_0_RestartBeforeContainerizerLaunch_q4MPqy/meta/slaves/20140529-092924-16842879-48472-18175-0/frameworks/20140529-092924-16842879-48472-18175-0000/executors/24a52e8f-0b30-4970-8829-a7383f19980e/runs/7fbaa2b9-d41e-4d3e-897f-3d593b1308c7/pids/forked.pid'
> I0529 09:29:24.563506 18201 slave.cpp:3086] Recovering framework 20140529-092924-16842879-48472-18175-0000
> I0529 09:29:24.563535 18201 slave.cpp:3462] Recovering executor '24a52e8f-0b30-4970-8829-a7383f19980e' of framework 20140529-092924-16842879-48472-18175-0000
> I0529 09:29:24.563608 18201 slave.cpp:3660] Terminating task 24a52e8f-0b30-4970-8829-a7383f19980e
> I0529 09:29:24.564241 18201 status_update_manager.cpp:193] Recovering status update manager
> I0529 09:29:24.564257 18201 status_update_manager.cpp:201] Recovering executor '24a52e8f-0b30-4970-8829-a7383f19980e' of framework 20140529-092924-16842879-48472-18175-0000
> I0529 09:29:24.564275 18201 status_update_manager.cpp:499] Creating StatusUpdate stream for task 24a52e8f-0b30-4970-8829-a7383f19980e of framework 20140529-092924-16842879-48472-18175-0000
> I0529 09:29:24.564371 18201 status_update_manager.hpp:306] Replaying status update stream for task 24a52e8f-0b30-4970-8829-a7383f19980e
> W0529 09:29:24.564391 18201 status_update_manager.cpp:381] Not forwarding status update TASK_FAILED (UUID: aee0620e-c349-42ce-8cce-7b3835adad95) for task 24a52e8f-0b30-4970-8829-a7383f19980e of framework 20140529-092924-16842879-48472-18175-0000 because no master is elected yet
> I0529 09:29:24.564512 18201 slave.cpp:497] Successfully attached file '/tmp/SlaveRecoveryTest_0_RestartBeforeContainerizerLaunch_q4MPqy/slaves/20140529-092924-16842879-48472-18175-0/frameworks/20140529-092924-16842879-48472-18175-0000/executors/24a52e8f-0b30-4970-8829-a7383f19980e/runs/7fbaa2b9-d41e-4d3e-897f-3d593b1308c7'
> I0529 09:29:24.564915 18194 slave.cpp:2967] Unable to reconnect to executor '24a52e8f-0b30-4970-8829-a7383f19980e' of framework 20140529-092924-16842879-48472-18175-0000 because no libprocess PID was found
> E0529 09:29:24.564950 18194 slave.cpp:2397] Termination of executor '24a52e8f-0b30-4970-8829-a7383f19980e' of framework '20140529-092924-16842879-48472-18175-0000' failed: Unknown container: 7fbaa2b9-d41e-4d3e-897f-3d593b1308c7
> E0529 09:29:24.565001 18194 slave.cpp:2686] Failed to unmonitor container for executor 24a52e8f-0b30-4970-8829-a7383f19980e of framework 20140529-092924-16842879-48472-18175-0000: Not monitored
> I0529 09:29:24.581280 18198 hierarchical_allocator_process.hpp:687] Performed allocation for 1 slaves in 56677ns
> I0529 09:29:24.581333 18198 slave.cpp:1967] Cleaning up un-reregistered executors
> I0529 09:29:24.581362 18198 slave.cpp:3018] Finished recovery
> I0529 09:29:24.581876 18198 slave.cpp:536] New master detected at master@127.0.1.1:48472
> I0529 09:29:24.581909 18198 slave.cpp:612] Authenticating with master master@127.0.1.1:48472
> I0529 09:29:24.581959 18198 slave.cpp:585] Detecting new master
> I0529 09:29:24.581992 18198 status_update_manager.cpp:167] New master detected at master@127.0.1.1:48472
> W0529 09:29:24.582008 18198 status_update_manager.cpp:181] Resending status update TASK_FAILED (UUID: aee0620e-c349-42ce-8cce-7b3835adad95) for task 24a52e8f-0b30-4970-8829-a7383f19980e of framework 20140529-092924-16842879-48472-18175-0000
> I0529 09:29:24.582025 18198 status_update_manager.cpp:373] Forwarding status update TASK_FAILED (UUID: aee0620e-c349-42ce-8cce-7b3835adad95) for task 24a52e8f-0b30-4970-8829-a7383f19980e of framework 20140529-092924-16842879-48472-18175-0000 to master@127.0.1.1:48472
> I0529 09:29:24.582099 18198 authenticatee.hpp:128] Creating new client SASL connection
> W0529 09:29:24.582298 18198 master.cpp:2621] Could not lookup task for status update TASK_FAILED (UUID: aee0620e-c349-42ce-8cce-7b3835adad95) for task 24a52e8f-0b30-4970-8829-a7383f19980e of framework 20140529-092924-16842879-48472-18175-0000 from slave 20140529-092924-16842879-48472-18175-0 at slave(136)@127.0.1.1:48472 (trusty)
> I0529 09:29:24.582356 18198 master.cpp:2986] Authenticating slave(137)@127.0.1.1:48472
> I0529 09:29:24.582557 18195 authenticator.hpp:156] Creating new server SASL connection
> I0529 09:29:24.582679 18195 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0529 09:29:24.582700 18195 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0529 09:29:24.582726 18195 authenticator.hpp:262] Received SASL authentication start
> I0529 09:29:24.582770 18195 authenticator.hpp:384] Authentication requires more steps
> I0529 09:29:24.582798 18195 authenticatee.hpp:265] Received SASL authentication step
> I0529 09:29:24.582834 18195 authenticator.hpp:290] Received SASL authentication step
> I0529 09:29:24.582852 18195 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
> I0529 09:29:24.582861 18195 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0529 09:29:24.582875 18195 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0529 09:29:24.582885 18195 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
> I0529 09:29:24.582892 18195 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0529 09:29:24.582898 18195 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0529 09:29:24.582911 18195 authenticator.hpp:376] Authentication success
> I0529 09:29:24.582938 18195 authenticatee.hpp:305] Authentication success
> I0529 09:29:24.582962 18195 master.cpp:3026] Successfully authenticated principal 'test-principal' at slave(137)@127.0.1.1:48472
> I0529 09:29:24.583034 18195 slave.cpp:669] Successfully authenticated with master master@127.0.1.1:48472
> I0529 09:29:24.583108 18195 slave.cpp:902] Will retry registration in 13.697338ms if necessary
> W0529 09:29:24.583199 18195 master.cpp:2417] Slave at slave(137)@127.0.1.1:48472 (trusty) is being allowed to re-register with an already in use id (20140529-092924-16842879-48472-18175-0)
> I0529 09:29:24.583282 18195 slave.cpp:753] Re-registered with master master@127.0.1.1:48472
> I0529 09:29:24.583312 18195 slave.cpp:1514] Updating framework 20140529-092924-16842879-48472-18175-0000 pid to scheduler(130)@127.0.1.1:48472
> I0529 09:29:24.583348 18195 slave.cpp:1522] Checkpointing framework pid 'scheduler(130)@127.0.1.1:48472' to '/tmp/SlaveRecoveryTest_0_RestartBeforeContainerizerLaunch_q4MPqy/meta/slaves/20140529-092924-16842879-48472-18175-0/frameworks/20140529-092924-16842879-48472-18175-0000/framework.pid'
> I0529 09:29:24.583536 18195 hierarchical_allocator_process.hpp:497] Slave 20140529-092924-16842879-48472-18175-0 reconnected
> W0529 09:29:24.583560 18195 status_update_manager.cpp:181] Resending status update TASK_FAILED (UUID: aee0620e-c349-42ce-8cce-7b3835adad95) for task 24a52e8f-0b30-4970-8829-a7383f19980e of framework 20140529-092924-16842879-48472-18175-0000
> I0529 09:29:24.583573 18195 status_update_manager.cpp:373] Forwarding status update TASK_FAILED (UUID: aee0620e-c349-42ce-8cce-7b3835adad95) for task 24a52e8f-0b30-4970-8829-a7383f19980e of framework 20140529-092924-16842879-48472-18175-0000 to master@127.0.1.1:48472
> W0529 09:29:24.583658 18195 master.cpp:2621] Could not lookup task for status update TASK_FAILED (UUID: aee0620e-c349-42ce-8cce-7b3835adad95) for task 24a52e8f-0b30-4970-8829-a7383f19980e of framework 20140529-092924-16842879-48472-18175-0000 from slave 20140529-092924-16842879-48472-18175-0 at slave(137)@127.0.1.1:48472 (trusty)
> I0529 09:29:24.584329 18198 sched.cpp:625] Scheduler::statusUpdate took 16101ns
> tests/slave_recovery_tests.cpp:3068: Failure
> Mock function called more times than expected - returning directly.
> Function call: statusUpdate(0x7fff69ebf410, @0x2ad9b40bc400 72-byte object <30-17 18-A5 D9-2A 00-00 00-00 00-00 00-00 00-00 90-31 03-B4 D9-2A 00-00 B0-B1 0F-B4 D9-2A 00-00 38-30 D1-00 00-00 00-00 A0-39 0C-B4 D9-2A 00-00 1B-13 63-6B 13-EB D4-41 03-00 00-00 00-00 00-00 37-00 00-00 00-00 00-00>)
> Expected: to be called once
> Actual: called twice - over-saturated and active
> I0529 09:29:24.584525 18198 sched.cpp:625] Scheduler::statusUpdate took 121892ns
> I0529 09:29:24.584609 18198 status_update_manager.cpp:398] Received status update acknowledgement (UUID: aee0620e-c349-42ce-8cce-7b3835adad95) for task 24a52e8f-0b30-4970-8829-a7383f19980e of framework 20140529-092924-16842879-48472-18175-0000
> I0529 09:29:24.584632 18198 status_update_manager.hpp:342] Checkpointing ACK for status update TASK_FAILED (UUID: aee0620e-c349-42ce-8cce-7b3835adad95) for task 24a52e8f-0b30-4970-8829-a7383f19980e of framework 20140529-092924-16842879-48472-18175-0000
> I0529 09:29:24.585109 18194 sched.cpp:730] Stopping framework '20140529-092924-16842879-48472-18175-0000'
> I0529 09:29:24.585196 18196 master.cpp:1272] Asked to unregister framework 20140529-092924-16842879-48472-18175-0000
> I0529 09:29:24.585211 18196 master.cpp:3344] Removing framework 20140529-092924-16842879-48472-18175-0000
> I0529 09:29:24.585304 18196 hierarchical_allocator_process.hpp:407] Deactivated framework 20140529-092924-16842879-48472-18175-0000
> I0529 09:29:24.585342 18196 hierarchical_allocator_process.hpp:362] Removed framework 20140529-092924-16842879-48472-18175-0000
> I0529 09:29:24.585366 18196 slave.cpp:1337] Asked to shut down framework 20140529-092924-16842879-48472-18175-0000 by master@127.0.1.1:48472
> I0529 09:29:24.585381 18196 slave.cpp:1362] Shutting down framework 20140529-092924-16842879-48472-18175-0000
> I0529 09:29:24.585396 18196 slave.cpp:2552] Cleaning up executor '24a52e8f-0b30-4970-8829-a7383f19980e' of framework 20140529-092924-16842879-48472-18175-0000
> I0529 09:29:24.585631 18196 slave.cpp:2627] Cleaning up framework 20140529-092924-16842879-48472-18175-0000
> I0529 09:29:24.585710 18196 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_RestartBeforeContainerizerLaunch_q4MPqy/slaves/20140529-092924-16842879-48472-18175-0/frameworks/20140529-092924-16842879-48472-18175-0000/executors/24a52e8f-0b30-4970-8829-a7383f19980e/runs/7fbaa2b9-d41e-4d3e-897f-3d593b1308c7' for gc 6.99999322304296days in the future
> I0529 09:29:24.585954 18196 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_RestartBeforeContainerizerLaunch_q4MPqy/slaves/20140529-092924-16842879-48472-18175-0/frameworks/20140529-092924-16842879-48472-18175-0000/executors/24a52e8f-0b30-4970-8829-a7383f19980e' for gc 6.99999322254518days in the future
> I0529 09:29:24.586061 18196 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_RestartBeforeContainerizerLaunch_q4MPqy/meta/slaves/20140529-092924-16842879-48472-18175-0/frameworks/20140529-092924-16842879-48472-18175-0000/executors/24a52e8f-0b30-4970-8829-a7383f19980e/runs/7fbaa2b9-d41e-4d3e-897f-3d593b1308c7' for gc 6.99999322225778days in the future
> I0529 09:29:24.586094 18196 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_RestartBeforeContainerizerLaunch_q4MPqy/meta/slaves/20140529-092924-16842879-48472-18175-0/frameworks/20140529-092924-16842879-48472-18175-0000/executors/24a52e8f-0b30-4970-8829-a7383f19980e' for gc 6.99999322199111days in the future
> I0529 09:29:24.586122 18196 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_RestartBeforeContainerizerLaunch_q4MPqy/slaves/20140529-092924-16842879-48472-18175-0/frameworks/20140529-092924-16842879-48472-18175-0000' for gc 6.99999322143407days in the future
> I0529 09:29:24.586148 18196 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_RestartBeforeContainerizerLaunch_q4MPqy/meta/slaves/20140529-092924-16842879-48472-18175-0/frameworks/20140529-092924-16842879-48472-18175-0000' for gc 6.99999322119111days in the future
> I0529 09:29:24.586599 18196 master.cpp:574] Master terminating
> I0529 09:29:24.589107 18199 slave.cpp:2224] master@127.0.1.1:48472 exited
> W0529 09:29:24.589130 18199 slave.cpp:2227] Master disconnected! Waiting for a new master to be elected
> I0529 09:29:24.589537 18198 status_update_manager.cpp:530] Cleaning up status update stream for task 24a52e8f-0b30-4970-8829-a7383f19980e of framework 20140529-092924-16842879-48472-18175-0000
> I0529 09:29:24.589920 18198 status_update_manager.cpp:398] Received status update acknowledgement (UUID: aee0620e-c349-42ce-8cce-7b3835adad95) for task 24a52e8f-0b30-4970-8829-a7383f19980e of framework 20140529-092924-16842879-48472-18175-0000
> I0529 09:29:24.590104 18199 slave.cpp:1604] Status update manager successfully handled status update acknowledgement (UUID: aee0620e-c349-42ce-8cce-7b3835adad95) for task 24a52e8f-0b30-4970-8829-a7383f19980e of framework 20140529-092924-16842879-48472-18175-0000
> E0529 09:29:24.590286 18199 slave.cpp:1615] Status update acknowledgement (UUID: aee0620e-c349-42ce-8cce-7b3835adad95) for task 24a52e8f-0b30-4970-8829-a7383f19980e of unknown framework 20140529-092924-16842879-48472-18175-0000
> I0529 09:29:24.590569 18198 status_update_manager.cpp:282] Closing status update streams for framework 20140529-092924-16842879-48472-18175-0000
> E0529 09:29:24.590759 18194 slave.cpp:1597] Failed to handle status update acknowledgement (UUID: aee0620e-c349-42ce-8cce-7b3835adad95) for task 24a52e8f-0b30-4970-8829-a7383f19980e of framework 20140529-092924-16842879-48472-18175-0000: Cannot find the status update stream for task 24a52e8f-0b30-4970-8829-a7383f19980e of framework 20140529-092924-16842879-48472-18175-0000
> I0529 09:29:24.592489 18175 slave.cpp:425] Slave terminating
> [ FAILED ] SlaveRecoveryTest/0.RestartBeforeContainerizerLaunch, where TypeParam = mesos::internal::slave::MesosContainerizer (112 ms)
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.2#6252)