mesos-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Benjamin Mahler (JIRA)" <j...@apache.org>
Subject [jira] [Resolved] (MESOS-1460) SlaveTest.TerminatingSlaveDoesNotRegister is flaky
Date Wed, 16 Jul 2014 03:02:05 GMT

     [ https://issues.apache.org/jira/browse/MESOS-1460?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]

Benjamin Mahler resolved MESOS-1460.
------------------------------------

    Resolution: Fixed

{noformat}
commit ebee9afee7f6e5f04a5f259642c12eb0b99c35e0
Author: Yifan Gu <yifan@mesosphere.io>
Date:   Thu Jun 12 12:24:46 2014 -0700

    Fixed a flaky test: SlaveTest.TerminatingSlaveDoesNotReregister.

    Review: https://reviews.apache.org/r/22472
{noformat}

> SlaveTest.TerminatingSlaveDoesNotRegister is flaky
> --------------------------------------------------
>
>                 Key: MESOS-1460
>                 URL: https://issues.apache.org/jira/browse/MESOS-1460
>             Project: Mesos
>          Issue Type: Bug
>            Reporter: Dominic Hamon
>            Assignee: Yifan Gu
>
> [ RUN      ] SlaveTest.TerminatingSlaveDoesNotReregister
> Using temporary directory '/tmp/SlaveTest_TerminatingSlaveDoesNotReregister_U2FkN5'
> I0605 11:04:21.890828 32082 leveldb.cpp:176] Opened db in 49.661187ms
> I0605 11:04:21.908869 32082 leveldb.cpp:183] Compacted db in 17.671793ms
> I0605 11:04:21.909230 32082 leveldb.cpp:198] Created db iterator in 26848ns
> I0605 11:04:21.909484 32082 leveldb.cpp:204] Seeked to beginning of db in 1705ns
> I0605 11:04:21.909740 32082 leveldb.cpp:273] Iterated through 0 keys in the db in 815ns
> I0605 11:04:21.910032 32082 replica.cpp:741] Replica recovered with log positions 0 ->
0 with 1 holes and 0 unlearned
> I0605 11:04:21.910549 32105 recover.cpp:425] Starting replica recovery
> I0605 11:04:21.910626 32105 recover.cpp:451] Replica is in EMPTY status
> I0605 11:04:21.910951 32105 replica.cpp:638] Replica in EMPTY status received a broadcasted
recover request
> I0605 11:04:21.911013 32105 recover.cpp:188] Received a recover response from a replica
in EMPTY status
> I0605 11:04:21.911113 32105 recover.cpp:542] Updating replica status to STARTING
> I0605 11:04:21.914664 32109 master.cpp:272] Master 20140605-110421-16842879-56385-32082
(precise) started on 127.0.1.1:56385
> I0605 11:04:21.914690 32109 master.cpp:309] Master only allowing authenticated frameworks
to register
> I0605 11:04:21.914695 32109 master.cpp:314] Master only allowing authenticated slaves
to register
> I0605 11:04:21.914702 32109 credentials.hpp:35] Loading credentials for authentication
from '/tmp/SlaveTest_TerminatingSlaveDoesNotReregister_U2FkN5/credentials'
> I0605 11:04:21.914765 32109 master.cpp:340] Master enabling authorization
> I0605 11:04:21.915194 32109 hierarchical_allocator_process.hpp:301] Initializing hierarchical
allocator process with master : master@127.0.1.1:56385
> I0605 11:04:21.915230 32109 master.cpp:108] No whitelist given. Advertising offers for
all slaves
> I0605 11:04:21.915393 32109 master.cpp:957] The newly elected leader is master@127.0.1.1:56385
with id 20140605-110421-16842879-56385-32082
> I0605 11:04:21.915405 32109 master.cpp:970] Elected as the leading master!
> I0605 11:04:21.915410 32109 master.cpp:788] Recovering from registrar
> I0605 11:04:21.915458 32109 registrar.cpp:313] Recovering registrar
> I0605 11:04:21.931046 32105 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb
took 19.869329ms
> I0605 11:04:21.931084 32105 replica.cpp:320] Persisted replica status to STARTING
> I0605 11:04:21.931169 32105 recover.cpp:451] Replica is in STARTING status
> I0605 11:04:21.931500 32105 replica.cpp:638] Replica in STARTING status received a broadcasted
recover request
> I0605 11:04:21.931560 32105 recover.cpp:188] Received a recover response from a replica
in STARTING status
> I0605 11:04:21.931656 32105 recover.cpp:542] Updating replica status to VOTING
> I0605 11:04:21.945734 32105 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb
took 14.013731ms
> I0605 11:04:21.945791 32105 replica.cpp:320] Persisted replica status to VOTING
> I0605 11:04:21.945868 32105 recover.cpp:556] Successfully joined the Paxos group
> I0605 11:04:21.945930 32105 recover.cpp:440] Recover process terminated
> I0605 11:04:21.946071 32105 log.cpp:656] Attempting to start the writer
> I0605 11:04:21.946374 32105 replica.cpp:474] Replica received implicit promise request
with proposal 1
> I0605 11:04:21.960847 32105 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb
took 14.444258ms
> I0605 11:04:21.961493 32105 replica.cpp:342] Persisted promised to 1
> I0605 11:04:21.965292 32107 coordinator.cpp:230] Coordinator attemping to fill missing
position
> I0605 11:04:21.965626 32107 replica.cpp:375] Replica received explicit promise request
for position 0 with proposal 2
> I0605 11:04:21.982533 32107 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took
16.8754ms
> I0605 11:04:21.982589 32107 replica.cpp:676] Persisted action at 0
> I0605 11:04:21.982921 32107 replica.cpp:508] Replica received write request for position
0
> I0605 11:04:21.982952 32107 leveldb.cpp:438] Reading position from leveldb took 16276ns
> I0605 11:04:21.999135 32107 leveldb.cpp:343] Persisting action (14 bytes) to leveldb
took 16.154427ms
> I0605 11:04:21.999191 32107 replica.cpp:676] Persisted action at 0
> I0605 11:04:22.001211 32103 replica.cpp:655] Replica received learned notice for position
0
> I0605 11:04:22.014621 32103 leveldb.cpp:343] Persisting action (16 bytes) to leveldb
took 13.37031ms
> I0605 11:04:22.014683 32103 replica.cpp:676] Persisted action at 0
> I0605 11:04:22.014694 32103 replica.cpp:661] Replica learned NOP action at position 0
> I0605 11:04:22.014941 32103 log.cpp:672] Writer started with ending position 0
> I0605 11:04:22.015223 32103 leveldb.cpp:438] Reading position from leveldb took 20406ns
> I0605 11:04:22.016233 32103 registrar.cpp:346] Successfully fetched the registry (0B)
> I0605 11:04:22.016258 32103 registrar.cpp:422] Attempting to update the 'registry'
> I0605 11:04:22.017735 32106 log.cpp:680] Attempting to append 120 bytes to the log
> I0605 11:04:22.017787 32106 coordinator.cpp:340] Coordinator attempting to write APPEND
action at position 1
> I0605 11:04:22.018004 32106 replica.cpp:508] Replica received write request for position
1
> I0605 11:04:22.043967 32106 leveldb.cpp:343] Persisting action (137 bytes) to leveldb
took 25.928415ms
> I0605 11:04:22.044034 32106 replica.cpp:676] Persisted action at 1
> I0605 11:04:22.044303 32106 replica.cpp:655] Replica received learned notice for position
1
> I0605 11:04:22.061302 32106 leveldb.cpp:343] Persisting action (139 bytes) to leveldb
took 16.968126ms
> I0605 11:04:22.061359 32106 replica.cpp:676] Persisted action at 1
> I0605 11:04:22.061370 32106 replica.cpp:661] Replica learned APPEND action at position
1
> I0605 11:04:22.062038 32109 registrar.cpp:479] Successfully updated 'registry'
> I0605 11:04:22.062085 32109 registrar.cpp:372] Successfully recovered registrar
> I0605 11:04:22.062127 32109 log.cpp:699] Attempting to truncate the log to 1
> I0605 11:04:22.062206 32109 master.cpp:815] Recovered 0 slaves from the Registry (84B)
; allowing 10mins for slaves to re-register
> I0605 11:04:22.062463 32106 coordinator.cpp:340] Coordinator attempting to write TRUNCATE
action at position 2
> I0605 11:04:22.062707 32106 replica.cpp:508] Replica received write request for position
2
> I0605 11:04:22.073505 32102 slave.cpp:143] Slave started on 5)@127.0.1.1:56385
> I0605 11:04:22.073529 32102 credentials.hpp:35] Loading credentials for authentication
from '/tmp/SlaveTest_TerminatingSlaveDoesNotReregister_QvxNv8/credential'
> I0605 11:04:22.073588 32102 slave.cpp:243] Slave using credential for: test-principal
> I0605 11:04:22.073674 32102 slave.cpp:256] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000]
> I0605 11:04:22.073731 32102 slave.cpp:284] Slave hostname: precise
> I0605 11:04:22.073742 32102 slave.cpp:285] Slave checkpoint: false
> I0605 11:04:22.074093 32102 state.cpp:33] Recovering state from '/tmp/SlaveTest_TerminatingSlaveDoesNotReregister_QvxNv8/meta'
> I0605 11:04:22.074180 32102 status_update_manager.cpp:193] Recovering status update manager
> I0605 11:04:22.074251 32102 slave.cpp:3024] Finished recovery
> I0605 11:04:22.074486 32102 slave.cpp:537] New master detected at master@127.0.1.1:56385
> I0605 11:04:22.074509 32102 slave.cpp:613] Authenticating with master master@127.0.1.1:56385
> I0605 11:04:22.074548 32102 slave.cpp:586] Detecting new master
> I0605 11:04:22.074580 32102 status_update_manager.cpp:167] New master detected at master@127.0.1.1:56385
> I0605 11:04:22.074620 32102 authenticatee.hpp:128] Creating new client SASL connection
> I0605 11:04:22.074754 32102 master.cpp:2966] Authenticating slave(5)@127.0.1.1:56385
> I0605 11:04:22.074838 32102 authenticator.hpp:156] Creating new server SASL connection
> I0605 11:04:22.074939 32102 authenticatee.hpp:219] Received SASL authentication mechanisms:
CRAM-MD5
> I0605 11:04:22.074956 32102 authenticatee.hpp:245] Attempting to authenticate with mechanism
'CRAM-MD5'
> I0605 11:04:22.074978 32102 authenticator.hpp:262] Received SASL authentication start
> I0605 11:04:22.075008 32102 authenticator.hpp:384] Authentication requires more steps
> I0605 11:04:22.075032 32102 authenticatee.hpp:265] Received SASL authentication step
> I0605 11:04:22.075064 32102 authenticator.hpp:290] Received SASL authentication step
> I0605 11:04:22.075079 32102 auxprop.cpp:81] Request to lookup properties for user: 'test-principal'
realm: 'precise' server FQDN: 'precise' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE:
false SASL_AUXPROP_AUTHZID: false 
> I0605 11:04:22.075086 32102 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0605 11:04:22.075095 32102 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0605 11:04:22.075103 32102 auxprop.cpp:81] Request to lookup properties for user: 'test-principal'
realm: 'precise' server FQDN: 'precise' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE:
false SASL_AUXPROP_AUTHZID: true 
> I0605 11:04:22.075109 32102 auxprop.cpp:103] Skipping auxiliary property '*userPassword'
since SASL_AUXPROP_AUTHZID == true
> I0605 11:04:22.075114 32102 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5'
since SASL_AUXPROP_AUTHZID == true
> I0605 11:04:22.075124 32102 authenticator.hpp:376] Authentication success
> I0605 11:04:22.075147 32102 authenticatee.hpp:305] Authentication success
> I0605 11:04:22.075167 32102 master.cpp:3006] Successfully authenticated principal 'test-principal'
at slave(5)@127.0.1.1:56385
> I0605 11:04:22.075237 32102 slave.cpp:670] Successfully authenticated with master master@127.0.1.1:56385
> I0605 11:04:22.075273 32102 slave.cpp:908] Will retry registration in 11.843015ms if
necessary
> I0605 11:04:22.075364 32105 master.cpp:2282] Registering slave at slave(5)@127.0.1.1:56385
(precise) with id 20140605-110421-16842879-56385-32082-0
> I0605 11:04:22.075458 32105 registrar.cpp:422] Attempting to update the 'registry'
> I0605 11:04:22.078232 32106 leveldb.cpp:343] Persisting action (16 bytes) to leveldb
took 15.505512ms
> I0605 11:04:22.078258 32106 replica.cpp:676] Persisted action at 2
> I0605 11:04:22.078446 32106 replica.cpp:655] Replica received learned notice for position
2
> I0605 11:04:22.079107 32082 sched.cpp:128] Version: 0.20.0
> I0605 11:04:22.079500 32108 sched.cpp:224] New master detected at master@127.0.1.1:56385
> I0605 11:04:22.079524 32108 sched.cpp:274] Authenticating with master master@127.0.1.1:56385
> I0605 11:04:22.079591 32108 authenticatee.hpp:128] Creating new client SASL connection
> I0605 11:04:22.079715 32108 master.cpp:2966] Authenticating scheduler(4)@127.0.1.1:56385
> I0605 11:04:22.079787 32108 authenticator.hpp:156] Creating new server SASL connection
> I0605 11:04:22.079885 32108 authenticatee.hpp:219] Received SASL authentication mechanisms:
CRAM-MD5
> I0605 11:04:22.079901 32108 authenticatee.hpp:245] Attempting to authenticate with mechanism
'CRAM-MD5'
> I0605 11:04:22.079923 32108 authenticator.hpp:262] Received SASL authentication start
> I0605 11:04:22.079951 32108 authenticator.hpp:384] Authentication requires more steps
> I0605 11:04:22.079973 32108 authenticatee.hpp:265] Received SASL authentication step
> I0605 11:04:22.080024 32108 authenticator.hpp:290] Received SASL authentication step
> I0605 11:04:22.080039 32108 auxprop.cpp:81] Request to lookup properties for user: 'test-principal'
realm: 'precise' server FQDN: 'precise' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE:
false SASL_AUXPROP_AUTHZID: false 
> I0605 11:04:22.080045 32108 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0605 11:04:22.080054 32108 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0605 11:04:22.080061 32108 auxprop.cpp:81] Request to lookup properties for user: 'test-principal'
realm: 'precise' server FQDN: 'precise' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE:
false SASL_AUXPROP_AUTHZID: true 
> I0605 11:04:22.080067 32108 auxprop.cpp:103] Skipping auxiliary property '*userPassword'
since SASL_AUXPROP_AUTHZID == true
> I0605 11:04:22.080071 32108 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5'
since SASL_AUXPROP_AUTHZID == true
> I0605 11:04:22.080081 32108 authenticator.hpp:376] Authentication success
> I0605 11:04:22.080106 32108 authenticatee.hpp:305] Authentication success
> I0605 11:04:22.080127 32108 master.cpp:3006] Successfully authenticated principal 'test-principal'
at scheduler(4)@127.0.1.1:56385
> I0605 11:04:22.080184 32108 sched.cpp:348] Successfully authenticated with master master@127.0.1.1:56385
> I0605 11:04:22.080198 32108 sched.cpp:467] Sending registration request to master@127.0.1.1:56385
> I0605 11:04:22.080238 32108 master.cpp:1048] Received registration request from scheduler(4)@127.0.1.1:56385
> I0605 11:04:22.080271 32108 master.cpp:1066] Registering framework 20140605-110421-16842879-56385-32082-0000
at scheduler(4)@127.0.1.1:56385
> I0605 11:04:22.080369 32108 sched.cpp:398] Framework registered with 20140605-110421-16842879-56385-32082-0000
> GMOCK WARNING:
> Uninteresting mock function call - returning directly.
>     Function call: registered(0x7fff48aa2d30, @0x2b3c0805bab0 20140605-110421-16842879-56385-32082-0000,
@0x2b3c0800d4d0 id: "20140605-110421-16842879-56385-32082"
> ip: 16842879
> port: 56385
> pid: "master@127.0.1.1:56385"
> hostname: "precise"
> )
> Stack trace:
> I0605 11:04:22.080492 32108 sched.cpp:412] Scheduler::registered took 106995ns
> I0605 11:04:22.080530 32108 hierarchical_allocator_process.hpp:331] Added framework 20140605-110421-16842879-56385-32082-0000
> I0605 11:04:22.080539 32108 hierarchical_allocator_process.hpp:725] No resources available
to allocate!
> I0605 11:04:22.080544 32108 hierarchical_allocator_process.hpp:687] Performed allocation
for 0 slaves in 5863ns
> I0605 11:04:22.087327 32107 slave.cpp:908] Will retry registration in 11.16674ms if necessary
> I0605 11:04:22.087386 32107 master.cpp:2270] Ignoring register slave message from slave(5)@127.0.1.1:56385
(precise) as admission is already in progress
> I0605 11:04:22.098687 32107 slave.cpp:908] Will retry registration in 76.680692ms if
necessary
> I0605 11:04:22.098767 32107 master.cpp:2270] Ignoring register slave message from slave(5)@127.0.1.1:56385
(precise) as admission is already in progress
> I0605 11:04:22.104486 32106 leveldb.cpp:343] Persisting action (18 bytes) to leveldb
took 26.017598ms
> I0605 11:04:22.104552 32106 leveldb.cpp:401] Deleting ~1 keys from leveldb took 39795ns
> I0605 11:04:22.104565 32106 replica.cpp:676] Persisted action at 2
> I0605 11:04:22.104575 32106 replica.cpp:661] Replica learned TRUNCATE action at position
2
> I0605 11:04:22.104816 32106 log.cpp:680] Attempting to append 295 bytes to the log
> I0605 11:04:22.104862 32106 coordinator.cpp:340] Coordinator attempting to write APPEND
action at position 3
> I0605 11:04:22.105161 32106 replica.cpp:508] Replica received write request for position
3
> I0605 11:04:22.121690 32106 leveldb.cpp:343] Persisting action (314 bytes) to leveldb
took 16.505497ms
> I0605 11:04:22.121726 32106 replica.cpp:676] Persisted action at 3
> I0605 11:04:22.121932 32106 replica.cpp:655] Replica received learned notice for position
3
> I0605 11:04:22.139792 32106 leveldb.cpp:343] Persisting action (316 bytes) to leveldb
took 17.831905ms
> I0605 11:04:22.139848 32106 replica.cpp:676] Persisted action at 3
> I0605 11:04:22.139859 32106 replica.cpp:661] Replica learned APPEND action at position
3
> I0605 11:04:22.140244 32106 registrar.cpp:479] Successfully updated 'registry'
> I0605 11:04:22.140324 32106 log.cpp:699] Attempting to truncate the log to 3
> I0605 11:04:22.140383 32106 master.cpp:2322] Registered slave 20140605-110421-16842879-56385-32082-0
at slave(5)@127.0.1.1:56385 (precise)
> I0605 11:04:22.140400 32106 master.cpp:3452] Adding slave 20140605-110421-16842879-56385-32082-0
at slave(5)@127.0.1.1:56385 (precise) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0605 11:04:22.140507 32106 coordinator.cpp:340] Coordinator attempting to write TRUNCATE
action at position 4
> I0605 11:04:22.140580 32106 slave.cpp:704] Registered with master master@127.0.1.1:56385;
given slave ID 20140605-110421-16842879-56385-32082-0
> I0605 11:04:22.140645 32106 hierarchical_allocator_process.hpp:444] Added slave 20140605-110421-16842879-56385-32082-0
(precise) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
> I0605 11:04:22.140702 32106 hierarchical_allocator_process.hpp:751] Offering cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140605-110421-16842879-56385-32082-0
to framework 20140605-110421-16842879-56385-32082-0000
> I0605 11:04:22.140781 32106 hierarchical_allocator_process.hpp:707] Performed allocation
for slave 20140605-110421-16842879-56385-32082-0 in 105666ns
> I0605 11:04:22.140868 32106 master.hpp:693] Adding offer 20140605-110421-16842879-56385-32082-0
with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140605-110421-16842879-56385-32082-0
(precise)
> I0605 11:04:22.140909 32106 master.cpp:2913] Sending 1 offers to framework 20140605-110421-16842879-56385-32082-0000
> I0605 11:04:22.141733 32107 replica.cpp:508] Replica received write request for position
4
> I0605 11:04:22.142477 32106 sched.cpp:535] Scheduler::resourceOffers took 199520ns
> I0605 11:04:22.143035 32103 master.hpp:703] Removing offer 20140605-110421-16842879-56385-32082-0
with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140605-110421-16842879-56385-32082-0
(precise)
> I0605 11:04:22.143091 32103 master.cpp:1869] Processing reply for offers: [ 20140605-110421-16842879-56385-32082-0
] on slave 20140605-110421-16842879-56385-32082-0 at slave(5)@127.0.1.1:56385 (precise) for
framework 20140605-110421-16842879-56385-32082-0000
> I0605 11:04:22.143153 32103 master.hpp:665] Adding task 0 with resources cpus(*):1; mem(*):64
on slave 20140605-110421-16842879-56385-32082-0 (precise)
> I0605 11:04:22.143177 32103 master.cpp:3091] Launching task 0 of framework 20140605-110421-16842879-56385-32082-0000
with resources cpus(*):1; mem(*):64 on slave 20140605-110421-16842879-56385-32082-0 at slave(5)@127.0.1.1:56385
(precise)
> I0605 11:04:22.143323 32103 slave.cpp:939] Got assigned task 0 for framework 20140605-110421-16842879-56385-32082-0000
> I0605 11:04:22.143491 32103 slave.cpp:1049] Launching task 0 for framework 20140605-110421-16842879-56385-32082-0000
> I0605 11:04:22.145248 32105 hierarchical_allocator_process.hpp:546] Framework 20140605-110421-16842879-56385-32082-0000
left cpus(*):1; mem(*):960; disk(*):1024; ports(*):[31000-32000] unused on slave 20140605-110421-16842879-56385-32082-0
> I0605 11:04:22.145328 32105 hierarchical_allocator_process.hpp:589] Framework 20140605-110421-16842879-56385-32082-0000
filtered slave 20140605-110421-16842879-56385-32082-0 for 5secs
> I0605 11:04:22.146132 32103 exec.cpp:131] Version: 0.20.0
> I0605 11:04:22.146538 32102 exec.cpp:181] Executor started at: executor(2)@127.0.1.1:56385
with pid 32082
> I0605 11:04:22.146879 32103 slave.cpp:1159] Queuing task '0' for executor default of
framework '20140605-110421-16842879-56385-32082-0000
> I0605 11:04:22.147294 32103 slave.cpp:498] Successfully attached file '/tmp/SlaveTest_TerminatingSlaveDoesNotReregister_QvxNv8/slaves/20140605-110421-16842879-56385-32082-0/frameworks/20140605-110421-16842879-56385-32082-0000/executors/default/runs/b92544a4-53b5-4d0e-818e-d9420ddbb680'
> I0605 11:04:22.147743 32103 slave.cpp:1670] Got registration for executor 'default' of
framework 20140605-110421-16842879-56385-32082-0000
> I0605 11:04:22.148249 32104 exec.cpp:205] Executor registered on slave 20140605-110421-16842879-56385-32082-0
> GMOCK WARNING:
> Uninteresting mock function call - returning directly.
>     Function call: registered(0x2b3c18006fc0, @0x187be20 executor_id {
>   value: "default"
> }
> command {
>   value: "exit 1"
> }
> framework_id {
>   value: "20140605-110421-16842879-56385-32082-0000"
> }
> , @0x183f960 88-byte object <50-F0 61-03 3C-2B 00-00 00-00 00-00 00-00 00-00 10-BF
87-01 00-00 00-00 A0-6B 87-01 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00
00-99 7D-01 00-00 00-00 F0-49 89-01 00-00 00-00 D0-62 87-01 00-00 00-00 00-98 62-82 00-00
00-00 C3-00 00-00 00-00 00-00>, @0x183f600 hostname: "precise"
> webui_hostname: "precise"
> resources {
>   name: "cpus"
>   type: SCALAR
>   scalar {
>     value: 2
>   }
>   role: "*"
> }
> resources {
>   name: "mem"
>   type: SCALAR
>   scalar {
>     value: 1024
>   }
>   role: "*"
> }
> resources {
>   name: "disk"
>   type: SCALAR
>   scalar {
>     value: 1024
>   }
>   role: "*"
> }
> resources {
>   name: "ports"
>   type: RANGES
>   ranges {
>     range {
>       begin: 31000
>       end: 32000
>     }
>   }
>   role: "*"
> }
> id {
>   value: "20140605-110421-16842879-56385-32082-0"
> }
> checkpoint: false
> port: 56385
> )
> Stack trace:
> I0605 11:04:22.149577 32104 exec.cpp:217] Executor::registered took 481501ns
> I0605 11:04:22.149824 32103 slave.cpp:1789] Flushing queued task 0 for executor 'default'
of framework 20140605-110421-16842879-56385-32082-0000
> I0605 11:04:22.150399 32108 exec.cpp:292] Executor asked to run task '0'
> I0605 11:04:22.150459 32108 exec.cpp:301] Executor::launchTask took 36122ns
> I0605 11:04:22.151250 32108 exec.cpp:524] Executor sending status update TASK_RUNNING
(UUID: eafe4341-4aec-490a-a4d0-841201abbb21) for task 0 of framework 20140605-110421-16842879-56385-32082-0000
> I0605 11:04:22.151509 32103 slave.cpp:2361] Monitoring executor 'default' of framework
'20140605-110421-16842879-56385-32082-0000' in container 'b92544a4-53b5-4d0e-818e-d9420ddbb680'
> I0605 11:04:22.152081 32103 slave.cpp:2024] Handling status update TASK_RUNNING (UUID:
eafe4341-4aec-490a-a4d0-841201abbb21) for task 0 of framework 20140605-110421-16842879-56385-32082-0000
from executor(2)@127.0.1.1:56385
> I0605 11:04:22.152534 32104 status_update_manager.cpp:320] Received status update TASK_RUNNING
(UUID: eafe4341-4aec-490a-a4d0-841201abbb21) for task 0 of framework 20140605-110421-16842879-56385-32082-0000
> I0605 11:04:22.152585 32104 status_update_manager.cpp:499] Creating StatusUpdate stream
for task 0 of framework 20140605-110421-16842879-56385-32082-0000
> I0605 11:04:22.152660 32104 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING
(UUID: eafe4341-4aec-490a-a4d0-841201abbb21) for task 0 of framework 20140605-110421-16842879-56385-32082-0000
to master@127.0.1.1:56385
> I0605 11:04:22.152786 32104 master.cpp:2608] Status update TASK_RUNNING (UUID: eafe4341-4aec-490a-a4d0-841201abbb21)
for task 0 of framework 20140605-110421-16842879-56385-32082-0000 from slave 20140605-110421-16842879-56385-32082-0
at slave(5)@127.0.1.1:56385 (precise)
> I0605 11:04:22.152858 32104 sched.cpp:626] Scheduler::statusUpdate took 16641ns
> I0605 11:04:22.154207 32102 status_update_manager.cpp:398] Received status update acknowledgement
(UUID: eafe4341-4aec-490a-a4d0-841201abbb21) for task 0 of framework 20140605-110421-16842879-56385-32082-0000
> I0605 11:04:22.154691 32103 slave.cpp:2145] Status update manager successfully handled
status update TASK_RUNNING (UUID: eafe4341-4aec-490a-a4d0-841201abbb21) for task 0 of framework
20140605-110421-16842879-56385-32082-0000
> I0605 11:04:22.154986 32107 leveldb.cpp:343] Persisting action (16 bytes) to leveldb
took 13.225157ms
> I0605 11:04:22.155125 32107 replica.cpp:676] Persisted action at 4
> I0605 11:04:22.155454 32107 replica.cpp:655] Replica received learned notice for position
4
> I0605 11:04:22.155921 32103 slave.cpp:2151] Sending acknowledgement for status update
TASK_RUNNING (UUID: eafe4341-4aec-490a-a4d0-841201abbb21) for task 0 of framework 20140605-110421-16842879-56385-32082-0000
to executor(2)@127.0.1.1:56385
> I0605 11:04:22.156515 32104 exec.cpp:338] Executor received status update acknowledgement
eafe4341-4aec-490a-a4d0-841201abbb21 for task 0 of framework 20140605-110421-16842879-56385-32082-0000
> I0605 11:04:22.156741 32103 slave.cpp:1610] Status update manager successfully handled
status update acknowledgement (UUID: eafe4341-4aec-490a-a4d0-841201abbb21) for task 0 of framework
20140605-110421-16842879-56385-32082-0000
> I0605 11:04:22.157342 32105 slave.cpp:537] New master detected at master@127.0.1.1:56385
> I0605 11:04:22.157377 32105 slave.cpp:613] Authenticating with master master@127.0.1.1:56385
> I0605 11:04:22.157425 32105 slave.cpp:586] Detecting new master
> I0605 11:04:22.157467 32105 status_update_manager.cpp:167] New master detected at master@127.0.1.1:56385
> I0605 11:04:22.157505 32105 authenticatee.hpp:128] Creating new client SASL connection
> I0605 11:04:22.157667 32105 master.cpp:1324] Disconnecting slave 20140605-110421-16842879-56385-32082-0
> I0605 11:04:22.157706 32105 master.cpp:2966] Authenticating slave(5)@127.0.1.1:56385
> I0605 11:04:22.157773 32105 hierarchical_allocator_process.hpp:483] Slave 20140605-110421-16842879-56385-32082-0
disconnected
> I0605 11:04:22.157804 32105 authenticator.hpp:156] Creating new server SASL connection
> I0605 11:04:22.157903 32105 authenticatee.hpp:219] Received SASL authentication mechanisms:
CRAM-MD5
> I0605 11:04:22.157922 32105 authenticatee.hpp:245] Attempting to authenticate with mechanism
'CRAM-MD5'
> I0605 11:04:22.157945 32105 authenticator.hpp:262] Received SASL authentication start
> I0605 11:04:22.157980 32105 authenticator.hpp:384] Authentication requires more steps
> I0605 11:04:22.158006 32105 authenticatee.hpp:265] Received SASL authentication step
> I0605 11:04:22.158041 32105 authenticator.hpp:290] Received SASL authentication step
> I0605 11:04:22.158056 32105 auxprop.cpp:81] Request to lookup properties for user: 'test-principal'
realm: 'precise' server FQDN: 'precise' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE:
false SASL_AUXPROP_AUTHZID: false 
> I0605 11:04:22.158062 32105 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0605 11:04:22.158071 32105 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0605 11:04:22.158081 32105 auxprop.cpp:81] Request to lookup properties for user: 'test-principal'
realm: 'precise' server FQDN: 'precise' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE:
false SASL_AUXPROP_AUTHZID: true 
> I0605 11:04:22.158087 32105 auxprop.cpp:103] Skipping auxiliary property '*userPassword'
since SASL_AUXPROP_AUTHZID == true
> I0605 11:04:22.158090 32105 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5'
since SASL_AUXPROP_AUTHZID == true
> I0605 11:04:22.158100 32105 authenticator.hpp:376] Authentication success
> I0605 11:04:22.158126 32105 authenticatee.hpp:305] Authentication success
> I0605 11:04:22.158149 32105 master.cpp:3006] Successfully authenticated principal 'test-principal'
at slave(5)@127.0.1.1:56385
> I0605 11:04:22.158215 32105 slave.cpp:670] Successfully authenticated with master master@127.0.1.1:56385
> I0605 11:04:22.158301 32105 slave.cpp:908] Will retry registration in 10.813938ms if
necessary
> W0605 11:04:22.158480 32109 master.cpp:2397] Slave at slave(5)@127.0.1.1:56385 (precise)
is being allowed to re-register with an already in use id (20140605-110421-16842879-56385-32082-0)
> I0605 11:04:22.158624 32109 hierarchical_allocator_process.hpp:497] Slave 20140605-110421-16842879-56385-32082-0
reconnected
> W0605 11:04:22.158699 32105 slave.cpp:1500] Dropping updateFramework message for 20140605-110421-16842879-56385-32082-0000
because the slave is in DISCONNECTED state
> I0605 11:04:22.173758 32107 leveldb.cpp:343] Persisting action (18 bytes) to leveldb
took 18.270894ms
> I0605 11:04:22.173862 32107 leveldb.cpp:401] Deleting ~2 keys from leveldb took 50358ns
> I0605 11:04:22.173879 32107 replica.cpp:676] Persisted action at 4
> I0605 11:04:22.173890 32107 replica.cpp:661] Replica learned TRUNCATE action at position
4
> I0605 11:04:22.179563 32109 slave.cpp:470] Slave asked to shut down by @0.0.0.0:0
> I0605 11:04:22.179608 32109 slave.cpp:1343] Asked to shut down framework 20140605-110421-16842879-56385-32082-0000
by @0.0.0.0:0
> I0605 11:04:22.179620 32109 slave.cpp:1368] Shutting down framework 20140605-110421-16842879-56385-32082-0000
> I0605 11:04:22.179641 32109 slave.cpp:2704] Shutting down executor 'default' of framework
20140605-110421-16842879-56385-32082-0000
> I0605 11:04:22.180539 32109 slave.cpp:805] Skipping registration because slave is terminating
> I0605 11:04:22.180564 32109 slave.cpp:805] Skipping registration because slave is terminating
> I0605 11:04:22.180634 32109 slave.cpp:2806] Ignoring registration timeout for executor
'default' because the  framework 20140605-110421-16842879-56385-32082-0000 is terminating
> I0605 11:04:22.180654 32109 slave.cpp:2774] Killing executor 'default' of framework 20140605-110421-16842879-56385-32082-0000
> I0605 11:04:22.180727 32109 slave.cpp:2879] Current usage 77.00%. Max allowed age: 21.844724210601111hrs
> I0605 11:04:22.180778 32109 slave.cpp:2419] Executor 'default' of framework 20140605-110421-16842879-56385-32082-0000
has exited with status 0
> I0605 11:04:22.180820 32109 slave.cpp:2558] Cleaning up executor 'default' of framework
20140605-110421-16842879-56385-32082-0000
> I0605 11:04:22.180919 32109 slave.cpp:2633] Cleaning up framework 20140605-110421-16842879-56385-32082-0000
> I0605 11:04:22.180970 32109 slave.cpp:426] Slave terminating
> I0605 11:04:22.181143 32109 hierarchical_allocator_process.hpp:751] Offering cpus(*):1;
mem(*):960; disk(*):1024; ports(*):[31000-32000] on slave 20140605-110421-16842879-56385-32082-0
to framework 20140605-110421-16842879-56385-32082-0000
> I0605 11:04:22.181239 32109 hierarchical_allocator_process.hpp:687] Performed allocation
for 1 slaves in 146650ns
> I0605 11:04:22.181448 32109 master.cpp:2684] Executor default of framework 20140605-110421-16842879-56385-32082-0000
on slave 20140605-110421-16842879-56385-32082-0 at slave(5)@127.0.1.1:56385 (precise) has
exited with status 0
> I0605 11:04:22.181505 32109 master.cpp:712] Slave 20140605-110421-16842879-56385-32082-0
at slave(5)@127.0.1.1:56385 (precise) disconnected
> I0605 11:04:22.181517 32109 master.cpp:716] Removing disconnected slave 20140605-110421-16842879-56385-32082-0
at slave(5)@127.0.1.1:56385 (precise) because it is not checkpointing!
> I0605 11:04:22.181535 32109 master.cpp:3585] Removing slave 20140605-110421-16842879-56385-32082-0
at slave(5)@127.0.1.1:56385 (precise)
> I0605 11:04:22.182390 32109 master.hpp:683] Removing task 0 with resources cpus(*):1;
mem(*):64 on slave 20140605-110421-16842879-56385-32082-0 (precise)
> W0605 11:04:22.182605 32109 master.cpp:2858] Master returning resources offered to framework
20140605-110421-16842879-56385-32082-0000 because slave 20140605-110421-16842879-56385-32082-0
is not valid
> I0605 11:04:22.182657 32109 master.cpp:108] No whitelist given. Advertising offers for
all slaves
> I0605 11:04:22.182694 32109 status_update_manager.cpp:282] Closing status update streams
for framework 20140605-110421-16842879-56385-32082-0000
> I0605 11:04:22.182710 32109 status_update_manager.cpp:530] Cleaning up status update
stream for task 0 of framework 20140605-110421-16842879-56385-32082-0000
> I0605 11:04:22.182765 32109 gc.cpp:56] Scheduling '/tmp/SlaveTest_TerminatingSlaveDoesNotReregister_QvxNv8/slaves/20140605-110421-16842879-56385-32082-0/frameworks/20140605-110421-16842879-56385-32082-0000/executors/default/runs/b92544a4-53b5-4d0e-818e-d9420ddbb680'
for gc 6.99999822731259days in the future
> I0605 11:04:22.182806 32109 gc.cpp:56] Scheduling '/tmp/SlaveTest_TerminatingSlaveDoesNotReregister_QvxNv8/slaves/20140605-110421-16842879-56385-32082-0/frameworks/20140605-110421-16842879-56385-32082-0000/executors/default'
for gc 6.99999822731259days in the future
> I0605 11:04:22.182840 32109 gc.cpp:56] Scheduling '/tmp/SlaveTest_TerminatingSlaveDoesNotReregister_QvxNv8/slaves/20140605-110421-16842879-56385-32082-0/frameworks/20140605-110421-16842879-56385-32082-0000'
for gc 6.99999822731259days in the future
> I0605 11:04:22.182909 32109 hierarchical_allocator_process.hpp:469] Removed slave 20140605-110421-16842879-56385-32082-0
> I0605 11:04:22.183038 32109 registrar.cpp:422] Attempting to update the 'registry'
> I0605 11:04:22.184106 32109 log.cpp:680] Attempting to append 122 bytes to the log
> I0605 11:04:22.184177 32109 coordinator.cpp:340] Coordinator attempting to write APPEND
action at position 5
> I0605 11:04:22.184423 32109 replica.cpp:508] Replica received write request for position
5
> I0605 11:04:22.206383 32109 leveldb.cpp:343] Persisting action (139 bytes) to leveldb
took 21.93184ms
> I0605 11:04:22.206696 32109 replica.cpp:676] Persisted action at 5
> I0605 11:04:22.213220 32108 replica.cpp:655] Replica received learned notice for position
5
> I0605 11:04:22.230458 32108 leveldb.cpp:343] Persisting action (141 bytes) to leveldb
took 17.203641ms
> I0605 11:04:22.230504 32108 replica.cpp:676] Persisted action at 5
> I0605 11:04:22.230515 32108 replica.cpp:661] Replica learned APPEND action at position
5
> I0605 11:04:22.230842 32108 registrar.cpp:479] Successfully updated 'registry'
> I0605 11:04:22.230953 32108 log.cpp:699] Attempting to truncate the log to 5
> I0605 11:04:22.231020 32108 master.cpp:3687] Removed slave 20140605-110421-16842879-56385-32082-0
(precise)
> I0605 11:04:22.231070 32108 master.cpp:3702] Notifying framework 20140605-110421-16842879-56385-32082-0000
of lost slave 20140605-110421-16842879-56385-32082-0 (precise) after recovering
> I0605 11:04:22.231104 32108 coordinator.cpp:340] Coordinator attempting to write TRUNCATE
action at position 6
> tests/slave_tests.cpp:753: Failure
> Mock function called more times than expected - returning directly.
>     Function call: statusUpdate(0x7fff48aa2d30, @0x2b3c08004320 80-byte object <D0-00
62-03 3C-2B 00-00 00-00 00-00 00-00 00-00 D0-5D 00-08 3C-2B 00-00 F0-D4 00-08 3C-2B 00-00
B8-80 E1-00 00-00 00-00 50-46 00-08 3C-2B 00-00 00-00 00-00 00-00 00-00 60-CD C9-76 2C-E4
D4-41 05-00 00-00 00-00 00-00 57-00 00-00 07-00 00-00>)
>          Expected: to be called once
>            Actual: called twice - over-saturated and active
> I0605 11:04:22.231379 32108 sched.cpp:626] Scheduler::statusUpdate took 125409ns
> I0605 11:04:22.231422 32108 sched.cpp:672] Lost slave 20140605-110421-16842879-56385-32082-0
> GMOCK WARNING:
> Uninteresting mock function call - returning directly.
>     Function call: slaveLost(0x7fff48aa2d30, @0x2b3c08004650 20140605-110421-16842879-56385-32082-0)
> Stack trace:
> I0605 11:04:22.231456 32108 sched.cpp:683] Scheduler::slaveLost took 19181ns
> I0605 11:04:22.231624 32108 replica.cpp:508] Replica received write request for position
6
> I0605 11:04:22.248874 32108 leveldb.cpp:343] Persisting action (16 bytes) to leveldb
took 17.220716ms
> I0605 11:04:22.249277 32108 replica.cpp:676] Persisted action at 6
> I0605 11:04:22.253284 32103 replica.cpp:655] Replica received learned notice for position
6
> I0605 11:04:22.270297 32103 leveldb.cpp:343] Persisting action (18 bytes) to leveldb
took 16.977544ms
> I0605 11:04:22.270397 32103 leveldb.cpp:401] Deleting ~2 keys from leveldb took 41220ns
> I0605 11:04:22.270411 32103 replica.cpp:676] Persisted action at 6
> I0605 11:04:22.270422 32103 replica.cpp:661] Replica learned TRUNCATE action at position
6
> I0605 11:04:22.276504 32082 master.cpp:574] Master terminating
> I0605 11:04:22.277667 32082 sched.cpp:731] Stopping framework '20140605-110421-16842879-56385-32082-0000'
> [  FAILED  ] SlaveTest.TerminatingSlaveDoesNotReregister (439 ms)



--
This message was sent by Atlassian JIRA
(v6.2#6252)

Mime
View raw message