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 2015/02/25 21:07:04 UTC
[jira] [Created] (MESOS-2403)
MasterAllocatorTest/0.FrameworkReregistersFirst is flaky
Vinod Kone created MESOS-2403:
---------------------------------
Summary: MasterAllocatorTest/0.FrameworkReregistersFirst is flaky
Key: MESOS-2403
URL: https://issues.apache.org/jira/browse/MESOS-2403
Project: Mesos
Issue Type: Bug
Components: test
Affects Versions: 0.23.0
Environment: ASF CI (Ubuntu)
Reporter: Vinod Kone
Assignee: Vinod Kone
{code}
[ RUN ] MasterAllocatorTest/0.FrameworkReregistersFirst
Using temporary directory '/tmp/MasterAllocatorTest_0_FrameworkReregistersFirst_Vy5Nml'
I0224 23:22:31.681670 30589 leveldb.cpp:176] Opened db in 2.943518ms
I0224 23:22:31.682152 30619 process.cpp:2117] Dropped / Lost event for PID: slave(65)@67.195.81.187:38391
I0224 23:22:31.682732 30589 leveldb.cpp:183] Compacted db in 1.029469ms
I0224 23:22:31.682777 30589 leveldb.cpp:198] Created db iterator in 15460ns
I0224 23:22:31.682792 30589 leveldb.cpp:204] Seeked to beginning of db in 1832ns
I0224 23:22:31.682802 30589 leveldb.cpp:273] Iterated through 0 keys in the db in 319ns
I0224 23:22:31.682833 30589 replica.cpp:744] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0224 23:22:31.683228 30605 recover.cpp:449] Starting replica recovery
I0224 23:22:31.683537 30605 recover.cpp:475] Replica is in 4 status
I0224 23:22:31.684624 30615 replica.cpp:641] Replica in 4 status received a broadcasted recover request
I0224 23:22:31.684978 30616 recover.cpp:195] Received a recover response from a replica in 4 status
I0224 23:22:31.685405 30610 recover.cpp:566] Updating replica status to 3
I0224 23:22:31.686249 30609 master.cpp:349] Master 20150224-232231-3142697795-38391-30589 (pomona.apache.org) started on 67.195.81.187:38391
I0224 23:22:31.686265 30617 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 717897ns
I0224 23:22:31.686319 30617 replica.cpp:323] Persisted replica status to 3
I0224 23:22:31.686336 30609 master.cpp:395] Master only allowing authenticated frameworks to register
I0224 23:22:31.686357 30609 master.cpp:400] Master only allowing authenticated slaves to register
I0224 23:22:31.686390 30609 credentials.hpp:37] Loading credentials for authentication from '/tmp/MasterAllocatorTest_0_FrameworkReregistersFirst_Vy5Nml/credentials'
I0224 23:22:31.686511 30606 recover.cpp:475] Replica is in 3 status
I0224 23:22:31.686563 30609 master.cpp:442] Authorization enabled
I0224 23:22:31.686929 30607 whitelist_watcher.cpp:79] No whitelist given
I0224 23:22:31.686954 30603 hierarchical.hpp:287] Initialized hierarchical allocator process
I0224 23:22:31.687134 30605 replica.cpp:641] Replica in 3 status received a broadcasted recover request
I0224 23:22:31.687731 30609 master.cpp:1356] The newly elected leader is master@67.195.81.187:38391 with id 20150224-232231-3142697795-38391-30589
I0224 23:22:31.839818 30609 master.cpp:1369] Elected as the leading master!
I0224 23:22:31.839834 30609 master.cpp:1187] Recovering from registrar
I0224 23:22:31.839926 30605 registrar.cpp:313] Recovering registrar
I0224 23:22:31.840000 30613 recover.cpp:195] Received a recover response from a replica in 3 status
I0224 23:22:31.840504 30606 recover.cpp:566] Updating replica status to 1
I0224 23:22:31.841599 30611 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 990330ns
I0224 23:22:31.841627 30611 replica.cpp:323] Persisted replica status to 1
I0224 23:22:31.841743 30611 recover.cpp:580] Successfully joined the Paxos group
I0224 23:22:31.841904 30611 recover.cpp:464] Recover process terminated
I0224 23:22:31.842366 30608 log.cpp:660] Attempting to start the writer
I0224 23:22:31.843557 30607 replica.cpp:477] Replica received implicit promise request with proposal 1
I0224 23:22:31.844312 30607 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 722368ns
I0224 23:22:31.844337 30607 replica.cpp:345] Persisted promised to 1
I0224 23:22:31.844889 30615 coordinator.cpp:230] Coordinator attemping to fill missing position
I0224 23:22:31.846043 30614 replica.cpp:378] Replica received explicit promise request for position 0 with proposal 2
I0224 23:22:31.846729 30614 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 660024ns
I0224 23:22:31.846746 30614 replica.cpp:679] Persisted action at 0
I0224 23:22:31.847671 30611 replica.cpp:511] Replica received write request for position 0
I0224 23:22:31.847723 30611 leveldb.cpp:438] Reading position from leveldb took 27349ns
I0224 23:22:31.848429 30611 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 671461ns
I0224 23:22:31.848454 30611 replica.cpp:679] Persisted action at 0
I0224 23:22:31.849041 30615 replica.cpp:658] Replica received learned notice for position 0
I0224 23:22:31.849762 30615 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 690386ns
I0224 23:22:31.849787 30615 replica.cpp:679] Persisted action at 0
I0224 23:22:31.849808 30615 replica.cpp:664] Replica learned 1 action at position 0
I0224 23:22:31.850416 30612 log.cpp:676] Writer started with ending position 0
I0224 23:22:31.851490 30615 leveldb.cpp:438] Reading position from leveldb took 30659ns
I0224 23:22:31.854452 30610 registrar.cpp:346] Successfully fetched the registry (0B) in 14.491136ms
I0224 23:22:31.854543 30610 registrar.cpp:445] Applied 1 operations in 18024ns; attempting to update the 'registry'
I0224 23:22:31.857095 30604 log.cpp:684] Attempting to append 139 bytes to the log
I0224 23:22:31.857208 30608 coordinator.cpp:340] Coordinator attempting to write 2 action at position 1
I0224 23:22:31.858073 30609 replica.cpp:511] Replica received write request for position 1
I0224 23:22:31.858808 30609 leveldb.cpp:343] Persisting action (158 bytes) to leveldb took 701708ns
I0224 23:22:31.858835 30609 replica.cpp:679] Persisted action at 1
I0224 23:22:31.859508 30618 replica.cpp:658] Replica received learned notice for position 1
I0224 23:22:31.860267 30618 leveldb.cpp:343] Persisting action (160 bytes) to leveldb took 731035ns
I0224 23:22:31.860309 30618 replica.cpp:679] Persisted action at 1
I0224 23:22:31.860332 30618 replica.cpp:664] Replica learned 2 action at position 1
I0224 23:22:31.860983 30609 registrar.cpp:490] Successfully updated the 'registry' in 6.39616ms
I0224 23:22:31.861071 30609 registrar.cpp:376] Successfully recovered registrar
I0224 23:22:31.861126 30608 log.cpp:703] Attempting to truncate the log to 1
I0224 23:22:31.861249 30603 coordinator.cpp:340] Coordinator attempting to write 3 action at position 2
I0224 23:22:31.861248 30617 master.cpp:1214] Recovered 0 slaves from the Registry (101B) ; allowing 10mins for slaves to re-register
I0224 23:22:31.861831 30613 replica.cpp:511] Replica received write request for position 2
I0224 23:22:31.862504 30613 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 648125ns
I0224 23:22:31.862531 30613 replica.cpp:679] Persisted action at 2
I0224 23:22:31.863067 30603 replica.cpp:658] Replica received learned notice for position 2
I0224 23:22:31.863689 30603 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 602784ns
I0224 23:22:31.863737 30603 leveldb.cpp:401] Deleting ~1 keys from leveldb took 28697ns
I0224 23:22:31.863751 30603 replica.cpp:679] Persisted action at 2
I0224 23:22:31.863767 30603 replica.cpp:664] Replica learned 3 action at position 2
I0224 23:22:31.875962 30610 slave.cpp:174] Slave started on 66)@67.195.81.187:38391
I0224 23:22:31.876008 30610 credentials.hpp:85] Loading credential for authentication from '/tmp/MasterAllocatorTest_0_FrameworkReregistersFirst_ikVXQM/credential'
I0224 23:22:31.876144 30610 slave.cpp:281] Slave using credential for: test-principal
I0224 23:22:31.876404 30610 slave.cpp:299] Slave resources: cpus(*):2; mem(*):1024; disk(*):3.70122e+06; ports(*):[31000-32000]
I0224 23:22:31.876489 30610 slave.cpp:328] Slave hostname: pomona.apache.org
I0224 23:22:31.876502 30610 slave.cpp:329] Slave checkpoint: false
W0224 23:22:31.876507 30610 slave.cpp:331] Disabling checkpointing is deprecated and the --checkpoint flag will be removed in a future release. Please avoid using this flag
I0224 23:22:31.877014 30603 state.cpp:35] Recovering state from '/tmp/MasterAllocatorTest_0_FrameworkReregistersFirst_ikVXQM/meta'
I0224 23:22:31.877230 30610 status_update_manager.cpp:197] Recovering status update manager
I0224 23:22:31.877495 30609 slave.cpp:3776] Finished recovery
I0224 23:22:31.877879 30607 status_update_manager.cpp:171] Pausing sending status updates
I0224 23:22:31.877879 30604 slave.cpp:624] New master detected at master@67.195.81.187:38391
I0224 23:22:31.877959 30604 slave.cpp:687] Authenticating with master master@67.195.81.187:38391
I0224 23:22:31.877975 30604 slave.cpp:692] Using default CRAM-MD5 authenticatee
I0224 23:22:31.878069 30604 slave.cpp:660] Detecting new master
I0224 23:22:31.878093 30608 authenticatee.hpp:139] Creating new client SASL connection
I0224 23:22:31.878223 30604 master.cpp:3813] Authenticating slave(66)@67.195.81.187:38391
I0224 23:22:31.878244 30604 master.cpp:3824] Using default CRAM-MD5 authenticator
I0224 23:22:31.878412 30613 authenticator.hpp:170] Creating new server SASL connection
I0224 23:22:31.878525 30603 authenticatee.hpp:230] Received SASL authentication mechanisms: CRAM-MD5
I0224 23:22:31.878551 30603 authenticatee.hpp:256] Attempting to authenticate with mechanism 'CRAM-MD5'
I0224 23:22:31.878625 30617 authenticator.hpp:276] Received SASL authentication start
I0224 23:22:31.878662 30617 authenticator.hpp:398] Authentication requires more steps
I0224 23:22:31.878727 30603 authenticatee.hpp:276] Received SASL authentication step
I0224 23:22:31.878815 30617 authenticator.hpp:304] Received SASL authentication step
I0224 23:22:31.878839 30617 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0224 23:22:31.878847 30617 auxprop.cpp:171] Looking up auxiliary property '*userPassword'
I0224 23:22:31.878875 30617 auxprop.cpp:171] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0224 23:22:31.878891 30617 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0224 23:22:31.878900 30617 auxprop.cpp:121] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0224 23:22:31.878906 30617 auxprop.cpp:121] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0224 23:22:31.878916 30617 authenticator.hpp:390] Authentication success
I0224 23:22:31.880717 30589 sched.cpp:157] Version: 0.23.0
I0224 23:22:32.017823 30611 authenticatee.hpp:316] Authentication success
I0224 23:22:32.017901 30618 master.cpp:3871] Successfully authenticated principal 'test-principal' at slave(66)@67.195.81.187:38391
I0224 23:22:32.018156 30615 sched.cpp:254] New master detected at master@67.195.81.187:38391
I0224 23:22:32.018240 30615 sched.cpp:310] Authenticating with master master@67.195.81.187:38391
I0224 23:22:32.018263 30615 sched.cpp:317] Using default CRAM-MD5 authenticatee
I0224 23:22:32.018496 30613 slave.cpp:758] Successfully authenticated with master master@67.195.81.187:38391
I0224 23:22:32.018579 30611 authenticatee.hpp:139] Creating new client SASL connection
I0224 23:22:32.018620 30613 slave.cpp:1090] Will retry registration in 363167ns if necessary
I0224 23:22:32.018811 30615 master.cpp:2938] Registering slave at slave(66)@67.195.81.187:38391 (pomona.apache.org) with id 20150224-232231-3142697795-38391-30589-S0
I0224 23:22:32.019122 30615 master.cpp:3813] Authenticating scheduler-9a3224cc-aef0-49a7-a240-4b85b913ff44@67.195.81.187:38391
I0224 23:22:32.019156 30615 master.cpp:3824] Using default CRAM-MD5 authenticator
I0224 23:22:32.019232 30612 registrar.cpp:445] Applied 1 operations in 57599ns; attempting to update the 'registry'
I0224 23:22:32.019394 30603 authenticator.hpp:170] Creating new server SASL connection
I0224 23:22:32.019541 30611 authenticatee.hpp:230] Received SASL authentication mechanisms: CRAM-MD5
I0224 23:22:32.019568 30611 authenticatee.hpp:256] Attempting to authenticate with mechanism 'CRAM-MD5'
I0224 23:22:32.019666 30605 authenticator.hpp:276] Received SASL authentication start
I0224 23:22:32.019717 30605 authenticator.hpp:398] Authentication requires more steps
I0224 23:22:32.019805 30615 authenticatee.hpp:276] Received SASL authentication step
I0224 23:22:32.019942 30605 authenticator.hpp:304] Received SASL authentication step
I0224 23:22:32.019979 30605 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0224 23:22:32.019994 30605 auxprop.cpp:171] Looking up auxiliary property '*userPassword'
I0224 23:22:32.020025 30605 auxprop.cpp:171] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0224 23:22:32.020036 30610 slave.cpp:1090] Will retry registration in 10.850555ms if necessary
I0224 23:22:32.020053 30605 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0224 23:22:32.020102 30605 auxprop.cpp:121] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0224 23:22:32.020117 30605 auxprop.cpp:121] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0224 23:22:32.020133 30605 authenticator.hpp:390] Authentication success
I0224 23:22:32.020151 30611 master.cpp:2926] Ignoring register slave message from slave(66)@67.195.81.187:38391 (pomona.apache.org) as admission is already in progress
I0224 23:22:32.020226 30603 authenticatee.hpp:316] Authentication success
I0224 23:22:32.020256 30611 master.cpp:3871] Successfully authenticated principal 'test-principal' at scheduler-9a3224cc-aef0-49a7-a240-4b85b913ff44@67.195.81.187:38391
I0224 23:22:32.020534 30615 sched.cpp:398] Successfully authenticated with master master@67.195.81.187:38391
I0224 23:22:32.020561 30615 sched.cpp:521] Sending registration request to master@67.195.81.187:38391
I0224 23:22:32.020635 30615 sched.cpp:554] Will retry registration in 490.035142ms if necessary
I0224 23:22:32.020720 30613 master.cpp:1574] Received registration request for framework 'default' at scheduler-9a3224cc-aef0-49a7-a240-4b85b913ff44@67.195.81.187:38391
I0224 23:22:32.020787 30613 master.cpp:1435] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0224 23:22:32.021122 30607 master.cpp:1638] Registering framework 20150224-232231-3142697795-38391-30589-0000 (default) at scheduler-9a3224cc-aef0-49a7-a240-4b85b913ff44@67.195.81.187:38391
I0224 23:22:32.021502 30611 hierarchical.hpp:321] Added framework 20150224-232231-3142697795-38391-30589-0000
I0224 23:22:32.021531 30611 hierarchical.hpp:834] No resources available to allocate!
I0224 23:22:32.021543 30611 hierarchical.hpp:741] Performed allocation for 0 slaves in 18915ns
I0224 23:22:32.021618 30609 sched.cpp:448] Framework registered with 20150224-232231-3142697795-38391-30589-0000
I0224 23:22:32.021673 30609 sched.cpp:462] Scheduler::registered took 26310ns
I0224 23:22:32.022400 30613 log.cpp:684] Attempting to append 316 bytes to the log
I0224 23:22:32.022523 30608 coordinator.cpp:340] Coordinator attempting to write 2 action at position 3
I0224 23:22:32.023232 30607 replica.cpp:511] Replica received write request for position 3
I0224 23:22:32.024055 30607 leveldb.cpp:343] Persisting action (335 bytes) to leveldb took 798548ns
I0224 23:22:32.024073 30607 replica.cpp:679] Persisted action at 3
I0224 23:22:32.024651 30610 replica.cpp:658] Replica received learned notice for position 3
I0224 23:22:32.025252 30610 leveldb.cpp:343] Persisting action (337 bytes) to leveldb took 580525ns
I0224 23:22:32.025271 30610 replica.cpp:679] Persisted action at 3
I0224 23:22:32.025297 30610 replica.cpp:664] Replica learned 2 action at position 3
I0224 23:22:32.025995 30618 registrar.cpp:490] Successfully updated the 'registry' in 6.586112ms
I0224 23:22:32.026228 30604 log.cpp:703] Attempting to truncate the log to 3
I0224 23:22:32.026360 30609 coordinator.cpp:340] Coordinator attempting to write 3 action at position 4
I0224 23:22:32.026669 30609 slave.cpp:2831] Received ping from slave-observer(66)@67.195.81.187:38391
I0224 23:22:32.026772 30609 slave.cpp:792] Registered with master master@67.195.81.187:38391; given slave ID 20150224-232231-3142697795-38391-30589-S0
I0224 23:22:32.026737 30603 master.cpp:2995] Registered slave 20150224-232231-3142697795-38391-30589-S0 at slave(66)@67.195.81.187:38391 (pomona.apache.org) with cpus(*):2; mem(*):1024; disk(*):3.70122e+06; ports(*):[31000-32000]
I0224 23:22:32.026867 30603 status_update_manager.cpp:178] Resuming sending status updates
I0224 23:22:32.026868 30617 hierarchical.hpp:455] Added slave 20150224-232231-3142697795-38391-30589-S0 (pomona.apache.org) with cpus(*):2; mem(*):1024; disk(*):3.70122e+06; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):3.70122e+06; ports(*):[31000-32000] available)
I0224 23:22:32.026921 30615 replica.cpp:511] Replica received write request for position 4
I0224 23:22:32.027276 30617 hierarchical.hpp:759] Performed allocation for slave 20150224-232231-3142697795-38391-30589-S0 in 351257ns
I0224 23:22:32.027580 30615 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 624249ns
I0224 23:22:32.027604 30615 replica.cpp:679] Persisted action at 4
I0224 23:22:32.027642 30618 master.cpp:3755] Sending 1 offers to framework 20150224-232231-3142697795-38391-30589-0000 (default) at scheduler-9a3224cc-aef0-49a7-a240-4b85b913ff44@67.195.81.187:38391
I0224 23:22:32.028223 30617 replica.cpp:658] Replica received learned notice for position 4
I0224 23:22:32.028621 30607 sched.cpp:611] Scheduler::resourceOffers took 648326ns
I0224 23:22:32.028916 30617 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 662416ns
I0224 23:22:32.028991 30617 leveldb.cpp:401] Deleting ~2 keys from leveldb took 47386ns
I0224 23:22:32.029021 30617 replica.cpp:679] Persisted action at 4
I0224 23:22:32.029044 30617 replica.cpp:664] Replica learned 3 action at position 4
I0224 23:22:32.029534 30613 master.cpp:2268] Processing ACCEPT call for offers: [ 20150224-232231-3142697795-38391-30589-O0 ] on slave 20150224-232231-3142697795-38391-30589-S0 at slave(66)@67.195.81.187:38391 (pomona.apache.org) for framework 20150224-232231-3142697795-38391-30589-0000 (default) at scheduler-9a3224cc-aef0-49a7-a240-4b85b913ff44@67.195.81.187:38391
I0224 23:22:32.190521 30613 master.cpp:2112] Authorizing framework principal 'test-principal' to launch task 0 as user 'jenkins'
W0224 23:22:32.191864 30604 validation.cpp:328] 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.
W0224 23:22:32.191905 30604 validation.cpp:340] 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.
I0224 23:22:32.192206 30604 master.hpp:822] Adding task 0 with resources cpus(*):1; mem(*):500 on slave 20150224-232231-3142697795-38391-30589-S0 (pomona.apache.org)
I0224 23:22:32.192318 30604 master.cpp:2545] Launching task 0 of framework 20150224-232231-3142697795-38391-30589-0000 (default) at scheduler-9a3224cc-aef0-49a7-a240-4b85b913ff44@67.195.81.187:38391 with resources cpus(*):1; mem(*):500 on slave 20150224-232231-3142697795-38391-30589-S0 at slave(66)@67.195.81.187:38391 (pomona.apache.org)
I0224 23:22:32.192659 30611 slave.cpp:1121] Got assigned task 0 for framework 20150224-232231-3142697795-38391-30589-0000
I0224 23:22:32.192847 30609 hierarchical.hpp:648] Recovered cpus(*):1; mem(*):524; disk(*):3.70122e+06; ports(*):[31000-32000] (total allocatable: cpus(*):1; mem(*):524; disk(*):3.70122e+06; ports(*):[31000-32000]) on slave 20150224-232231-3142697795-38391-30589-S0 from framework 20150224-232231-3142697795-38391-30589-0000
I0224 23:22:32.192916 30609 hierarchical.hpp:684] Framework 20150224-232231-3142697795-38391-30589-0000 filtered slave 20150224-232231-3142697795-38391-30589-S0 for 5secs
I0224 23:22:32.193327 30611 slave.cpp:1231] Launching task 0 for framework 20150224-232231-3142697795-38391-30589-0000
I0224 23:22:32.196038 30611 slave.cpp:4178] Launching executor default of framework 20150224-232231-3142697795-38391-30589-0000 in work directory '/tmp/MasterAllocatorTest_0_FrameworkReregistersFirst_ikVXQM/slaves/20150224-232231-3142697795-38391-30589-S0/frameworks/20150224-232231-3142697795-38391-30589-0000/executors/default/runs/7c203619-b40f-4d0a-9b75-9ddeecb63472'
I0224 23:22:32.197996 30611 exec.cpp:132] Version: 0.23.0
I0224 23:22:32.198206 30605 exec.cpp:182] Executor started at: executor(32)@67.195.81.187:38391 with pid 30589
I0224 23:22:32.198314 30611 slave.cpp:1378] Queuing task '0' for executor default of framework '20150224-232231-3142697795-38391-30589-0000
I0224 23:22:32.198407 30611 slave.cpp:577] Successfully attached file '/tmp/MasterAllocatorTest_0_FrameworkReregistersFirst_ikVXQM/slaves/20150224-232231-3142697795-38391-30589-S0/frameworks/20150224-232231-3142697795-38391-30589-0000/executors/default/runs/7c203619-b40f-4d0a-9b75-9ddeecb63472'
I0224 23:22:32.198508 30611 slave.cpp:3133] Monitoring executor 'default' of framework '20150224-232231-3142697795-38391-30589-0000' in container '7c203619-b40f-4d0a-9b75-9ddeecb63472'
I0224 23:22:32.198637 30611 slave.cpp:2141] Got registration for executor 'default' of framework 20150224-232231-3142697795-38391-30589-0000 from executor(32)@67.195.81.187:38391
I0224 23:22:32.198839 30604 exec.cpp:206] Executor registered on slave 20150224-232231-3142697795-38391-30589-S0
I0224 23:22:32.199090 30611 slave.cpp:1532] Sending queued task '0' to executor 'default' of framework 20150224-232231-3142697795-38391-30589-0000
I0224 23:22:32.200916 30604 exec.cpp:218] Executor::registered took 24976ns
I0224 23:22:32.201087 30604 exec.cpp:293] Executor asked to run task '0'
I0224 23:22:32.201164 30604 exec.cpp:302] Executor::launchTask took 54201ns
I0224 23:22:32.203301 30604 exec.cpp:525] Executor sending status update TASK_RUNNING (UUID: 49340611-fb39-423b-96f6-6c1e724c1a53) for task 0 of framework 20150224-232231-3142697795-38391-30589-0000
I0224 23:22:32.203533 30618 slave.cpp:2508] Handling status update TASK_RUNNING (UUID: 49340611-fb39-423b-96f6-6c1e724c1a53) for task 0 of framework 20150224-232231-3142697795-38391-30589-0000 from executor(32)@67.195.81.187:38391
I0224 23:22:32.203799 30604 status_update_manager.cpp:317] Received status update TASK_RUNNING (UUID: 49340611-fb39-423b-96f6-6c1e724c1a53) for task 0 of framework 20150224-232231-3142697795-38391-30589-0000
I0224 23:22:32.203840 30604 status_update_manager.cpp:494] Creating StatusUpdate stream for task 0 of framework 20150224-232231-3142697795-38391-30589-0000
I0224 23:22:32.204038 30604 status_update_manager.cpp:371] Forwarding update TASK_RUNNING (UUID: 49340611-fb39-423b-96f6-6c1e724c1a53) for task 0 of framework 20150224-232231-3142697795-38391-30589-0000 to the slave
I0224 23:22:32.204262 30607 slave.cpp:2751] Forwarding the update TASK_RUNNING (UUID: 49340611-fb39-423b-96f6-6c1e724c1a53) for task 0 of framework 20150224-232231-3142697795-38391-30589-0000 to master@67.195.81.187:38391
I0224 23:22:32.204473 30607 slave.cpp:2678] Status update manager successfully handled status update TASK_RUNNING (UUID: 49340611-fb39-423b-96f6-6c1e724c1a53) for task 0 of framework 20150224-232231-3142697795-38391-30589-0000
I0224 23:22:32.204511 30607 slave.cpp:2684] Sending acknowledgement for status update TASK_RUNNING (UUID: 49340611-fb39-423b-96f6-6c1e724c1a53) for task 0 of framework 20150224-232231-3142697795-38391-30589-0000 to executor(32)@67.195.81.187:38391
I0224 23:22:32.204558 30616 master.cpp:3295] Status update TASK_RUNNING (UUID: 49340611-fb39-423b-96f6-6c1e724c1a53) for task 0 of framework 20150224-232231-3142697795-38391-30589-0000 from slave 20150224-232231-3142697795-38391-30589-S0 at slave(66)@67.195.81.187:38391 (pomona.apache.org)
I0224 23:22:32.204602 30616 master.cpp:3336] Forwarding status update TASK_RUNNING (UUID: 49340611-fb39-423b-96f6-6c1e724c1a53) for task 0 of framework 20150224-232231-3142697795-38391-30589-0000
I0224 23:22:32.204676 30610 exec.cpp:339] Executor received status update acknowledgement 49340611-fb39-423b-96f6-6c1e724c1a53 for task 0 of framework 20150224-232231-3142697795-38391-30589-0000
I0224 23:22:32.204753 30616 master.cpp:4615] Updating the latest state of task 0 of framework 20150224-232231-3142697795-38391-30589-0000 to TASK_RUNNING
I0224 23:22:32.204874 30603 sched.cpp:717] Scheduler::statusUpdate took 52057ns
I0224 23:22:32.205277 30614 master.cpp:2782] Forwarding status update acknowledgement 49340611-fb39-423b-96f6-6c1e724c1a53 for task 0 of framework 20150224-232231-3142697795-38391-30589-0000 (default) at scheduler-9a3224cc-aef0-49a7-a240-4b85b913ff44@67.195.81.187:38391 to slave 20150224-232231-3142697795-38391-30589-S0 at slave(66)@67.195.81.187:38391 (pomona.apache.org)
I0224 23:22:32.205579 30618 status_update_manager.cpp:389] Received status update acknowledgement (UUID: 49340611-fb39-423b-96f6-6c1e724c1a53) for task 0 of framework 20150224-232231-3142697795-38391-30589-0000
I0224 23:22:32.205798 30604 slave.cpp:2081] Status update manager successfully handled status update acknowledgement (UUID: 49340611-fb39-423b-96f6-6c1e724c1a53) for task 0 of framework 20150224-232231-3142697795-38391-30589-0000
I0224 23:22:32.206073 30607 master.cpp:787] Master terminating
W0224 23:22:32.206197 30607 master.cpp:4668] Removing task 0 with resources cpus(*):1; mem(*):500 of framework 20150224-232231-3142697795-38391-30589-0000 on slave 20150224-232231-3142697795-38391-30589-S0 at slave(66)@67.195.81.187:38391 (pomona.apache.org) in non-terminal state TASK_RUNNING
I0224 23:22:32.206420 30614 hierarchical.hpp:648] Recovered cpus(*):1; mem(*):500 (total allocatable: cpus(*):2; mem(*):1024; disk(*):3.70122e+06; ports(*):[31000-32000]) on slave 20150224-232231-3142697795-38391-30589-S0 from framework 20150224-232231-3142697795-38391-30589-0000
I0224 23:22:32.206552 30607 master.cpp:4711] Removing executor 'default' with resources of framework 20150224-232231-3142697795-38391-30589-0000 on slave 20150224-232231-3142697795-38391-30589-S0 at slave(66)@67.195.81.187:38391 (pomona.apache.org)
I0224 23:22:32.321058 30619 process.cpp:2117] Dropped / Lost event for PID: hierarchical-allocator(81)@67.195.81.187:38391
I0224 23:22:32.367074 30612 slave.cpp:2916] master@67.195.81.187:38391 exited
W0224 23:22:32.367101 30612 slave.cpp:2919] Master disconnected! Waiting for a new master to be elected
I0224 23:22:32.368388 30589 process.cpp:2117] Dropped / Lost event for PID: master@67.195.81.187:38391
I0224 23:22:32.368482 30589 process.cpp:2117] Dropped / Lost event for PID: master@67.195.81.187:38391
I0224 23:22:32.375794 30589 leveldb.cpp:176] Opened db in 3.725405ms
I0224 23:22:32.379137 30589 leveldb.cpp:183] Compacted db in 3.309337ms
I0224 23:22:32.379196 30589 leveldb.cpp:198] Created db iterator in 21994ns
I0224 23:22:32.379236 30589 leveldb.cpp:204] Seeked to beginning of db in 20370ns
I0224 23:22:32.379356 30589 leveldb.cpp:273] Iterated through 3 keys in the db in 102640ns
I0224 23:22:32.379411 30589 replica.cpp:744] Replica recovered with log positions 3 -> 4 with 0 holes and 0 unlearned
I0224 23:22:32.379884 30610 recover.cpp:449] Starting replica recovery
I0224 23:22:32.380156 30610 recover.cpp:475] Replica is in 1 status
I0224 23:22:32.380460 30610 recover.cpp:464] Recover process terminated
I0224 23:22:32.381878 30616 master.cpp:349] Master 20150224-232232-3142697795-38391-30589 (pomona.apache.org) started on 67.195.81.187:38391
I0224 23:22:32.381927 30616 master.cpp:395] Master only allowing authenticated frameworks to register
I0224 23:22:32.381945 30616 master.cpp:400] Master only allowing authenticated slaves to register
I0224 23:22:32.381974 30616 credentials.hpp:37] Loading credentials for authentication from '/tmp/MasterAllocatorTest_0_FrameworkReregistersFirst_Vy5Nml/credentials'
I0224 23:22:32.382220 30616 master.cpp:442] Authorization enabled
I0224 23:22:32.382783 30604 whitelist_watcher.cpp:79] No whitelist given
I0224 23:22:32.382861 30607 hierarchical.hpp:287] Initialized hierarchical allocator process
I0224 23:22:32.384114 30616 master.cpp:1356] The newly elected leader is master@67.195.81.187:38391 with id 20150224-232232-3142697795-38391-30589
I0224 23:22:32.384150 30616 master.cpp:1369] Elected as the leading master!
I0224 23:22:32.384178 30616 master.cpp:1187] Recovering from registrar
I0224 23:22:32.384330 30617 registrar.cpp:313] Recovering registrar
I0224 23:22:32.384851 30606 log.cpp:660] Attempting to start the writer
I0224 23:22:32.386044 30615 replica.cpp:477] Replica received implicit promise request with proposal 2
I0224 23:22:32.386862 30615 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 790008ns
I0224 23:22:32.386888 30615 replica.cpp:345] Persisted promised to 2
I0224 23:22:32.387544 30612 coordinator.cpp:230] Coordinator attemping to fill missing position
I0224 23:22:32.387799 30615 log.cpp:676] Writer started with ending position 4
I0224 23:22:32.388854 30606 leveldb.cpp:438] Reading position from leveldb took 51391ns
I0224 23:22:32.388949 30606 leveldb.cpp:438] Reading position from leveldb took 40544ns
I0224 23:22:32.390015 30611 registrar.cpp:346] Successfully fetched the registry (277B) in 5.604096ms
I0224 23:22:32.390182 30611 registrar.cpp:445] Applied 1 operations in 46501ns; attempting to update the 'registry'
I0224 23:22:32.392963 30608 log.cpp:684] Attempting to append 316 bytes to the log
I0224 23:22:32.393081 30606 coordinator.cpp:340] Coordinator attempting to write 2 action at position 5
I0224 23:22:32.393875 30607 replica.cpp:511] Replica received write request for position 5
I0224 23:22:32.394582 30607 leveldb.cpp:343] Persisting action (335 bytes) to leveldb took 675133ns
I0224 23:22:32.394609 30607 replica.cpp:679] Persisted action at 5
I0224 23:22:32.395190 30614 replica.cpp:658] Replica received learned notice for position 5
I0224 23:22:32.395917 30614 leveldb.cpp:343] Persisting action (337 bytes) to leveldb took 701360ns
I0224 23:22:32.395944 30614 replica.cpp:679] Persisted action at 5
I0224 23:22:32.395966 30614 replica.cpp:664] Replica learned 2 action at position 5
I0224 23:22:32.396880 30614 registrar.cpp:490] Successfully updated the 'registry' in 6.644224ms
I0224 23:22:32.397056 30614 registrar.cpp:376] Successfully recovered registrar
I0224 23:22:32.397111 30604 log.cpp:703] Attempting to truncate the log to 5
I0224 23:22:32.397274 30616 coordinator.cpp:340] Coordinator attempting to write 3 action at position 6
I0224 23:22:32.397708 30615 master.cpp:1214] Recovered 1 slaves from the Registry (277B) ; allowing 10mins for slaves to re-register
I0224 23:22:32.398107 30612 replica.cpp:511] Replica received write request for position 6
I0224 23:22:32.398763 30612 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 625992ns
I0224 23:22:32.398789 30612 replica.cpp:679] Persisted action at 6
I0224 23:22:32.399373 30615 replica.cpp:658] Replica received learned notice for position 6
I0224 23:22:32.400152 30615 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 754us
I0224 23:22:32.400228 30615 leveldb.cpp:401] Deleting ~2 keys from leveldb took 39811ns
I0224 23:22:32.400250 30615 replica.cpp:679] Persisted action at 6
I0224 23:22:32.400274 30615 replica.cpp:664] Replica learned 3 action at position 6
I0224 23:22:32.410408 30604 sched.cpp:248] Scheduler::disconnected took 15348ns
I0224 23:22:32.410430 30604 sched.cpp:254] New master detected at master@67.195.81.187:38391
I0224 23:22:32.410508 30604 sched.cpp:310] Authenticating with master master@67.195.81.187:38391
I0224 23:22:32.410531 30604 sched.cpp:317] Using default CRAM-MD5 authenticatee
I0224 23:22:32.410781 30605 authenticatee.hpp:139] Creating new client SASL connection
I0224 23:22:32.410964 30608 master.cpp:3813] Authenticating scheduler-9a3224cc-aef0-49a7-a240-4b85b913ff44@67.195.81.187:38391
I0224 23:22:32.410991 30608 master.cpp:3824] Using default CRAM-MD5 authenticator
I0224 23:22:32.411188 30617 authenticator.hpp:170] Creating new server SASL connection
I0224 23:22:32.411362 30612 authenticatee.hpp:230] Received SASL authentication mechanisms: CRAM-MD5
I0224 23:22:32.411391 30612 authenticatee.hpp:256] Attempting to authenticate with mechanism 'CRAM-MD5'
I0224 23:22:32.411499 30618 authenticator.hpp:276] Received SASL authentication start
I0224 23:22:32.411600 30618 authenticator.hpp:398] Authentication requires more steps
I0224 23:22:32.411710 30614 authenticatee.hpp:276] Received SASL authentication step
I0224 23:22:32.411818 30618 authenticator.hpp:304] Received SASL authentication step
I0224 23:22:32.411849 30618 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0224 23:22:32.411861 30618 auxprop.cpp:171] Looking up auxiliary property '*userPassword'
I0224 23:22:32.411897 30618 auxprop.cpp:171] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0224 23:22:32.411922 30618 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0224 23:22:32.411934 30618 auxprop.cpp:121] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0224 23:22:32.411942 30618 auxprop.cpp:121] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0224 23:22:32.411958 30618 authenticator.hpp:390] Authentication success
I0224 23:22:32.412032 30614 authenticatee.hpp:316] Authentication success
I0224 23:22:32.412061 30612 master.cpp:3871] Successfully authenticated principal 'test-principal' at scheduler-9a3224cc-aef0-49a7-a240-4b85b913ff44@67.195.81.187:38391
I0224 23:22:32.412345 30605 sched.cpp:398] Successfully authenticated with master master@67.195.81.187:38391
I0224 23:22:32.412375 30605 sched.cpp:521] Sending registration request to master@67.195.81.187:38391
I0224 23:22:32.528939 30605 sched.cpp:554] Will retry registration in 718.250035ms if necessary
I0224 23:22:32.529072 30605 sched.cpp:521] Sending registration request to master@67.195.81.187:38391
I0224 23:22:32.529136 30605 sched.cpp:554] Will retry registration in 2.186117614secs if necessary
I0224 23:22:32.529161 30618 master.cpp:1711] Received re-registration request from framework 20150224-232231-3142697795-38391-30589-0000 (default) at scheduler-9a3224cc-aef0-49a7-a240-4b85b913ff44@67.195.81.187:38391
I0224 23:22:32.529274 30618 master.cpp:1435] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0224 23:22:32.529597 30618 master.cpp:1711] Received re-registration request from framework 20150224-232231-3142697795-38391-30589-0000 (default) at scheduler-9a3224cc-aef0-49a7-a240-4b85b913ff44@67.195.81.187:38391
I0224 23:22:32.529662 30618 master.cpp:1435] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0224 23:22:32.529856 30618 master.cpp:1764] Re-registering framework 20150224-232231-3142697795-38391-30589-0000 (default) at scheduler-9a3224cc-aef0-49a7-a240-4b85b913ff44@67.195.81.187:38391
I0224 23:22:32.530449 30614 hierarchical.hpp:321] Added framework 20150224-232231-3142697795-38391-30589-0000
I0224 23:22:32.530490 30614 hierarchical.hpp:834] No resources available to allocate!
I0224 23:22:32.530510 30614 hierarchical.hpp:741] Performed allocation for 0 slaves in 32479ns
I0224 23:22:32.530743 30618 master.cpp:1764] Re-registering framework 20150224-232231-3142697795-38391-30589-0000 (default) at scheduler-9a3224cc-aef0-49a7-a240-4b85b913ff44@67.195.81.187:38391
I0224 23:22:32.530777 30611 sched.cpp:448] Framework registered with 20150224-232231-3142697795-38391-30589-0000
I0224 23:22:32.530787 30618 master.cpp:1804] Allowing framework 20150224-232231-3142697795-38391-30589-0000 (default) at scheduler-9a3224cc-aef0-49a7-a240-4b85b913ff44@67.195.81.187:38391 to re-register with an already used id
I0224 23:22:32.530824 30611 sched.cpp:462] Scheduler::registered took 20697ns
I0224 23:22:32.530948 30605 sched.cpp:477] Ignoring framework re-registered message because the driver is already connected!
I0224 23:22:32.533220 30606 status_update_manager.cpp:171] Pausing sending status updates
I0224 23:22:32.533226 30605 slave.cpp:624] New master detected at master@67.195.81.187:38391
I0224 23:22:32.533362 30605 slave.cpp:687] Authenticating with master master@67.195.81.187:38391
I0224 23:22:32.533385 30605 slave.cpp:692] Using default CRAM-MD5 authenticatee
I0224 23:22:32.533529 30605 slave.cpp:660] Detecting new master
I0224 23:22:32.533576 30612 authenticatee.hpp:139] Creating new client SASL connection
I0224 23:22:32.533759 30603 master.cpp:3813] Authenticating slave(66)@67.195.81.187:38391
I0224 23:22:32.533790 30603 master.cpp:3824] Using default CRAM-MD5 authenticator
I0224 23:22:32.534018 30605 authenticator.hpp:170] Creating new server SASL connection
I0224 23:22:32.534195 30609 authenticatee.hpp:230] Received SASL authentication mechanisms: CRAM-MD5
I0224 23:22:32.534227 30609 authenticatee.hpp:256] Attempting to authenticate with mechanism 'CRAM-MD5'
I0224 23:22:32.534339 30609 authenticator.hpp:276] Received SASL authentication start
I0224 23:22:32.534394 30609 authenticator.hpp:398] Authentication requires more steps
I0224 23:22:32.534494 30609 authenticatee.hpp:276] Received SASL authentication step
I0224 23:22:32.534600 30609 authenticator.hpp:304] Received SASL authentication step
I0224 23:22:32.534629 30609 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0224 23:22:32.534642 30609 auxprop.cpp:171] Looking up auxiliary property '*userPassword'
I0224 23:22:32.534692 30609 auxprop.cpp:171] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0224 23:22:32.534725 30609 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0224 23:22:32.534740 30609 auxprop.cpp:121] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0224 23:22:32.534749 30609 auxprop.cpp:121] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0224 23:22:32.534765 30609 authenticator.hpp:390] Authentication success
I0224 23:22:32.534891 30604 authenticatee.hpp:316] Authentication success
I0224 23:22:32.534906 30609 master.cpp:3871] Successfully authenticated principal 'test-principal' at slave(66)@67.195.81.187:38391
I0224 23:22:32.535146 30608 slave.cpp:758] Successfully authenticated with master master@67.195.81.187:38391
I0224 23:22:32.535567 30608 slave.cpp:1090] Will retry registration in 10.96399ms if necessary
I0224 23:22:32.535843 30610 master.cpp:3120] Re-registering slave 20150224-232231-3142697795-38391-30589-S0 at slave(66)@67.195.81.187:38391 (pomona.apache.org)
I0224 23:22:32.536542 30606 registrar.cpp:445] Applied 1 operations in 71981ns; attempting to update the 'registry'
I0224 23:22:32.539535 30612 log.cpp:684] Attempting to append 316 bytes to the log
I0224 23:22:32.539682 30617 coordinator.cpp:340] Coordinator attempting to write 2 action at position 7
I0224 23:22:32.540549 30608 replica.cpp:511] Replica received write request for position 7
I0224 23:22:32.540832 30608 leveldb.cpp:343] Persisting action (335 bytes) to leveldb took 249089ns
I0224 23:22:32.540858 30608 replica.cpp:679] Persisted action at 7
I0224 23:22:32.541555 30604 replica.cpp:658] Replica received learned notice for position 7
I0224 23:22:32.542254 30604 leveldb.cpp:343] Persisting action (337 bytes) to leveldb took 671501ns
I0224 23:22:32.542294 30604 replica.cpp:679] Persisted action at 7
I0224 23:22:32.542320 30604 replica.cpp:664] Replica learned 2 action at position 7
I0224 23:22:32.543231 30603 registrar.cpp:490] Successfully updated the 'registry' in 6.617088ms
I0224 23:22:32.543637 30613 log.cpp:703] Attempting to truncate the log to 7
I0224 23:22:32.543784 30611 coordinator.cpp:340] Coordinator attempting to write 3 action at position 8
I0224 23:22:32.544088 30610 master.hpp:822] Adding task 0 with resources cpus(*):1; mem(*):500 on slave 20150224-232231-3142697795-38391-30589-S0 (pomona.apache.org)
I0224 23:22:32.544503 30612 slave.cpp:2831] Received ping from slave-observer(67)@67.195.81.187:38391
I0224 23:22:32.544530 30618 replica.cpp:511] Replica received write request for position 8
I0224 23:22:32.544800 30610 master.cpp:3191] Re-registered slave 20150224-232231-3142697795-38391-30589-S0 at slave(66)@67.195.81.187:38391 (pomona.apache.org) with cpus(*):2; mem(*):1024; disk(*):3.70122e+06; ports(*):[31000-32000]
I0224 23:22:32.544862 30607 slave.cpp:860] Re-registered with master master@67.195.81.187:38391
I0224 23:22:32.544961 30606 status_update_manager.cpp:178] Resuming sending status updates
I0224 23:22:32.544975 30610 master.cpp:3219] Sending updated checkpointed resources to slave 20150224-232231-3142697795-38391-30589-S0 at slave(66)@67.195.81.187:38391 (pomona.apache.org)
I0224 23:22:32.545047 30612 hierarchical.hpp:455] Added slave 20150224-232231-3142697795-38391-30589-S0 (pomona.apache.org) with cpus(*):2; mem(*):1024; disk(*):3.70122e+06; ports(*):[31000-32000] (and cpus(*):1; mem(*):524; disk(*):3.70122e+06; ports(*):[31000-32000] available)
I0224 23:22:32.545090 30603 slave.cpp:1922] Updating framework 20150224-232231-3142697795-38391-30589-0000 pid to scheduler-9a3224cc-aef0-49a7-a240-4b85b913ff44@67.195.81.187:38391
I0224 23:22:32.545128 30618 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 567893ns
I0224 23:22:32.545155 30618 replica.cpp:679] Persisted action at 8
I0224 23:22:32.545240 30613 status_update_manager.cpp:178] Resuming sending status updates
I0224 23:22:32.545424 30603 slave.cpp:2010] Updated checkpointed resources from to
I0224 23:22:32.545569 30612 hierarchical.hpp:759] Performed allocation for slave 20150224-232231-3142697795-38391-30589-S0 in 472208ns
I0224 23:22:32.545915 30610 replica.cpp:658] Replica received learned notice for position 8
I0224 23:22:32.545930 30607 master.cpp:3755] Sending 1 offers to framework 20150224-232231-3142697795-38391-30589-0000 (default) at scheduler-9a3224cc-aef0-49a7-a240-4b85b913ff44@67.195.81.187:38391
I0224 23:22:32.688380 30615 hierarchical.hpp:741] Performed allocation for 1 slaves in 418073ns
I0224 23:22:32.691712 30607 master.cpp:3755] Sending 1 offers to framework 20150224-232231-3142697795-38391-30589-0000 (default) at scheduler-9a3224cc-aef0-49a7-a240-4b85b913ff44@67.195.81.187:38391
I0224 23:22:32.691795 30605 sched.cpp:611] Scheduler::resourceOffers took 95977ns
I0224 23:22:32.691961 30610 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 649479ns
I0224 23:22:32.692033 30610 leveldb.cpp:401] Deleting ~2 keys from leveldb took 43354ns
I0224 23:22:32.692061 30610 replica.cpp:679] Persisted action at 8
I0224 23:22:32.692093 30610 replica.cpp:664] Replica learned 3 action at position 8
I0224 23:22:32.692191 30589 sched.cpp:1589] Asked to stop the driver
../../src/tests/master_allocator_tests.cpp:1308: Failure
Mock function called more times than expected - returning directly.
Function call: resourceOffers(0x7fff88bc3d10, @0x2b8726c54b30 { 128-byte object <D0-C4 A2-22 87-2B 00-00 00-00 00-00 00-00 00-00 E0-C2 00-3C 87-2B 00-00 60-C3 00-3C 87-2B 00-00 E0-C3 00-3C 87-2B 00-00 D0-C0 00-3C 87-2B 00-00 50-7B 00-3C 87-2B 00-00 04-00 00-00 04-00 00-00 04-00 00-00 20-69 73-20 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 20-6E 65-76 50-C2 00-3C 87-2B 00-00 01-00 00-00 01-00 00-00 04-00 00-00 00-00 00-00 00-00 00-00 0F-00 00-00> })
Expected: to be called once
Actual: called twice - over-saturated and active
I0224 23:22:32.692252 30605 sched.cpp:611] Scheduler::resourceOffers took 213312ns
I0224 23:22:32.692296 30610 master.cpp:787] Master terminating
I0224 23:22:32.692387 30605 sched.cpp:831] Stopping framework '20150224-232231-3142697795-38391-30589-0000'
W0224 23:22:32.692448 30610 master.cpp:4668] Removing task 0 with resources cpus(*):1; mem(*):500 of framework 20150224-232231-3142697795-38391-30589-0000 on slave 20150224-232231-3142697795-38391-30589-S0 at slave(66)@67.195.81.187:38391 (pomona.apache.org) in non-terminal state TASK_RUNNING
I0224 23:22:32.692739 30613 hierarchical.hpp:648] Recovered cpus(*):1; mem(*):500 (total allocatable: cpus(*):1; mem(*):500) on slave 20150224-232231-3142697795-38391-30589-S0 from framework 20150224-232231-3142697795-38391-30589-0000
I0224 23:22:32.692939 30610 master.cpp:4711] Removing executor 'default' with resources of framework 20150224-232231-3142697795-38391-30589-0000 on slave 20150224-232231-3142697795-38391-30589-S0 at slave(66)@67.195.81.187:38391 (pomona.apache.org)
I0224 23:22:32.693953 30610 slave.cpp:2916] master@67.195.81.187:38391 exited
W0224 23:22:32.693982 30610 slave.cpp:2919] Master disconnected! Waiting for a new master to be elected
I0224 23:22:32.695185 30589 process.cpp:2117] Dropped / Lost event for PID: master@67.195.81.187:38391
I0224 23:22:32.695327 30589 process.cpp:2117] Dropped / Lost event for PID: master@67.195.81.187:38391
I0224 23:22:32.697404 30613 slave.cpp:3191] Executor 'default' of framework 20150224-232231-3142697795-38391-30589-0000 exited with status 0
I0224 23:22:32.699574 30613 slave.cpp:2508] Handling status update TASK_LOST (UUID: d33cdd1e-5586-4ae5-94b0-870a1443844b) for task 0 of framework 20150224-232231-3142697795-38391-30589-0000 from @0.0.0.0:0
I0224 23:22:32.699658 30613 slave.cpp:4486] Terminating task 0
I0224 23:22:32.699964 30613 process.cpp:2117] Dropped / Lost event for PID: master@67.195.81.187:38391
I0224 23:22:32.700003 30613 slave.cpp:506] Slave terminating
I0224 23:22:32.700073 30613 slave.cpp:1745] Asked to shut down framework 20150224-232231-3142697795-38391-30589-0000 by @0.0.0.0:0
I0224 23:22:32.700098 30613 slave.cpp:1770] Shutting down framework 20150224-232231-3142697795-38391-30589-0000
I0224 23:22:32.700160 30613 slave.cpp:3300] Cleaning up executor 'default' of framework 20150224-232231-3142697795-38391-30589-0000
I0224 23:22:32.700355 30610 gc.cpp:56] Scheduling '/tmp/MasterAllocatorTest_0_FrameworkReregistersFirst_ikVXQM/slaves/20150224-232231-3142697795-38391-30589-S0/frameworks/20150224-232231-3142697795-38391-30589-0000/executors/default/runs/7c203619-b40f-4d0a-9b75-9ddeecb63472' for gc 6.99999189524148days in the future
I0224 23:22:32.700449 30613 slave.cpp:3379] Cleaning up framework 20150224-232231-3142697795-38391-30589-0000
I0224 23:22:32.700522 30610 gc.cpp:56] Scheduling '/tmp/MasterAllocatorTest_0_FrameworkReregistersFirst_ikVXQM/slaves/20150224-232231-3142697795-38391-30589-S0/frameworks/20150224-232231-3142697795-38391-30589-0000/executors/default' for gc 6.99999189365926days in the future
I0224 23:22:32.700580 30608 status_update_manager.cpp:279] Closing status update streams for framework 20150224-232231-3142697795-38391-30589-0000
I0224 23:22:32.700630 30610 gc.cpp:56] Scheduling '/tmp/MasterAllocatorTest_0_FrameworkReregistersFirst_ikVXQM/slaves/20150224-232231-3142697795-38391-30589-S0/frameworks/20150224-232231-3142697795-38391-30589-0000' for gc 6.99999189199111days in the future
I0224 23:22:32.700666 30608 status_update_manager.cpp:525] Cleaning up status update stream for task 0 of framework 20150224-232231-3142697795-38391-30589-0000
I0224 23:22:32.702638 30589 process.cpp:2117] Dropped / Lost event for PID: scheduler-9a3224cc-aef0-49a7-a240-4b85b913ff44@67.195.81.187:38391
I0224 23:22:32.702955 30589 process.cpp:2117] Dropped / Lost event for PID: slave(66)@67.195.81.187:38391
[ FAILED ] MasterAllocatorTest/0.FrameworkReregistersFirst, where TypeParam = mesos::internal::master::allocator::MesosAllocator<mesos::internal::master::allocator::HierarchicalAllocatorProcess<mesos::internal::master::allocator::DRFSorter, mesos::internal::master::allocator::DRFSorter> > (1027 ms)
{code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)