[
https://issues.apache.org/jira/browse/MESOS-820?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13826029#comment-13826029
]
Benjamin Mahler commented on MESOS-820:
---------------------------------------
See: https://reviews.apache.org/r/15662/
> 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
> [email protected]:45888
> I1118 12:54:17.987949 27146 sched.cpp:285] Authenticating with master
> [email protected]:45888
> I1118 12:54:17.988095 27146 hierarchical_allocator_process.hpp:302]
> Initializing hierarchical allocator process with master :
> [email protected]: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
> [email protected]: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 [email protected]: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
> [email protected]: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 [email protected]: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 [email protected]: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 [email protected]: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)
