[ https://issues.apache.org/jira/browse/MESOS-2366?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Benjamin Mahler reassigned MESOS-2366: -------------------------------------- Assignee: Dominic Hamon Assigning to [~dhamon]: please follow up, this test is consistently flaky on our internal CI. > 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)