[ https://issues.apache.org/jira/browse/MESOS-2226?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Marco Massenzio updated MESOS-2226: ----------------------------------- Story Points: 5 > HookTest.VerifySlaveLaunchExecutorHook is flaky > ----------------------------------------------- > > Key: MESOS-2226 > URL: https://issues.apache.org/jira/browse/MESOS-2226 > Project: Mesos > Issue Type: Bug > Components: test > Affects Versions: 0.22.0 > Reporter: Vinod Kone > Assignee: Kapil Arya > Labels: flaky, flaky-test > > Observed this on internal CI > {code} > [ RUN ] HookTest.VerifySlaveLaunchExecutorHook > Using temporary directory '/tmp/HookTest_VerifySlaveLaunchExecutorHook_GjBgME' > I0114 18:51:34.659353 4720 leveldb.cpp:176] Opened db in 1.255951ms > I0114 18:51:34.662112 4720 leveldb.cpp:183] Compacted db in 596090ns > I0114 18:51:34.662364 4720 leveldb.cpp:198] Created db iterator in 177877ns > I0114 18:51:34.662719 4720 leveldb.cpp:204] Seeked to beginning of db in > 19709ns > I0114 18:51:34.663010 4720 leveldb.cpp:273] Iterated through 0 keys in the > db in 18208ns > I0114 18:51:34.663312 4720 replica.cpp:744] Replica recovered with log > positions 0 -> 0 with 1 holes and 0 unlearned > I0114 18:51:34.664266 4735 recover.cpp:449] Starting replica recovery > I0114 18:51:34.664908 4735 recover.cpp:475] Replica is in EMPTY status > I0114 18:51:34.667842 4734 replica.cpp:641] Replica in EMPTY status received > a broadcasted recover request > I0114 18:51:34.669117 4735 recover.cpp:195] Received a recover response from > a replica in EMPTY status > I0114 18:51:34.677913 4735 recover.cpp:566] Updating replica status to > STARTING > I0114 18:51:34.683157 4735 leveldb.cpp:306] Persisting metadata (8 bytes) to > leveldb took 137939ns > I0114 18:51:34.683507 4735 replica.cpp:323] Persisted replica status to > STARTING > I0114 18:51:34.684013 4735 recover.cpp:475] Replica is in STARTING status > I0114 18:51:34.685554 4738 replica.cpp:641] Replica in STARTING status > received a broadcasted recover request > I0114 18:51:34.696512 4736 recover.cpp:195] Received a recover response from > a replica in STARTING status > I0114 18:51:34.700552 4735 recover.cpp:566] Updating replica status to VOTING > I0114 18:51:34.701128 4735 leveldb.cpp:306] Persisting metadata (8 bytes) to > leveldb took 115624ns > I0114 18:51:34.701478 4735 replica.cpp:323] Persisted replica status to > VOTING > I0114 18:51:34.701817 4735 recover.cpp:580] Successfully joined the Paxos > group > I0114 18:51:34.702569 4735 recover.cpp:464] Recover process terminated > I0114 18:51:34.716439 4736 master.cpp:262] Master > 20150114-185134-2272962752-57018-4720 (fedora-19) started on > 192.168.122.135:57018 > I0114 18:51:34.716913 4736 master.cpp:308] Master only allowing > authenticated frameworks to register > I0114 18:51:34.717136 4736 master.cpp:313] Master only allowing > authenticated slaves to register > I0114 18:51:34.717488 4736 credentials.hpp:36] Loading credentials for > authentication from > '/tmp/HookTest_VerifySlaveLaunchExecutorHook_GjBgME/credentials' > I0114 18:51:34.718077 4736 master.cpp:357] Authorization enabled > I0114 18:51:34.719238 4738 whitelist_watcher.cpp:65] No whitelist given > I0114 18:51:34.719755 4737 hierarchical_allocator_process.hpp:285] > Initialized hierarchical allocator process > I0114 18:51:34.722584 4736 master.cpp:1219] The newly elected leader is > master@192.168.122.135:57018 with id 20150114-185134-2272962752-57018-4720 > I0114 18:51:34.722865 4736 master.cpp:1232] Elected as the leading master! > I0114 18:51:34.723310 4736 master.cpp:1050] Recovering from registrar > I0114 18:51:34.723760 4734 registrar.cpp:313] Recovering registrar > I0114 18:51:34.725229 4740 log.cpp:660] Attempting to start the writer > I0114 18:51:34.727893 4739 replica.cpp:477] Replica received implicit > promise request with proposal 1 > I0114 18:51:34.728425 4739 leveldb.cpp:306] Persisting metadata (8 bytes) to > leveldb took 114781ns > I0114 18:51:34.728662 4739 replica.cpp:345] Persisted promised to 1 > I0114 18:51:34.731271 4741 coordinator.cpp:230] Coordinator attemping to > fill missing position > I0114 18:51:34.733223 4734 replica.cpp:378] Replica received explicit > promise request for position 0 with proposal 2 > I0114 18:51:34.734076 4734 leveldb.cpp:343] Persisting action (8 bytes) to > leveldb took 87441ns > I0114 18:51:34.734441 4734 replica.cpp:679] Persisted action at 0 > I0114 18:51:34.740272 4739 replica.cpp:511] Replica received write request > for position 0 > I0114 18:51:34.740910 4739 leveldb.cpp:438] Reading position from leveldb > took 59846ns > I0114 18:51:34.741672 4739 leveldb.cpp:343] Persisting action (14 bytes) to > leveldb took 189259ns > I0114 18:51:34.741919 4739 replica.cpp:679] Persisted action at 0 > I0114 18:51:34.743000 4739 replica.cpp:658] Replica received learned notice > for position 0 > I0114 18:51:34.746844 4739 leveldb.cpp:343] Persisting action (16 bytes) to > leveldb took 328487ns > I0114 18:51:34.747118 4739 replica.cpp:679] Persisted action at 0 > I0114 18:51:34.747553 4739 replica.cpp:664] Replica learned NOP action at > position 0 > I0114 18:51:34.751344 4737 log.cpp:676] Writer started with ending position 0 > I0114 18:51:34.753504 4734 leveldb.cpp:438] Reading position from leveldb > took 61183ns > I0114 18:51:34.762962 4737 registrar.cpp:346] Successfully fetched the > registry (0B) in 38.907904ms > I0114 18:51:34.763610 4737 registrar.cpp:445] Applied 1 operations in > 67206ns; attempting to update the 'registry' > I0114 18:51:34.766079 4736 log.cpp:684] Attempting to append 130 bytes to > the log > I0114 18:51:34.766769 4736 coordinator.cpp:340] Coordinator attempting to > write APPEND action at position 1 > I0114 18:51:34.768215 4741 replica.cpp:511] Replica received write request > for position 1 > I0114 18:51:34.768759 4741 leveldb.cpp:343] Persisting action (149 bytes) to > leveldb took 87970ns > I0114 18:51:34.768995 4741 replica.cpp:679] Persisted action at 1 > I0114 18:51:34.770691 4736 replica.cpp:658] Replica received learned notice > for position 1 > I0114 18:51:34.771273 4736 leveldb.cpp:343] Persisting action (151 bytes) to > leveldb took 83590ns > I0114 18:51:34.771579 4736 replica.cpp:679] Persisted action at 1 > I0114 18:51:34.771917 4736 replica.cpp:664] Replica learned APPEND action at > position 1 > I0114 18:51:34.773252 4738 log.cpp:703] Attempting to truncate the log to 1 > I0114 18:51:34.773756 4735 coordinator.cpp:340] Coordinator attempting to > write TRUNCATE action at position 2 > I0114 18:51:34.775552 4736 replica.cpp:511] Replica received write request > for position 2 > I0114 18:51:34.775846 4736 leveldb.cpp:343] Persisting action (16 bytes) to > leveldb took 71503ns > I0114 18:51:34.776695 4736 replica.cpp:679] Persisted action at 2 > I0114 18:51:34.785259 4739 replica.cpp:658] Replica received learned notice > for position 2 > I0114 18:51:34.786252 4737 registrar.cpp:490] Successfully updated the > 'registry' in 22.340864ms > I0114 18:51:34.787094 4737 registrar.cpp:376] Successfully recovered > registrar > I0114 18:51:34.787749 4737 master.cpp:1077] Recovered 0 slaves from the > Registry (94B) ; allowing 10mins for slaves to re-register > I0114 18:51:34.787282 4739 leveldb.cpp:343] Persisting action (18 bytes) to > leveldb took 707150ns > I0114 18:51:34.788692 4739 leveldb.cpp:401] Deleting ~1 keys from leveldb > took 60262ns > I0114 18:51:34.789048 4739 replica.cpp:679] Persisted action at 2 > I0114 18:51:34.789329 4739 replica.cpp:664] Replica learned TRUNCATE action > at position 2 > I0114 18:51:34.819548 4738 slave.cpp:173] Slave started on > 171)@192.168.122.135:57018 > I0114 18:51:34.820530 4738 credentials.hpp:84] Loading credential for > authentication from > '/tmp/HookTest_VerifySlaveLaunchExecutorHook_AYxNqe/credential' > I0114 18:51:34.820952 4738 slave.cpp:282] Slave using credential for: > test-principal > I0114 18:51:34.821516 4738 slave.cpp:300] Slave resources: cpus(*):2; > mem(*):1024; disk(*):1024; ports(*):[31000-32000] > I0114 18:51:34.822217 4738 slave.cpp:329] Slave hostname: fedora-19 > I0114 18:51:34.822502 4738 slave.cpp:330] Slave checkpoint: false > W0114 18:51:34.822857 4738 slave.cpp:332] Disabling checkpointing is > deprecated and the --checkpoint flag will be removed in a future release. > Please avoid using this flag > I0114 18:51:34.824998 4737 state.cpp:33] Recovering state from > '/tmp/HookTest_VerifySlaveLaunchExecutorHook_AYxNqe/meta' > I0114 18:51:34.834015 4738 status_update_manager.cpp:197] Recovering status > update manager > I0114 18:51:34.834810 4738 slave.cpp:3519] Finished recovery > I0114 18:51:34.835906 4734 status_update_manager.cpp:171] Pausing sending > status updates > I0114 18:51:34.836423 4738 slave.cpp:613] New master detected at > master@192.168.122.135:57018 > I0114 18:51:34.836908 4738 slave.cpp:676] Authenticating with master > master@192.168.122.135:57018 > I0114 18:51:34.837190 4738 slave.cpp:681] Using default CRAM-MD5 > authenticatee > I0114 18:51:34.837820 4737 authenticatee.hpp:138] Creating new client SASL > connection > I0114 18:51:34.838784 4738 slave.cpp:649] Detecting new master > I0114 18:51:34.839306 4740 master.cpp:4130] Authenticating > slave(171)@192.168.122.135:57018 > I0114 18:51:34.839957 4740 master.cpp:4141] Using default CRAM-MD5 > authenticator > I0114 18:51:34.841236 4740 authenticator.hpp:170] Creating new server SASL > connection > I0114 18:51:34.842681 4741 authenticatee.hpp:229] Received SASL > authentication mechanisms: CRAM-MD5 > I0114 18:51:34.843118 4741 authenticatee.hpp:255] Attempting to authenticate > with mechanism 'CRAM-MD5' > I0114 18:51:34.843581 4740 authenticator.hpp:276] Received SASL > authentication start > I0114 18:51:34.843962 4740 authenticator.hpp:398] Authentication requires > more steps > I0114 18:51:34.844357 4740 authenticatee.hpp:275] Received SASL > authentication step > I0114 18:51:34.844780 4740 authenticator.hpp:304] Received SASL > authentication step > I0114 18:51:34.845113 4740 auxprop.cpp:99] Request to lookup properties for > user: 'test-principal' realm: 'fedora-19' server FQDN: 'fedora-19' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: false > I0114 18:51:34.845507 4740 auxprop.cpp:171] Looking up auxiliary property > '*userPassword' > I0114 18:51:34.845835 4740 auxprop.cpp:171] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > I0114 18:51:34.846238 4740 auxprop.cpp:99] Request to lookup properties for > user: 'test-principal' realm: 'fedora-19' server FQDN: 'fedora-19' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: true > I0114 18:51:34.846542 4740 auxprop.cpp:121] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > I0114 18:51:34.846806 4740 auxprop.cpp:121] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > I0114 18:51:34.847110 4740 authenticator.hpp:390] Authentication success > I0114 18:51:34.847808 4734 authenticatee.hpp:315] Authentication success > I0114 18:51:34.851029 4734 slave.cpp:747] Successfully authenticated with > master master@192.168.122.135:57018 > I0114 18:51:34.851608 4737 master.cpp:4188] Successfully authenticated > principal 'test-principal' at slave(171)@192.168.122.135:57018 > I0114 18:51:34.854962 4720 sched.cpp:151] Version: 0.22.0 > I0114 18:51:34.856674 4734 slave.cpp:1075] Will retry registration in > 3.085482ms if necessary > I0114 18:51:34.857434 4739 sched.cpp:248] New master detected at > master@192.168.122.135:57018 > I0114 18:51:34.861433 4739 sched.cpp:304] Authenticating with master > master@192.168.122.135:57018 > I0114 18:51:34.861693 4739 sched.cpp:311] Using default CRAM-MD5 > authenticatee > I0114 18:51:34.857795 4737 master.cpp:3276] Registering slave at > slave(171)@192.168.122.135:57018 (fedora-19) with id > 20150114-185134-2272962752-57018-4720-S0 > I0114 18:51:34.862951 4737 authenticatee.hpp:138] Creating new client SASL > connection > I0114 18:51:34.863919 4735 registrar.cpp:445] Applied 1 operations in > 120272ns; attempting to update the 'registry' > I0114 18:51:34.864645 4738 master.cpp:4130] Authenticating > scheduler-c45273e4-6eb5-44ee-bf45-71b353db648f@192.168.122.135:57018 > I0114 18:51:34.865033 4738 master.cpp:4141] Using default CRAM-MD5 > authenticator > I0114 18:51:34.866904 4738 authenticator.hpp:170] Creating new server SASL > connection > I0114 18:51:34.868840 4737 authenticatee.hpp:229] Received SASL > authentication mechanisms: CRAM-MD5 > I0114 18:51:34.869125 4737 authenticatee.hpp:255] Attempting to authenticate > with mechanism 'CRAM-MD5' > I0114 18:51:34.869523 4737 authenticator.hpp:276] Received SASL > authentication start > I0114 18:51:34.869835 4737 authenticator.hpp:398] Authentication requires > more steps > I0114 18:51:34.870213 4737 authenticatee.hpp:275] Received SASL > authentication step > I0114 18:51:34.870622 4737 authenticator.hpp:304] Received SASL > authentication step > I0114 18:51:34.870946 4737 auxprop.cpp:99] Request to lookup properties for > user: 'test-principal' realm: 'fedora-19' server FQDN: 'fedora-19' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: false > I0114 18:51:34.871219 4737 auxprop.cpp:171] Looking up auxiliary property > '*userPassword' > I0114 18:51:34.871554 4737 auxprop.cpp:171] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > I0114 18:51:34.871968 4737 auxprop.cpp:99] Request to lookup properties for > user: 'test-principal' realm: 'fedora-19' server FQDN: 'fedora-19' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: true > I0114 18:51:34.872297 4737 auxprop.cpp:121] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > I0114 18:51:34.872655 4737 auxprop.cpp:121] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > I0114 18:51:34.873024 4737 authenticator.hpp:390] Authentication success > I0114 18:51:34.873428 4737 authenticatee.hpp:315] Authentication success > I0114 18:51:34.873632 4739 master.cpp:4188] Successfully authenticated > principal 'test-principal' at > scheduler-c45273e4-6eb5-44ee-bf45-71b353db648f@192.168.122.135:57018 > I0114 18:51:34.875006 4740 sched.cpp:392] Successfully authenticated with > master master@192.168.122.135:57018 > I0114 18:51:34.875319 4740 sched.cpp:515] Sending registration request to > master@192.168.122.135:57018 > I0114 18:51:34.876200 4740 sched.cpp:548] Will retry registration in > 1.952991346secs if necessary > I0114 18:51:34.876729 4738 master.cpp:1417] Received registration request > for framework 'default' at > scheduler-c45273e4-6eb5-44ee-bf45-71b353db648f@192.168.122.135:57018 > I0114 18:51:34.877040 4738 master.cpp:1298] Authorizing framework principal > 'test-principal' to receive offers for role '*' > I0114 18:51:34.878059 4738 master.cpp:1481] Registering framework > 20150114-185134-2272962752-57018-4720-0000 (default) at > scheduler-c45273e4-6eb5-44ee-bf45-71b353db648f@192.168.122.135:57018 > I0114 18:51:34.878473 4739 log.cpp:684] Attempting to append 300 bytes to > the log > I0114 18:51:34.879464 4737 coordinator.cpp:340] Coordinator attempting to > write APPEND action at position 3 > I0114 18:51:34.880116 4734 hierarchical_allocator_process.hpp:319] Added > framework 20150114-185134-2272962752-57018-4720-0000 > I0114 18:51:34.880470 4734 hierarchical_allocator_process.hpp:839] No > resources available to allocate! > I0114 18:51:34.882331 4734 hierarchical_allocator_process.hpp:746] Performed > allocation for 0 slaves in 1.901284ms > I0114 18:51:34.884024 4741 sched.cpp:442] Framework registered with > 20150114-185134-2272962752-57018-4720-0000 > I0114 18:51:34.884454 4741 sched.cpp:456] Scheduler::registered took 44320ns > I0114 18:51:34.881965 4737 replica.cpp:511] Replica received write request > for position 3 > I0114 18:51:34.885218 4737 leveldb.cpp:343] Persisting action (319 bytes) to > leveldb took 134480ns > I0114 18:51:34.885716 4737 replica.cpp:679] Persisted action at 3 > I0114 18:51:34.886034 4739 slave.cpp:1075] Will retry registration in > 22.947772ms if necessary > I0114 18:51:34.886291 4740 master.cpp:3264] Ignoring register slave message > from slave(171)@192.168.122.135:57018 (fedora-19) as admission is already in > progress > I0114 18:51:34.894690 4736 replica.cpp:658] Replica received learned notice > for position 3 > I0114 18:51:34.898638 4736 leveldb.cpp:343] Persisting action (321 bytes) to > leveldb took 215501ns > I0114 18:51:34.899055 4736 replica.cpp:679] Persisted action at 3 > I0114 18:51:34.899416 4736 replica.cpp:664] Replica learned APPEND action at > position 3 > I0114 18:51:34.911782 4736 registrar.cpp:490] Successfully updated the > 'registry' in 46.176768ms > I0114 18:51:34.912286 4740 log.cpp:703] Attempting to truncate the log to 3 > I0114 18:51:34.913108 4740 coordinator.cpp:340] Coordinator attempting to > write TRUNCATE action at position 4 > I0114 18:51:34.915027 4736 master.cpp:3330] Registered slave > 20150114-185134-2272962752-57018-4720-S0 at slave(171)@192.168.122.135:57018 > (fedora-19) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] > I0114 18:51:34.915642 4735 hierarchical_allocator_process.hpp:453] Added > slave 20150114-185134-2272962752-57018-4720-S0 (fedora-19) with cpus(*):2; > mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; > mem(*):1024; disk(*):1024; ports(*):[31000-32000] available) > I0114 18:51:34.917809 4735 hierarchical_allocator_process.hpp:764] Performed > allocation for slave 20150114-185134-2272962752-57018-4720-S0 in 514027ns > I0114 18:51:34.916689 4738 replica.cpp:511] Replica received write request > for position 4 > I0114 18:51:34.915784 4741 slave.cpp:781] Registered with master > master@192.168.122.135:57018; given slave ID > 20150114-185134-2272962752-57018-4720-S0 > I0114 18:51:34.919293 4741 slave.cpp:2588] Received ping from > slave-observer(156)@192.168.122.135:57018 > I0114 18:51:34.919775 4740 status_update_manager.cpp:178] Resuming sending > status updates > I0114 18:51:34.920374 4736 master.cpp:4072] Sending 1 offers to framework > 20150114-185134-2272962752-57018-4720-0000 (default) at > scheduler-c45273e4-6eb5-44ee-bf45-71b353db648f@192.168.122.135:57018 > I0114 18:51:34.920569 4738 leveldb.cpp:343] Persisting action (16 bytes) to > leveldb took 1.540136ms > I0114 18:51:34.921092 4738 replica.cpp:679] Persisted action at 4 > I0114 18:51:34.927111 4735 replica.cpp:658] Replica received learned notice > for position 4 > I0114 18:51:34.927299 4734 sched.cpp:605] Scheduler::resourceOffers took > 1.335524ms > I0114 18:51:34.930418 4735 leveldb.cpp:343] Persisting action (18 bytes) to > leveldb took 1.596377ms > I0114 18:51:34.930882 4735 leveldb.cpp:401] Deleting ~2 keys from leveldb > took 67578ns > I0114 18:51:34.931115 4735 replica.cpp:679] Persisted action at 4 > I0114 18:51:34.931529 4735 replica.cpp:664] Replica learned TRUNCATE action > at position 4 > I0114 18:51:34.930356 4734 master.cpp:2541] Processing reply for offers: [ > 20150114-185134-2272962752-57018-4720-O0 ] on slave > 20150114-185134-2272962752-57018-4720-S0 at slave(171)@192.168.122.135:57018 > (fedora-19) for framework 20150114-185134-2272962752-57018-4720-0000 > (default) at > scheduler-c45273e4-6eb5-44ee-bf45-71b353db648f@192.168.122.135:57018 > I0114 18:51:34.932834 4734 master.cpp:2647] Authorizing framework principal > 'test-principal' to launch task 1 as user 'jenkins' > W0114 18:51:34.934442 4736 master.cpp:2124] 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. > W0114 18:51:34.934960 4736 master.cpp:2136] 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. > I0114 18:51:34.935878 4736 master.hpp:766] Adding task 1 with resources > cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave > 20150114-185134-2272962752-57018-4720-S0 (fedora-19) > I0114 18:51:34.939453 4738 hierarchical_allocator_process.hpp:610] Updated > allocation of framework 20150114-185134-2272962752-57018-4720-0000 on slave > 20150114-185134-2272962752-57018-4720-S0 from cpus(*):2; mem(*):1024; > disk(*):1024; ports(*):[31000-32000] to cpus(*):2; mem(*):1024; disk(*):1024; > ports(*):[31000-32000] > I0114 18:51:34.939950 4736 master.cpp:2897] Launching task 1 of framework > 20150114-185134-2272962752-57018-4720-0000 (default) at > scheduler-c45273e4-6eb5-44ee-bf45-71b353db648f@192.168.122.135:57018 with > resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on > slave 20150114-185134-2272962752-57018-4720-S0 at > slave(171)@192.168.122.135:57018 (fedora-19) > I0114 18:51:34.940467 4736 test_hook_module.cpp:52] Executing > 'masterLaunchTaskLabelDecorator' hook > I0114 18:51:34.941490 4740 slave.cpp:1130] Got assigned task 1 for framework > 20150114-185134-2272962752-57018-4720-0000 > I0114 18:51:34.942873 4740 slave.cpp:1245] Launching task 1 for framework > 20150114-185134-2272962752-57018-4720-0000 > I0114 18:51:34.943469 4740 test_hook_module.cpp:71] Executing > 'slaveLaunchExecutorEnvironmentDecorator' hook > I0114 18:51:34.946705 4740 slave.cpp:3921] Launching executor default of > framework 20150114-185134-2272962752-57018-4720-0000 in work directory > '/tmp/HookTest_VerifySlaveLaunchExecutorHook_AYxNqe/slaves/20150114-185134-2272962752-57018-4720-S0/frameworks/20150114-185134-2272962752-57018-4720-0000/executors/default/runs/d73da0e7-3d52-4a0e-91d0-eaef735fd65d' > I0114 18:51:34.956496 4740 exec.cpp:147] Version: 0.22.0 > I0114 18:51:34.960752 4737 exec.cpp:197] Executor started at: > executor(56)@192.168.122.135:57018 with pid 4720 > I0114 18:51:34.964501 4740 slave.cpp:1368] Queuing task '1' for executor > default of framework '20150114-185134-2272962752-57018-4720-0000 > I0114 18:51:34.965133 4740 slave.cpp:566] Successfully attached file > '/tmp/HookTest_VerifySlaveLaunchExecutorHook_AYxNqe/slaves/20150114-185134-2272962752-57018-4720-S0/frameworks/20150114-185134-2272962752-57018-4720-0000/executors/default/runs/d73da0e7-3d52-4a0e-91d0-eaef735fd65d' > I0114 18:51:34.965605 4740 slave.cpp:1912] Got registration for executor > 'default' of framework 20150114-185134-2272962752-57018-4720-0000 from > executor(56)@192.168.122.135:57018 > I0114 18:51:34.966933 4734 exec.cpp:221] Executor registered on slave > 20150114-185134-2272962752-57018-4720-S0 > I0114 18:51:34.968889 4740 slave.cpp:2031] Flushing queued task 1 for > executor 'default' of framework 20150114-185134-2272962752-57018-4720-0000 > I0114 18:51:34.969743 4740 slave.cpp:2890] Monitoring executor 'default' of > framework '20150114-185134-2272962752-57018-4720-0000' in container > 'd73da0e7-3d52-4a0e-91d0-eaef735fd65d' > I0114 18:51:34.973484 4734 exec.cpp:233] Executor::registered took 4.814445ms > I0114 18:51:34.974081 4734 exec.cpp:308] Executor asked to run task '1' > I0114 18:51:34.974431 4734 exec.cpp:317] Executor::launchTask took 184910ns > I0114 18:51:34.975292 4720 sched.cpp:1471] Asked to stop the driver > I0114 18:51:34.975817 4738 sched.cpp:808] Stopping framework > '20150114-185134-2272962752-57018-4720-0000' > I0114 18:51:34.975697 4720 master.cpp:654] Master terminating > W0114 18:51:34.976610 4720 master.cpp:4980] Removing task 1 with resources > cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework > 20150114-185134-2272962752-57018-4720-0000 on slave > 20150114-185134-2272962752-57018-4720-S0 at slave(171)@192.168.122.135:57018 > (fedora-19) in non-terminal state TASK_STAGING > I0114 18:51:34.977880 4720 master.cpp:5023] Removing executor 'default' with > resources of framework 20150114-185134-2272962752-57018-4720-0000 on slave > 20150114-185134-2272962752-57018-4720-S0 at slave(171)@192.168.122.135:57018 > (fedora-19) > I0114 18:51:34.978196 4741 hierarchical_allocator_process.hpp:653] Recovered > cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total > allocatable: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on > slave 20150114-185134-2272962752-57018-4720-S0 from framework > 20150114-185134-2272962752-57018-4720-0000 > I0114 18:51:34.982658 4735 slave.cpp:2673] master@192.168.122.135:57018 > exited > W0114 18:51:34.983065 4735 slave.cpp:2676] Master disconnected! Waiting for > a new master to be elected > I0114 18:51:35.029485 4720 slave.cpp:495] Slave terminating > I0114 18:51:35.034024 4720 slave.cpp:1585] Asked to shut down framework > 20150114-185134-2272962752-57018-4720-0000 by @0.0.0.0:0 > I0114 18:51:35.034335 4720 slave.cpp:1610] Shutting down framework > 20150114-185134-2272962752-57018-4720-0000 > I0114 18:51:35.034857 4720 slave.cpp:3198] Shutting down executor 'default' > of framework 20150114-185134-2272962752-57018-4720-0000 > tests/hook_tests.cpp:271: Failure > Value of: os::isfile(path.get()) > Actual: true > Expected: false > [ FAILED ] HookTest.VerifySlaveLaunchExecutorHook (412 ms) > {code} -- This message was sent by Atlassian JIRA (v6.3.4#6332)