You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "Vinod Kone (JIRA)" <ji...@apache.org> on 2014/09/03 19:16:52 UTC
[jira] [Resolved] (MESOS-1007) Python framework unable to parse
framework messages
[ 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)