You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "Dominic Hamon (JIRA)" <ji...@apache.org> on 2015/02/23 21:11:12 UTC
[jira] [Comment Edited] (MESOS-2366)
MasterSlaveReconciliationTest.ReconcileLostTask is flaky
[ https://issues.apache.org/jira/browse/MESOS-2366?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14333701#comment-14333701 ]
Dominic Hamon edited comment on MESOS-2366 at 2/23/15 8:10 PM:
---------------------------------------------------------------
looks like waiting for the status update acknowledgement message should be enough.
The master updates the metrics in {{updateTask}}, called from {{statusUpdate}}. It's possible that the StatusUpdate message has been sent (which we check for) but not acted on by the Master yet, hence the metrics have not been updated. Waiting for the explicit acknowledgement is a proxy signal that the Master has updated the metrics.
was (Author: dhamon):
looks like waiting for the status update acknowledgement message should be enough.
> 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 master@67.195.81.187: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: scheduler-93f78006-5b69-498b-b4e3-87cdf8062263@67.195.81.187: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 master@67.195.81.187:57268
> I0218 01:53:27.954833 13935 sched.cpp:304] Authenticating with master master@67.195.81.187: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 master@67.195.81.187:57268
> I0218 01:53:27.955238 13934 master.cpp:3811] Authenticating scheduler-17aa8fa2-195f-43d6-85d7-87b949d4419b@67.195.81.187: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 master@67.195.81.187: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: scheduler-4eee5e93-d6bb-4af4-9795-0aec0916dfa5@67.195.81.187: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 scheduler-17aa8fa2-195f-43d6-85d7-87b949d4419b@67.195.81.187: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 master@67.195.81.187:57268
> I0218 01:53:28.593519 13941 sched.cpp:515] Sending registration request to master@67.195.81.187: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 scheduler-17aa8fa2-195f-43d6-85d7-87b949d4419b@67.195.81.187: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 master@67.195.81.187: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 scheduler-17aa8fa2-195f-43d6-85d7-87b949d4419b@67.195.81.187: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 master@67.195.81.187: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 scheduler-17aa8fa2-195f-43d6-85d7-87b949d4419b@67.195.81.187: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 scheduler-17aa8fa2-195f-43d6-85d7-87b949d4419b@67.195.81.187: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 scheduler-17aa8fa2-195f-43d6-85d7-87b949d4419b@67.195.81.187: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 master@67.195.81.187: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 master@67.195.81.187: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 master@67.195.81.187: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 master@67.195.81.187: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 master@67.195.81.187: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: scheduler-7c9ec50c-5c07-4e08-b863-850694a30a74@67.195.81.187: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 scheduler-17aa8fa2-195f-43d6-85d7-87b949d4419b@67.195.81.187: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] master@67.195.81.187: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: master@67.195.81.187:57268
> I0218 01:53:29.214001 13918 process.cpp:2117] Dropped / Lost event for PID: master@67.195.81.187: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: scheduler-17aa8fa2-195f-43d6-85d7-87b949d4419b@67.195.81.187: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)