You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@mesos.apache.org by "Benjamin Mahler (JIRA)" <ji...@apache.org> on 2013/11/19 00:39:20 UTC
[jira] [Created] (MESOS-820) IsolatorTest.Usage failed on Jenkins
Benjamin Mahler created MESOS-820:
-------------------------------------
Summary: IsolatorTest.Usage failed on Jenkins
Key: MESOS-820
URL: https://issues.apache.org/jira/browse/MESOS-820
Project: Mesos
Issue Type: Bug
Components: test
Reporter: Benjamin Mahler
Assignee: Benjamin Mahler
[ RUN ] IsolatorTest/0.Usage
I1118 12:54:17.987071 27146 master.cpp:293] Master started on 127.0.1.1:45888
I1118 12:54:17.987098 27146 master.cpp:308] Master ID: 201311181254-16842879-45888-27125
I1118 12:54:17.987104 27146 master.cpp:311] Master only allowing authenticated frameworks to register!
I1118 12:54:17.987390 27145 slave.cpp:109] Slave started on 52)@127.0.1.1:45888
I1118 12:54:17.987489 27145 slave.cpp:209] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I1118 12:54:17.987857 27146 master.cpp:706] Elected as master!
I1118 12:54:17.987933 27146 sched.cpp:199] New master at master@127.0.1.1:45888
I1118 12:54:17.987949 27146 sched.cpp:285] Authenticating with master master@127.0.1.1:45888
I1118 12:54:17.988095 27146 hierarchical_allocator_process.hpp:302] Initializing hierarchical allocator process with master : master@127.0.1.1:45888
I1118 12:54:17.988126 27146 master.cpp:85] No whitelist given. Advertising offers for all slaves
I1118 12:54:17.988153 27146 authenticatee.hpp:124] Creating new client SASL connection
I1118 12:54:17.988786 27145 slave.cpp:488] New master detected at master@127.0.1.1:45888
I1118 12:54:17.988811 27145 slave.cpp:503] Postponing registration until recovery is complete
I1118 12:54:17.988888 27145 status_update_manager.cpp:158] New master detected at master@127.0.1.1:45888
I1118 12:54:17.988942 27145 state.cpp:33] Recovering state from '/tmp/IsolatorTest_0_Usage_jFkdWi/meta'
I1118 12:54:17.989013 27145 status_update_manager.cpp:180] Recovering status update manager
I1118 12:54:17.989047 27145 process_isolator.cpp:317] Recovering isolator
I1118 12:54:17.989081 27145 slave.cpp:2748] Finished recovery
I1118 12:54:17.989162 27145 master.cpp:1232] Attempting to register slave on raring at slave(52)@127.0.1.1:45888
I1118 12:54:17.989176 27145 master.cpp:2479] Adding slave 201311181254-16842879-45888-27125-0 at raring with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I1118 12:54:17.989258 27145 slave.cpp:554] Registered with master master@127.0.1.1:45888; given slave ID 201311181254-16842879-45888-27125-0
I1118 12:54:17.989310 27145 hierarchical_allocator_process.hpp:445] Added slave 201311181254-16842879-45888-27125-0 (raring) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
I1118 12:54:17.989343 27145 hierarchical_allocator_process.hpp:708] Performed allocation for slave 201311181254-16842879-45888-27125-0 in 6495ns
I1118 12:54:17.989459 27146 master.cpp:1700] Authenticating framework at scheduler(68)@127.0.1.1:45888
I1118 12:54:17.989537 27146 authenticator.hpp:140] Creating new server SASL connection
I1118 12:54:17.989629 27146 authenticatee.hpp:212] Received SASL authentication mechanisms: CRAM-MD5
I1118 12:54:17.989647 27146 authenticatee.hpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
I1118 12:54:17.989665 27146 authenticator.hpp:243] Received SASL authentication start
I1118 12:54:17.989697 27146 authenticator.hpp:325] Authentication requires more steps
I1118 12:54:17.989714 27146 authenticatee.hpp:258] Received SASL authentication step
I1118 12:54:17.989740 27146 authenticator.hpp:271] Received SASL authentication step
I1118 12:54:17.989755 27146 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'raring' server FQDN: 'raring' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1118 12:54:17.989761 27146 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I1118 12:54:17.989771 27146 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1118 12:54:17.989780 27146 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'raring' server FQDN: 'raring' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1118 12:54:17.989785 27146 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1118 12:54:17.989789 27146 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1118 12:54:17.989800 27146 authenticator.hpp:317] Authentication success
I1118 12:54:17.989817 27146 authenticatee.hpp:298] Authentication success
I1118 12:54:17.989831 27146 master.cpp:1740] Successfully authenticated framework at scheduler(68)@127.0.1.1:45888
I1118 12:54:17.989883 27146 sched.cpp:347] Successfully authenticated with master master@127.0.1.1:45888
I1118 12:54:17.989919 27146 master.cpp:764] Received registration request from scheduler(68)@127.0.1.1:45888
I1118 12:54:17.989982 27146 master.cpp:782] Registering framework 201311181254-16842879-45888-27125-0000 at scheduler(68)@127.0.1.1:45888
I1118 12:54:17.990032 27146 sched.cpp:386] Framework registered with 201311181254-16842879-45888-27125-0000
I1118 12:54:17.990056 27146 sched.cpp:400] Scheduler::registered took 13677ns
I1118 12:54:17.990077 27146 hierarchical_allocator_process.hpp:332] Added framework 201311181254-16842879-45888-27125-0000
I1118 12:54:17.990108 27146 hierarchical_allocator_process.hpp:752] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 201311181254-16842879-45888-27125-0 to framework 201311181254-16842879-45888-27125-0000
I1118 12:54:17.990190 27146 hierarchical_allocator_process.hpp:688] Performed allocation for 1 slaves in 102695ns
I1118 12:54:17.990242 27146 master.hpp:419] Adding offer 201311181254-16842879-45888-27125-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 201311181254-16842879-45888-27125-0 (raring)
I1118 12:54:17.990280 27146 master.cpp:1666] Sending 1 offers to framework 201311181254-16842879-45888-27125-0000
I1118 12:54:17.990378 27146 sched.cpp:493] Scheduler::resourceOffers took 14556ns
I1118 12:54:17.990736 27146 master.cpp:1992] Processing reply for offer 201311181254-16842879-45888-27125-0 on slave 201311181254-16842879-45888-27125-0 (raring) for framework 201311181254-16842879-45888-27125-0000
I1118 12:54:17.990881 27146 master.hpp:391] Adding task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 201311181254-16842879-45888-27125-0 (raring)
I1118 12:54:17.991415 27146 master.cpp:2116] Launching task 1 of framework 201311181254-16842879-45888-27125-0000 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 201311181254-16842879-45888-27125-0 (raring)
I1118 12:54:17.993443 27146 master.hpp:429] Removing offer 201311181254-16842879-45888-27125-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 201311181254-16842879-45888-27125-0 (raring)
I1118 12:54:17.993526 27147 slave.cpp:728] Got assigned task 1 for framework 201311181254-16842879-45888-27125-0000
I1118 12:54:17.993710 27147 slave.cpp:839] Launching task 1 for framework 201311181254-16842879-45888-27125-0000
I1118 12:54:17.995797 27147 slave.cpp:949] Queuing task '1' for executor 1 of framework '201311181254-16842879-45888-27125-0000
I1118 12:54:17.995905 27147 process_isolator.cpp:100] Launching 1 (/var/jenkins/workspace/mesos-ubuntu-13.04-gcc/src/mesos-executor) in /tmp/IsolatorTest_0_Usage_jFkdWi/slaves/201311181254-16842879-45888-27125-0/frameworks/201311181254-16842879-45888-27125-0000/executors/1/runs/8f8cb212-55c4-40b2-96d1-668ae30d6e89 with resources ' for framework 201311181254-16842879-45888-27125-0000
I1118 12:54:17.997860 27145 slave.cpp:470] Successfully attached file '/tmp/IsolatorTest_0_Usage_jFkdWi/slaves/201311181254-16842879-45888-27125-0/frameworks/201311181254-16842879-45888-27125-0000/executors/1/runs/8f8cb212-55c4-40b2-96d1-668ae30d6e89'
I1118 12:54:18.002439 27147 process_isolator.cpp:163] Forked executor at 27811
I1118 12:54:18.004621 27146 slave.cpp:2078] Monitoring executor 1 of framework 201311181254-16842879-45888-27125-0000 forked at pid 27811
Fetching resources into '/tmp/IsolatorTest_0_Usage_jFkdWi/slaves/201311181254-16842879-45888-27125-0/frameworks/201311181254-16842879-45888-27125-0000/executors/1/runs/8f8cb212-55c4-40b2-96d1-668ae30d6e89'
WARNING: Logging before InitGoogleLogging() is written to STDERR
I1118 12:54:18.073647 27829 process.cpp:1561] libprocess is initialized on 127.0.1.1:56497 for 4 cpus
I1118 12:54:18.076702 27844 exec.cpp:178] Executor started at: executor(1)@127.0.1.1:56497 with pid 27829
I1118 12:54:18.077427 27146 slave.cpp:1411] Got registration for executor '1' of framework 201311181254-16842879-45888-27125-0000
I1118 12:54:18.077689 27146 slave.cpp:1532] Flushing queued task 1 for executor '1' of framework 201311181254-16842879-45888-27125-0000
I1118 12:54:18.078177 27847 process.cpp:992] Socket closed while receiving
I1118 12:54:18.078418 27846 exec.cpp:202] Executor registered on slave 201311181254-16842879-45888-27125-0
IRegistered executor on raring
1118 12:54:18.079560 27846 exec.cpp:214] Executor::registered took 104993ns
I1118 12:54:18.080068 27846 exec.cpp:289] Executor asked to run task '1'
IStarting task 1
1118 12:54:18.080298 27846 exec.cpp:298] Executor::launchTask took 39627ns
sh -c 'top -b -d 0 -n 30000 2>&1 > /dev/null & touch /tmp/IsolatorTest_0_Usage_jFkdWi/ready; sleep 60'
Forked command at 27848
I1118 12:54:18.085307 27845 exec.cpp:521] Executor sending status update TASK_RUNNING (UUID: 970a7b8d-f69d-466c-843b-21cbd519d203) for task 1 of framework 201311181254-16842879-45888-27125-0000
I1118 12:54:18.086050 27146 slave.cpp:1745] Handling status update TASK_RUNNING (UUID: 970a7b8d-f69d-466c-843b-21cbd519d203) for task 1 of framework 201311181254-16842879-45888-27125-0000 from executor(1)@127.0.1.1:56497
I1118 12:54:18.086149 27146 status_update_manager.cpp:305] Received status update TASK_RUNNING (UUID: 970a7b8d-f69d-466c-843b-21cbd519d203) for task 1 of framework 201311181254-16842879-45888-27125-0000
I1118 12:54:18.086163 27146 status_update_manager.cpp:476] Creating StatusUpdate stream for task 1 of framework 201311181254-16842879-45888-27125-0000
I1118 12:54:18.086241 27146 status_update_manager.cpp:356] Forwarding status update TASK_RUNNING (UUID: 970a7b8d-f69d-466c-843b-21cbd519d203) for task 1 of framework 201311181254-16842879-45888-27125-0000 to master@127.0.1.1:45888
I1118 12:54:18.086377 27146 master.cpp:1418] Status update TASK_RUNNING (UUID: 970a7b8d-f69d-466c-843b-21cbd519d203) for task 1 of framework 201311181254-16842879-45888-27125-0000 from slave(52)@127.0.1.1:45888
I1118 12:54:18.086403 27146 slave.cpp:1864] Status update manager successfully handled status update TASK_RUNNING (UUID: 970a7b8d-f69d-466c-843b-21cbd519d203) for task 1 of framework 201311181254-16842879-45888-27125-0000
I1118 12:54:18.086412 27146 slave.cpp:1870] Sending acknowledgement for status update TASK_RUNNING (UUID: 970a7b8d-f69d-466c-843b-21cbd519d203) for task 1 of framework 201311181254-16842879-45888-27125-0000 to executor(1)@127.0.1.1:56497
I1118 12:54:18.086599 27146 sched.cpp:548] Scheduler::statusUpdate took 52682ns
I1118 12:54:18.086797 27148 status_update_manager.cpp:380] Received status update acknowledgement (UUID: 970a7b8d-f69d-466c-843b-21cbd519d203) for task 1 of framework 201311181254-16842879-45888-27125-0000
I1118 12:54:18.092715 27847 process.cpp:992] Socket closed while receiving
I1118 12:54:18.092843 27845 exec.cpp:335] Executor received status update acknowledgement 970a7b8d-f69d-466c-843b-21cbd519d203 for task 1 of framework 201311181254-16842879-45888-27125-0000
I1118 12:54:18.094049 27148 slave.cpp:1351] Status update manager successfully handled status update acknowledgement (UUID: 970a7b8d-f69d-466c-843b-21cbd519d203) for task 1 of framework 201311181254-16842879-45888-27125-0000
I1118 12:54:18.643317 27146 master.cpp:1097] Asked to kill task 1 of framework 201311181254-16842879-45888-27125-0000
I1118 12:54:18.643360 27146 master.cpp:1115] Telling slave 201311181254-16842879-45888-27125-0 (raring) to kill task 1 of framework 201311181254-16842879-45888-27125-0000
I1118 12:54:18.643383 27146 slave.cpp:1000] Asked to kill task 1 of framework 201311181254-16842879-45888-27125-0000
I1118 12:54:18.644222 27844 exec.cpp:309] Executor asked to kill task '1'
I1118 12:54:18.644253 27844 exec.cpp:318] Executor::killTask took 11829ns
Shutting down
Killing process tree at pid 27848
I1118 12:54:18.654855 27847 process.cpp:992] Socket closed while receiving
Killed the following process trees:
[
-+- 27848 sh -c top -b -d 0 -n 30000 2>&1 > /dev/null & touch /tmp/IsolatorTest_0_Usage_jFkdWi/ready; sleep 60
|--- 27849 top -b -d 0 -n 30000
\--- 27851 sleep 60
]
I1118 12:54:18.988940 27148 hierarchical_allocator_process.hpp:688] Performed allocation for 1 slaves in 41240ns
I1118 12:54:19.018187 27145 monitor.cpp:193] Publishing resource usage for executor '1' of framework '201311181254-16842879-45888-27125-0000'
Command terminated with signal Killed (pid: 27848)
I1118 12:54:19.077869 27846 exec.cpp:521] Executor sending status update TASK_KILLED (UUID: 3b26f8d5-a07b-49ea-b226-9e375a8a93d2) for task 1 of framework 201311181254-16842879-45888-27125-0000
I1118 12:54:19.079604 27149 process.cpp:992] Socket closed while receiving
I1118 12:54:19.681885 27678 exec.cpp:84] Committing suicide by killing the process group
I1118 12:54:19.682127 27669 exec.cpp:84] Committing suicide by killing the process group
I1118 12:54:19.682942 27674 exec.cpp:84] Committing suicide by killing the process group
I1118 12:54:19.988126 27145 process_isolator.cpp:482] Telling slave of terminated executor '1' of framework 201311181254-16842879-45888-27125-0000
I1118 12:54:19.991073 27147 slave.cpp:2134] Executor '1' of framework 201311181254-16842879-45888-27125-0000 has exited with status 0
I1118 12:54:19.991808 27147 slave.cpp:1745] Handling status update TASK_FAILED (UUID: dd6c3f6e-d337-44c7-bf11-49d1ceb3f372) for task 1 of framework 201311181254-16842879-45888-27125-0000 from @0.0.0.0:0
I1118 12:54:19.991842 27147 slave.cpp:3185] Terminating task 1
I1118 12:54:19.992017 27147 status_update_manager.cpp:305] Received status update TASK_FAILED (UUID: dd6c3f6e-d337-44c7-bf11-49d1ceb3f372) for task 1 of framework 201311181254-16842879-45888-27125-0000
I1118 12:54:19.992048 27147 status_update_manager.cpp:356] Forwarding status update TASK_FAILED (UUID: dd6c3f6e-d337-44c7-bf11-49d1ceb3f372) for task 1 of framework 201311181254-16842879-45888-27125-0000 to master@127.0.1.1:45888
I1118 12:54:19.992216 27147 master.cpp:1418] Status update TASK_FAILED (UUID: dd6c3f6e-d337-44c7-bf11-49d1ceb3f372) for task 1 of framework 201311181254-16842879-45888-27125-0000 from slave(52)@127.0.1.1:45888
I1118 12:54:19.992270 27147 master.hpp:409] Removing task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 201311181254-16842879-45888-27125-0 (raring)
I1118 12:54:19.992352 27147 slave.cpp:1864] Status update manager successfully handled status update TASK_FAILED (UUID: dd6c3f6e-d337-44c7-bf11-49d1ceb3f372) for task 1 of framework 201311181254-16842879-45888-27125-0000
I1118 12:54:19.992418 27147 sched.cpp:548] Scheduler::statusUpdate took 22524ns
I1118 12:54:19.992522 27147 hierarchical_allocator_process.hpp:637] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total allocatable: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on slave 201311181254-16842879-45888-27125-0 from framework 201311181254-16842879-45888-27125-0000
I1118 12:54:19.992633 27146 status_update_manager.cpp:380] Received status update acknowledgement (UUID: dd6c3f6e-d337-44c7-bf11-49d1ceb3f372) for task 1 of framework 201311181254-16842879-45888-27125-0000
I1118 12:54:19.992660 27146 status_update_manager.cpp:507] Cleaning up status update stream for task 1 of framework 201311181254-16842879-45888-27125-0000
tests/isolator_tests.cpp:199: Failure
Value of: status.get().state()
Actual: TASK_FAILED
Expected: TASK_KILLED
I1118 12:54:19.993759 27146 slave.cpp:1351] Status update manager successfully handled status update acknowledgement (UUID: dd6c3f6e-d337-44c7-bf11-49d1ceb3f372) for task 1 of framework 201311181254-16842879-45888-27125-0000
I1118 12:54:19.993782 27146 slave.cpp:3208] Completing task 1
I1118 12:54:19.993808 27146 slave.cpp:2269] Cleaning up executor '1' of framework 201311181254-16842879-45888-27125-0000
I1118 12:54:19.993914 27146 slave.cpp:2340] Cleaning up framework 201311181254-16842879-45888-27125-0000
I1118 12:54:19.993964 27146 gc.cpp:56] Scheduling '/tmp/IsolatorTest_0_Usage_jFkdWi/slaves/201311181254-16842879-45888-27125-0/frameworks/201311181254-16842879-45888-27125-0000/executors/1/runs/8f8cb212-55c4-40b2-96d1-668ae30d6e89' for gc 6.99998849698074days in the future
I1118 12:54:19.994006 27146 gc.cpp:56] Scheduling '/tmp/IsolatorTest_0_Usage_jFkdWi/slaves/201311181254-16842879-45888-27125-0/frameworks/201311181254-16842879-45888-27125-0000/executors/1' for gc 6.9999884965037days in the future
I1118 12:54:19.994034 27146 gc.cpp:56] Scheduling '/tmp/IsolatorTest_0_Usage_jFkdWi/slaves/201311181254-16842879-45888-27125-0/frameworks/201311181254-16842879-45888-27125-0000' for gc 6.99998849600889days in the future
I1118 12:54:19.994060 27146 status_update_manager.cpp:267] Closing status update streams for framework 201311181254-16842879-45888-27125-0000
I1118 12:54:19.994110 27125 master.cpp:566] Master terminating
I1118 12:54:19.994129 27125 master.cpp:218] Shutting down master
I1118 12:54:19.994175 27125 master.cpp:261] Removing slave 201311181254-16842879-45888-27125-0 (raring)
I1118 12:54:19.994446 27125 slave.cpp:395] Slave terminating
I1118 12:54:19.994488 27146 sched.cpp:651] Stopping framework '201311181254-16842879-45888-27125-0000'
W1118 12:54:20.005861 27145 process_isolator.cpp:268] Failed to kill the process tree rooted at pid 27811: Failed to find process 27811
[ FAILED ] IsolatorTest/0.Usage, where TypeParam = mesos::internal::slave::ProcessIsolator (2022 ms)
--
This message was sent by Atlassian JIRA
(v6.1#6144)