Niklas Quarfot Nielsen created MESOS-2366:
---------------------------------------------
Summary: MasterSlaveReconciliationTest.ReconcileLostTask is flaky
Key: MESOS-2366
URL: https://issues.apache.org/jira/browse/MESOS-2366
Project: Mesos
Issue Type: Task
Reporter: Niklas Quarfot Nielsen
https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/2746/changes
{code}
[ RUN ] MasterSlaveReconciliationTest.ReconcileLostTask
Using temporary directory
'/tmp/MasterSlaveReconciliationTest_ReconcileLostTask_Rgb8FF'
I0218 01:53:26.881561 13918 leveldb.cpp:175] Opened db in 2.891605ms
I0218 01:53:26.882547 13918 leveldb.cpp:182] Compacted db in 953447ns
I0218 01:53:26.882596 13918 leveldb.cpp:197] Created db iterator in 20629ns
I0218 01:53:26.882616 13918 leveldb.cpp:203] Seeked to beginning of db in 2370ns
I0218 01:53:26.882627 13918 leveldb.cpp:272] Iterated through 0 keys in the db
in 348ns
I0218 01:53:26.882664 13918 replica.cpp:743] Replica recovered with log
positions 0 -> 0 with 1 holes and 0 unlearned
I0218 01:53:26.883124 13947 recover.cpp:448] Starting replica recovery
I0218 01:53:26.883625 13941 recover.cpp:474] Replica is in 4 status
I0218 01:53:26.884744 13945 replica.cpp:640] Replica in 4 status received a
broadcasted recover request
I0218 01:53:26.885118 13939 recover.cpp:194] Received a recover response from a
replica in 4 status
I0218 01:53:26.885565 13933 recover.cpp:565] Updating replica status to 3
I0218 01:53:26.886548 13932 leveldb.cpp:305] Persisting metadata (8 bytes) to
leveldb took 733223ns
I0218 01:53:26.886574 13932 replica.cpp:322] Persisted replica status to 3
I0218 01:53:26.886714 13943 master.cpp:347] Master
20150218-015326-3142697795-57268-13918 (pomona.apache.org) started on
67.195.81.187:57268
I0218 01:53:26.886760 13943 master.cpp:393] Master only allowing authenticated
frameworks to register
I0218 01:53:26.886772 13943 master.cpp:398] Master only allowing authenticated
slaves to register
I0218 01:53:26.886798 13943 credentials.hpp:36] Loading credentials for
authentication from
'/tmp/MasterSlaveReconciliationTest_ReconcileLostTask_Rgb8FF/credentials'
I0218 01:53:26.886826 13934 recover.cpp:474] Replica is in 3 status
I0218 01:53:26.887151 13943 master.cpp:440] Authorization enabled
I0218 01:53:26.887866 13944 replica.cpp:640] Replica in 3 status received a
broadcasted recover request
I0218 01:53:26.887969 13942 whitelist_watcher.cpp:78] No whitelist given
I0218 01:53:26.888021 13940 hierarchical.hpp:286] Initialized hierarchical
allocator process
I0218 01:53:26.888178 13934 recover.cpp:194] Received a recover response from a
replica in 3 status
I0218 01:53:26.889114 13943 master.cpp:1354] The newly elected leader is
[email protected]:57268 with id 20150218-015326-3142697795-57268-13918
I0218 01:53:27.064930 13948 process.cpp:2117] Dropped / Lost event for PID:
hierarchical-allocator(183)@67.195.81.187:57268
I0218 01:53:27.911870 13943 master.cpp:1367] Elected as the leading master!
I0218 01:53:27.911911 13943 master.cpp:1185] Recovering from registrar
I0218 01:53:27.912106 13948 process.cpp:2117] Dropped / Lost event for PID:
[email protected]:57268
I0218 01:53:27.912255 13932 registrar.cpp:312] Recovering registrar
I0218 01:53:27.912307 13948 process.cpp:2117] Dropped / Lost event for PID:
hierarchical-allocator(179)@67.195.81.187:57268
I0218 01:53:27.912626 13940 hierarchical.hpp:831] No resources available to
allocate!
I0218 01:53:27.912658 13940 hierarchical.hpp:738] Performed allocation for 0
slaves in 60316ns
I0218 01:53:27.912838 13947 recover.cpp:565] Updating replica status to 1
I0218 01:53:27.913966 13947 leveldb.cpp:305] Persisting metadata (8 bytes) to
leveldb took 921045ns
I0218 01:53:27.913998 13947 replica.cpp:322] Persisted replica status to 1
I0218 01:53:27.914106 13932 recover.cpp:579] Successfully joined the Paxos group
I0218 01:53:27.914378 13932 recover.cpp:463] Recover process terminated
I0218 01:53:27.914916 13939 log.cpp:659] Attempting to start the writer
I0218 01:53:27.916374 13937 replica.cpp:476] Replica received implicit promise
request with proposal 1
I0218 01:53:27.916941 13937 leveldb.cpp:305] Persisting metadata (8 bytes) to
leveldb took 534122ns
I0218 01:53:27.916967 13937 replica.cpp:344] Persisted promised to 1
I0218 01:53:27.917795 13936 coordinator.cpp:229] Coordinator attemping to fill
missing position
I0218 01:53:27.919147 13941 replica.cpp:377] Replica received explicit promise
request for position 0 with proposal 2
I0218 01:53:27.919492 13941 leveldb.cpp:342] Persisting action (8 bytes) to
leveldb took 306270ns
I0218 01:53:27.919517 13941 replica.cpp:678] Persisted action at 0
I0218 01:53:27.920755 13934 replica.cpp:510] Replica received write request for
position 0
I0218 01:53:27.920819 13934 leveldb.cpp:437] Reading position from leveldb took
33747ns
I0218 01:53:27.921195 13934 leveldb.cpp:342] Persisting action (14 bytes) to
leveldb took 340479ns
I0218 01:53:27.921221 13934 replica.cpp:678] Persisted action at 0
I0218 01:53:27.921916 13932 replica.cpp:657] Replica received learned notice
for position 0
I0218 01:53:27.922339 13932 leveldb.cpp:342] Persisting action (16 bytes) to
leveldb took 392653ns
I0218 01:53:27.922365 13932 replica.cpp:678] Persisted action at 0
I0218 01:53:27.922386 13932 replica.cpp:663] Replica learned 1 action at
position 0
I0218 01:53:27.923009 13945 log.cpp:675] Writer started with ending position 0
I0218 01:53:27.924167 13937 leveldb.cpp:437] Reading position from leveldb took
29219ns
I0218 01:53:27.927683 13932 registrar.cpp:345] Successfully fetched the
registry (0B) in 15.376128ms
I0218 01:53:27.927789 13932 registrar.cpp:444] Applied 1 operations in 23004ns;
attempting to update the 'registry'
I0218 01:53:27.929957 13947 log.cpp:683] Attempting to append 139 bytes to the
log
I0218 01:53:27.930058 13936 coordinator.cpp:339] Coordinator attempting to
write 2 action at position 1
I0218 01:53:27.930637 13934 replica.cpp:510] Replica received write request for
position 1
I0218 01:53:27.930954 13934 leveldb.cpp:342] Persisting action (158 bytes) to
leveldb took 286664ns
I0218 01:53:27.930975 13934 replica.cpp:678] Persisted action at 1
I0218 01:53:27.931521 13942 replica.cpp:657] Replica received learned notice
for position 1
I0218 01:53:27.931813 13942 leveldb.cpp:342] Persisting action (160 bytes) to
leveldb took 267316ns
I0218 01:53:27.931833 13942 replica.cpp:678] Persisted action at 1
I0218 01:53:27.931849 13942 replica.cpp:663] Replica learned 2 action at
position 1
I0218 01:53:27.932617 13935 registrar.cpp:489] Successfully updated the
'registry' in 4.722944ms
I0218 01:53:27.932726 13935 registrar.cpp:375] Successfully recovered registrar
I0218 01:53:27.932751 13940 log.cpp:702] Attempting to truncate the log to 1
I0218 01:53:27.932865 13944 coordinator.cpp:339] Coordinator attempting to
write 3 action at position 2
I0218 01:53:27.932998 13939 master.cpp:1212] Recovered 0 slaves from the
Registry (101B) ; allowing 10mins for slaves to re-register
I0218 01:53:27.933732 13936 replica.cpp:510] Replica received write request for
position 2
I0218 01:53:27.934146 13936 leveldb.cpp:342] Persisting action (16 bytes) to
leveldb took 386584ns
I0218 01:53:27.934167 13936 replica.cpp:678] Persisted action at 2
I0218 01:53:27.934708 13935 replica.cpp:657] Replica received learned notice
for position 2
I0218 01:53:27.935081 13935 leveldb.cpp:342] Persisting action (18 bytes) to
leveldb took 350891ns
I0218 01:53:27.935127 13935 leveldb.cpp:400] Deleting ~1 keys from leveldb took
24983ns
I0218 01:53:27.935140 13935 replica.cpp:678] Persisted action at 2
I0218 01:53:27.935158 13935 replica.cpp:663] Replica learned 3 action at
position 2
I0218 01:53:27.947561 13918 containerizer.cpp:104] Using isolation:
posix/cpu,posix/mem
I0218 01:53:27.948971 13941 slave.cpp:173] Slave started on
150)@67.195.81.187:57268
I0218 01:53:27.949003 13941 credentials.hpp:84] Loading credential for
authentication from
'/tmp/MasterSlaveReconciliationTest_ReconcileLostTask_5No5Rj/credential'
I0218 01:53:27.949167 13941 slave.cpp:280] Slave using credential for:
test-principal
I0218 01:53:27.949465 13941 slave.cpp:298] Slave resources: cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0218 01:53:27.949556 13941 slave.cpp:327] Slave hostname: pomona.apache.org
I0218 01:53:27.949575 13941 slave.cpp:328] Slave checkpoint: false
W0218 01:53:27.949587 13941 slave.cpp:330] Disabling checkpointing is
deprecated and the --checkpoint flag will be removed in a future release.
Please avoid using this flag
I0218 01:53:27.950536 13932 state.cpp:34] Recovering state from
'/tmp/MasterSlaveReconciliationTest_ReconcileLostTask_5No5Rj/meta'
I0218 01:53:27.950783 13940 status_update_manager.cpp:196] Recovering status
update manager
I0218 01:53:27.953531 13944 containerizer.cpp:301] Recovering containerizer
I0218 01:53:27.953944 13918 sched.cpp:151] Version: 0.22.0
I0218 01:53:27.954617 13932 slave.cpp:3611] Finished recovery
I0218 01:53:27.954732 13935 sched.cpp:248] New master detected at
[email protected]:57268
I0218 01:53:27.954833 13935 sched.cpp:304] Authenticating with master
[email protected]:57268
I0218 01:53:27.954856 13935 sched.cpp:311] Using default CRAM-MD5 authenticatee
I0218 01:53:27.955037 13947 authenticatee.hpp:138] Creating new client SASL
connection
I0218 01:53:27.955198 13944 status_update_manager.cpp:170] Pausing sending
status updates
I0218 01:53:27.955195 13941 slave.cpp:623] New master detected at
[email protected]:57268
I0218 01:53:27.955238 13934 master.cpp:3811] Authenticating
[email protected]:57268
I0218 01:53:27.955270 13934 master.cpp:3822] Using default CRAM-MD5
authenticator
I0218 01:53:27.955317 13941 slave.cpp:686] Authenticating with master
[email protected]:57268
I0218 01:53:27.955348 13941 slave.cpp:691] Using default CRAM-MD5 authenticatee
I0218 01:53:27.955518 13933 authenticator.hpp:169] Creating new server SASL
connection
I0218 01:53:27.955534 13939 authenticatee.hpp:138] Creating new client SASL
connection
I0218 01:53:27.955693 13935 authenticatee.hpp:229] Received SASL authentication
mechanisms: CRAM-MD5
I0218 01:53:27.955732 13935 authenticatee.hpp:255] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0218 01:53:27.955844 13932 authenticator.hpp:275] Received SASL authentication
start
I0218 01:53:27.955905 13932 authenticator.hpp:397] Authentication requires more
steps
I0218 01:53:27.955999 13935 authenticatee.hpp:275] Received SASL authentication
step
I0218 01:53:27.956120 13932 authenticator.hpp:303] Received SASL authentication
step
I0218 01:53:27.957321 13941 slave.cpp:659] Detecting new master
I0218 01:53:27.957473 13934 master.cpp:3811] Authenticating
slave(150)@67.195.81.187:57268
I0218 01:53:28.009866 13948 process.cpp:2117] Dropped / Lost event for PID:
slave(146)@67.195.81.187:57268
I0218 01:53:28.592335 13932 auxprop.cpp:98] 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
I0218 01:53:28.592350 13934 master.cpp:3822] Using default CRAM-MD5
authenticator
I0218 01:53:28.592367 13932 auxprop.cpp:170] Looking up auxiliary property
'*userPassword'
I0218 01:53:28.592434 13932 auxprop.cpp:170] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0218 01:53:28.592483 13932 auxprop.cpp:98] 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
I0218 01:53:28.592501 13932 auxprop.cpp:120] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0218 01:53:28.592510 13932 auxprop.cpp:120] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0218 01:53:28.592530 13932 authenticator.hpp:389] Authentication success
I0218 01:53:28.592646 13935 authenticatee.hpp:315] Authentication success
I0218 01:53:28.592686 13948 process.cpp:2117] Dropped / Lost event for PID:
[email protected]:57268
I0218 01:53:28.592800 13939 authenticator.hpp:169] Creating new server SASL
connection
I0218 01:53:28.592836 13948 process.cpp:2117] Dropped / Lost event for PID:
hierarchical-allocator(180)@67.195.81.187:57268
I0218 01:53:28.592864 13934 master.cpp:3869] Successfully authenticated
principal 'test-principal' at
[email protected]:57268
I0218 01:53:28.592990 13933 authenticatee.hpp:229] Received SASL authentication
mechanisms: CRAM-MD5
I0218 01:53:28.593029 13933 authenticatee.hpp:255] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0218 01:53:28.593245 13933 authenticator.hpp:275] Received SASL authentication
start
I0218 01:53:28.593364 13933 authenticator.hpp:397] Authentication requires more
steps
I0218 01:53:28.593490 13941 sched.cpp:392] Successfully authenticated with
master [email protected]:57268
I0218 01:53:28.593519 13941 sched.cpp:515] Sending registration request to
[email protected]:57268
I0218 01:53:28.593531 13945 authenticatee.hpp:275] Received SASL authentication
step
I0218 01:53:28.593606 13941 sched.cpp:548] Will retry registration in
1.707160316secs if necessary
I0218 01:53:28.593720 13933 authenticator.hpp:303] Received SASL authentication
step
I0218 01:53:28.593731 13939 master.cpp:1572] Received registration request for
framework 'default' at
[email protected]:57268
I0218 01:53:28.593757 13933 auxprop.cpp:98] 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
I0218 01:53:28.593780 13933 auxprop.cpp:170] Looking up auxiliary property
'*userPassword'
I0218 01:53:28.593818 13939 master.cpp:1433] Authorizing framework principal
'test-principal' to receive offers for role '*'
I0218 01:53:28.593823 13933 auxprop.cpp:170] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0218 01:53:28.593891 13933 auxprop.cpp:98] 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
I0218 01:53:28.593909 13933 auxprop.cpp:120] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0218 01:53:28.593919 13933 auxprop.cpp:120] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0218 01:53:28.593947 13933 authenticator.hpp:389] Authentication success
I0218 01:53:28.594048 13945 authenticatee.hpp:315] Authentication success
I0218 01:53:28.594140 13946 master.cpp:3869] Successfully authenticated
principal 'test-principal' at slave(150)@67.195.81.187:57268
I0218 01:53:28.594383 13947 slave.cpp:757] Successfully authenticated with
master [email protected]:57268
I0218 01:53:28.594571 13947 slave.cpp:1089] Will retry registration in
17.484321ms if necessary
I0218 01:53:28.594606 13946 master.cpp:1636] Registering framework
20150218-015326-3142697795-57268-13918-0000 (default) at
[email protected]:57268
I0218 01:53:28.594995 13944 hierarchical.hpp:320] Added framework
20150218-015326-3142697795-57268-13918-0000
I0218 01:53:28.595034 13944 hierarchical.hpp:831] No resources available to
allocate!
I0218 01:53:28.595057 13944 hierarchical.hpp:738] Performed allocation for 0
slaves in 35451ns
I0218 01:53:28.595185 13937 sched.cpp:442] Framework registered with
20150218-015326-3142697795-57268-13918-0000
I0218 01:53:28.595232 13937 sched.cpp:456] Scheduler::registered took 22922ns
I0218 01:53:28.595273 13946 master.cpp:2936] Registering slave at
slave(150)@67.195.81.187:57268 (pomona.apache.org) with id
20150218-015326-3142697795-57268-13918-S0
I0218 01:53:28.595803 13934 registrar.cpp:444] Applied 1 operations in 74798ns;
attempting to update the 'registry'
I0218 01:53:28.598387 13939 log.cpp:683] Attempting to append 316 bytes to the
log
I0218 01:53:28.598578 13938 coordinator.cpp:339] Coordinator attempting to
write 2 action at position 3
I0218 01:53:28.599488 13932 replica.cpp:510] Replica received write request for
position 3
I0218 01:53:28.599758 13932 leveldb.cpp:342] Persisting action (335 bytes) to
leveldb took 234907ns
I0218 01:53:28.599786 13932 replica.cpp:678] Persisted action at 3
I0218 01:53:28.600777 13939 replica.cpp:657] Replica received learned notice
for position 3
I0218 01:53:28.601304 13939 leveldb.cpp:342] Persisting action (337 bytes) to
leveldb took 503852ns
I0218 01:53:28.601326 13939 replica.cpp:678] Persisted action at 3
I0218 01:53:28.601346 13939 replica.cpp:663] Replica learned 2 action at
position 3
I0218 01:53:28.602901 13934 log.cpp:702] Attempting to truncate the log to 3
I0218 01:53:28.603011 13938 coordinator.cpp:339] Coordinator attempting to
write 3 action at position 4
I0218 01:53:28.603135 13932 registrar.cpp:489] Successfully updated the
'registry' in 7.035904ms
I0218 01:53:28.603687 13932 replica.cpp:510] Replica received write request for
position 4
I0218 01:53:28.603844 13934 slave.cpp:2666] Received ping from
slave-observer(147)@67.195.81.187:57268
I0218 01:53:28.603945 13941 master.cpp:2993] Registered slave
20150218-015326-3142697795-57268-13918-S0 at slave(150)@67.195.81.187:57268
(pomona.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000]
I0218 01:53:28.604046 13933 hierarchical.hpp:452] Added slave
20150218-015326-3142697795-57268-13918-S0 (pomona.apache.org) with cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024;
disk(*):1024; ports(*):[31000-32000] available)
I0218 01:53:28.604112 13932 leveldb.cpp:342] Persisting action (16 bytes) to
leveldb took 399822ns
I0218 01:53:28.604131 13932 replica.cpp:678] Persisted action at 4
I0218 01:53:28.605741 13933 hierarchical.hpp:756] Performed allocation for
slave 20150218-015326-3142697795-57268-13918-S0 in 1.649293ms
I0218 01:53:28.605836 13934 slave.cpp:791] Registered with master
[email protected]:57268; given slave ID
20150218-015326-3142697795-57268-13918-S0
I0218 01:53:28.606003 13933 replica.cpp:657] Replica received learned notice
for position 4
I0218 01:53:28.606037 13947 status_update_manager.cpp:177] Resuming sending
status updates
I0218 01:53:28.606075 13937 master.cpp:3753] Sending 1 offers to framework
20150218-015326-3142697795-57268-13918-0000 (default) at
[email protected]:57268
I0218 01:53:28.606547 13933 leveldb.cpp:342] Persisting action (18 bytes) to
leveldb took 517378ns
I0218 01:53:29.008322 13933 leveldb.cpp:400] Deleting ~2 keys from leveldb took
86406ns
I0218 01:53:29.008350 13933 replica.cpp:678] Persisted action at 4
I0218 01:53:29.008380 13933 replica.cpp:663] Replica learned 3 action at
position 4
I0218 01:53:28.912961 13946 hierarchical.hpp:831] No resources available to
allocate!
I0218 01:53:29.008543 13946 hierarchical.hpp:738] Performed allocation for 1
slaves in 95.683965ms
I0218 01:53:29.008621 13944 sched.cpp:605] Scheduler::resourceOffers took
74896ns
I0218 01:53:29.009996 13932 master.cpp:2266] Processing ACCEPT call for offers:
[ 20150218-015326-3142697795-57268-13918-O0 ] on slave
20150218-015326-3142697795-57268-13918-S0 at slave(150)@67.195.81.187:57268
(pomona.apache.org) for framework 20150218-015326-3142697795-57268-13918-0000
(default) at [email protected]:57268
I0218 01:53:29.010035 13932 master.cpp:2110] Authorizing framework principal
'test-principal' to launch task 1 as user 'jenkins'
W0218 01:53:29.011081 13932 validation.cpp:326] Executor default for task 1
uses less CPUs (None) than the minimum required (0.01). Please update your
executor, as this will be mandatory in future releases.
W0218 01:53:29.011111 13932 validation.cpp:338] Executor default for task 1
uses less memory (None) than the minimum required (32MB). Please update your
executor, as this will be mandatory in future releases.
I0218 01:53:29.011418 13932 master.hpp:821] Adding task 1 with resources
cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
20150218-015326-3142697795-57268-13918-S0 (pomona.apache.org)
I0218 01:53:29.011518 13932 master.cpp:2543] Launching task 1 of framework
20150218-015326-3142697795-57268-13918-0000 (default) at
[email protected]:57268 with
resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
20150218-015326-3142697795-57268-13918-S0 at slave(150)@67.195.81.187:57268
(pomona.apache.org)
I0218 01:53:29.014303 13944 slave.cpp:623] New master detected at
[email protected]:57268
I0218 01:53:29.014310 13935 status_update_manager.cpp:170] Pausing sending
status updates
I0218 01:53:29.014451 13944 slave.cpp:686] Authenticating with master
[email protected]:57268
I0218 01:53:29.014467 13944 slave.cpp:691] Using default CRAM-MD5 authenticatee
I0218 01:53:29.014600 13938 authenticatee.hpp:138] Creating new client SASL
connection
I0218 01:53:29.014634 13944 slave.cpp:659] Detecting new master
I0218 01:53:29.014930 13944 master.cpp:3811] Authenticating
slave(150)@67.195.81.187:57268
I0218 01:53:29.014953 13944 master.cpp:3822] Using default CRAM-MD5
authenticator
I0218 01:53:29.015183 13932 authenticator.hpp:169] Creating new server SASL
connection
I0218 01:53:29.015403 13932 authenticatee.hpp:229] Received SASL authentication
mechanisms: CRAM-MD5
I0218 01:53:29.015426 13932 authenticatee.hpp:255] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0218 01:53:29.015540 13941 authenticator.hpp:275] Received SASL authentication
start
I0218 01:53:29.015609 13941 authenticator.hpp:397] Authentication requires more
steps
I0218 01:53:29.015678 13941 authenticatee.hpp:275] Received SASL authentication
step
I0218 01:53:29.015746 13941 authenticator.hpp:303] Received SASL authentication
step
I0218 01:53:29.015771 13941 auxprop.cpp:98] 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
I0218 01:53:29.015785 13941 auxprop.cpp:170] Looking up auxiliary property
'*userPassword'
I0218 01:53:29.015820 13941 auxprop.cpp:170] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0218 01:53:29.015843 13941 auxprop.cpp:98] 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
I0218 01:53:29.015908 13941 auxprop.cpp:120] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0218 01:53:29.015915 13941 auxprop.cpp:120] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0218 01:53:29.015928 13941 authenticator.hpp:389] Authentication success
I0218 01:53:29.016016 13941 authenticatee.hpp:315] Authentication success
I0218 01:53:29.016041 13932 master.cpp:3869] Successfully authenticated
principal 'test-principal' at slave(150)@67.195.81.187:57268
I0218 01:53:29.016445 13938 slave.cpp:757] Successfully authenticated with
master [email protected]:57268
I0218 01:53:29.016556 13938 slave.cpp:1089] Will retry registration in
3.449224ms if necessary
I0218 01:53:29.016757 13932 master.cpp:3067] Re-registering slave
20150218-015326-3142697795-57268-13918-S0 at slave(150)@67.195.81.187:57268
(pomona.apache.org)
W0218 01:53:29.016921 13932 master.cpp:3932] Task 1 of framework
20150218-015326-3142697795-57268-13918-0000 unknown to the slave
20150218-015326-3142697795-57268-13918-S0 at slave(150)@67.195.81.187:57268
(pomona.apache.org) during re-registration: reconciling with the slave
W0218 01:53:29.017177 13932 master.cpp:4013] Executor default of framework
20150218-015326-3142697795-57268-13918-0000 possibly unknown to the slave
20150218-015326-3142697795-57268-13918-S0 at slave(150)@67.195.81.187:57268
(pomona.apache.org)
I0218 01:53:29.017258 13932 master.cpp:4712] Removing executor 'default' with
resources of framework 20150218-015326-3142697795-57268-13918-0000 on slave
20150218-015326-3142697795-57268-13918-S0 at slave(150)@67.195.81.187:57268
(pomona.apache.org)
I0218 01:53:29.017482 13943 slave.cpp:859] Re-registered with master
[email protected]:57268
I0218 01:53:29.017513 13932 master.cpp:3217] Sending updated checkpointed
resources to slave 20150218-015326-3142697795-57268-13918-S0 at
slave(150)@67.195.81.187:57268 (pomona.apache.org)
I0218 01:53:29.017704 13944 status_update_manager.cpp:177] Resuming sending
status updates
W0218 01:53:29.017705 13943 slave.cpp:917] Slave reconciling task 1 of
framework 20150218-015326-3142697795-57268-13918-0000 in state TASK_LOST: task
unknown to the slave
I0218 01:53:29.020056 13934 status_update_manager.cpp:316] Received status
update TASK_LOST (UUID: 46c6fdee-5cda-4bf9-8dfd-4ea3b2e4bb05) for task 1 of
framework 20150218-015326-3142697795-57268-13918-0000
I0218 01:53:29.020102 13934 status_update_manager.cpp:493] Creating
StatusUpdate stream for task 1 of framework
20150218-015326-3142697795-57268-13918-0000
I0218 01:53:29.020321 13934 status_update_manager.cpp:370] Forwarding update
TASK_LOST (UUID: 46c6fdee-5cda-4bf9-8dfd-4ea3b2e4bb05) for task 1 of framework
20150218-015326-3142697795-57268-13918-0000 to the slave
I0218 01:53:29.020339 13943 slave.cpp:1859] Updated checkpointed resources from
to
I0218 01:53:29.020434 13943 slave.cpp:2586] Forwarding the update TASK_LOST
(UUID: 46c6fdee-5cda-4bf9-8dfd-4ea3b2e4bb05) for task 1 of framework
20150218-015326-3142697795-57268-13918-0000 to [email protected]:57268
I0218 01:53:29.020776 13932 slave.cpp:2513] Status update manager successfully
handled status update TASK_LOST (UUID: 46c6fdee-5cda-4bf9-8dfd-4ea3b2e4bb05)
for task 1 of framework 20150218-015326-3142697795-57268-13918-0000
I0218 01:53:29.020819 13943 master.cpp:3293] Status update TASK_LOST (UUID:
46c6fdee-5cda-4bf9-8dfd-4ea3b2e4bb05) for task 1 of framework
20150218-015326-3142697795-57268-13918-0000 from slave
20150218-015326-3142697795-57268-13918-S0 at slave(150)@67.195.81.187:57268
(pomona.apache.org)
I0218 01:53:29.020858 13943 master.cpp:3334] Forwarding status update TASK_LOST
(UUID: 46c6fdee-5cda-4bf9-8dfd-4ea3b2e4bb05) for task 1 of framework
20150218-015326-3142697795-57268-13918-0000
I0218 01:53:29.020985 13943 master.cpp:4616] Updating the latest state of task
1 of framework 20150218-015326-3142697795-57268-13918-0000 to TASK_LOST
I0218 01:53:29.021073 13937 sched.cpp:696] Scheduler::statusUpdate took 29989ns
I0218 01:53:29.023674 13940 process.cpp:2770] Handling HTTP event for process
'metrics' with path: '/metrics/snapshot'
I0218 01:53:29.068902 13948 process.cpp:2117] Dropped / Lost event for PID:
slave(147)@67.195.81.187:57268
I0218 01:53:29.160341 13939 hierarchical.hpp:645] Recovered cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total allocatable:
cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on slave
20150218-015326-3142697795-57268-13918-S0 from framework
20150218-015326-3142697795-57268-13918-0000
I0218 01:53:29.160444 13948 process.cpp:2117] Dropped / Lost event for PID:
[email protected]:57268
I0218 01:53:29.160960 13943 master.cpp:4683] Removing task 1 with resources
cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework
20150218-015326-3142697795-57268-13918-0000 on slave
20150218-015326-3142697795-57268-13918-S0 at slave(150)@67.195.81.187:57268
(pomona.apache.org)
I0218 01:53:29.161125 13943 master.cpp:2780] Forwarding status update
acknowledgement 46c6fdee-5cda-4bf9-8dfd-4ea3b2e4bb05 for task 1 of framework
20150218-015326-3142697795-57268-13918-0000 (default) at
[email protected]:57268 to slave
20150218-015326-3142697795-57268-13918-S0 at slave(150)@67.195.81.187:57268
(pomona.apache.org)
I0218 01:53:29.161495 13943 status_update_manager.cpp:388] Received status
update acknowledgement (UUID: 46c6fdee-5cda-4bf9-8dfd-4ea3b2e4bb05) for task 1
of framework 20150218-015326-3142697795-57268-13918-0000
I0218 01:53:29.161571 13943 status_update_manager.cpp:524] Cleaning up status
update stream for task 1 of framework
20150218-015326-3142697795-57268-13918-0000
I0218 01:53:29.161779 13943 slave.cpp:1930] Status update manager successfully
handled status update acknowledgement (UUID:
46c6fdee-5cda-4bf9-8dfd-4ea3b2e4bb05) for task 1 of framework
20150218-015326-3142697795-57268-13918-0000
E0218 01:53:29.161803 13943 slave.cpp:1941] Status update acknowledgement
(UUID: 46c6fdee-5cda-4bf9-8dfd-4ea3b2e4bb05) for task 1 of unknown framework
20150218-015326-3142697795-57268-13918-0000
../../src/tests/master_slave_reconciliation_tests.cpp:240: Failure
Value of: stats.values.count(
"master/task_lost/source_slave/reason_reconciliation")
Actual: 0
Expected: 1u
Which is: 1
../../src/tests/master_slave_reconciliation_tests.cpp:243: Failure
Value of: stats.values["master/task_lost/source_slave/reason_reconciliation"]
Actual: 16-byte object <00-00 00-00 74-65 73-74 B0-B1 25-05 00-00 00-00>
Expected: 1u
Which is: 1
I0218 01:53:29.212201 13918 sched.cpp:1470] Asked to stop the driver
I0218 01:53:29.212276 13918 master.cpp:785] Master terminating
I0218 01:53:29.212319 13937 sched.cpp:808] Stopping framework
'20150218-015326-3142697795-57268-13918-0000'
I0218 01:53:29.212798 13942 slave.cpp:2751] [email protected]:57268 exited
W0218 01:53:29.212821 13942 slave.cpp:2754] Master disconnected! Waiting for a
new master to be elected
I0218 01:53:29.213912 13918 process.cpp:2117] Dropped / Lost event for PID:
[email protected]:57268
I0218 01:53:29.214001 13918 process.cpp:2117] Dropped / Lost event for PID:
[email protected]:57268
I0218 01:53:29.216212 13934 slave.cpp:505] Slave terminating
I0218 01:53:29.217798 13918 process.cpp:2117] Dropped / Lost event for PID:
[email protected]:57268
I0218 01:53:29.217994 13918 process.cpp:2117] Dropped / Lost event for PID:
slave(150)@67.195.81.187:57268
[ FAILED ] MasterSlaveReconciliationTest.ReconcileLostTask (2341 ms)
{code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
