[
https://issues.apache.org/jira/browse/MESOS-2366?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Dominic Hamon updated MESOS-2366:
---------------------------------
Story Points: 1
> 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
> Assignee: Dominic Hamon
> Labels: flaky-test
>
> 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)
