You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "Vinod Kone (JIRA)" <ji...@apache.org> on 2014/09/30 03:31:34 UTC
[jira] [Created] (MESOS-1844) AllocatorTest/0.SlaveLost is flaky
Vinod Kone created MESOS-1844:
---------------------------------
Summary: AllocatorTest/0.SlaveLost is flaky
Key: MESOS-1844
URL: https://issues.apache.org/jira/browse/MESOS-1844
Project: Mesos
Issue Type: Bug
Components: test
Environment: Fedora 20. GCC
Reporter: Vinod Kone
Assignee: Vinod Kone
{code}
[ RUN ] AllocatorTest/0.SlaveLost
Using temporary directory '/tmp/AllocatorTest_0_SlaveLost_Z2oazw'
I0929 16:58:29.484141 3486 leveldb.cpp:176] Opened db in 604109ns
I0929 16:58:29.484629 3486 leveldb.cpp:183] Compacted db in 172697ns
I0929 16:58:29.484912 3486 leveldb.cpp:198] Created db iterator in 6429ns
I0929 16:58:29.485133 3486 leveldb.cpp:204] Seeked to beginning of db in 1618ns
I0929 16:58:29.485337 3486 leveldb.cpp:273] Iterated through 0 keys in the db in 752ns
I0929 16:58:29.485595 3486 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0929 16:58:29.486017 3500 recover.cpp:425] Starting replica recovery
I0929 16:58:29.486304 3500 recover.cpp:451] Replica is in EMPTY status
I0929 16:58:29.486793 3500 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request
I0929 16:58:29.487205 3500 recover.cpp:188] Received a recover response from a replica in EMPTY status
I0929 16:58:29.487540 3500 recover.cpp:542] Updating replica status to STARTING
I0929 16:58:29.487911 3500 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 36629ns
I0929 16:58:29.488173 3500 replica.cpp:320] Persisted replica status to STARTING
I0929 16:58:29.488438 3500 recover.cpp:451] Replica is in STARTING status
I0929 16:58:29.488891 3500 replica.cpp:638] Replica in STARTING status received a broadcasted recover request
I0929 16:58:29.489187 3500 recover.cpp:188] Received a recover response from a replica in STARTING status
I0929 16:58:29.489516 3500 recover.cpp:542] Updating replica status to VOTING
I0929 16:58:29.489887 3502 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 32099ns
I0929 16:58:29.490124 3502 replica.cpp:320] Persisted replica status to VOTING
I0929 16:58:29.490381 3500 recover.cpp:556] Successfully joined the Paxos group
I0929 16:58:29.490713 3500 recover.cpp:440] Recover process terminated
I0929 16:58:29.493401 3506 master.cpp:312] Master 20140929-165829-2759502016-55618-3486 (fedora-20) started on 192.168.122.164:55618
I0929 16:58:29.493700 3506 master.cpp:358] Master only allowing authenticated frameworks to register
I0929 16:58:29.493921 3506 master.cpp:363] Master only allowing authenticated slaves to register
I0929 16:58:29.494123 3506 credentials.hpp:36] Loading credentials for authentication from '/tmp/AllocatorTest_0_SlaveLost_Z2oazw/credentials'
I0929 16:58:29.494500 3506 master.cpp:392] Authorization enabled
I0929 16:58:29.495249 3506 master.cpp:120] No whitelist given. Advertising offers for all slaves
I0929 16:58:29.495728 3502 hierarchical_allocator_process.hpp:299] Initializing hierarchical allocator process with master : master@192.168.122.164:55618
I0929 16:58:29.496196 3506 master.cpp:1241] The newly elected leader is master@192.168.122.164:55618 with id 20140929-165829-2759502016-55618-3486
I0929 16:58:29.496469 3506 master.cpp:1254] Elected as the leading master!
I0929 16:58:29.496713 3506 master.cpp:1072] Recovering from registrar
I0929 16:58:29.497020 3506 registrar.cpp:312] Recovering registrar
I0929 16:58:29.497486 3506 log.cpp:656] Attempting to start the writer
I0929 16:58:29.498105 3506 replica.cpp:474] Replica received implicit promise request with proposal 1
I0929 16:58:29.498373 3506 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 27145ns
I0929 16:58:29.498605 3506 replica.cpp:342] Persisted promised to 1
I0929 16:58:29.500880 3500 coordinator.cpp:230] Coordinator attemping to fill missing position
I0929 16:58:29.501404 3500 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
I0929 16:58:29.501687 3500 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 57971ns
I0929 16:58:29.501935 3500 replica.cpp:676] Persisted action at 0
I0929 16:58:29.504905 3507 replica.cpp:508] Replica received write request for position 0
I0929 16:58:29.505130 3507 leveldb.cpp:438] Reading position from leveldb took 18418ns
I0929 16:58:29.505377 3507 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 19998ns
I0929 16:58:29.505571 3507 replica.cpp:676] Persisted action at 0
I0929 16:58:29.505957 3507 replica.cpp:655] Replica received learned notice for position 0
I0929 16:58:29.506186 3507 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 21648ns
I0929 16:58:29.506433 3507 replica.cpp:676] Persisted action at 0
I0929 16:58:29.506767 3507 replica.cpp:661] Replica learned NOP action at position 0
I0929 16:58:29.507199 3507 log.cpp:672] Writer started with ending position 0
I0929 16:58:29.507730 3507 leveldb.cpp:438] Reading position from leveldb took 11532ns
I0929 16:58:29.508915 3507 registrar.cpp:345] Successfully fetched the registry (0B)
I0929 16:58:29.509230 3507 registrar.cpp:421] Attempting to update the 'registry'
I0929 16:58:29.510516 3500 log.cpp:680] Attempting to append 130 bytes to the log
I0929 16:58:29.510949 3500 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
I0929 16:58:29.511363 3500 replica.cpp:508] Replica received write request for position 1
I0929 16:58:29.511697 3500 leveldb.cpp:343] Persisting action (149 bytes) to leveldb took 66530ns
I0929 16:58:29.512039 3500 replica.cpp:676] Persisted action at 1
I0929 16:58:29.512460 3500 replica.cpp:655] Replica received learned notice for position 1
I0929 16:58:29.512778 3500 leveldb.cpp:343] Persisting action (151 bytes) to leveldb took 24121ns
I0929 16:58:29.513013 3500 replica.cpp:676] Persisted action at 1
I0929 16:58:29.513239 3500 replica.cpp:661] Replica learned APPEND action at position 1
I0929 16:58:29.513674 3500 log.cpp:699] Attempting to truncate the log to 1
I0929 16:58:29.513954 3500 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
I0929 16:58:29.514385 3500 replica.cpp:508] Replica received write request for position 2
I0929 16:58:29.514680 3500 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 65014ns
I0929 16:58:29.514991 3500 replica.cpp:676] Persisted action at 2
I0929 16:58:29.516978 3501 replica.cpp:655] Replica received learned notice for position 2
I0929 16:58:29.517319 3501 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 24103ns
I0929 16:58:29.517546 3501 leveldb.cpp:401] Deleting ~1 keys from leveldb took 16533ns
I0929 16:58:29.517801 3501 replica.cpp:676] Persisted action at 2
I0929 16:58:29.518039 3501 replica.cpp:661] Replica learned TRUNCATE action at position 2
I0929 16:58:29.518539 3507 registrar.cpp:478] Successfully updated 'registry'
I0929 16:58:29.518885 3507 registrar.cpp:371] Successfully recovered registrar
I0929 16:58:29.519201 3507 master.cpp:1099] Recovered 0 slaves from the Registry (94B) ; allowing 10mins for slaves to re-register
I0929 16:58:29.533073 3505 slave.cpp:169] Slave started on 57)@192.168.122.164:55618
I0929 16:58:29.533500 3505 credentials.hpp:84] Loading credential for authentication from '/tmp/AllocatorTest_0_SlaveLost_xdXHfg/credential'
I0929 16:58:29.533834 3505 slave.cpp:276] Slave using credential for: test-principal
I0929 16:58:29.534168 3505 slave.cpp:289] Slave resources: cpus(*):2; mem(*):1024; disk(*):752; ports(*):[31000-32000]
I0929 16:58:29.534751 3505 slave.cpp:317] Slave hostname: fedora-20
I0929 16:58:29.534965 3505 slave.cpp:318] Slave checkpoint: false
I0929 16:58:29.535557 3505 state.cpp:33] Recovering state from '/tmp/AllocatorTest_0_SlaveLost_xdXHfg/meta'
I0929 16:58:29.535951 3505 status_update_manager.cpp:193] Recovering status update manager
I0929 16:58:29.536290 3505 slave.cpp:3271] Finished recovery
I0929 16:58:29.536782 3505 slave.cpp:598] New master detected at master@192.168.122.164:55618
I0929 16:58:29.537122 3505 slave.cpp:672] Authenticating with master master@192.168.122.164:55618
I0929 16:58:29.537492 3505 slave.cpp:645] Detecting new master
I0929 16:58:29.537294 3506 status_update_manager.cpp:167] New master detected at master@192.168.122.164:55618
I0929 16:58:29.537642 3507 authenticatee.hpp:128] Creating new client SASL connection
I0929 16:58:29.538769 3502 master.cpp:3737] Authenticating slave(57)@192.168.122.164:55618
I0929 16:58:29.539091 3502 authenticator.hpp:156] Creating new server SASL connection
I0929 16:58:29.539710 3503 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0929 16:58:29.539943 3503 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0929 16:58:29.540206 3502 authenticator.hpp:262] Received SASL authentication start
I0929 16:58:29.540457 3502 authenticator.hpp:384] Authentication requires more steps
I0929 16:58:29.540757 3502 authenticatee.hpp:265] Received SASL authentication step
I0929 16:58:29.541121 3502 authenticator.hpp:290] Received SASL authentication step
I0929 16:58:29.541368 3502 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'fedora-20' server FQDN: 'fedora-20' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0929 16:58:29.541599 3502 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I0929 16:58:29.541874 3502 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0929 16:58:29.542129 3502 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'fedora-20' server FQDN: 'fedora-20' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0929 16:58:29.542333 3502 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0929 16:58:29.542553 3502 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0929 16:58:29.542785 3502 authenticator.hpp:376] Authentication success
I0929 16:58:29.543047 3502 authenticatee.hpp:305] Authentication success
I0929 16:58:29.543381 3502 slave.cpp:729] Successfully authenticated with master master@192.168.122.164:55618
I0929 16:58:29.543707 3502 slave.cpp:992] Will retry registration in 11.795692ms if necessary
I0929 16:58:29.543179 3503 master.cpp:3777] Successfully authenticated principal 'test-principal' at slave(57)@192.168.122.164:55618
I0929 16:58:29.544255 3503 master.cpp:2930] Registering slave at slave(57)@192.168.122.164:55618 (fedora-20) with id 20140929-165829-2759502016-55618-3486-0
I0929 16:58:29.544587 3503 registrar.cpp:421] Attempting to update the 'registry'
I0929 16:58:29.545816 3500 log.cpp:680] Attempting to append 299 bytes to the log
I0929 16:58:29.546267 3500 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
I0929 16:58:29.546749 3500 replica.cpp:508] Replica received write request for position 3
I0929 16:58:29.547030 3500 leveldb.cpp:343] Persisting action (318 bytes) to leveldb took 31759ns
I0929 16:58:29.547236 3500 replica.cpp:676] Persisted action at 3
I0929 16:58:29.548902 3506 replica.cpp:655] Replica received learned notice for position 3
I0929 16:58:29.549139 3506 leveldb.cpp:343] Persisting action (320 bytes) to leveldb took 25595ns
I0929 16:58:29.549343 3506 replica.cpp:676] Persisted action at 3
I0929 16:58:29.549607 3506 replica.cpp:661] Replica learned APPEND action at position 3
I0929 16:58:29.550081 3506 log.cpp:699] Attempting to truncate the log to 3
I0929 16:58:29.550497 3506 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
I0929 16:58:29.550943 3506 replica.cpp:508] Replica received write request for position 4
I0929 16:58:29.551198 3506 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 20852ns
I0929 16:58:29.551409 3506 replica.cpp:676] Persisted action at 4
I0929 16:58:29.551795 3506 replica.cpp:655] Replica received learned notice for position 4
I0929 16:58:29.552094 3506 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 22182ns
I0929 16:58:29.552320 3506 leveldb.cpp:401] Deleting ~2 keys from leveldb took 18503ns
I0929 16:58:29.552525 3506 replica.cpp:676] Persisted action at 4
I0929 16:58:29.552781 3506 replica.cpp:661] Replica learned TRUNCATE action at position 4
I0929 16:58:29.550289 3503 registrar.cpp:478] Successfully updated 'registry'
I0929 16:58:29.553553 3503 master.cpp:2970] Registered slave 20140929-165829-2759502016-55618-3486-0 at slave(57)@192.168.122.164:55618 (fedora-20)
I0929 16:58:29.553807 3503 master.cpp:4180] Adding slave 20140929-165829-2759502016-55618-3486-0 at slave(57)@192.168.122.164:55618 (fedora-20) with cpus(*):2; mem(*):1024; disk(*):752; ports(*):[31000-32000]
I0929 16:58:29.554152 3503 slave.cpp:763] Registered with master master@192.168.122.164:55618; given slave ID 20140929-165829-2759502016-55618-3486-0
I0929 16:58:29.554455 3503 slave.cpp:2345] Received ping from slave-observer(56)@192.168.122.164:55618
I0929 16:58:29.554707 3504 hierarchical_allocator_process.hpp:442] Added slave 20140929-165829-2759502016-55618-3486-0 (fedora-20) with cpus(*):2; mem(*):1024; disk(*):752; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):752; ports(*):[31000-32000] available)
I0929 16:58:29.555064 3504 hierarchical_allocator_process.hpp:679] Performed allocation for slave 20140929-165829-2759502016-55618-3486-0 in 13111ns
I0929 16:58:29.558220 3486 sched.cpp:137] Version: 0.21.0
I0929 16:58:29.558821 3501 sched.cpp:233] New master detected at master@192.168.122.164:55618
I0929 16:58:29.559054 3501 sched.cpp:283] Authenticating with master master@192.168.122.164:55618
I0929 16:58:29.559360 3501 authenticatee.hpp:128] Creating new client SASL connection
I0929 16:58:29.560096 3501 master.cpp:3737] Authenticating scheduler-c8df3f3b-2552-476f-9daf-9aa2f012ad28@192.168.122.164:55618
I0929 16:58:29.560430 3501 authenticator.hpp:156] Creating new server SASL connection
I0929 16:58:29.561141 3501 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0929 16:58:29.561465 3501 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0929 16:58:29.561743 3501 authenticator.hpp:262] Received SASL authentication start
I0929 16:58:29.562098 3501 authenticator.hpp:384] Authentication requires more steps
I0929 16:58:29.562353 3501 authenticatee.hpp:265] Received SASL authentication step
I0929 16:58:29.562721 3507 authenticator.hpp:290] Received SASL authentication step
I0929 16:58:29.563022 3507 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'fedora-20' server FQDN: 'fedora-20' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0929 16:58:29.563254 3507 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I0929 16:58:29.563484 3507 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0929 16:58:29.563736 3507 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'fedora-20' server FQDN: 'fedora-20' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0929 16:58:29.563976 3507 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0929 16:58:29.564188 3507 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0929 16:58:29.564415 3507 authenticator.hpp:376] Authentication success
I0929 16:58:29.564673 3507 master.cpp:3777] Successfully authenticated principal 'test-principal' at scheduler-c8df3f3b-2552-476f-9daf-9aa2f012ad28@192.168.122.164:55618
I0929 16:58:29.568681 3501 authenticatee.hpp:305] Authentication success
I0929 16:58:29.569046 3501 sched.cpp:357] Successfully authenticated with master master@192.168.122.164:55618
I0929 16:58:29.569286 3501 sched.cpp:476] Sending registration request to master@192.168.122.164:55618
I0929 16:58:29.569581 3507 master.cpp:1360] Received registration request from scheduler-c8df3f3b-2552-476f-9daf-9aa2f012ad28@192.168.122.164:55618
I0929 16:58:29.569846 3507 master.cpp:1320] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0929 16:58:29.570219 3507 master.cpp:1419] Registering framework 20140929-165829-2759502016-55618-3486-0000 at scheduler-c8df3f3b-2552-476f-9daf-9aa2f012ad28@192.168.122.164:55618
I0929 16:58:29.570543 3506 sched.cpp:407] Framework registered with 20140929-165829-2759502016-55618-3486-0000
I0929 16:58:29.570811 3506 sched.cpp:421] Scheduler::registered took 13811ns
I0929 16:58:29.571135 3502 hierarchical_allocator_process.hpp:329] Added framework 20140929-165829-2759502016-55618-3486-0000
I0929 16:58:29.571393 3502 hierarchical_allocator_process.hpp:734] Offering cpus(*):2; mem(*):1024; disk(*):752; ports(*):[31000-32000] on slave 20140929-165829-2759502016-55618-3486-0 to framework 20140929-165829-2759502016-55618-3486-0000
I0929 16:58:29.571723 3502 hierarchical_allocator_process.hpp:659] Performed allocation for 1 slaves in 368547ns
I0929 16:58:29.572125 3507 master.hpp:868] Adding offer 20140929-165829-2759502016-55618-3486-0 with resources cpus(*):2; mem(*):1024; disk(*):752; ports(*):[31000-32000] on slave 20140929-165829-2759502016-55618-3486-0 (fedora-20)
I0929 16:58:29.572374 3507 master.cpp:3679] Sending 1 offers to framework 20140929-165829-2759502016-55618-3486-0000
I0929 16:58:29.572841 3503 sched.cpp:544] Scheduler::resourceOffers took 114306ns
I0929 16:58:29.573197 3507 master.hpp:877] Removing offer 20140929-165829-2759502016-55618-3486-0 with resources cpus(*):2; mem(*):1024; disk(*):752; ports(*):[31000-32000] on slave 20140929-165829-2759502016-55618-3486-0 (fedora-20)
I0929 16:58:29.573457 3507 master.cpp:2274] Processing reply for offers: [ 20140929-165829-2759502016-55618-3486-0 ] on slave 20140929-165829-2759502016-55618-3486-0 at slave(57)@192.168.122.164:55618 (fedora-20) for framework 20140929-165829-2759502016-55618-3486-0000
W0929 16:58:29.573717 3507 master.cpp:1944] Executor default for task 0 uses less CPUs (None) than the minimum required (0.01). Please update your executor, as this will be mandatory in future releases.
W0929 16:58:29.573953 3507 master.cpp:1955] Executor default for task 0 uses less memory (None) than the minimum required (32MB). Please update your executor, as this will be mandatory in future releases.
I0929 16:58:29.574177 3507 master.cpp:2357] Authorizing framework principal 'test-principal' to launch task 0 as user 'jenkins'
I0929 16:58:29.574745 3507 master.hpp:845] Adding task 0 with resources cpus(*):2; mem(*):512 on slave 20140929-165829-2759502016-55618-3486-0 (fedora-20)
I0929 16:58:29.574992 3507 master.cpp:2423] Launching task 0 of framework 20140929-165829-2759502016-55618-3486-0000 with resources cpus(*):2; mem(*):512 on slave 20140929-165829-2759502016-55618-3486-0 at slave(57)@192.168.122.164:55618 (fedora-20)
I0929 16:58:29.575315 3503 slave.cpp:1023] Got assigned task 0 for framework 20140929-165829-2759502016-55618-3486-0000
I0929 16:58:29.575724 3503 slave.cpp:1133] Launching task 0 for framework 20140929-165829-2759502016-55618-3486-0000
I0929 16:58:29.578129 3503 exec.cpp:132] Version: 0.21.0
I0929 16:58:29.578505 3504 exec.cpp:182] Executor started at: executor(30)@192.168.122.164:55618 with pid 3486
I0929 16:58:29.578867 3503 slave.cpp:1246] Queuing task '0' for executor default of framework '20140929-165829-2759502016-55618-3486-0000
I0929 16:58:29.579144 3503 slave.cpp:554] Successfully attached file '/tmp/AllocatorTest_0_SlaveLost_xdXHfg/slaves/20140929-165829-2759502016-55618-3486-0/frameworks/20140929-165829-2759502016-55618-3486-0000/executors/default/runs/b0de9759-7054-4763-90f4-889ddc3a8524'
I0929 16:58:29.579401 3503 slave.cpp:1756] Got registration for executor 'default' of framework 20140929-165829-2759502016-55618-3486-0000 from executor(30)@192.168.122.164:55618
I0929 16:58:29.579879 3506 exec.cpp:206] Executor registered on slave 20140929-165829-2759502016-55618-3486-0
I0929 16:58:29.580921 3506 exec.cpp:218] Executor::registered took 17644ns
I0929 16:58:29.581188 3503 slave.cpp:1875] Flushing queued task 0 for executor 'default' of framework 20140929-165829-2759502016-55618-3486-0000
I0929 16:58:29.581526 3504 exec.cpp:293] Executor asked to run task '0'
I0929 16:58:29.581807 3504 exec.cpp:302] Executor::launchTask took 42649ns
I0929 16:58:29.583133 3504 exec.cpp:525] Executor sending status update TASK_RUNNING (UUID: 454bdb88-fd27-4201-b2c7-4ea03a6d00b3) for task 0 of framework 20140929-165829-2759502016-55618-3486-0000
I0929 16:58:29.586869 3503 slave.cpp:2611] Monitoring executor 'default' of framework '20140929-165829-2759502016-55618-3486-0000' in container 'b0de9759-7054-4763-90f4-889ddc3a8524'
I0929 16:58:29.587252 3503 slave.cpp:2109] Handling status update TASK_RUNNING (UUID: 454bdb88-fd27-4201-b2c7-4ea03a6d00b3) for task 0 of framework 20140929-165829-2759502016-55618-3486-0000 from executor(30)@192.168.122.164:55618
I0929 16:58:29.587723 3502 hierarchical_allocator_process.hpp:563] Recovered mem(*):512; disk(*):752; ports(*):[31000-32000] (total allocatable: mem(*):512; disk(*):752; ports(*):[31000-32000]) on slave 20140929-165829-2759502016-55618-3486-0 from framework 20140929-165829-2759502016-55618-3486-0000
I0929 16:58:29.588127 3502 hierarchical_allocator_process.hpp:599] Framework 20140929-165829-2759502016-55618-3486-0000 filtered slave 20140929-165829-2759502016-55618-3486-0 for 5secs
I0929 16:58:29.588433 3506 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 454bdb88-fd27-4201-b2c7-4ea03a6d00b3) for task 0 of framework 20140929-165829-2759502016-55618-3486-0000
I0929 16:58:29.588767 3506 status_update_manager.cpp:499] Creating StatusUpdate stream for task 0 of framework 20140929-165829-2759502016-55618-3486-0000
I0929 16:58:29.589054 3506 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: 454bdb88-fd27-4201-b2c7-4ea03a6d00b3) for task 0 of framework 20140929-165829-2759502016-55618-3486-0000 to master@192.168.122.164:55618
I0929 16:58:29.589400 3506 master.cpp:3301] Forwarding status update TASK_RUNNING (UUID: 454bdb88-fd27-4201-b2c7-4ea03a6d00b3) for task 0 of framework 20140929-165829-2759502016-55618-3486-0000
I0929 16:58:29.589702 3506 master.cpp:3273] Status update TASK_RUNNING (UUID: 454bdb88-fd27-4201-b2c7-4ea03a6d00b3) for task 0 of framework 20140929-165829-2759502016-55618-3486-0000 from slave 20140929-165829-2759502016-55618-3486-0 at slave(57)@192.168.122.164:55618 (fedora-20)
I0929 16:58:29.589923 3500 sched.cpp:635] Scheduler::statusUpdate took 36034ns
I0929 16:58:29.590337 3500 master.cpp:2777] Forwarding status update acknowledgement 454bdb88-fd27-4201-b2c7-4ea03a6d00b3 for task 0 of framework 20140929-165829-2759502016-55618-3486-0000 to slave 20140929-165829-2759502016-55618-3486-0 at slave(57)@192.168.122.164:55618 (fedora-20)
I0929 16:58:29.590643 3503 slave.cpp:477] Slave terminating
I0929 16:58:29.590893 3503 slave.cpp:1429] Asked to shut down framework 20140929-165829-2759502016-55618-3486-0000 by @0.0.0.0:0
I0929 16:58:29.591136 3503 slave.cpp:1454] Shutting down framework 20140929-165829-2759502016-55618-3486-0000
I0929 16:58:29.591367 3503 slave.cpp:2951] Shutting down executor 'default' of framework 20140929-165829-2759502016-55618-3486-0000
I0929 16:58:29.591701 3501 master.cpp:817] Slave 20140929-165829-2759502016-55618-3486-0 at slave(57)@192.168.122.164:55618 (fedora-20) disconnected
I0929 16:58:29.591917 3501 master.cpp:821] Removing disconnected slave 20140929-165829-2759502016-55618-3486-0 at slave(57)@192.168.122.164:55618 (fedora-20) because it is not checkpointing!
I0929 16:58:29.592149 3501 master.cpp:4301] Removing slave 20140929-165829-2759502016-55618-3486-0 at slave(57)@192.168.122.164:55618 (fedora-20)
I0929 16:58:29.593868 3505 hierarchical_allocator_process.hpp:467] Removed slave 20140929-165829-2759502016-55618-3486-0
I0929 16:58:29.594907 3486 containerizer.cpp:89] Using isolation: posix/cpu,posix/mem
I0929 16:58:29.595091 3501 master.cpp:4485] Removing task 0 with resources cpus(*):2; mem(*):512 of framework 20140929-165829-2759502016-55618-3486-0000 on slave 20140929-165829-2759502016-55618-3486-0 at slave(57)@192.168.122.164:55618 (fedora-20)
I0929 16:58:29.595960 3501 master.cpp:4514] Removing executor 'default' with resources of framework 20140929-165829-2759502016-55618-3486-0000 on slave 20140929-165829-2759502016-55618-3486-0 at slave(57)@192.168.122.164:55618 (fedora-20)
tests/allocator_tests.cpp:1552: Failure
Mock function called more times than expected - taking default action specified at:
./tests/mesos.hpp:616:
Function call: resourcesRecovered(@0x7f958007f590 20140929-165829-2759502016-55618-3486-0000, @0x7f958007f5b0 20140929-165829-2759502016-55618-3486-0, @0x7f958007f5d0 {}, @0x7f958007f5e8 16-byte object <01-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00>)
Expected: to be called twice
I0929 16:58:29.596640 3506 registrar.cpp:421] Attempting to update the 'registry'
Actual: called 3 times - over-saturated and active
I0929 16:58:29.598697 3506 log.cpp:680] Attempting to append 133 bytes to the log
I0929 16:58:29.598984 3500 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 5
I0929 16:58:29.599422 3500 replica.cpp:508] Replica received write request for position 5
I0929 16:58:29.599712 3500 leveldb.cpp:343] Persisting action (152 bytes) to leveldb took 65914ns
I0929 16:58:29.599931 3500 replica.cpp:676] Persisted action at 5
I0929 16:58:29.600332 3500 replica.cpp:655] Replica received learned notice for position 5
I0929 16:58:29.600621 3500 leveldb.cpp:343] Persisting action (154 bytes) to leveldb took 24641ns
I0929 16:58:29.600858 3500 replica.cpp:676] Persisted action at 5
I0929 16:58:29.601060 3500 replica.cpp:661] Replica learned APPEND action at position 5
I0929 16:58:29.601588 3506 registrar.cpp:478] Successfully updated 'registry'
I0929 16:58:29.601765 3500 log.cpp:699] Attempting to truncate the log to 5
I0929 16:58:29.602308 3501 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 6
I0929 16:58:29.602736 3505 replica.cpp:508] Replica received write request for position 6
I0929 16:58:29.602967 3505 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 22681ns
I0929 16:58:29.603175 3505 replica.cpp:676] Persisted action at 6
I0929 16:58:29.603591 3501 replica.cpp:655] Replica received learned notice for position 6
I0929 16:58:29.603903 3501 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 23564ns
I0929 16:58:29.604161 3501 leveldb.cpp:401] Deleting ~2 keys from leveldb took 18683ns
I0929 16:58:29.604378 3501 replica.cpp:676] Persisted action at 6
I0929 16:58:29.604575 3501 replica.cpp:661] Replica learned TRUNCATE action at position 6
I0929 16:58:29.604970 3502 master.cpp:4393] Removed slave 20140929-165829-2759502016-55618-3486-0 (fedora-20)
I0929 16:58:29.605197 3502 master.cpp:3296] Sending status update TASK_LOST (UUID: cfc350bc-4ebf-4ea1-9fe4-27f53825c787) for task 0 of framework 20140929-165829-2759502016-55618-3486-0000 'Slave fedora-20 removed'
I0929 16:58:29.605445 3502 master.cpp:4411] Notifying framework 20140929-165829-2759502016-55618-3486-0000 of lost slave 20140929-165829-2759502016-55618-3486-0 (fedora-20) after recovering
I0929 16:58:29.605756 3502 sched.cpp:635] Scheduler::statusUpdate took 9369ns
I0929 16:58:29.605996 3502 sched.cpp:686] Lost slave 20140929-165829-2759502016-55618-3486-0
I0929 16:58:29.606210 3502 sched.cpp:697] Scheduler::slaveLost took 13761ns
I0929 16:58:29.607326 3501 slave.cpp:169] Slave started on 58)@192.168.122.164:55618
I0929 16:58:29.607640 3501 credentials.hpp:84] Loading credential for authentication from '/tmp/AllocatorTest_0_SlaveLost_NcoJ6Z/credential'
I0929 16:58:29.607975 3501 slave.cpp:276] Slave using credential for: test-principal
I0929 16:58:29.608253 3501 slave.cpp:289] Slave resources: cpus(*):3; mem(*):256; disk(*):1024; ports(*):[31000-32000]
I0929 16:58:29.608832 3501 slave.cpp:317] Slave hostname: fedora-20
I0929 16:58:29.608989 3501 slave.cpp:318] Slave checkpoint: false
I0929 16:58:29.609542 3501 state.cpp:33] Recovering state from '/tmp/AllocatorTest_0_SlaveLost_NcoJ6Z/meta'
I0929 16:58:29.609904 3500 status_update_manager.cpp:193] Recovering status update manager
I0929 16:58:29.610119 3500 containerizer.cpp:252] Recovering containerizer
I0929 16:58:29.610589 3507 slave.cpp:3271] Finished recovery
I0929 16:58:29.611037 3507 slave.cpp:598] New master detected at master@192.168.122.164:55618
I0929 16:58:29.611264 3507 slave.cpp:672] Authenticating with master master@192.168.122.164:55618
I0929 16:58:29.611529 3507 slave.cpp:645] Detecting new master
I0929 16:58:29.611385 3506 status_update_manager.cpp:167] New master detected at master@192.168.122.164:55618
I0929 16:58:29.611719 3503 authenticatee.hpp:128] Creating new client SASL connection
I0929 16:58:29.612570 3503 master.cpp:3737] Authenticating slave(58)@192.168.122.164:55618
I0929 16:58:29.612843 3503 authenticator.hpp:156] Creating new server SASL connection
I0929 16:58:29.613394 3503 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0929 16:58:29.613706 3503 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0929 16:58:29.614083 3503 authenticator.hpp:262] Received SASL authentication start
I0929 16:58:29.614326 3503 authenticator.hpp:384] Authentication requires more steps
I0929 16:58:29.614552 3503 authenticatee.hpp:265] Received SASL authentication step
I0929 16:58:29.614828 3503 authenticator.hpp:290] Received SASL authentication step
I0929 16:58:29.615067 3503 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'fedora-20' server FQDN: 'fedora-20' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0929 16:58:29.615314 3503 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I0929 16:58:29.615562 3503 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0929 16:58:29.615766 3503 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'fedora-20' server FQDN: 'fedora-20' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0929 16:58:29.616060 3503 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0929 16:58:29.616387 3503 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0929 16:58:29.616631 3503 authenticator.hpp:376] Authentication success
I0929 16:58:29.616929 3503 authenticatee.hpp:305] Authentication success
I0929 16:58:29.617081 3501 master.cpp:3777] Successfully authenticated principal 'test-principal' at slave(58)@192.168.122.164:55618
I0929 16:58:29.620779 3500 slave.cpp:729] Successfully authenticated with master master@192.168.122.164:55618
I0929 16:58:29.621150 3500 slave.cpp:992] Will retry registration in 15.66596ms if necessary
I0929 16:58:29.621526 3501 master.cpp:2930] Registering slave at slave(58)@192.168.122.164:55618 (fedora-20) with id 20140929-165829-2759502016-55618-3486-1
I0929 16:58:29.621976 3501 registrar.cpp:421] Attempting to update the 'registry'
I0929 16:58:29.623364 3506 log.cpp:680] Attempting to append 299 bytes to the log
I0929 16:58:29.623780 3506 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 7
I0929 16:58:29.624407 3506 replica.cpp:508] Replica received write request for position 7
I0929 16:58:29.624712 3506 leveldb.cpp:343] Persisting action (318 bytes) to leveldb took 64462ns
I0929 16:58:29.624984 3506 replica.cpp:676] Persisted action at 7
I0929 16:58:29.625460 3506 replica.cpp:655] Replica received learned notice for position 7
I0929 16:58:29.625838 3506 leveldb.cpp:343] Persisting action (320 bytes) to leveldb took 30316ns
I0929 16:58:29.626093 3506 replica.cpp:676] Persisted action at 7
I0929 16:58:29.626382 3506 replica.cpp:661] Replica learned APPEND action at position 7
I0929 16:58:29.626832 3506 log.cpp:699] Attempting to truncate the log to 7
I0929 16:58:29.627231 3506 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 8
I0929 16:58:29.627789 3506 replica.cpp:508] Replica received write request for position 8
I0929 16:58:29.628073 3506 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 26181ns
I0929 16:58:29.628347 3506 replica.cpp:676] Persisted action at 8
I0929 16:58:29.628829 3506 replica.cpp:655] Replica received learned notice for position 8
I0929 16:58:29.629323 3506 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 28559ns
I0929 16:58:29.629581 3506 leveldb.cpp:401] Deleting ~2 keys from leveldb took 22253ns
I0929 16:58:29.629897 3506 replica.cpp:676] Persisted action at 8
I0929 16:58:29.630159 3506 replica.cpp:661] Replica learned TRUNCATE action at position 8
I0929 16:58:29.630910 3501 registrar.cpp:478] Successfully updated 'registry'
I0929 16:58:29.631356 3501 master.cpp:2970] Registered slave 20140929-165829-2759502016-55618-3486-1 at slave(58)@192.168.122.164:55618 (fedora-20)
I0929 16:58:29.631624 3501 master.cpp:4180] Adding slave 20140929-165829-2759502016-55618-3486-1 at slave(58)@192.168.122.164:55618 (fedora-20) with cpus(*):3; mem(*):256; disk(*):1024; ports(*):[31000-32000]
I0929 16:58:29.632066 3501 slave.cpp:763] Registered with master master@192.168.122.164:55618; given slave ID 20140929-165829-2759502016-55618-3486-1
I0929 16:58:29.632493 3501 slave.cpp:2345] Received ping from slave-observer(57)@192.168.122.164:55618
I0929 16:58:29.632298 3506 hierarchical_allocator_process.hpp:442] Added slave 20140929-165829-2759502016-55618-3486-1 (fedora-20) with cpus(*):3; mem(*):256; disk(*):1024; ports(*):[31000-32000] (and cpus(*):3; mem(*):256; disk(*):1024; ports(*):[31000-32000] available)
I0929 16:58:29.633102 3506 hierarchical_allocator_process.hpp:734] Offering cpus(*):3; mem(*):256; disk(*):1024; ports(*):[31000-32000] on slave 20140929-165829-2759502016-55618-3486-1 to framework 20140929-165829-2759502016-55618-3486-0000
I0929 16:58:29.633496 3507 master.hpp:868] Adding offer 20140929-165829-2759502016-55618-3486-1 with resources cpus(*):3; mem(*):256; disk(*):1024; ports(*):[31000-32000] on slave 20140929-165829-2759502016-55618-3486-1 (fedora-20)
I0929 16:58:29.633833 3507 master.cpp:3679] Sending 1 offers to framework 20140929-165829-2759502016-55618-3486-0000
I0929 16:58:29.634218 3507 sched.cpp:544] Scheduler::resourceOffers took 32550ns
I0929 16:58:29.634784 3507 sched.cpp:745] Stopping framework '20140929-165829-2759502016-55618-3486-0000'
I0929 16:58:29.634558 3486 master.cpp:676] Master terminating
I0929 16:58:29.635319 3486 master.hpp:877] Removing offer 20140929-165829-2759502016-55618-3486-1 with resources cpus(*):3; mem(*):256; disk(*):1024; ports(*):[31000-32000] on slave 20140929-165829-2759502016-55618-3486-1 (fedora-20)
I0929 16:58:29.635725 3506 hierarchical_allocator_process.hpp:679] Performed allocation for slave 20140929-165829-2759502016-55618-3486-1 in 2.656855ms
I0929 16:58:29.644737 3503 slave.cpp:2430] master@192.168.122.164:55618 exited
W0929 16:58:29.645407 3503 slave.cpp:2433] Master disconnected! Waiting for a new master to be elected
I0929 16:58:29.656318 3486 slave.cpp:477] Slave terminating
tests/allocator_tests.cpp:1532: Failure
Actual function call count doesn't match EXPECT_CALL(this->allocator, resourcesRecovered(_, _, _, _))...
Expected: to be called once
Actual: never called - unsatisfied and active
[ FAILED ] AllocatorTest/0.SlaveLost, where TypeParam = mesos::internal::master::allocator::HierarchicalAllocatorProcess<mesos::internal::master::allocator::DRFSorter, mesos::internal::master::allocator::DRFSorter> (179 ms)
{code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)