You are viewing a plain text version of this content. The canonical link for it is here.
Posted to builds@mesos.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2015/06/29 19:36:16 UTC
Build failed in Jenkins: Mesos » gcc,docker||Hadoop,centos:7 #451
See <https://builds.apache.org/job/Mesos/COMPILER=gcc,LABEL=docker%7C%7CHadoop,OS=centos%3A7/451/changes>
Changes:
[benjamin.mahler] Updated the executor driver to set TaskStatus.uuid.
[benjamin.mahler] Moved StatusUpdate.uuid from required to optional.
[benjamin.mahler] Updated createdStatusUpdate to take an optional UUID.
------------------------------------------
[...truncated 38727 lines...]
I0629 17:35:58.811671 27262 slave.cpp:354] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0629 17:35:58.811769 27262 slave.cpp:384] Slave hostname: b9dd4e6544ca
I0629 17:35:58.811789 27262 slave.cpp:389] Slave checkpoint: true
I0629 17:35:58.812510 27264 state.cpp:36] Recovering state from '/tmp/HookTest_VerifySlaveLaunchExecutorHook_KQ5s9p/meta'
I0629 17:35:58.812932 27267 status_update_manager.cpp:202] Recovering status update manager
I0629 17:35:58.813328 27274 slave.cpp:4026] Finished recovery
I0629 17:35:58.813850 27274 slave.cpp:4179] Querying resource estimator for oversubscribable resources
I0629 17:35:58.814153 27274 slave.cpp:684] New master detected at master@172.17.0.10:46893
I0629 17:35:58.814165 27273 status_update_manager.cpp:176] Pausing sending status updates
I0629 17:35:58.814262 27274 slave.cpp:747] Authenticating with master master@172.17.0.10:46893
I0629 17:35:58.814290 27274 slave.cpp:752] Using default CRAM-MD5 authenticatee
I0629 17:35:58.814458 27274 slave.cpp:720] Detecting new master
I0629 17:35:58.814543 27265 authenticatee.cpp:115] Creating new client SASL connection
I0629 17:35:58.814646 27274 slave.cpp:4193] Received oversubscribable resources from the resource estimator
I0629 17:35:58.814859 27272 master.cpp:4224] Authenticating slave(55)@172.17.0.10:46893
I0629 17:35:58.814982 27267 authenticator.cpp:406] Starting authentication session for crammd5_authenticatee(156)@172.17.0.10:46893
I0629 17:35:58.815366 27274 authenticator.cpp:92] Creating new server SASL connection
I0629 17:35:58.815579 27240 sched.cpp:157] Version: 0.23.0
I0629 17:35:58.815637 27270 authenticatee.cpp:206] Received SASL authentication mechanisms: CRAM-MD5
I0629 17:35:58.815682 27270 authenticatee.cpp:232] Attempting to authenticate with mechanism 'CRAM-MD5'
I0629 17:35:58.815866 27265 authenticator.cpp:197] Received SASL authentication start
I0629 17:35:58.815935 27265 authenticator.cpp:319] Authentication requires more steps
I0629 17:35:58.816093 27259 authenticatee.cpp:252] Received SASL authentication step
I0629 17:35:58.816133 27262 sched.cpp:254] New master detected at master@172.17.0.10:46893
I0629 17:35:58.816217 27259 authenticator.cpp:225] Received SASL authentication step
I0629 17:35:58.816218 27262 sched.cpp:310] Authenticating with master master@172.17.0.10:46893
I0629 17:35:58.816254 27259 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: 'b9dd4e6544ca' server FQDN: 'b9dd4e6544ca' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0629 17:35:58.816265 27262 sched.cpp:317] Using default CRAM-MD5 authenticatee
I0629 17:35:58.816270 27259 auxprop.cpp:174] Looking up auxiliary property '*userPassword'
I0629 17:35:58.816349 27259 auxprop.cpp:174] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0629 17:35:58.816401 27259 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: 'b9dd4e6544ca' server FQDN: 'b9dd4e6544ca' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0629 17:35:58.816417 27259 auxprop.cpp:124] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0629 17:35:58.816428 27259 auxprop.cpp:124] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0629 17:35:58.816452 27259 authenticator.cpp:311] Authentication success
I0629 17:35:58.816494 27261 authenticatee.cpp:115] Creating new client SASL connection
I0629 17:35:58.816579 27273 master.cpp:4254] Successfully authenticated principal 'test-principal' at slave(55)@172.17.0.10:46893
I0629 17:35:58.816627 27272 authenticator.cpp:424] Authentication session cleanup for crammd5_authenticatee(156)@172.17.0.10:46893
I0629 17:35:58.816665 27266 authenticatee.cpp:292] Authentication success
I0629 17:35:58.816819 27273 master.cpp:4224] Authenticating scheduler-0dcb03b0-b522-45e3-aaa6-0bd794915f6b@172.17.0.10:46893
I0629 17:35:58.816962 27272 authenticator.cpp:406] Starting authentication session for crammd5_authenticatee(157)@172.17.0.10:46893
I0629 17:35:58.816962 27262 slave.cpp:815] Successfully authenticated with master master@172.17.0.10:46893
I0629 17:35:58.817101 27262 slave.cpp:1204] Will retry registration in 2.203108ms if necessary
I0629 17:35:58.817183 27263 authenticator.cpp:92] Creating new server SASL connection
I0629 17:35:58.817291 27265 master.cpp:3185] Registering slave at slave(55)@172.17.0.10:46893 (b9dd4e6544ca) with id 20150629-173558-167776684-46893-27240-S0
I0629 17:35:58.817411 27263 authenticatee.cpp:206] Received SASL authentication mechanisms: CRAM-MD5
I0629 17:35:58.817445 27263 authenticatee.cpp:232] Attempting to authenticate with mechanism 'CRAM-MD5'
I0629 17:35:58.817550 27267 authenticator.cpp:197] Received SASL authentication start
I0629 17:35:58.817603 27267 authenticator.cpp:319] Authentication requires more steps
I0629 17:35:58.817684 27274 registrar.cpp:445] Applied 1 operations in 45586ns; attempting to update the 'registry'
I0629 17:35:58.817699 27263 authenticatee.cpp:252] Received SASL authentication step
I0629 17:35:58.817867 27260 authenticator.cpp:225] Received SASL authentication step
I0629 17:35:58.817898 27260 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: 'b9dd4e6544ca' server FQDN: 'b9dd4e6544ca' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0629 17:35:58.817909 27260 auxprop.cpp:174] Looking up auxiliary property '*userPassword'
I0629 17:35:58.817932 27260 auxprop.cpp:174] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0629 17:35:58.817953 27260 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: 'b9dd4e6544ca' server FQDN: 'b9dd4e6544ca' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0629 17:35:58.817962 27260 auxprop.cpp:124] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0629 17:35:58.817968 27260 auxprop.cpp:124] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0629 17:35:58.817981 27260 authenticator.cpp:311] Authentication success
I0629 17:35:58.818097 27263 master.cpp:4254] Successfully authenticated principal 'test-principal' at scheduler-0dcb03b0-b522-45e3-aaa6-0bd794915f6b@172.17.0.10:46893
I0629 17:35:58.818114 27267 authenticatee.cpp:292] Authentication success
I0629 17:35:58.818151 27273 authenticator.cpp:424] Authentication session cleanup for crammd5_authenticatee(157)@172.17.0.10:46893
I0629 17:35:58.818393 27264 sched.cpp:398] Successfully authenticated with master master@172.17.0.10:46893
I0629 17:35:58.818418 27264 sched.cpp:521] Sending registration request to master@172.17.0.10:46893
I0629 17:35:58.818477 27264 sched.cpp:554] Will retry registration in 1.060275311secs if necessary
I0629 17:35:58.818562 27268 master.cpp:1719] Received registration request for framework 'default' at scheduler-0dcb03b0-b522-45e3-aaa6-0bd794915f6b@172.17.0.10:46893
I0629 17:35:58.818739 27268 master.cpp:1559] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0629 17:35:58.819119 27262 master.cpp:1786] Registering framework 20150629-173558-167776684-46893-27240-0000 (default) at scheduler-0dcb03b0-b522-45e3-aaa6-0bd794915f6b@172.17.0.10:46893 with checkpointing disabled and capabilities [ ]
I0629 17:35:58.819399 27268 hierarchical.hpp:386] Added framework 20150629-173558-167776684-46893-27240-0000
I0629 17:35:58.819432 27268 hierarchical.hpp:955] No resources available to allocate!
I0629 17:35:58.819452 27268 hierarchical.hpp:855] Performed allocation for 0 slaves in 26126ns
I0629 17:35:58.819497 27266 sched.cpp:448] Framework registered with 20150629-173558-167776684-46893-27240-0000
I0629 17:35:58.819530 27266 sched.cpp:462] Scheduler::registered took 13858ns
I0629 17:35:58.820142 27262 log.cpp:685] Attempting to append 301 bytes to the log
I0629 17:35:58.820241 27265 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
I0629 17:35:58.820626 27264 slave.cpp:1204] Will retry registration in 27.175132ms if necessary
I0629 17:35:58.820731 27272 master.cpp:3173] Ignoring register slave message from slave(55)@172.17.0.10:46893 (b9dd4e6544ca) as admission is already in progress
I0629 17:35:58.821208 27268 replica.cpp:511] Replica received write request for position 3
I0629 17:35:58.821387 27268 leveldb.cpp:343] Persisting action (320 bytes) to leveldb took 146339ns
I0629 17:35:58.821419 27268 replica.cpp:679] Persisted action at 3
I0629 17:35:58.822021 27261 replica.cpp:658] Replica received learned notice for position 3
I0629 17:35:58.822415 27261 leveldb.cpp:343] Persisting action (322 bytes) to leveldb took 368065ns
I0629 17:35:58.822440 27261 replica.cpp:679] Persisted action at 3
I0629 17:35:58.822464 27261 replica.cpp:664] Replica learned APPEND action at position 3
I0629 17:35:58.823909 27267 registrar.cpp:490] Successfully updated the 'registry' in 6.08384ms
I0629 17:35:58.824255 27266 log.cpp:704] Attempting to truncate the log to 3
I0629 17:35:58.824620 27273 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
I0629 17:35:58.824755 27259 slave.cpp:3002] Received ping from slave-observer(54)@172.17.0.10:46893
I0629 17:35:58.824955 27265 master.cpp:3248] Registered slave 20150629-173558-167776684-46893-27240-S0 at slave(55)@172.17.0.10:46893 (b9dd4e6544ca) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0629 17:35:58.825104 27259 slave.cpp:859] Registered with master master@172.17.0.10:46893; given slave ID 20150629-173558-167776684-46893-27240-S0
I0629 17:35:58.825238 27259 fetcher.cpp:77] Clearing fetcher cache
I0629 17:35:58.825227 27270 hierarchical.hpp:528] Added slave 20150629-173558-167776684-46893-27240-S0 (b9dd4e6544ca) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
I0629 17:35:58.825445 27273 status_update_manager.cpp:183] Resuming sending status updates
I0629 17:35:58.825778 27271 replica.cpp:511] Replica received write request for position 4
I0629 17:35:58.825795 27259 slave.cpp:882] Checkpointing SlaveInfo to '/tmp/HookTest_VerifySlaveLaunchExecutorHook_KQ5s9p/meta/slaves/20150629-173558-167776684-46893-27240-S0/slave.info'
I0629 17:35:58.826066 27270 hierarchical.hpp:873] Performed allocation for slave 20150629-173558-167776684-46893-27240-S0 in 765164ns
I0629 17:35:58.826426 27259 slave.cpp:918] Forwarding total oversubscribed resources
I0629 17:35:58.826436 27271 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 608626ns
I0629 17:35:58.826472 27271 replica.cpp:679] Persisted action at 4
I0629 17:35:58.826542 27272 master.cpp:4143] Sending 1 offers to framework 20150629-173558-167776684-46893-27240-0000 (default) at scheduler-0dcb03b0-b522-45e3-aaa6-0bd794915f6b@172.17.0.10:46893
I0629 17:35:58.826829 27272 master.cpp:3540] Received update of slave 20150629-173558-167776684-46893-27240-S0 at slave(55)@172.17.0.10:46893 (b9dd4e6544ca) with total oversubscribed resources
I0629 17:35:58.827280 27265 sched.cpp:611] Scheduler::resourceOffers took 121108ns
I0629 17:35:58.827687 27274 hierarchical.hpp:588] Slave 20150629-173558-167776684-46893-27240-S0 (b9dd4e6544ca) updated with oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000])
I0629 17:35:58.828286 27274 hierarchical.hpp:955] No resources available to allocate!
I0629 17:35:58.828310 27274 hierarchical.hpp:873] Performed allocation for slave 20150629-173558-167776684-46893-27240-S0 in 534400ns
I0629 17:35:58.828460 27264 replica.cpp:658] Replica received learned notice for position 4
I0629 17:35:58.828955 27264 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 368270ns
I0629 17:35:58.829071 27264 leveldb.cpp:401] Deleting ~2 keys from leveldb took 57129ns
I0629 17:35:58.829107 27264 replica.cpp:679] Persisted action at 4
I0629 17:35:58.829145 27264 replica.cpp:664] Replica learned TRUNCATE action at position 4
I0629 17:35:58.829252 27273 master.cpp:2428] Processing ACCEPT call for offers: [ 20150629-173558-167776684-46893-27240-O0 ] on slave 20150629-173558-167776684-46893-27240-S0 at slave(55)@172.17.0.10:46893 (b9dd4e6544ca) for framework 20150629-173558-167776684-46893-27240-0000 (default) at scheduler-0dcb03b0-b522-45e3-aaa6-0bd794915f6b@172.17.0.10:46893
I0629 17:35:58.829310 27273 master.cpp:2271] Authorizing framework principal 'test-principal' to launch task 1 as user 'mesos'
W0629 17:35:58.830822 27273 validation.cpp:328] 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.
W0629 17:35:58.830870 27273 validation.cpp:340] 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.
I0629 17:35:58.831290 27273 master.hpp:159] Adding task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20150629-173558-167776684-46893-27240-S0 (b9dd4e6544ca)
I0629 17:35:58.831493 27273 master.cpp:2758] Launching task 1 of framework 20150629-173558-167776684-46893-27240-0000 (default) at scheduler-0dcb03b0-b522-45e3-aaa6-0bd794915f6b@172.17.0.10:46893 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20150629-173558-167776684-46893-27240-S0 at slave(55)@172.17.0.10:46893 (b9dd4e6544ca)
I0629 17:35:58.831640 27273 test_hook_module.cpp:66] Executing 'masterLaunchTaskLabelDecorator' hook
I0629 17:35:58.832002 27270 slave.cpp:1244] Got assigned task 1 for framework 20150629-173558-167776684-46893-27240-0000
I0629 17:35:58.832092 27270 test_hook_module.cpp:92] Executing 'slaveRunTaskLabelDecorator' hook
I0629 17:35:58.832823 27270 slave.cpp:1355] Launching task 1 for framework 20150629-173558-167776684-46893-27240-0000
I0629 17:35:58.842185 27270 slave.cpp:4733] Launching executor default of framework 20150629-173558-167776684-46893-27240-0000 with resources in work directory '/tmp/HookTest_VerifySlaveLaunchExecutorHook_KQ5s9p/slaves/20150629-173558-167776684-46893-27240-S0/frameworks/20150629-173558-167776684-46893-27240-0000/executors/default/runs/cccce08c-e942-4ffc-8fa8-09689ce17c04'
I0629 17:35:58.843968 27270 test_hook_module.cpp:116] Executing 'slaveExecutorEnvironmentDecorator' hook
I0629 17:35:58.846326 27270 exec.cpp:132] Version: 0.23.0
I0629 17:35:58.846624 27272 exec.cpp:182] Executor started at: executor(17)@172.17.0.10:46893 with pid 27240
I0629 17:35:58.846937 27270 slave.cpp:1573] Queuing task '1' for executor default of framework '20150629-173558-167776684-46893-27240-0000
I0629 17:35:58.847128 27270 slave.cpp:637] Successfully attached file '/tmp/HookTest_VerifySlaveLaunchExecutorHook_KQ5s9p/slaves/20150629-173558-167776684-46893-27240-S0/frameworks/20150629-173558-167776684-46893-27240-0000/executors/default/runs/cccce08c-e942-4ffc-8fa8-09689ce17c04'
I0629 17:35:58.847225 27270 slave.cpp:2333] Got registration for executor 'default' of framework 20150629-173558-167776684-46893-27240-0000 from executor(17)@172.17.0.10:46893
I0629 17:35:58.847578 27267 exec.cpp:206] Executor registered on slave 20150629-173558-167776684-46893-27240-S0
I0629 17:35:58.848170 27270 slave.cpp:1729] Sending queued task '1' to executor 'default' of framework 20150629-173558-167776684-46893-27240-0000
I0629 17:35:58.849452 27267 exec.cpp:218] Executor::registered took 33615ns
I0629 17:35:58.849668 27267 exec.cpp:293] Executor asked to run task '1'
I0629 17:35:58.849774 27267 exec.cpp:302] Executor::launchTask took 75896ns
I0629 17:35:58.852018 27267 exec.cpp:515] Executor sending status update TASK_RUNNING (UUID: 37c681e4-a5d1-498e-9d33-92a3dacc44ea) for task 1 of framework 20150629-173558-167776684-46893-27240-0000
I0629 17:35:58.852291 27267 slave.cpp:2671] Handling status update TASK_RUNNING (UUID: 37c681e4-a5d1-498e-9d33-92a3dacc44ea) for task 1 of framework 20150629-173558-167776684-46893-27240-0000 from executor(17)@172.17.0.10:46893
I0629 17:35:58.852602 27264 status_update_manager.cpp:322] Received status update TASK_RUNNING (UUID: 37c681e4-a5d1-498e-9d33-92a3dacc44ea) for task 1 of framework 20150629-173558-167776684-46893-27240-0000
I0629 17:35:58.852654 27264 status_update_manager.cpp:499] Creating StatusUpdate stream for task 1 of framework 20150629-173558-167776684-46893-27240-0000
I0629 17:35:58.852983 27264 status_update_manager.cpp:376] Forwarding update TASK_RUNNING (UUID: 37c681e4-a5d1-498e-9d33-92a3dacc44ea) for task 1 of framework 20150629-173558-167776684-46893-27240-0000 to the slave
I0629 17:35:58.853212 27270 slave.cpp:2926] Forwarding the update TASK_RUNNING (UUID: 37c681e4-a5d1-498e-9d33-92a3dacc44ea) for task 1 of framework 20150629-173558-167776684-46893-27240-0000 to master@172.17.0.10:46893
I0629 17:35:58.853384 27270 slave.cpp:2850] Status update manager successfully handled status update TASK_RUNNING (UUID: 37c681e4-a5d1-498e-9d33-92a3dacc44ea) for task 1 of framework 20150629-173558-167776684-46893-27240-0000
I0629 17:35:58.853423 27270 slave.cpp:2856] Sending acknowledgement for status update TASK_RUNNING (UUID: 37c681e4-a5d1-498e-9d33-92a3dacc44ea) for task 1 of framework 20150629-173558-167776684-46893-27240-0000 to executor(17)@172.17.0.10:46893
I0629 17:35:58.853626 27259 exec.cpp:339] Executor received status update acknowledgement 37c681e4-a5d1-498e-9d33-92a3dacc44ea for task 1 of framework 20150629-173558-167776684-46893-27240-0000
I0629 17:35:58.853631 27265 master.cpp:3611] Status update TASK_RUNNING (UUID: 37c681e4-a5d1-498e-9d33-92a3dacc44ea) for task 1 of framework 20150629-173558-167776684-46893-27240-0000 from slave 20150629-173558-167776684-46893-27240-S0 at slave(55)@172.17.0.10:46893 (b9dd4e6544ca)
I0629 17:35:58.853689 27265 master.cpp:3650] Forwarding status update TASK_RUNNING (UUID: 37c681e4-a5d1-498e-9d33-92a3dacc44ea) for task 1 of framework 20150629-173558-167776684-46893-27240-0000
I0629 17:35:58.853850 27265 master.cpp:5031] Updating the latest state of task 1 of framework 20150629-173558-167776684-46893-27240-0000 to TASK_RUNNING
I0629 17:35:58.853996 27270 sched.cpp:720] Scheduler::statusUpdate took 84688ns
I0629 17:35:58.854410 27264 master.cpp:3025] Forwarding status update acknowledgement 37c681e4-a5d1-498e-9d33-92a3dacc44ea for task 1 of framework 20150629-173558-167776684-46893-27240-0000 (default) at scheduler-0dcb03b0-b522-45e3-aaa6-0bd794915f6b@172.17.0.10:46893 to slave 20150629-173558-167776684-46893-27240-S0 at slave(55)@172.17.0.10:46893 (b9dd4e6544ca)
I0629 17:35:58.854485 27240 sched.cpp:1589] Asked to stop the driver
I0629 17:35:58.854657 27259 sched.cpp:834] Stopping framework '20150629-173558-167776684-46893-27240-0000'
I0629 17:35:58.854816 27262 status_update_manager.cpp:394] Received status update acknowledgement (UUID: 37c681e4-a5d1-498e-9d33-92a3dacc44ea) for task 1 of framework 20150629-173558-167776684-46893-27240-0000
I0629 17:35:58.855003 27268 master.cpp:2057] Asked to unregister framework 20150629-173558-167776684-46893-27240-0000
I0629 17:35:58.855041 27268 master.cpp:4571] Removing framework 20150629-173558-167776684-46893-27240-0000 (default) at scheduler-0dcb03b0-b522-45e3-aaa6-0bd794915f6b@172.17.0.10:46893
I0629 17:35:58.855105 27265 slave.cpp:2273] Status update manager successfully handled status update acknowledgement (UUID: 37c681e4-a5d1-498e-9d33-92a3dacc44ea) for task 1 of framework 20150629-173558-167776684-46893-27240-0000
I0629 17:35:58.855259 27266 hierarchical.hpp:469] Deactivated framework 20150629-173558-167776684-46893-27240-0000
I0629 17:35:58.855329 27260 slave.cpp:1946] Asked to shut down framework 20150629-173558-167776684-46893-27240-0000 by master@172.17.0.10:46893
I0629 17:35:58.855351 27268 master.cpp:5031] Updating the latest state of task 1 of framework 20150629-173558-167776684-46893-27240-0000 to TASK_KILLED
I0629 17:35:58.855396 27260 slave.cpp:1971] Shutting down framework 20150629-173558-167776684-46893-27240-0000
I0629 17:35:58.855511 27260 slave.cpp:3667] Shutting down executor 'default' of framework 20150629-173558-167776684-46893-27240-0000
I0629 17:35:58.855648 27264 exec.cpp:379] Executor asked to shutdown
I0629 17:35:58.855708 27264 exec.cpp:394] Executor::shutdown took 28039ns
I0629 17:35:58.855938 27268 master.cpp:5099] Removing task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework 20150629-173558-167776684-46893-27240-0000 on slave 20150629-173558-167776684-46893-27240-S0 at slave(55)@172.17.0.10:46893 (b9dd4e6544ca)
I0629 17:35:58.856024 27267 hierarchical.hpp:761] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on slave 20150629-173558-167776684-46893-27240-S0 from framework 20150629-173558-167776684-46893-27240-0000
I0629 17:35:58.856410 27268 master.cpp:5128] Removing executor 'default' with resources of framework 20150629-173558-167776684-46893-27240-0000 on slave 20150629-173558-167776684-46893-27240-S0 at slave(55)@172.17.0.10:46893 (b9dd4e6544ca)
I0629 17:35:58.856936 27263 hierarchical.hpp:423] Removed framework 20150629-173558-167776684-46893-27240-0000
I0629 17:35:59.772678 27274 hierarchical.hpp:955] No resources available to allocate!
I0629 17:35:59.772714 27274 hierarchical.hpp:855] Performed allocation for 1 slaves in 177999ns
I0629 17:36:00.773757 27266 hierarchical.hpp:955] No resources available to allocate!
I0629 17:36:00.773792 27266 hierarchical.hpp:855] Performed allocation for 1 slaves in 160595ns
I0629 17:36:01.775199 27269 hierarchical.hpp:955] No resources available to allocate!
I0629 17:36:01.775233 27269 hierarchical.hpp:855] Performed allocation for 1 slaves in 192374ns
I0629 17:36:02.776159 27262 hierarchical.hpp:955] No resources available to allocate!
I0629 17:36:02.776192 27262 hierarchical.hpp:855] Performed allocation for 1 slaves in 214744ns
I0629 17:36:03.776553 27261 hierarchical.hpp:955] No resources available to allocate!
I0629 17:36:03.776587 27261 hierarchical.hpp:855] Performed allocation for 1 slaves in 170958ns
I0629 17:36:03.856886 27271 slave.cpp:3736] Killing executor 'default' of framework 20150629-173558-167776684-46893-27240-0000
I0629 17:36:03.857148 27271 slave.cpp:3356] Executor 'default' of framework 20150629-173558-167776684-46893-27240-0000 exited with status 0
I0629 17:36:03.857275 27271 slave.cpp:3460] Cleaning up executor 'default' of framework 20150629-173558-167776684-46893-27240-0000
W0629 17:36:03.857501 27265 master.cpp:3697] Ignoring unknown exited executor 'default' of framework 20150629-173558-167776684-46893-27240-0000 on slave 20150629-173558-167776684-46893-27240-S0 at slave(55)@172.17.0.10:46893 (b9dd4e6544ca)
I0629 17:36:03.857789 27273 gc.cpp:56] Scheduling '/tmp/HookTest_VerifySlaveLaunchExecutorHook_KQ5s9p/slaves/20150629-173558-167776684-46893-27240-S0/frameworks/20150629-173558-167776684-46893-27240-0000/executors/default/runs/cccce08c-e942-4ffc-8fa8-09689ce17c04' for gc 6.99999007317333days in the future
I0629 17:36:03.857889 27271 test_hook_module.cpp:138] Executing 'slaveRemoveExecutorHook'
I0629 17:36:03.857987 27273 gc.cpp:56] Scheduling '/tmp/HookTest_VerifySlaveLaunchExecutorHook_KQ5s9p/slaves/20150629-173558-167776684-46893-27240-S0/frameworks/20150629-173558-167776684-46893-27240-0000/executors/default' for gc 6.99999007116741days in the future
I0629 17:36:03.858441 27271 slave.cpp:3549] Cleaning up framework 20150629-173558-167776684-46893-27240-0000
I0629 17:36:03.858536 27268 status_update_manager.cpp:284] Closing status update streams for framework 20150629-173558-167776684-46893-27240-0000
I0629 17:36:03.858618 27268 status_update_manager.cpp:530] Cleaning up status update stream for task 1 of framework 20150629-173558-167776684-46893-27240-0000
I0629 17:36:03.858639 27259 gc.cpp:56] Scheduling '/tmp/HookTest_VerifySlaveLaunchExecutorHook_KQ5s9p/slaves/20150629-173558-167776684-46893-27240-S0/frameworks/20150629-173558-167776684-46893-27240-0000' for gc 6.99999006289185days in the future
I0629 17:36:04.777987 27266 hierarchical.hpp:955] No resources available to allocate!
I0629 17:36:04.778020 27266 hierarchical.hpp:855] Performed allocation for 1 slaves in 156462ns
I0629 17:36:05.779075 27262 hierarchical.hpp:955] No resources available to allocate!
I0629 17:36:05.779114 27262 hierarchical.hpp:855] Performed allocation for 1 slaves in 181970ns
I0629 17:36:06.780197 27272 hierarchical.hpp:955] No resources available to allocate!
I0629 17:36:06.780231 27272 hierarchical.hpp:855] Performed allocation for 1 slaves in 158825ns
I0629 17:36:07.781527 27267 hierarchical.hpp:955] No resources available to allocate!
I0629 17:36:07.781560 27267 hierarchical.hpp:855] Performed allocation for 1 slaves in 168575ns
I0629 17:36:08.782826 27263 hierarchical.hpp:955] No resources available to allocate!
I0629 17:36:08.782860 27263 hierarchical.hpp:855] Performed allocation for 1 slaves in 158986ns
I0629 17:36:09.783218 27269 hierarchical.hpp:955] No resources available to allocate!
I0629 17:36:09.783253 27269 hierarchical.hpp:855] Performed allocation for 1 slaves in 156192ns
I0629 17:36:10.783875 27274 hierarchical.hpp:955] No resources available to allocate!
I0629 17:36:10.783915 27274 hierarchical.hpp:855] Performed allocation for 1 slaves in 160866ns
I0629 17:36:11.784690 27271 hierarchical.hpp:955] No resources available to allocate!
I0629 17:36:11.784723 27271 hierarchical.hpp:855] Performed allocation for 1 slaves in 155123ns
I0629 17:36:12.785611 27263 hierarchical.hpp:955] No resources available to allocate!
I0629 17:36:12.785650 27263 hierarchical.hpp:855] Performed allocation for 1 slaves in 165081ns
I0629 17:36:13.786465 27266 hierarchical.hpp:955] No resources available to allocate!
I0629 17:36:13.786499 27266 hierarchical.hpp:855] Performed allocation for 1 slaves in 155404ns
I0629 17:36:13.815742 27274 slave.cpp:4179] Querying resource estimator for oversubscribable resources
I0629 17:36:13.816068 27269 slave.cpp:4193] Received oversubscribable resources from the resource estimator
I0629 17:36:13.825381 27264 slave.cpp:3002] Received ping from slave-observer(54)@172.17.0.10:46893
../../src/tests/hook_tests.cpp:331: Failure
Failed to wait 15secs for hookFuture
I0629 17:36:13.858559 27270 master.cpp:843] Master terminating
I0629 17:36:13.859208 27262 hierarchical.hpp:559] Removed slave 20150629-173558-167776684-46893-27240-S0
I0629 17:36:13.860424 27269 slave.cpp:3087] master@172.17.0.10:46893 exited
W0629 17:36:13.860466 27269 slave.cpp:3090] Master disconnected! Waiting for a new master to be elected
F0629 17:36:13.860466 27240 logging.cpp:57] RAW: Pure virtual method called
@ 0x7f835f99ad12 google::LogMessage::Fail()
@ 0x7f835f9a01f4 google::RawLog__()
@ 0x7f835eef865a __cxa_pure_virtual
@ 0x887918 mesos::internal::tests::Cluster::Slaves::shutdown()
@ 0xe84772 mesos::internal::tests::MesosTest::ShutdownSlaves()
@ 0xe84734 mesos::internal::tests::MesosTest::Shutdown()
@ 0xe80d19 mesos::internal::tests::MesosTest::TearDown()
@ 0x11f7cd7 testing::internal::HandleSehExceptionsInMethodIfSupported<>()
@ 0x11f2ee2 testing::internal::HandleExceptionsInMethodIfSupported<>()
@ 0x11db354 testing::Test::Run()
@ 0x11dba2e testing::TestInfo::Run()
@ 0x11dbfb6 testing::TestCase::Run()
@ 0x11e0d32 testing::internal::UnitTestImpl::RunAllTests()
@ 0x11f8b49 testing::internal::HandleSehExceptionsInMethodIfSupported<>()
@ 0x11f3bc5 testing::internal::HandleExceptionsInMethodIfSupported<>()
@ 0x11dfbe2 testing::UnitTest::Run()
@ 0xcfaf8c main
@ 0x7f835aff2af5 __libc_start_main
@ 0x87d799 (unknown)
make[4]: *** [check-local] Aborted
make[4]: Leaving directory `/mesos/mesos-0.23.0/_build/src'
make[3]: *** [check-am] Error 2
make[3]: Leaving directory `/mesos/mesos-0.23.0/_build/src'
make[2]: *** [check] Error 2
make[2]: Leaving directory `/mesos/mesos-0.23.0/_build/src'
make[1]: *** [check-recursive] Error 1
make[1]: Leaving directory `/mesos/mesos-0.23.0/_build'
make: *** [distcheck] Error 1
+ docker rmi mesos-1435598474-8698
Untagged: mesos-1435598474-8698:latest
Deleted: 2ce6453f3e15b0d3c89c4775d0464ca66ecebbb04fa1d73b4c849b596f8091f7
Deleted: 6a69c92e3b176ed14ea5e2a4d8fc3c4a4f4bc9ce3d8bfd9acd0f982917d94bc1
Deleted: 03cfc56fd90c029b97374a4f9ad42f450b9526c7285c70a9b8f96aa16fc246fb
Deleted: f2583c3f812e0ae1dc0418932b6f896b516f3b4d7909793f562b113327335f96
Deleted: 71be0f90118bd15db88c9a304663fe210b014d37ccdf943e9f9ecbd56fcab40d
Build step 'Execute shell' marked build as failure
Jenkins build is back to normal : Mesos » gcc,docker||Hadoop,centos:7 #452
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/Mesos/COMPILER=gcc,LABEL=docker%7C%7CHadoop,OS=centos%3A7/452/changes>
Re: Build failed in Jenkins: Mesos » gcc,docker||Hadoop,centos:7 #451
Posted by Vinod Kone <vi...@gmail.com>.
@kapil: are you triaging this?
On Mon, Jun 29, 2015 at 10:36 AM, Apache Jenkins Server <
jenkins@builds.apache.org> wrote:
> See <
> https://builds.apache.org/job/Mesos/COMPILER=gcc,LABEL=docker%7C%7CHadoop,OS=centos%3A7/451/changes
> >
>
> Changes:
>
> [benjamin.mahler] Updated the executor driver to set TaskStatus.uuid.
>
> [benjamin.mahler] Moved StatusUpdate.uuid from required to optional.
>
> [benjamin.mahler] Updated createdStatusUpdate to take an optional UUID.
>
> ------------------------------------------
> [...truncated 38727 lines...]
> I0629 17:35:58.811671 27262 slave.cpp:354] Slave resources: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0629 17:35:58.811769 27262 slave.cpp:384] Slave hostname: b9dd4e6544ca
> I0629 17:35:58.811789 27262 slave.cpp:389] Slave checkpoint: true
> I0629 17:35:58.812510 27264 state.cpp:36] Recovering state from
> '/tmp/HookTest_VerifySlaveLaunchExecutorHook_KQ5s9p/meta'
> I0629 17:35:58.812932 27267 status_update_manager.cpp:202] Recovering
> status update manager
> I0629 17:35:58.813328 27274 slave.cpp:4026] Finished recovery
> I0629 17:35:58.813850 27274 slave.cpp:4179] Querying resource estimator
> for oversubscribable resources
> I0629 17:35:58.814153 27274 slave.cpp:684] New master detected at
> master@172.17.0.10:46893
> I0629 17:35:58.814165 27273 status_update_manager.cpp:176] Pausing sending
> status updates
> I0629 17:35:58.814262 27274 slave.cpp:747] Authenticating with master
> master@172.17.0.10:46893
> I0629 17:35:58.814290 27274 slave.cpp:752] Using default CRAM-MD5
> authenticatee
> I0629 17:35:58.814458 27274 slave.cpp:720] Detecting new master
> I0629 17:35:58.814543 27265 authenticatee.cpp:115] Creating new client
> SASL connection
> I0629 17:35:58.814646 27274 slave.cpp:4193] Received oversubscribable
> resources from the resource estimator
> I0629 17:35:58.814859 27272 master.cpp:4224] Authenticating slave(55)@
> 172.17.0.10:46893
> I0629 17:35:58.814982 27267 authenticator.cpp:406] Starting authentication
> session for crammd5_authenticatee(156)@172.17.0.10:46893
> I0629 17:35:58.815366 27274 authenticator.cpp:92] Creating new server SASL
> connection
> I0629 17:35:58.815579 27240 sched.cpp:157] Version: 0.23.0
> I0629 17:35:58.815637 27270 authenticatee.cpp:206] Received SASL
> authentication mechanisms: CRAM-MD5
> I0629 17:35:58.815682 27270 authenticatee.cpp:232] Attempting to
> authenticate with mechanism 'CRAM-MD5'
> I0629 17:35:58.815866 27265 authenticator.cpp:197] Received SASL
> authentication start
> I0629 17:35:58.815935 27265 authenticator.cpp:319] Authentication requires
> more steps
> I0629 17:35:58.816093 27259 authenticatee.cpp:252] Received SASL
> authentication step
> I0629 17:35:58.816133 27262 sched.cpp:254] New master detected at
> master@172.17.0.10:46893
> I0629 17:35:58.816217 27259 authenticator.cpp:225] Received SASL
> authentication step
> I0629 17:35:58.816218 27262 sched.cpp:310] Authenticating with master
> master@172.17.0.10:46893
> I0629 17:35:58.816254 27259 auxprop.cpp:102] Request to lookup properties
> for user: 'test-principal' realm: 'b9dd4e6544ca' server FQDN:
> 'b9dd4e6544ca' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0629 17:35:58.816265 27262 sched.cpp:317] Using default CRAM-MD5
> authenticatee
> I0629 17:35:58.816270 27259 auxprop.cpp:174] Looking up auxiliary property
> '*userPassword'
> I0629 17:35:58.816349 27259 auxprop.cpp:174] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0629 17:35:58.816401 27259 auxprop.cpp:102] Request to lookup properties
> for user: 'test-principal' realm: 'b9dd4e6544ca' server FQDN:
> 'b9dd4e6544ca' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0629 17:35:58.816417 27259 auxprop.cpp:124] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0629 17:35:58.816428 27259 auxprop.cpp:124] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0629 17:35:58.816452 27259 authenticator.cpp:311] Authentication success
> I0629 17:35:58.816494 27261 authenticatee.cpp:115] Creating new client
> SASL connection
> I0629 17:35:58.816579 27273 master.cpp:4254] Successfully authenticated
> principal 'test-principal' at slave(55)@172.17.0.10:46893
> I0629 17:35:58.816627 27272 authenticator.cpp:424] Authentication session
> cleanup for crammd5_authenticatee(156)@172.17.0.10:46893
> I0629 17:35:58.816665 27266 authenticatee.cpp:292] Authentication success
> I0629 17:35:58.816819 27273 master.cpp:4224] Authenticating
> scheduler-0dcb03b0-b522-45e3-aaa6-0bd794915f6b@172.17.0.10:46893
> I0629 17:35:58.816962 27272 authenticator.cpp:406] Starting authentication
> session for crammd5_authenticatee(157)@172.17.0.10:46893
> I0629 17:35:58.816962 27262 slave.cpp:815] Successfully authenticated with
> master master@172.17.0.10:46893
> I0629 17:35:58.817101 27262 slave.cpp:1204] Will retry registration in
> 2.203108ms if necessary
> I0629 17:35:58.817183 27263 authenticator.cpp:92] Creating new server SASL
> connection
> I0629 17:35:58.817291 27265 master.cpp:3185] Registering slave at
> slave(55)@172.17.0.10:46893 (b9dd4e6544ca) with id
> 20150629-173558-167776684-46893-27240-S0
> I0629 17:35:58.817411 27263 authenticatee.cpp:206] Received SASL
> authentication mechanisms: CRAM-MD5
> I0629 17:35:58.817445 27263 authenticatee.cpp:232] Attempting to
> authenticate with mechanism 'CRAM-MD5'
> I0629 17:35:58.817550 27267 authenticator.cpp:197] Received SASL
> authentication start
> I0629 17:35:58.817603 27267 authenticator.cpp:319] Authentication requires
> more steps
> I0629 17:35:58.817684 27274 registrar.cpp:445] Applied 1 operations in
> 45586ns; attempting to update the 'registry'
> I0629 17:35:58.817699 27263 authenticatee.cpp:252] Received SASL
> authentication step
> I0629 17:35:58.817867 27260 authenticator.cpp:225] Received SASL
> authentication step
> I0629 17:35:58.817898 27260 auxprop.cpp:102] Request to lookup properties
> for user: 'test-principal' realm: 'b9dd4e6544ca' server FQDN:
> 'b9dd4e6544ca' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0629 17:35:58.817909 27260 auxprop.cpp:174] Looking up auxiliary property
> '*userPassword'
> I0629 17:35:58.817932 27260 auxprop.cpp:174] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0629 17:35:58.817953 27260 auxprop.cpp:102] Request to lookup properties
> for user: 'test-principal' realm: 'b9dd4e6544ca' server FQDN:
> 'b9dd4e6544ca' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0629 17:35:58.817962 27260 auxprop.cpp:124] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0629 17:35:58.817968 27260 auxprop.cpp:124] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0629 17:35:58.817981 27260 authenticator.cpp:311] Authentication success
> I0629 17:35:58.818097 27263 master.cpp:4254] Successfully authenticated
> principal 'test-principal' at
> scheduler-0dcb03b0-b522-45e3-aaa6-0bd794915f6b@172.17.0.10:46893
> I0629 17:35:58.818114 27267 authenticatee.cpp:292] Authentication success
> I0629 17:35:58.818151 27273 authenticator.cpp:424] Authentication session
> cleanup for crammd5_authenticatee(157)@172.17.0.10:46893
> I0629 17:35:58.818393 27264 sched.cpp:398] Successfully authenticated with
> master master@172.17.0.10:46893
> I0629 17:35:58.818418 27264 sched.cpp:521] Sending registration request to
> master@172.17.0.10:46893
> I0629 17:35:58.818477 27264 sched.cpp:554] Will retry registration in
> 1.060275311secs if necessary
> I0629 17:35:58.818562 27268 master.cpp:1719] Received registration request
> for framework 'default' at
> scheduler-0dcb03b0-b522-45e3-aaa6-0bd794915f6b@172.17.0.10:46893
> I0629 17:35:58.818739 27268 master.cpp:1559] Authorizing framework
> principal 'test-principal' to receive offers for role '*'
> I0629 17:35:58.819119 27262 master.cpp:1786] Registering framework
> 20150629-173558-167776684-46893-27240-0000 (default) at
> scheduler-0dcb03b0-b522-45e3-aaa6-0bd794915f6b@172.17.0.10:46893 with
> checkpointing disabled and capabilities [ ]
> I0629 17:35:58.819399 27268 hierarchical.hpp:386] Added framework
> 20150629-173558-167776684-46893-27240-0000
> I0629 17:35:58.819432 27268 hierarchical.hpp:955] No resources available
> to allocate!
> I0629 17:35:58.819452 27268 hierarchical.hpp:855] Performed allocation for
> 0 slaves in 26126ns
> I0629 17:35:58.819497 27266 sched.cpp:448] Framework registered with
> 20150629-173558-167776684-46893-27240-0000
> I0629 17:35:58.819530 27266 sched.cpp:462] Scheduler::registered took
> 13858ns
> I0629 17:35:58.820142 27262 log.cpp:685] Attempting to append 301 bytes to
> the log
> I0629 17:35:58.820241 27265 coordinator.cpp:340] Coordinator attempting to
> write APPEND action at position 3
> I0629 17:35:58.820626 27264 slave.cpp:1204] Will retry registration in
> 27.175132ms if necessary
> I0629 17:35:58.820731 27272 master.cpp:3173] Ignoring register slave
> message from slave(55)@172.17.0.10:46893 (b9dd4e6544ca) as admission is
> already in progress
> I0629 17:35:58.821208 27268 replica.cpp:511] Replica received write
> request for position 3
> I0629 17:35:58.821387 27268 leveldb.cpp:343] Persisting action (320 bytes)
> to leveldb took 146339ns
> I0629 17:35:58.821419 27268 replica.cpp:679] Persisted action at 3
> I0629 17:35:58.822021 27261 replica.cpp:658] Replica received learned
> notice for position 3
> I0629 17:35:58.822415 27261 leveldb.cpp:343] Persisting action (322 bytes)
> to leveldb took 368065ns
> I0629 17:35:58.822440 27261 replica.cpp:679] Persisted action at 3
> I0629 17:35:58.822464 27261 replica.cpp:664] Replica learned APPEND action
> at position 3
> I0629 17:35:58.823909 27267 registrar.cpp:490] Successfully updated the
> 'registry' in 6.08384ms
> I0629 17:35:58.824255 27266 log.cpp:704] Attempting to truncate the log to
> 3
> I0629 17:35:58.824620 27273 coordinator.cpp:340] Coordinator attempting to
> write TRUNCATE action at position 4
> I0629 17:35:58.824755 27259 slave.cpp:3002] Received ping from
> slave-observer(54)@172.17.0.10:46893
> I0629 17:35:58.824955 27265 master.cpp:3248] Registered slave
> 20150629-173558-167776684-46893-27240-S0 at slave(55)@172.17.0.10:46893
> (b9dd4e6544ca) with cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000]
> I0629 17:35:58.825104 27259 slave.cpp:859] Registered with master
> master@172.17.0.10:46893; given slave ID
> 20150629-173558-167776684-46893-27240-S0
> I0629 17:35:58.825238 27259 fetcher.cpp:77] Clearing fetcher cache
> I0629 17:35:58.825227 27270 hierarchical.hpp:528] Added slave
> 20150629-173558-167776684-46893-27240-S0 (b9dd4e6544ca) with cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
> I0629 17:35:58.825445 27273 status_update_manager.cpp:183] Resuming
> sending status updates
> I0629 17:35:58.825778 27271 replica.cpp:511] Replica received write
> request for position 4
> I0629 17:35:58.825795 27259 slave.cpp:882] Checkpointing SlaveInfo to
> '/tmp/HookTest_VerifySlaveLaunchExecutorHook_KQ5s9p/meta/slaves/20150629-173558-167776684-46893-27240-S0/
> slave.info'
> I0629 17:35:58.826066 27270 hierarchical.hpp:873] Performed allocation for
> slave 20150629-173558-167776684-46893-27240-S0 in 765164ns
> I0629 17:35:58.826426 27259 slave.cpp:918] Forwarding total oversubscribed
> resources
> I0629 17:35:58.826436 27271 leveldb.cpp:343] Persisting action (16 bytes)
> to leveldb took 608626ns
> I0629 17:35:58.826472 27271 replica.cpp:679] Persisted action at 4
> I0629 17:35:58.826542 27272 master.cpp:4143] Sending 1 offers to framework
> 20150629-173558-167776684-46893-27240-0000 (default) at
> scheduler-0dcb03b0-b522-45e3-aaa6-0bd794915f6b@172.17.0.10:46893
> I0629 17:35:58.826829 27272 master.cpp:3540] Received update of slave
> 20150629-173558-167776684-46893-27240-S0 at slave(55)@172.17.0.10:46893
> (b9dd4e6544ca) with total oversubscribed resources
> I0629 17:35:58.827280 27265 sched.cpp:611] Scheduler::resourceOffers took
> 121108ns
> I0629 17:35:58.827687 27274 hierarchical.hpp:588] Slave
> 20150629-173558-167776684-46893-27240-S0 (b9dd4e6544ca) updated with
> oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000])
> I0629 17:35:58.828286 27274 hierarchical.hpp:955] No resources available
> to allocate!
> I0629 17:35:58.828310 27274 hierarchical.hpp:873] Performed allocation for
> slave 20150629-173558-167776684-46893-27240-S0 in 534400ns
> I0629 17:35:58.828460 27264 replica.cpp:658] Replica received learned
> notice for position 4
> I0629 17:35:58.828955 27264 leveldb.cpp:343] Persisting action (18 bytes)
> to leveldb took 368270ns
> I0629 17:35:58.829071 27264 leveldb.cpp:401] Deleting ~2 keys from leveldb
> took 57129ns
> I0629 17:35:58.829107 27264 replica.cpp:679] Persisted action at 4
> I0629 17:35:58.829145 27264 replica.cpp:664] Replica learned TRUNCATE
> action at position 4
> I0629 17:35:58.829252 27273 master.cpp:2428] Processing ACCEPT call for
> offers: [ 20150629-173558-167776684-46893-27240-O0 ] on slave
> 20150629-173558-167776684-46893-27240-S0 at slave(55)@172.17.0.10:46893
> (b9dd4e6544ca) for framework 20150629-173558-167776684-46893-27240-0000
> (default) at
> scheduler-0dcb03b0-b522-45e3-aaa6-0bd794915f6b@172.17.0.10:46893
> I0629 17:35:58.829310 27273 master.cpp:2271] Authorizing framework
> principal 'test-principal' to launch task 1 as user 'mesos'
> W0629 17:35:58.830822 27273 validation.cpp:328] 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.
> W0629 17:35:58.830870 27273 validation.cpp:340] 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.
> I0629 17:35:58.831290 27273 master.hpp:159] Adding task 1 with resources
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
> 20150629-173558-167776684-46893-27240-S0 (b9dd4e6544ca)
> I0629 17:35:58.831493 27273 master.cpp:2758] Launching task 1 of framework
> 20150629-173558-167776684-46893-27240-0000 (default) at
> scheduler-0dcb03b0-b522-45e3-aaa6-0bd794915f6b@172.17.0.10:46893 with
> resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on
> slave 20150629-173558-167776684-46893-27240-S0 at slave(55)@
> 172.17.0.10:46893 (b9dd4e6544ca)
> I0629 17:35:58.831640 27273 test_hook_module.cpp:66] Executing
> 'masterLaunchTaskLabelDecorator' hook
> I0629 17:35:58.832002 27270 slave.cpp:1244] Got assigned task 1 for
> framework 20150629-173558-167776684-46893-27240-0000
> I0629 17:35:58.832092 27270 test_hook_module.cpp:92] Executing
> 'slaveRunTaskLabelDecorator' hook
> I0629 17:35:58.832823 27270 slave.cpp:1355] Launching task 1 for framework
> 20150629-173558-167776684-46893-27240-0000
> I0629 17:35:58.842185 27270 slave.cpp:4733] Launching executor default of
> framework 20150629-173558-167776684-46893-27240-0000 with resources in
> work directory
> '/tmp/HookTest_VerifySlaveLaunchExecutorHook_KQ5s9p/slaves/20150629-173558-167776684-46893-27240-S0/frameworks/20150629-173558-167776684-46893-27240-0000/executors/default/runs/cccce08c-e942-4ffc-8fa8-09689ce17c04'
> I0629 17:35:58.843968 27270 test_hook_module.cpp:116] Executing
> 'slaveExecutorEnvironmentDecorator' hook
> I0629 17:35:58.846326 27270 exec.cpp:132] Version: 0.23.0
> I0629 17:35:58.846624 27272 exec.cpp:182] Executor started at:
> executor(17)@172.17.0.10:46893 with pid 27240
> I0629 17:35:58.846937 27270 slave.cpp:1573] Queuing task '1' for executor
> default of framework '20150629-173558-167776684-46893-27240-0000
> I0629 17:35:58.847128 27270 slave.cpp:637] Successfully attached file
> '/tmp/HookTest_VerifySlaveLaunchExecutorHook_KQ5s9p/slaves/20150629-173558-167776684-46893-27240-S0/frameworks/20150629-173558-167776684-46893-27240-0000/executors/default/runs/cccce08c-e942-4ffc-8fa8-09689ce17c04'
> I0629 17:35:58.847225 27270 slave.cpp:2333] Got registration for executor
> 'default' of framework 20150629-173558-167776684-46893-27240-0000 from
> executor(17)@172.17.0.10:46893
> I0629 17:35:58.847578 27267 exec.cpp:206] Executor registered on slave
> 20150629-173558-167776684-46893-27240-S0
> I0629 17:35:58.848170 27270 slave.cpp:1729] Sending queued task '1' to
> executor 'default' of framework 20150629-173558-167776684-46893-27240-0000
> I0629 17:35:58.849452 27267 exec.cpp:218] Executor::registered took 33615ns
> I0629 17:35:58.849668 27267 exec.cpp:293] Executor asked to run task '1'
> I0629 17:35:58.849774 27267 exec.cpp:302] Executor::launchTask took 75896ns
> I0629 17:35:58.852018 27267 exec.cpp:515] Executor sending status update
> TASK_RUNNING (UUID: 37c681e4-a5d1-498e-9d33-92a3dacc44ea) for task 1 of
> framework 20150629-173558-167776684-46893-27240-0000
> I0629 17:35:58.852291 27267 slave.cpp:2671] Handling status update
> TASK_RUNNING (UUID: 37c681e4-a5d1-498e-9d33-92a3dacc44ea) for task 1 of
> framework 20150629-173558-167776684-46893-27240-0000 from executor(17)@
> 172.17.0.10:46893
> I0629 17:35:58.852602 27264 status_update_manager.cpp:322] Received status
> update TASK_RUNNING (UUID: 37c681e4-a5d1-498e-9d33-92a3dacc44ea) for task 1
> of framework 20150629-173558-167776684-46893-27240-0000
> I0629 17:35:58.852654 27264 status_update_manager.cpp:499] Creating
> StatusUpdate stream for task 1 of framework
> 20150629-173558-167776684-46893-27240-0000
> I0629 17:35:58.852983 27264 status_update_manager.cpp:376] Forwarding
> update TASK_RUNNING (UUID: 37c681e4-a5d1-498e-9d33-92a3dacc44ea) for task 1
> of framework 20150629-173558-167776684-46893-27240-0000 to the slave
> I0629 17:35:58.853212 27270 slave.cpp:2926] Forwarding the update
> TASK_RUNNING (UUID: 37c681e4-a5d1-498e-9d33-92a3dacc44ea) for task 1 of
> framework 20150629-173558-167776684-46893-27240-0000 to
> master@172.17.0.10:46893
> I0629 17:35:58.853384 27270 slave.cpp:2850] Status update manager
> successfully handled status update TASK_RUNNING (UUID:
> 37c681e4-a5d1-498e-9d33-92a3dacc44ea) for task 1 of framework
> 20150629-173558-167776684-46893-27240-0000
> I0629 17:35:58.853423 27270 slave.cpp:2856] Sending acknowledgement for
> status update TASK_RUNNING (UUID: 37c681e4-a5d1-498e-9d33-92a3dacc44ea) for
> task 1 of framework 20150629-173558-167776684-46893-27240-0000 to
> executor(17)@172.17.0.10:46893
> I0629 17:35:58.853626 27259 exec.cpp:339] Executor received status update
> acknowledgement 37c681e4-a5d1-498e-9d33-92a3dacc44ea for task 1 of
> framework 20150629-173558-167776684-46893-27240-0000
> I0629 17:35:58.853631 27265 master.cpp:3611] Status update TASK_RUNNING
> (UUID: 37c681e4-a5d1-498e-9d33-92a3dacc44ea) for task 1 of framework
> 20150629-173558-167776684-46893-27240-0000 from slave
> 20150629-173558-167776684-46893-27240-S0 at slave(55)@172.17.0.10:46893
> (b9dd4e6544ca)
> I0629 17:35:58.853689 27265 master.cpp:3650] Forwarding status update
> TASK_RUNNING (UUID: 37c681e4-a5d1-498e-9d33-92a3dacc44ea) for task 1 of
> framework 20150629-173558-167776684-46893-27240-0000
> I0629 17:35:58.853850 27265 master.cpp:5031] Updating the latest state of
> task 1 of framework 20150629-173558-167776684-46893-27240-0000 to
> TASK_RUNNING
> I0629 17:35:58.853996 27270 sched.cpp:720] Scheduler::statusUpdate took
> 84688ns
> I0629 17:35:58.854410 27264 master.cpp:3025] Forwarding status update
> acknowledgement 37c681e4-a5d1-498e-9d33-92a3dacc44ea for task 1 of
> framework 20150629-173558-167776684-46893-27240-0000 (default) at
> scheduler-0dcb03b0-b522-45e3-aaa6-0bd794915f6b@172.17.0.10:46893 to slave
> 20150629-173558-167776684-46893-27240-S0 at slave(55)@172.17.0.10:46893
> (b9dd4e6544ca)
> I0629 17:35:58.854485 27240 sched.cpp:1589] Asked to stop the driver
> I0629 17:35:58.854657 27259 sched.cpp:834] Stopping framework
> '20150629-173558-167776684-46893-27240-0000'
> I0629 17:35:58.854816 27262 status_update_manager.cpp:394] Received status
> update acknowledgement (UUID: 37c681e4-a5d1-498e-9d33-92a3dacc44ea) for
> task 1 of framework 20150629-173558-167776684-46893-27240-0000
> I0629 17:35:58.855003 27268 master.cpp:2057] Asked to unregister framework
> 20150629-173558-167776684-46893-27240-0000
> I0629 17:35:58.855041 27268 master.cpp:4571] Removing framework
> 20150629-173558-167776684-46893-27240-0000 (default) at
> scheduler-0dcb03b0-b522-45e3-aaa6-0bd794915f6b@172.17.0.10:46893
> I0629 17:35:58.855105 27265 slave.cpp:2273] Status update manager
> successfully handled status update acknowledgement (UUID:
> 37c681e4-a5d1-498e-9d33-92a3dacc44ea) for task 1 of framework
> 20150629-173558-167776684-46893-27240-0000
> I0629 17:35:58.855259 27266 hierarchical.hpp:469] Deactivated framework
> 20150629-173558-167776684-46893-27240-0000
> I0629 17:35:58.855329 27260 slave.cpp:1946] Asked to shut down framework
> 20150629-173558-167776684-46893-27240-0000 by master@172.17.0.10:46893
> I0629 17:35:58.855351 27268 master.cpp:5031] Updating the latest state of
> task 1 of framework 20150629-173558-167776684-46893-27240-0000 to
> TASK_KILLED
> I0629 17:35:58.855396 27260 slave.cpp:1971] Shutting down framework
> 20150629-173558-167776684-46893-27240-0000
> I0629 17:35:58.855511 27260 slave.cpp:3667] Shutting down executor
> 'default' of framework 20150629-173558-167776684-46893-27240-0000
> I0629 17:35:58.855648 27264 exec.cpp:379] Executor asked to shutdown
> I0629 17:35:58.855708 27264 exec.cpp:394] Executor::shutdown took 28039ns
> I0629 17:35:58.855938 27268 master.cpp:5099] Removing task 1 with
> resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of
> framework 20150629-173558-167776684-46893-27240-0000 on slave
> 20150629-173558-167776684-46893-27240-S0 at slave(55)@172.17.0.10:46893
> (b9dd4e6544ca)
> I0629 17:35:58.856024 27267 hierarchical.hpp:761] Recovered cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on slave
> 20150629-173558-167776684-46893-27240-S0 from framework
> 20150629-173558-167776684-46893-27240-0000
> I0629 17:35:58.856410 27268 master.cpp:5128] Removing executor 'default'
> with resources of framework 20150629-173558-167776684-46893-27240-0000 on
> slave 20150629-173558-167776684-46893-27240-S0 at slave(55)@
> 172.17.0.10:46893 (b9dd4e6544ca)
> I0629 17:35:58.856936 27263 hierarchical.hpp:423] Removed framework
> 20150629-173558-167776684-46893-27240-0000
> I0629 17:35:59.772678 27274 hierarchical.hpp:955] No resources available
> to allocate!
> I0629 17:35:59.772714 27274 hierarchical.hpp:855] Performed allocation for
> 1 slaves in 177999ns
> I0629 17:36:00.773757 27266 hierarchical.hpp:955] No resources available
> to allocate!
> I0629 17:36:00.773792 27266 hierarchical.hpp:855] Performed allocation for
> 1 slaves in 160595ns
> I0629 17:36:01.775199 27269 hierarchical.hpp:955] No resources available
> to allocate!
> I0629 17:36:01.775233 27269 hierarchical.hpp:855] Performed allocation for
> 1 slaves in 192374ns
> I0629 17:36:02.776159 27262 hierarchical.hpp:955] No resources available
> to allocate!
> I0629 17:36:02.776192 27262 hierarchical.hpp:855] Performed allocation for
> 1 slaves in 214744ns
> I0629 17:36:03.776553 27261 hierarchical.hpp:955] No resources available
> to allocate!
> I0629 17:36:03.776587 27261 hierarchical.hpp:855] Performed allocation for
> 1 slaves in 170958ns
> I0629 17:36:03.856886 27271 slave.cpp:3736] Killing executor 'default' of
> framework 20150629-173558-167776684-46893-27240-0000
> I0629 17:36:03.857148 27271 slave.cpp:3356] Executor 'default' of
> framework 20150629-173558-167776684-46893-27240-0000 exited with status 0
> I0629 17:36:03.857275 27271 slave.cpp:3460] Cleaning up executor 'default'
> of framework 20150629-173558-167776684-46893-27240-0000
> W0629 17:36:03.857501 27265 master.cpp:3697] Ignoring unknown exited
> executor 'default' of framework 20150629-173558-167776684-46893-27240-0000
> on slave 20150629-173558-167776684-46893-27240-S0 at slave(55)@
> 172.17.0.10:46893 (b9dd4e6544ca)
> I0629 17:36:03.857789 27273 gc.cpp:56] Scheduling
> '/tmp/HookTest_VerifySlaveLaunchExecutorHook_KQ5s9p/slaves/20150629-173558-167776684-46893-27240-S0/frameworks/20150629-173558-167776684-46893-27240-0000/executors/default/runs/cccce08c-e942-4ffc-8fa8-09689ce17c04'
> for gc 6.99999007317333days in the future
> I0629 17:36:03.857889 27271 test_hook_module.cpp:138] Executing
> 'slaveRemoveExecutorHook'
> I0629 17:36:03.857987 27273 gc.cpp:56] Scheduling
> '/tmp/HookTest_VerifySlaveLaunchExecutorHook_KQ5s9p/slaves/20150629-173558-167776684-46893-27240-S0/frameworks/20150629-173558-167776684-46893-27240-0000/executors/default'
> for gc 6.99999007116741days in the future
> I0629 17:36:03.858441 27271 slave.cpp:3549] Cleaning up framework
> 20150629-173558-167776684-46893-27240-0000
> I0629 17:36:03.858536 27268 status_update_manager.cpp:284] Closing status
> update streams for framework 20150629-173558-167776684-46893-27240-0000
> I0629 17:36:03.858618 27268 status_update_manager.cpp:530] Cleaning up
> status update stream for task 1 of framework
> 20150629-173558-167776684-46893-27240-0000
> I0629 17:36:03.858639 27259 gc.cpp:56] Scheduling
> '/tmp/HookTest_VerifySlaveLaunchExecutorHook_KQ5s9p/slaves/20150629-173558-167776684-46893-27240-S0/frameworks/20150629-173558-167776684-46893-27240-0000'
> for gc 6.99999006289185days in the future
> I0629 17:36:04.777987 27266 hierarchical.hpp:955] No resources available
> to allocate!
> I0629 17:36:04.778020 27266 hierarchical.hpp:855] Performed allocation for
> 1 slaves in 156462ns
> I0629 17:36:05.779075 27262 hierarchical.hpp:955] No resources available
> to allocate!
> I0629 17:36:05.779114 27262 hierarchical.hpp:855] Performed allocation for
> 1 slaves in 181970ns
> I0629 17:36:06.780197 27272 hierarchical.hpp:955] No resources available
> to allocate!
> I0629 17:36:06.780231 27272 hierarchical.hpp:855] Performed allocation for
> 1 slaves in 158825ns
> I0629 17:36:07.781527 27267 hierarchical.hpp:955] No resources available
> to allocate!
> I0629 17:36:07.781560 27267 hierarchical.hpp:855] Performed allocation for
> 1 slaves in 168575ns
> I0629 17:36:08.782826 27263 hierarchical.hpp:955] No resources available
> to allocate!
> I0629 17:36:08.782860 27263 hierarchical.hpp:855] Performed allocation for
> 1 slaves in 158986ns
> I0629 17:36:09.783218 27269 hierarchical.hpp:955] No resources available
> to allocate!
> I0629 17:36:09.783253 27269 hierarchical.hpp:855] Performed allocation for
> 1 slaves in 156192ns
> I0629 17:36:10.783875 27274 hierarchical.hpp:955] No resources available
> to allocate!
> I0629 17:36:10.783915 27274 hierarchical.hpp:855] Performed allocation for
> 1 slaves in 160866ns
> I0629 17:36:11.784690 27271 hierarchical.hpp:955] No resources available
> to allocate!
> I0629 17:36:11.784723 27271 hierarchical.hpp:855] Performed allocation for
> 1 slaves in 155123ns
> I0629 17:36:12.785611 27263 hierarchical.hpp:955] No resources available
> to allocate!
> I0629 17:36:12.785650 27263 hierarchical.hpp:855] Performed allocation for
> 1 slaves in 165081ns
> I0629 17:36:13.786465 27266 hierarchical.hpp:955] No resources available
> to allocate!
> I0629 17:36:13.786499 27266 hierarchical.hpp:855] Performed allocation for
> 1 slaves in 155404ns
> I0629 17:36:13.815742 27274 slave.cpp:4179] Querying resource estimator
> for oversubscribable resources
> I0629 17:36:13.816068 27269 slave.cpp:4193] Received oversubscribable
> resources from the resource estimator
> I0629 17:36:13.825381 27264 slave.cpp:3002] Received ping from
> slave-observer(54)@172.17.0.10:46893
> ../../src/tests/hook_tests.cpp:331: Failure
> Failed to wait 15secs for hookFuture
> I0629 17:36:13.858559 27270 master.cpp:843] Master terminating
> I0629 17:36:13.859208 27262 hierarchical.hpp:559] Removed slave
> 20150629-173558-167776684-46893-27240-S0
> I0629 17:36:13.860424 27269 slave.cpp:3087] master@172.17.0.10:46893
> exited
> W0629 17:36:13.860466 27269 slave.cpp:3090] Master disconnected! Waiting
> for a new master to be elected
> F0629 17:36:13.860466 27240 logging.cpp:57] RAW: Pure virtual method called
> @ 0x7f835f99ad12 google::LogMessage::Fail()
> @ 0x7f835f9a01f4 google::RawLog__()
> @ 0x7f835eef865a __cxa_pure_virtual
> @ 0x887918
> mesos::internal::tests::Cluster::Slaves::shutdown()
> @ 0xe84772
> mesos::internal::tests::MesosTest::ShutdownSlaves()
> @ 0xe84734 mesos::internal::tests::MesosTest::Shutdown()
> @ 0xe80d19 mesos::internal::tests::MesosTest::TearDown()
> @ 0x11f7cd7
> testing::internal::HandleSehExceptionsInMethodIfSupported<>()
> @ 0x11f2ee2
> testing::internal::HandleExceptionsInMethodIfSupported<>()
> @ 0x11db354 testing::Test::Run()
> @ 0x11dba2e testing::TestInfo::Run()
> @ 0x11dbfb6 testing::TestCase::Run()
> @ 0x11e0d32 testing::internal::UnitTestImpl::RunAllTests()
> @ 0x11f8b49
> testing::internal::HandleSehExceptionsInMethodIfSupported<>()
> @ 0x11f3bc5
> testing::internal::HandleExceptionsInMethodIfSupported<>()
> @ 0x11dfbe2 testing::UnitTest::Run()
> @ 0xcfaf8c main
> @ 0x7f835aff2af5 __libc_start_main
> @ 0x87d799 (unknown)
> make[4]: *** [check-local] Aborted
> make[4]: Leaving directory `/mesos/mesos-0.23.0/_build/src'
> make[3]: *** [check-am] Error 2
> make[3]: Leaving directory `/mesos/mesos-0.23.0/_build/src'
> make[2]: *** [check] Error 2
> make[2]: Leaving directory `/mesos/mesos-0.23.0/_build/src'
> make[1]: *** [check-recursive] Error 1
> make[1]: Leaving directory `/mesos/mesos-0.23.0/_build'
> make: *** [distcheck] Error 1
> + docker rmi mesos-1435598474-8698
> Untagged: mesos-1435598474-8698:latest
> Deleted: 2ce6453f3e15b0d3c89c4775d0464ca66ecebbb04fa1d73b4c849b596f8091f7
> Deleted: 6a69c92e3b176ed14ea5e2a4d8fc3c4a4f4bc9ce3d8bfd9acd0f982917d94bc1
> Deleted: 03cfc56fd90c029b97374a4f9ad42f450b9526c7285c70a9b8f96aa16fc246fb
> Deleted: f2583c3f812e0ae1dc0418932b6f896b516f3b4d7909793f562b113327335f96
> Deleted: 71be0f90118bd15db88c9a304663fe210b014d37ccdf943e9f9ecbd56fcab40d
> Build step 'Execute shell' marked build as failure
>