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 20:28:11 UTC
[jira] [Updated] (MESOS-2366)
MasterSlaveReconciliationTest.ReconcileLostTask is flaky
[ https://issues.apache.org/jira/browse/MESOS-2366?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Dominic Hamon updated MESOS-2366:
---------------------------------
Sprint: Twitter Mesos Q1 Sprint 3
> 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)