[ https://issues.apache.org/jira/browse/MESOS-1007?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Vinod Kone resolved MESOS-1007. ------------------------------- Resolution: Cannot Reproduce Haven't seen this in a while. So closing this as "cannot reproduce". > Python framework unable to parse framework messages > --------------------------------------------------- > > Key: MESOS-1007 > URL: https://issues.apache.org/jira/browse/MESOS-1007 > Project: Mesos > Issue Type: Bug > Environment: Fedora 20. Cxx11 > Reporter: Vinod Kone > > [ RUN ] ExamplesTest.PythonFramework > Using temporary directory '/tmp/ExamplesTest_PythonFramework_bk0KRb' > WARNING: Logging before InitGoogleLogging() is written to STDERR > I0213 22:15:39.954318 17373 process.cpp:1591] libprocess is initialized on > 192.168.122.164:47130 for 8 cpus > I0213 22:15:39.955761 17373 logging.cpp:140] Logging to STDERR > I0213 22:15:39.959444 17373 master.cpp:240] Master ID: > 2014-02-13-22:15:39-2759502016-47130-17373 Hostname: fedora-20 > I0213 22:15:39.960225 17383 master.cpp:322] Master started on > 192.168.122.164:47130 > I0213 22:15:39.960244 17383 master.cpp:325] Master only allowing > authenticated frameworks to register! > I0213 22:15:39.961699 17387 master.cpp:86] No whitelist given. Advertising > offers for all slaves > I0213 22:15:39.962286 17382 hierarchical_allocator_process.hpp:302] > Initializing hierarchical allocator process with master : > master@192.168.122.164:47130 > I0213 22:15:39.963912 17373 containerizer.cpp:180] Using isolation: > posix/cpu,posix/mem > I0213 22:15:39.965071 17373 containerizer.cpp:180] Using isolation: > posix/cpu,posix/mem > I0213 22:15:39.965754 17384 slave.cpp:112] Slave started on > 1)@192.168.122.164:47130 > I0213 22:15:39.966032 17387 master.cpp:760] The newly elected leader is > master@192.168.122.164:47130 with id > 2014-02-13-22:15:39-2759502016-47130-17373 > I0213 22:15:39.966341 17387 master.cpp:770] Elected as the leading master! > I0213 22:15:39.966227 17384 slave.cpp:122] Slave resources: cpus(*):1; > mem(*):979; disk(*):1001; ports(*):[31000-32000] > I0213 22:15:39.967811 17384 slave.cpp:150] Slave hostname: fedora-20 > I0213 22:15:39.967828 17384 slave.cpp:151] Slave checkpoint: true > I0213 22:15:39.968070 17384 state.cpp:33] Recovering state from > '/tmp/mesos-KG9dIs/0/meta' > I0213 22:15:39.968147 17384 status_update_manager.cpp:188] Recovering status > update manager > I0213 22:15:39.968200 17384 mesos_containerizer.cpp:137] Recovering > containerizer > I0213 22:15:39.969071 17384 slave.cpp:2670] Finished recovery > I0213 22:15:39.969290 17384 slave.cpp:397] New master detected at > master@192.168.122.164:47130 > I0213 22:15:39.970041 17384 slave.cpp:422] Detecting new master > I0213 22:15:39.970067 17384 status_update_manager.cpp:162] New master > detected at master@192.168.122.164:47130 > I0213 22:15:39.970116 17384 master.cpp:1840] Attempting to register slave on > fedora-20 at slave(1)@192.168.122.164:47130 > I0213 22:15:39.970130 17384 master.cpp:2810] Adding slave > 2014-02-13-22:15:39-2759502016-47130-17373-0 at fedora-20 with cpus(*):1; > mem(*):979; disk(*):1001; ports(*):[31000-32000] > I0213 22:15:39.970213 17384 slave.cpp:440] Registered with master > master@192.168.122.164:47130; given slave ID > 2014-02-13-22:15:39-2759502016-47130-17373-0 > I0213 22:15:39.970365 17384 slave.cpp:453] Checkpointing SlaveInfo to > '/tmp/mesos-KG9dIs/0/meta/slaves/2014-02-13-22:15:39-2759502016-47130-17373-0/slave.info' > I0213 22:15:39.971178 17382 hierarchical_allocator_process.hpp:445] Added > slave 2014-02-13-22:15:39-2759502016-47130-17373-0 (fedora-20) with > cpus(*):1; mem(*):979; disk(*):1001; ports(*):[31000-32000] (and cpus(*):1; > mem(*):979; disk(*):1001; ports(*):[31000-32000] available) > I0213 22:15:39.971231 17382 hierarchical_allocator_process.hpp:708] Performed > allocation for slave 2014-02-13-22:15:39-2759502016-47130-17373-0 in 9023ns > I0213 22:15:39.972479 17373 containerizer.cpp:180] Using isolation: > posix/cpu,posix/mem > I0213 22:15:39.973124 17381 slave.cpp:112] Slave started on > 2)@192.168.122.164:47130 > I0213 22:15:39.973276 17381 slave.cpp:122] Slave resources: cpus(*):1; > mem(*):979; disk(*):1001; ports(*):[31000-32000] > I0213 22:15:39.974185 17381 slave.cpp:150] Slave hostname: fedora-20 > I0213 22:15:39.974202 17381 slave.cpp:151] Slave checkpoint: true > I0213 22:15:39.975014 17381 state.cpp:33] Recovering state from > '/tmp/mesos-KG9dIs/1/meta' > I0213 22:15:39.975071 17381 status_update_manager.cpp:188] Recovering status > update manager > I0213 22:15:39.975098 17381 mesos_containerizer.cpp:137] Recovering > containerizer > I0213 22:15:39.975219 17381 slave.cpp:2670] Finished recovery > I0213 22:15:39.976111 17381 slave.cpp:397] New master detected at > master@192.168.122.164:47130 > I0213 22:15:39.976758 17381 slave.cpp:422] Detecting new master > I0213 22:15:39.976796 17381 status_update_manager.cpp:162] New master > detected at master@192.168.122.164:47130 > I0213 22:15:39.976830 17381 master.cpp:1840] Attempting to register slave on > fedora-20 at slave(2)@192.168.122.164:47130 > I0213 22:15:39.976840 17381 master.cpp:2810] Adding slave > 2014-02-13-22:15:39-2759502016-47130-17373-1 at fedora-20 with cpus(*):1; > mem(*):979; disk(*):1001; ports(*):[31000-32000] > I0213 22:15:39.976904 17381 slave.cpp:440] Registered with master > master@192.168.122.164:47130; given slave ID > 2014-02-13-22:15:39-2759502016-47130-17373-1 > I0213 22:15:39.977027 17381 slave.cpp:453] Checkpointing SlaveInfo to > '/tmp/mesos-KG9dIs/1/meta/slaves/2014-02-13-22:15:39-2759502016-47130-17373-1/slave.info' > I0213 22:15:39.977148 17381 hierarchical_allocator_process.hpp:445] Added > slave 2014-02-13-22:15:39-2759502016-47130-17373-1 (fedora-20) with > cpus(*):1; mem(*):979; disk(*):1001; ports(*):[31000-32000] (and cpus(*):1; > mem(*):979; disk(*):1001; ports(*):[31000-32000] available) > I0213 22:15:39.978591 17387 slave.cpp:112] Slave started on > 3)@192.168.122.164:47130 > I0213 22:15:39.978715 17387 slave.cpp:122] Slave resources: cpus(*):1; > mem(*):979; disk(*):1001; ports(*):[31000-32000] > I0213 22:15:39.979027 17387 slave.cpp:150] Slave hostname: fedora-20 > I0213 22:15:39.979040 17387 slave.cpp:151] Slave checkpoint: true > I0213 22:15:39.979228 17387 state.cpp:33] Recovering state from > '/tmp/mesos-KG9dIs/2/meta' > I0213 22:15:39.979279 17387 status_update_manager.cpp:188] Recovering status > update manager > I0213 22:15:39.979313 17387 mesos_containerizer.cpp:137] Recovering > containerizer > I0213 22:15:39.979580 17387 slave.cpp:2670] Finished recovery > I0213 22:15:39.979766 17387 slave.cpp:397] New master detected at > master@192.168.122.164:47130 > I0213 22:15:39.979806 17387 slave.cpp:422] Detecting new master > I0213 22:15:39.979826 17387 status_update_manager.cpp:162] New master > detected at master@192.168.122.164:47130 > I0213 22:15:39.979856 17387 master.cpp:1840] Attempting to register slave on > fedora-20 at slave(3)@192.168.122.164:47130 > I0213 22:15:39.979866 17387 master.cpp:2810] Adding slave > 2014-02-13-22:15:39-2759502016-47130-17373-2 at fedora-20 with cpus(*):1; > mem(*):979; disk(*):1001; ports(*):[31000-32000] > I0213 22:15:39.979929 17387 slave.cpp:440] Registered with master > master@192.168.122.164:47130; given slave ID > 2014-02-13-22:15:39-2759502016-47130-17373-2 > I0213 22:15:39.980051 17387 slave.cpp:453] Checkpointing SlaveInfo to > '/tmp/mesos-KG9dIs/2/meta/slaves/2014-02-13-22:15:39-2759502016-47130-17373-2/slave.info' > I0213 22:15:39.977181 17381 hierarchical_allocator_process.hpp:708] Performed > allocation for slave 2014-02-13-22:15:39-2759502016-47130-17373-1 in 3790ns > I0213 22:15:39.981469 17381 hierarchical_allocator_process.hpp:445] Added > slave 2014-02-13-22:15:39-2759502016-47130-17373-2 (fedora-20) with > cpus(*):1; mem(*):979; disk(*):1001; ports(*):[31000-32000] (and cpus(*):1; > mem(*):979; disk(*):1001; ports(*):[31000-32000] available) > I0213 22:15:39.981503 17381 hierarchical_allocator_process.hpp:708] Performed > allocation for slave 2014-02-13-22:15:39-2759502016-47130-17373-2 in 4086ns > I0213 22:15:39.983192 17373 sched.cpp:121] Version: 0.19.0 > I0213 22:15:39.983958 17382 sched.cpp:217] New master detected at > master@192.168.122.164:47130 > I0213 22:15:39.983981 17382 sched.cpp:267] Authenticating with master > master@192.168.122.164:47130 > I0213 22:15:39.984061 17382 authenticatee.hpp:100] Initializing client SASL > I0213 22:15:39.986805 17382 authenticatee.hpp:124] Creating new client SASL > connection > I0213 22:15:39.988211 17385 master.cpp:2323] Authenticating framework at > scheduler(1)@192.168.122.164:47130 > I0213 22:15:39.988309 17385 authenticator.hpp:83] Initializing server SASL > I0213 22:15:39.988519 17385 auxprop.cpp:45] Initialized in-memory auxiliary > property plugin > I0213 22:15:39.988531 17385 authenticator.hpp:140] Creating new server SASL > connection > I0213 22:15:39.990200 17382 authenticatee.hpp:212] Received SASL > authentication mechanisms: CRAM-MD5 > I0213 22:15:39.990803 17382 authenticatee.hpp:238] Attempting to authenticate > with mechanism 'CRAM-MD5' > I0213 22:15:39.991400 17385 authenticator.hpp:243] Received SASL > authentication start > I0213 22:15:39.991436 17385 authenticator.hpp:325] Authentication requires > more steps > I0213 22:15:39.992053 17382 authenticatee.hpp:258] Received SASL > authentication step > I0213 22:15:39.992799 17386 authenticator.hpp:271] Received SASL > authentication step > I0213 22:15:39.992828 17386 auxprop.cpp:81] Request to lookup properties for > user: 'test-principal' realm: 'fedora-20' server FQDN: 'fedora-20' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: false > I0213 22:15:39.992836 17386 auxprop.cpp:153] Looking up auxiliary property > '*userPassword' > I0213 22:15:39.992846 17386 auxprop.cpp:153] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > I0213 22:15:39.992856 17386 auxprop.cpp:81] Request to lookup properties for > user: 'test-principal' realm: 'fedora-20' server FQDN: 'fedora-20' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: true > I0213 22:15:39.992862 17386 auxprop.cpp:103] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > I0213 22:15:39.992866 17386 auxprop.cpp:103] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > I0213 22:15:39.992877 17386 authenticator.hpp:317] Authentication success > I0213 22:15:39.992966 17386 master.cpp:2363] Successfully authenticated > framework at scheduler(1)@192.168.122.164:47130 > I0213 22:15:39.999557 17382 authenticatee.hpp:298] Authentication success > I0213 22:15:40.000488 17382 sched.cpp:341] Successfully authenticated with > master master@192.168.122.164:47130 > I0213 22:15:40.000509 17382 sched.cpp:460] Sending registration request to > master@192.168.122.164:47130 > I0213 22:15:40.001138 17386 master.cpp:818] Received registration request > from scheduler(1)@192.168.122.164:47130 > I0213 22:15:40.001785 17386 master.cpp:836] Registering framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 at > scheduler(1)@192.168.122.164:47130 > I0213 22:15:40.002450 17387 sched.cpp:391] Framework registered with > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:40.002812 17387 sched.cpp:405] Scheduler::registered took 342468ns > I0213 22:15:40.003443 17384 hierarchical_allocator_process.hpp:332] Added > framework 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:40.003486 17384 hierarchical_allocator_process.hpp:752] Offering > cpus(*):1; mem(*):979; disk(*):1001; ports(*):[31000-32000] on slave > 2014-02-13-22:15:39-2759502016-47130-17373-0 to framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:40.003568 17384 hierarchical_allocator_process.hpp:752] Offering > cpus(*):1; mem(*):979; disk(*):1001; ports(*):[31000-32000] on slave > 2014-02-13-22:15:39-2759502016-47130-17373-1 to framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:40.003624 17384 hierarchical_allocator_process.hpp:752] Offering > cpus(*):1; mem(*):979; disk(*):1001; ports(*):[31000-32000] on slave > 2014-02-13-22:15:39-2759502016-47130-17373-2 to framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:40.003711 17384 hierarchical_allocator_process.hpp:688] Performed > allocation for 3 slaves in 250585ns > I0213 22:15:40.003845 17386 master.hpp:439] Adding offer > 2014-02-13-22:15:39-2759502016-47130-17373-0 with resources cpus(*):1; > mem(*):979; disk(*):1001; ports(*):[31000-32000] on slave > 2014-02-13-22:15:39-2759502016-47130-17373-2 (fedora-20) > I0213 22:15:40.003919 17386 master.hpp:439] Adding offer > 2014-02-13-22:15:39-2759502016-47130-17373-1 with resources cpus(*):1; > mem(*):979; disk(*):1001; ports(*):[31000-32000] on slave > 2014-02-13-22:15:39-2759502016-47130-17373-1 (fedora-20) > I0213 22:15:40.003979 17386 master.hpp:439] Adding offer > 2014-02-13-22:15:39-2759502016-47130-17373-2 with resources cpus(*):1; > mem(*):979; disk(*):1001; ports(*):[31000-32000] on slave > 2014-02-13-22:15:39-2759502016-47130-17373-0 (fedora-20) > I0213 22:15:40.004010 17386 master.cpp:2278] Sending 3 offers to framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:40.008587 17385 sched.cpp:528] Scheduler::resourceOffers took > 4.435927ms > I0213 22:15:40.009693 17382 master.hpp:449] Removing offer > 2014-02-13-22:15:39-2759502016-47130-17373-0 with resources cpus(*):1; > mem(*):979; disk(*):1001; ports(*):[31000-32000] on slave > 2014-02-13-22:15:39-2759502016-47130-17373-2 (fedora-20) > I0213 22:15:40.009745 17382 master.cpp:1574] Processing reply for offers: [ > 2014-02-13-22:15:39-2759502016-47130-17373-0 ] on slave > 2014-02-13-22:15:39-2759502016-47130-17373-2 (fedora-20) for framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:40.009810 17382 master.hpp:411] Adding task 0 with resources > cpus(*):1; mem(*):32 on slave 2014-02-13-22:15:39-2759502016-47130-17373-2 > (fedora-20) > I0213 22:15:40.009838 17382 master.cpp:2447] Launching task 0 of framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 with resources cpus(*):1; > mem(*):32 on slave 2014-02-13-22:15:39-2759502016-47130-17373-2 (fedora-20) > I0213 22:15:40.009943 17382 slave.cpp:625] Got assigned task 0 for framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:40.010087 17382 slave.cpp:734] Launching task 0 for framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:40.010593 17387 hierarchical_allocator_process.hpp:547] Framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 left mem(*):947; > disk(*):1001; ports(*):[31000-32000] unused on slave > 2014-02-13-22:15:39-2759502016-47130-17373-2 > I0213 22:15:40.010656 17387 hierarchical_allocator_process.hpp:590] Framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 filtered slave > 2014-02-13-22:15:39-2759502016-47130-17373-2 for 5secs > I0213 22:15:40.012295 17380 mesos_containerizer.cpp:363] Starting container > '5c917cb7-a0f7-46db-a8ce-d0213552cde8' for executor 'default' of framework > '2014-02-13-22:15:39-2759502016-47130-17373-0000' > I0213 22:15:40.012648 17380 mesos_containerizer.cpp:504] Fetching URIs for > container '5c917cb7-a0f7-46db-a8ce-d0213552cde8' using command '/usr/bin/env > MESOS_EXECUTOR_URIS= > MESOS_WORK_DIRECTORY=/tmp/mesos-KG9dIs/2/slaves/2014-02-13-22:15:39-2759502016-47130-17373-2/frameworks/2014-02-13-22:15:39-2759502016-47130-17373-0000/executors/default/runs/5c917cb7-a0f7-46db-a8ce-d0213552cde8 > MESOS_USER=jenkins MESOS_FRAMEWORKS_HOME= HADOOP_HOME= > /var/jenkins/workspace/mesos-fedora-20-gcc-cxx11/src/mesos-fetcher' > I0213 22:15:40.016403 17382 slave.cpp:844] Queuing task '0' for executor > default of framework '2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:40.017197 17382 slave.cpp:358] Successfully attached file > '/tmp/mesos-KG9dIs/2/slaves/2014-02-13-22:15:39-2759502016-47130-17373-2/frameworks/2014-02-13-22:15:39-2759502016-47130-17373-0000/executors/default/runs/5c917cb7-a0f7-46db-a8ce-d0213552cde8' > I0213 22:15:40.019753 17381 master.hpp:449] Removing offer > 2014-02-13-22:15:39-2759502016-47130-17373-1 with resources cpus(*):1; > mem(*):979; disk(*):1001; ports(*):[31000-32000] on slave > 2014-02-13-22:15:39-2759502016-47130-17373-1 (fedora-20) > I0213 22:15:40.019851 17381 master.cpp:1574] Processing reply for offers: [ > 2014-02-13-22:15:39-2759502016-47130-17373-1 ] on slave > 2014-02-13-22:15:39-2759502016-47130-17373-1 (fedora-20) for framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:40.019920 17381 master.hpp:411] Adding task 1 with resources > cpus(*):1; mem(*):32 on slave 2014-02-13-22:15:39-2759502016-47130-17373-1 > (fedora-20) > I0213 22:15:40.019942 17381 master.cpp:2447] Launching task 1 of framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 with resources cpus(*):1; > mem(*):32 on slave 2014-02-13-22:15:39-2759502016-47130-17373-1 (fedora-20) > I0213 22:15:40.020867 17384 slave.cpp:625] Got assigned task 1 for framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:40.021042 17384 slave.cpp:734] Launching task 1 for framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:40.022826 17381 hierarchical_allocator_process.hpp:547] Framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 left mem(*):947; > disk(*):1001; ports(*):[31000-32000] unused on slave > 2014-02-13-22:15:39-2759502016-47130-17373-1 > I0213 22:15:40.022894 17381 hierarchical_allocator_process.hpp:590] Framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 filtered slave > 2014-02-13-22:15:39-2759502016-47130-17373-1 for 5secs > I0213 22:15:40.023960 17384 slave.cpp:844] Queuing task '1' for executor > default of framework '2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:40.024056 17384 mesos_containerizer.cpp:363] Starting container > '61fd0991-dfe6-43f3-aebf-c3582897a5c3' for executor 'default' of framework > '2014-02-13-22:15:39-2759502016-47130-17373-0000' > I0213 22:15:40.024253 17384 slave.cpp:358] Successfully attached file > '/tmp/mesos-KG9dIs/1/slaves/2014-02-13-22:15:39-2759502016-47130-17373-1/frameworks/2014-02-13-22:15:39-2759502016-47130-17373-0000/executors/default/runs/61fd0991-dfe6-43f3-aebf-c3582897a5c3' > I0213 22:15:40.024360 17384 mesos_containerizer.cpp:504] Fetching URIs for > container '61fd0991-dfe6-43f3-aebf-c3582897a5c3' using command '/usr/bin/env > MESOS_EXECUTOR_URIS= > MESOS_WORK_DIRECTORY=/tmp/mesos-KG9dIs/1/slaves/2014-02-13-22:15:39-2759502016-47130-17373-1/frameworks/2014-02-13-22:15:39-2759502016-47130-17373-0000/executors/default/runs/61fd0991-dfe6-43f3-aebf-c3582897a5c3 > MESOS_USER=jenkins MESOS_FRAMEWORKS_HOME= HADOOP_HOME= > /var/jenkins/workspace/mesos-fedora-20-gcc-cxx11/src/mesos-fetcher' > I0213 22:15:40.026907 17382 master.hpp:449] Removing offer > 2014-02-13-22:15:39-2759502016-47130-17373-2 with resources cpus(*):1; > mem(*):979; disk(*):1001; ports(*):[31000-32000] on slave > 2014-02-13-22:15:39-2759502016-47130-17373-0 (fedora-20) > I0213 22:15:40.026996 17382 master.cpp:1574] Processing reply for offers: [ > 2014-02-13-22:15:39-2759502016-47130-17373-2 ] on slave > 2014-02-13-22:15:39-2759502016-47130-17373-0 (fedora-20) for framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:40.027055 17382 master.hpp:411] Adding task 2 with resources > cpus(*):1; mem(*):32 on slave 2014-02-13-22:15:39-2759502016-47130-17373-0 > (fedora-20) > I0213 22:15:40.027076 17382 master.cpp:2447] Launching task 2 of framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 with resources cpus(*):1; > mem(*):32 on slave 2014-02-13-22:15:39-2759502016-47130-17373-0 (fedora-20) > I0213 22:15:40.027211 17382 slave.cpp:625] Got assigned task 2 for framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:40.027346 17382 slave.cpp:734] Launching task 2 for framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:40.028373 17387 hierarchical_allocator_process.hpp:547] Framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 left mem(*):947; > disk(*):1001; ports(*):[31000-32000] unused on slave > 2014-02-13-22:15:39-2759502016-47130-17373-0 > I0213 22:15:40.028476 17387 hierarchical_allocator_process.hpp:590] Framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 filtered slave > 2014-02-13-22:15:39-2759502016-47130-17373-0 for 5secs > I0213 22:15:40.031975 17382 slave.cpp:844] Queuing task '2' for executor > default of framework '2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:40.033087 17382 slave.cpp:358] Successfully attached file > '/tmp/mesos-KG9dIs/0/slaves/2014-02-13-22:15:39-2759502016-47130-17373-0/frameworks/2014-02-13-22:15:39-2759502016-47130-17373-0000/executors/default/runs/920c402a-d794-415d-b140-14c48e5185df' > I0213 22:15:40.032888 17385 mesos_containerizer.cpp:363] Starting container > '920c402a-d794-415d-b140-14c48e5185df' for executor 'default' of framework > '2014-02-13-22:15:39-2759502016-47130-17373-0000' > I0213 22:15:40.034847 17385 mesos_containerizer.cpp:504] Fetching URIs for > container '920c402a-d794-415d-b140-14c48e5185df' using command '/usr/bin/env > MESOS_EXECUTOR_URIS= > MESOS_WORK_DIRECTORY=/tmp/mesos-KG9dIs/0/slaves/2014-02-13-22:15:39-2759502016-47130-17373-0/frameworks/2014-02-13-22:15:39-2759502016-47130-17373-0000/executors/default/runs/920c402a-d794-415d-b140-14c48e5185df > MESOS_USER=jenkins MESOS_FRAMEWORKS_HOME= HADOOP_HOME= > /var/jenkins/workspace/mesos-fedora-20-gcc-cxx11/src/mesos-fetcher' > I0213 22:15:40.963394 17387 hierarchical_allocator_process.hpp:835] Filtered > mem(*):947; disk(*):1001; ports(*):[31000-32000] on slave > 2014-02-13-22:15:39-2759502016-47130-17373-0 for framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:40.963486 17387 hierarchical_allocator_process.hpp:835] Filtered > mem(*):947; disk(*):1001; ports(*):[31000-32000] on slave > 2014-02-13-22:15:39-2759502016-47130-17373-1 for framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:40.963523 17387 hierarchical_allocator_process.hpp:835] Filtered > mem(*):947; disk(*):1001; ports(*):[31000-32000] on slave > 2014-02-13-22:15:39-2759502016-47130-17373-2 for framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:40.963564 17387 hierarchical_allocator_process.hpp:688] Performed > allocation for 3 slaves in 246441ns > I0213 22:15:41.018864 17383 launcher.cpp:120] Forked child with pid '17439' > for container '920c402a-d794-415d-b140-14c48e5185df' > I0213 22:15:41.020393 17386 launcher.cpp:120] Forked child with pid '17440' > for container '61fd0991-dfe6-43f3-aebf-c3582897a5c3' > I0213 22:15:41.021778 17386 slave.cpp:1989] Monitoring executor 'default' of > framework '2014-02-13-22:15:39-2759502016-47130-17373-0000' in container > '61fd0991-dfe6-43f3-aebf-c3582897a5c3' > I0213 22:15:41.022833 17383 slave.cpp:1989] Monitoring executor 'default' of > framework '2014-02-13-22:15:39-2759502016-47130-17373-0000' in container > '920c402a-d794-415d-b140-14c48e5185df' > I0213 22:15:41.023444 17387 launcher.cpp:120] Forked child with pid '17438' > for container '5c917cb7-a0f7-46db-a8ce-d0213552cde8' > I0213 22:15:41.025220 17387 slave.cpp:1989] Monitoring executor 'default' of > framework '2014-02-13-22:15:39-2759502016-47130-17373-0000' in container > '5c917cb7-a0f7-46db-a8ce-d0213552cde8' > I0213 22:15:41.963726 17387 hierarchical_allocator_process.hpp:835] Filtered > mem(*):947; disk(*):1001; ports(*):[31000-32000] on slave > 2014-02-13-22:15:39-2759502016-47130-17373-0 for framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:41.963807 17387 hierarchical_allocator_process.hpp:835] Filtered > mem(*):947; disk(*):1001; ports(*):[31000-32000] on slave > 2014-02-13-22:15:39-2759502016-47130-17373-1 for framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:41.963841 17387 hierarchical_allocator_process.hpp:835] Filtered > mem(*):947; disk(*):1001; ports(*):[31000-32000] on slave > 2014-02-13-22:15:39-2759502016-47130-17373-2 for framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:41.963857 17387 hierarchical_allocator_process.hpp:688] Performed > allocation for 3 slaves in 208844ns > I0213 22:15:42.022104 17387 monitor.cpp:140] Failed to collect resource usage > for container '61fd0991-dfe6-43f3-aebf-c3582897a5c3' for executor 'default' > of framework '2014-02-13-22:15:39-2759502016-47130-17373-0000': Unknown > container: 61fd0991-dfe6-43f3-aebf-c3582897a5c3 > I0213 22:15:42.028655 17384 monitor.cpp:140] Failed to collect resource usage > for container '5c917cb7-a0f7-46db-a8ce-d0213552cde8' for executor 'default' > of framework '2014-02-13-22:15:39-2759502016-47130-17373-0000': Unknown > container: 5c917cb7-a0f7-46db-a8ce-d0213552cde8 > I0213 22:15:42.565881 17314 exec.cpp:85] Committing suicide by killing the > process group > I0213 22:15:42.566293 17330 exec.cpp:85] Committing suicide by killing the > process group > I0213 22:15:42.569000 17320 exec.cpp:85] Committing suicide by killing the > process group > I0213 22:15:42.964812 17386 hierarchical_allocator_process.hpp:835] Filtered > mem(*):947; disk(*):1001; ports(*):[31000-32000] on slave > 2014-02-13-22:15:39-2759502016-47130-17373-0 for framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:42.964902 17386 hierarchical_allocator_process.hpp:835] Filtered > mem(*):947; disk(*):1001; ports(*):[31000-32000] on slave > 2014-02-13-22:15:39-2759502016-47130-17373-1 for framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:42.964932 17386 hierarchical_allocator_process.hpp:835] Filtered > mem(*):947; disk(*):1001; ports(*):[31000-32000] on slave > 2014-02-13-22:15:39-2759502016-47130-17373-2 for framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:42.964964 17386 hierarchical_allocator_process.hpp:688] Performed > allocation for 3 slaves in 210746ns > I0213 22:15:43.023181 17386 monitor.cpp:140] Failed to collect resource usage > for container '61fd0991-dfe6-43f3-aebf-c3582897a5c3' for executor 'default' > of framework '2014-02-13-22:15:39-2759502016-47130-17373-0000': Unknown > container: 61fd0991-dfe6-43f3-aebf-c3582897a5c3 > I0213 22:15:43.029309 17386 monitor.cpp:140] Failed to collect resource usage > for container '5c917cb7-a0f7-46db-a8ce-d0213552cde8' for executor 'default' > of framework '2014-02-13-22:15:39-2759502016-47130-17373-0000': Unknown > container: 5c917cb7-a0f7-46db-a8ce-d0213552cde8 > I0213 22:15:43.965808 17384 hierarchical_allocator_process.hpp:835] Filtered > mem(*):947; disk(*):1001; ports(*):[31000-32000] on slave > 2014-02-13-22:15:39-2759502016-47130-17373-0 for framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:43.965888 17384 hierarchical_allocator_process.hpp:835] Filtered > mem(*):947; disk(*):1001; ports(*):[31000-32000] on slave > 2014-02-13-22:15:39-2759502016-47130-17373-1 for framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:43.965917 17384 hierarchical_allocator_process.hpp:835] Filtered > mem(*):947; disk(*):1001; ports(*):[31000-32000] on slave > 2014-02-13-22:15:39-2759502016-47130-17373-2 for framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:43.965934 17384 hierarchical_allocator_process.hpp:688] Performed > allocation for 3 slaves in 206572ns > I0213 22:15:44.024154 17384 monitor.cpp:140] Failed to collect resource usage > for container '61fd0991-dfe6-43f3-aebf-c3582897a5c3' for executor 'default' > of framework '2014-02-13-22:15:39-2759502016-47130-17373-0000': Unknown > container: 61fd0991-dfe6-43f3-aebf-c3582897a5c3 > I0213 22:15:44.030320 17385 monitor.cpp:140] Failed to collect resource usage > for container '5c917cb7-a0f7-46db-a8ce-d0213552cde8' for executor 'default' > of framework '2014-02-13-22:15:39-2759502016-47130-17373-0000': Unknown > container: 5c917cb7-a0f7-46db-a8ce-d0213552cde8 > I0213 22:15:44.962515 17383 master.cpp:86] No whitelist given. Advertising > offers for all slaves > I0213 22:15:44.966637 17383 hierarchical_allocator_process.hpp:835] Filtered > mem(*):947; disk(*):1001; ports(*):[31000-32000] on slave > 2014-02-13-22:15:39-2759502016-47130-17373-0 for framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:44.966691 17383 hierarchical_allocator_process.hpp:835] Filtered > mem(*):947; disk(*):1001; ports(*):[31000-32000] on slave > 2014-02-13-22:15:39-2759502016-47130-17373-1 for framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:44.966718 17383 hierarchical_allocator_process.hpp:835] Filtered > mem(*):947; disk(*):1001; ports(*):[31000-32000] on slave > 2014-02-13-22:15:39-2759502016-47130-17373-2 for framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:44.966734 17383 hierarchical_allocator_process.hpp:688] Performed > allocation for 3 slaves in 148762ns > I0213 22:15:45.024610 17383 monitor.cpp:140] Failed to collect resource usage > for container '61fd0991-dfe6-43f3-aebf-c3582897a5c3' for executor 'default' > of framework '2014-02-13-22:15:39-2759502016-47130-17373-0000': Unknown > container: 61fd0991-dfe6-43f3-aebf-c3582897a5c3 > I0213 22:15:45.030858 17383 monitor.cpp:140] Failed to collect resource usage > for container '5c917cb7-a0f7-46db-a8ce-d0213552cde8' for executor 'default' > of framework '2014-02-13-22:15:39-2759502016-47130-17373-0000': Unknown > container: 5c917cb7-a0f7-46db-a8ce-d0213552cde8 > WARNING: Logging before InitGoogleLogging() is written to STDERR > I0213 22:15:45.436172 17438 process.cpp:1591] libprocess is initialized on > 192.168.122.164:47089 for 8 cpus > I0213 22:15:45.437582 17438 exec.cpp:131] Version: 0.19.0 > I0213 22:15:45.439138 17449 exec.cpp:181] Executor started at: > executor(1)@192.168.122.164:47089 with pid 17438 > I0213 22:15:45.440340 17385 slave.cpp:1316] Got registration for executor > 'default' of framework 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:45.440734 17385 slave.cpp:1434] Flushing queued task 0 for > executor 'default' of framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:45.441625 17448 exec.cpp:205] Executor registered on slave > 2014-02-13-22:15:39-2759502016-47130-17373-2 > I0213 22:15:45.443183 17448 exec.cpp:217] Executor::registered took 555300ns > I0213 22:15:45.443704 17449 exec.cpp:292] Executor asked to run task '0' > I0213 22:15:45.444715 17452 process.cpp:1010] Socket closed while receiving > I0213 22:15:45.445168 17449 exec.cpp:301] Executor::launchTask took 1.091928ms > Starting executor > Running task 0 > I0213 22:15:45.447093 17451 exec.cpp:524] Executor sending status update > TASK_RUNNING (UUID: 5d7e0bbe-2bca-46f6-99b9-789d0cc656a3) for task 0 of > framework 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:45.447760 17385 slave.cpp:1643] Handling status update > TASK_RUNNING (UUID: 5d7e0bbe-2bca-46f6-99b9-789d0cc656a3) for task 0 of > framework 2014-02-13-22:15:39-2759502016-47130-17373-0000 from > executor(1)@192.168.122.164:47089 > I0213 22:15:45.447860 17385 status_update_manager.cpp:315] Received status > update TASK_RUNNING (UUID: 5d7e0bbe-2bca-46f6-99b9-789d0cc656a3) for task 0 > of framework 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:45.447873 17385 status_update_manager.cpp:494] Creating > StatusUpdate stream for task 0 of framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:45.447940 17385 status_update_manager.cpp:368] Forwarding status > update TASK_RUNNING (UUID: 5d7e0bbe-2bca-46f6-99b9-789d0cc656a3) for task 0 > of framework 2014-02-13-22:15:39-2759502016-47130-17373-0000 to > master@192.168.122.164:47130 > I0213 22:15:45.448047 17385 master.cpp:2026] Status update TASK_RUNNING > (UUID: 5d7e0bbe-2bca-46f6-99b9-789d0cc656a3) for task 0 of framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 from > slave(3)@192.168.122.164:47130 > I0213 22:15:45.448071 17385 slave.cpp:1763] Status update manager > successfully handled status update TASK_RUNNING (UUID: > 5d7e0bbe-2bca-46f6-99b9-789d0cc656a3) for task 0 of framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:45.448079 17385 slave.cpp:1769] Sending acknowledgement for > status update TASK_RUNNING (UUID: 5d7e0bbe-2bca-46f6-99b9-789d0cc656a3) for > task 0 of framework 2014-02-13-22:15:39-2759502016-47130-17373-0000 to > executor(1)@192.168.122.164:47089 > I0213 22:15:45.449355 17385 sched.cpp:619] Scheduler::statusUpdate took > 1.069957ms > I0213 22:15:45.450139 17381 status_update_manager.cpp:393] Received status > update acknowledgement (UUID: 5d7e0bbe-2bca-46f6-99b9-789d0cc656a3) for task > 0 of framework 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:45.450202 17381 slave.cpp:1256] Status update manager > successfully handled status update acknowledgement (UUID: > 5d7e0bbe-2bca-46f6-99b9-789d0cc656a3) for task 0 of framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:45.450896 17452 process.cpp:1010] Socket closed while receiving > I0213 22:15:45.451138 17445 exec.cpp:338] Executor received status update > acknowledgement 5d7e0bbe-2bca-46f6-99b9-789d0cc656a3 for task 0 of framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > Sending status update... > I0213 22:15:45.452801 17450 exec.cpp:524] Executor sending status update > TASK_FINISHED (UUID: 844af297-36ca-4354-844c-f6a0205bfbc4) for task 0 of > framework 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:45.453207 17381 slave.cpp:1643] Handling status update > TASK_FINISHED (UUID: 844af297-36ca-4354-844c-f6a0205bfbc4) for task 0 of > framework 2014-02-13-22:15:39-2759502016-47130-17373-0000 from > executor(1)@192.168.122.164:47089 > I0213 22:15:45.453235 17381 slave.cpp:3142] Terminating task 0 > I0213 22:15:45.453320 17381 status_update_manager.cpp:315] Received status > update TASK_FINISHED (UUID: 844af297-36ca-4354-844c-f6a0205bfbc4) for task 0 > of framework 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:45.453341 17381 status_update_manager.cpp:368] Forwarding status > update TASK_FINISHED (UUID: 844af297-36ca-4354-844c-f6a0205bfbc4) for task 0 > of framework 2014-02-13-22:15:39-2759502016-47130-17373-0000 to > master@192.168.122.164:47130 > I0213 22:15:45.453455 17381 master.cpp:2026] Status update TASK_FINISHED > (UUID: 844af297-36ca-4354-844c-f6a0205bfbc4) for task 0 of framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 from > slave(3)@192.168.122.164:47130 > I0213 22:15:45.453496 17381 master.hpp:429] Removing task 0 with resources > cpus(*):1; mem(*):32 on slave 2014-02-13-22:15:39-2759502016-47130-17373-2 > (fedora-20) > I0213 22:15:45.453630 17381 slave.cpp:1763] Status update manager > successfully handled status update TASK_FINISHED (UUID: > 844af297-36ca-4354-844c-f6a0205bfbc4) for task 0 of framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:45.453646 17381 slave.cpp:1769] Sending acknowledgement for > status update TASK_FINISHED (UUID: 844af297-36ca-4354-844c-f6a0205bfbc4) for > task 0 of framework 2014-02-13-22:15:39-2759502016-47130-17373-0000 to > executor(1)@192.168.122.164:47089 > I0213 22:15:45.454188 17381 sched.cpp:619] Scheduler::statusUpdate took > 327761ns > I0213 22:15:45.454274 17381 hierarchical_allocator_process.hpp:637] Recovered > cpus(*):1; mem(*):32 (total allocatable: mem(*):979; disk(*):1001; > ports(*):[31000-32000]; cpus(*):1) on slave > 2014-02-13-22:15:39-2759502016-47130-17373-2 from framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:45.454340 17381 status_update_manager.cpp:393] Received status > update acknowledgement (UUID: 844af297-36ca-4354-844c-f6a0205bfbc4) for task > 0 of framework 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:45.454361 17381 status_update_manager.cpp:525] Cleaning up status > update stream for task 0 of framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:45.454395 17381 slave.cpp:1256] Status update manager > successfully handled status update acknowledgement (UUID: > 844af297-36ca-4354-844c-f6a0205bfbc4) for task 0 of framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:45.454406 17381 slave.cpp:3165] Completing task 0 > I0213 22:15:45.454776 17452 process.cpp:1010] Socket closed while receiving > I0213 22:15:45.454874 17447 exec.cpp:338] Executor received status update > acknowledgement 844af297-36ca-4354-844c-f6a0205bfbc4 for task 0 of framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:45.454907 17447 exec.cpp:359] Executor received framework message > I0213 22:15:45.454982 17447 exec.cpp:368] Executor::frameworkMessage took > 65255ns > Sent status update > I0213 22:15:45.455256 17381 slave.cpp:1822] Sending message for framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 to > scheduler(1)@192.168.122.164:47130 > I0213 22:15:45.455405 17381 sched.cpp:704] Scheduler::frameworkMessage took > 106466ns > Traceback (most recent call last): > File > "/var/jenkins/workspace/mesos-fedora-20-gcc-cxx11/src/examples/python/test_executor.py", > line 23, in <module> > import mesos > File "build/bdist.linux-x86_64/egg/mesos.py", line 26, in <module> > File "build/bdist.linux-x86_64/egg/_mesos.py", line 7, in <module> > File "build/bdist.linux-x86_64/egg/_mesos.py", line 6, in __bootstrap__ > ImportError: > /home/jenkins/.python-eggs/mesos-0.19.0-py2.7-linux-x86_64.egg-tmp/_mesos.so: > ELF load command past end of file > I0213 22:15:45.967828 17387 hierarchical_allocator_process.hpp:752] Offering > mem(*):979; disk(*):1001; ports(*):[31000-32000]; cpus(*):1 on slave > 2014-02-13-22:15:39-2759502016-47130-17373-2 to framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:45.967947 17387 hierarchical_allocator_process.hpp:688] Performed > allocation for 3 slaves in 238715ns > I0213 22:15:45.968009 17387 master.hpp:439] Adding offer > 2014-02-13-22:15:39-2759502016-47130-17373-3 with resources mem(*):979; > disk(*):1001; ports(*):[31000-32000]; cpus(*):1 on slave > 2014-02-13-22:15:39-2759502016-47130-17373-2 (fedora-20) > I0213 22:15:45.968050 17387 master.cpp:2278] Sending 1 offers to framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:45.969501 17387 sched.cpp:528] Scheduler::resourceOffers took > 1.366302ms > I0213 22:15:45.969679 17387 master.hpp:449] Removing offer > 2014-02-13-22:15:39-2759502016-47130-17373-3 with resources mem(*):979; > disk(*):1001; ports(*):[31000-32000]; cpus(*):1 on slave > 2014-02-13-22:15:39-2759502016-47130-17373-2 (fedora-20) > I0213 22:15:45.969725 17387 master.cpp:1574] Processing reply for offers: [ > 2014-02-13-22:15:39-2759502016-47130-17373-3 ] on slave > 2014-02-13-22:15:39-2759502016-47130-17373-2 (fedora-20) for framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:45.969782 17387 master.hpp:411] Adding task 3 with resources > cpus(*):1; mem(*):32 on slave 2014-02-13-22:15:39-2759502016-47130-17373-2 > (fedora-20) > I0213 22:15:45.969805 17387 master.cpp:2447] Launching task 3 of framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 with resources cpus(*):1; > mem(*):32 on slave 2014-02-13-22:15:39-2759502016-47130-17373-2 (fedora-20) > I0213 22:15:45.969898 17387 slave.cpp:625] Got assigned task 3 for framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:45.969964 17387 slave.cpp:734] Launching task 3 for framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:45.970001 17387 slave.cpp:866] Sending task '3' to executor > 'default' of framework 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:45.971524 17448 exec.cpp:292] Executor asked to run task '3' > I0213 22:15:45.972405 17448 exec.cpp:301] Executor::launchTask took 825129ns > Running task 3 > I0213 22:15:45.973731 17446 exec.cpp:524] Executor sending status update > TASK_RUNNING (UUID: 79775756-776f-4265-a66b-0dcda4e0f0ff) for task 3 of > framework 2014-02-13-22:15:39-2759502016-47130-17373-0000 > Sending status update... > I0213 22:15:45.978966 17451 exec.cpp:524] Executor sending status update > TASK_FINISHED (UUID: c0c48bf6-8f81-4ef4-93c8-810097c57d1a) for task 3 of > framework 2014-02-13-22:15:39-2759502016-47130-17373-0000 > Sent status update > I0213 22:15:45.980880 17452 process.cpp:1010] Socket closed while receiving > I0213 22:15:45.982945 17387 slave.cpp:1643] Handling status update > TASK_RUNNING (UUID: 79775756-776f-4265-a66b-0dcda4e0f0ff) for task 3 of > framework 2014-02-13-22:15:39-2759502016-47130-17373-0000 from > executor(1)@192.168.122.164:47089 > I0213 22:15:45.983031 17387 slave.cpp:1643] Handling status update > TASK_FINISHED (UUID: c0c48bf6-8f81-4ef4-93c8-810097c57d1a) for task 3 of > framework 2014-02-13-22:15:39-2759502016-47130-17373-0000 from > executor(1)@192.168.122.164:47089 > I0213 22:15:45.983047 17387 slave.cpp:3142] Terminating task 3 > I0213 22:15:45.983105 17387 hierarchical_allocator_process.hpp:547] Framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 left mem(*):947; > disk(*):1001; ports(*):[31000-32000] unused on slave > 2014-02-13-22:15:39-2759502016-47130-17373-2 > I0213 22:15:45.983171 17387 hierarchical_allocator_process.hpp:590] Framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 filtered slave > 2014-02-13-22:15:39-2759502016-47130-17373-2 for 5secs > I0213 22:15:45.985877 17382 status_update_manager.cpp:315] Received status > update TASK_RUNNING (UUID: 79775756-776f-4265-a66b-0dcda4e0f0ff) for task 3 > of framework 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:45.985905 17382 status_update_manager.cpp:494] Creating > StatusUpdate stream for task 3 of framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:45.987220 17382 status_update_manager.cpp:368] Forwarding status > update TASK_RUNNING (UUID: 79775756-776f-4265-a66b-0dcda4e0f0ff) for task 3 > of framework 2014-02-13-22:15:39-2759502016-47130-17373-0000 to > master@192.168.122.164:47130 > I0213 22:15:45.987316 17382 status_update_manager.cpp:315] Received status > update TASK_FINISHED (UUID: c0c48bf6-8f81-4ef4-93c8-810097c57d1a) for task 3 > of framework 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:45.987392 17382 master.cpp:2026] Status update TASK_RUNNING > (UUID: 79775756-776f-4265-a66b-0dcda4e0f0ff) for task 3 of framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 from > slave(3)@192.168.122.164:47130 > I0213 22:15:45.987414 17382 slave.cpp:1763] Status update manager > successfully handled status update TASK_RUNNING (UUID: > 79775756-776f-4265-a66b-0dcda4e0f0ff) for task 3 of framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:45.987422 17382 slave.cpp:1769] Sending acknowledgement for > status update TASK_RUNNING (UUID: 79775756-776f-4265-a66b-0dcda4e0f0ff) for > task 3 of framework 2014-02-13-22:15:39-2759502016-47130-17373-0000 to > executor(1)@192.168.122.164:47089 > I0213 22:15:45.989044 17387 sched.cpp:619] Scheduler::statusUpdate took > 176389ns > I0213 22:15:45.991576 17444 exec.cpp:338] Executor received status update > acknowledgement 79775756-776f-4265-a66b-0dcda4e0f0ff for task 3 of framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:45.993021 17452 process.cpp:1010] Socket closed while receiving > I0213 22:15:45.993955 17382 slave.cpp:1763] Status update manager > successfully handled status update TASK_FINISHED (UUID: > c0c48bf6-8f81-4ef4-93c8-810097c57d1a) for task 3 of framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:45.993996 17382 slave.cpp:1769] Sending acknowledgement for > status update TASK_FINISHED (UUID: c0c48bf6-8f81-4ef4-93c8-810097c57d1a) for > task 3 of framework 2014-02-13-22:15:39-2759502016-47130-17373-0000 to > executor(1)@192.168.122.164:47089 > I0213 22:15:45.995705 17444 exec.cpp:338] Executor received status update > acknowledgement c0c48bf6-8f81-4ef4-93c8-810097c57d1a for task 3 of framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:45.996507 17452 process.cpp:1010] Socket closed while receiving > I0213 22:15:45.997968 17386 status_update_manager.cpp:393] Received status > update acknowledgement (UUID: 79775756-776f-4265-a66b-0dcda4e0f0ff) for task > 3 of framework 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:45.998059 17386 status_update_manager.cpp:368] Forwarding status > update TASK_FINISHED (UUID: c0c48bf6-8f81-4ef4-93c8-810097c57d1a) for task 3 > of framework 2014-02-13-22:15:39-2759502016-47130-17373-0000 to > master@192.168.122.164:47130 > I0213 22:15:45.998200 17386 master.cpp:2026] Status update TASK_FINISHED > (UUID: c0c48bf6-8f81-4ef4-93c8-810097c57d1a) for task 3 of framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 from > slave(3)@192.168.122.164:47130 > I0213 22:15:45.998375 17386 master.hpp:429] Removing task 3 with resources > cpus(*):1; mem(*):32 on slave 2014-02-13-22:15:39-2759502016-47130-17373-2 > (fedora-20) > I0213 22:15:45.999208 17386 sched.cpp:619] Scheduler::statusUpdate took > 760887ns > I0213 22:15:45.999285 17386 hierarchical_allocator_process.hpp:637] Recovered > cpus(*):1; mem(*):32 (total allocatable: mem(*):979; disk(*):1001; > ports(*):[31000-32000]; cpus(*):1) on slave > 2014-02-13-22:15:39-2759502016-47130-17373-2 from framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:46.001346 17444 exec.cpp:359] Executor received framework message > I0213 22:15:46.001395 17444 exec.cpp:368] Executor::frameworkMessage took > 30730ns > I0213 22:15:46.002631 17452 process.cpp:1010] Socket closed while receiving > I0213 22:15:46.003365 17381 status_update_manager.cpp:393] Received status > update acknowledgement (UUID: c0c48bf6-8f81-4ef4-93c8-810097c57d1a) for task > 3 of framework 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:46.003394 17381 status_update_manager.cpp:525] Cleaning up status > update stream for task 3 of framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:46.003514 17382 slave.cpp:1256] Status update manager > successfully handled status update acknowledgement (UUID: > 79775756-776f-4265-a66b-0dcda4e0f0ff) for task 3 of framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:46.004482 17382 slave.cpp:1822] Sending message for framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 to > scheduler(1)@192.168.122.164:47130 > I0213 22:15:46.005331 17380 sched.cpp:704] Scheduler::frameworkMessage took > 147661ns > I0213 22:15:46.005781 17382 slave.cpp:1256] Status update manager > successfully handled status update acknowledgement (UUID: > c0c48bf6-8f81-4ef4-93c8-810097c57d1a) for task 3 of framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:46.006345 17382 slave.cpp:3165] Completing task 3 > I0213 22:15:46.021203 17386 mesos_containerizer.cpp:874] Executor for > container '61fd0991-dfe6-43f3-aebf-c3582897a5c3' has exited > I0213 22:15:46.021222 17386 mesos_containerizer.cpp:791] Destroying container > '61fd0991-dfe6-43f3-aebf-c3582897a5c3' > I0213 22:15:46.025365 17381 monitor.cpp:140] Failed to collect resource usage > for container '61fd0991-dfe6-43f3-aebf-c3582897a5c3' for executor 'default' > of framework '2014-02-13-22:15:39-2759502016-47130-17373-0000': Unknown > container: 61fd0991-dfe6-43f3-aebf-c3582897a5c3 > I0213 22:15:46.032027 17381 monitor.cpp:140] Failed to collect resource usage > for container '5c917cb7-a0f7-46db-a8ce-d0213552cde8' for executor 'default' > of framework '2014-02-13-22:15:39-2759502016-47130-17373-0000': Unknown > container: 5c917cb7-a0f7-46db-a8ce-d0213552cde8 > I0213 22:15:46.035960 17381 slave.cpp:2047] Executor 'default' of framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 has exited with status 1 > I0213 22:15:46.038244 17381 slave.cpp:1643] Handling status update TASK_LOST > (UUID: 754186b9-569c-456b-940d-967d6c38f790) for task 1 of framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 from @0.0.0.0:0 > I0213 22:15:46.038270 17381 slave.cpp:3142] Terminating task 1 > I0213 22:15:46.038370 17381 status_update_manager.cpp:315] Received status > update TASK_LOST (UUID: 754186b9-569c-456b-940d-967d6c38f790) for task 1 of > framework 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:46.038383 17381 status_update_manager.cpp:494] Creating > StatusUpdate stream for task 1 of framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:46.038445 17381 status_update_manager.cpp:368] Forwarding status > update TASK_LOST (UUID: 754186b9-569c-456b-940d-967d6c38f790) for task 1 of > framework 2014-02-13-22:15:39-2759502016-47130-17373-0000 to > master@192.168.122.164:47130 > I0213 22:15:46.038585 17385 slave.cpp:1763] Status update manager > successfully handled status update TASK_LOST (UUID: > 754186b9-569c-456b-940d-967d6c38f790) for task 1 of framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:46.039693 17381 master.cpp:2083] Executor default of framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 on slave > 2014-02-13-22:15:39-2759502016-47130-17373-1 (fedora-20) has exited with > status 1 > Enabling authentication for the framework > Registered with framework ID 2014-02-13-22:15:39-2759502016-47130-17373-0000 > Got 3 resource offers > Got resource offer 2014-02-13-22:15:39-2759502016-47130-17373-0 > Accepting offer on fedora-20 to start task 0 > Got resource offer 2014-02-13-22:15:39-2759502016-47130-17373-1 > Accepting offer on fedora-20 to start task 1 > Got resource offer 2014-02-13-22:15:39-2759502016-47130-17373-2 > Accepting offer on fedora-20 to start task 2 > Task 0 is in state 1 > Task 0 is in state 2 > Received message: 'data with a \x00 byte' > Got 1 resource offers > Got resource offer 2014-02-13-22:15:39-2759502016-47130-17373-3 > Accepting offer on fedora-20 to start task 3 > Task 3 is in state 1 > Task 3 is in state 2 > Received message: 'data with a \x00 byte' > Task 1 is in state 5 > The update data did not match! > Expected: 'data with a \x00 byte' > Actual: '' > Failed to call scheduler's statusUpdate > I0213 22:15:46.045435 17381 master.cpp:2026] Status update TASK_LOST (UUID: > 754186b9-569c-456b-940d-967d6c38f790) for task 1 of framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 from > slave(2)@192.168.122.164:47130 > I0213 22:15:46.045485 17381 master.hpp:429] Removing task 1 with resources > cpus(*):1; mem(*):32 on slave 2014-02-13-22:15:39-2759502016-47130-17373-1 > (fedora-20) > I0213 22:15:46.049846 17385 hierarchical_allocator_process.hpp:637] Recovered > cpus(*):1; mem(*):32 (total allocatable: mem(*):979; disk(*):1001; > ports(*):[31000-32000]; cpus(*):1) on slave > 2014-02-13-22:15:39-2759502016-47130-17373-1 from framework > 2014-02-13-22:15:39-2759502016-47130-17373-0000 > I0213 22:15:46.099185 17452 process.cpp:1010] Socket closed while receiving > I0213 22:15:46.099313 17444 exec.cpp:458] Slave exited ... shutting down > I0213 22:15:46.099385 17444 exec.cpp:475] Executor::shutdown took 35477ns > I0213 22:15:46.099403 17444 exec.cpp:77] Scheduling shutdown of the executor > tests/script.cpp:78: Failure > Failed > python_framework_test.sh exited with status 1 > [ FAILED ] ExamplesTest.PythonFramework (8325 ms) -- This message was sent by Atlassian JIRA (v6.3.4#6332)