mesos-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Niklas Quarfot Nielsen (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (MESOS-2226) HookTest.VerifySlaveLaunchExecutorHook is flaky
Date Wed, 03 Jun 2015 17:51:38 GMT

    [ https://issues.apache.org/jira/browse/MESOS-2226?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14571397#comment-14571397
] 

Niklas Quarfot Nielsen commented on MESOS-2226:
-----------------------------------------------

[~karya] Any ideas to what may be going on here?

> 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)

Mime
View raw message