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 2017/06/29 17:57:00 UTC
[jira] [Commented] (MESOS-7440) Various DefaultExecutorCheckTest*
tests flaky on ASF CI
[ https://issues.apache.org/jira/browse/MESOS-7440?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16068710#comment-16068710 ]
Vinod Kone commented on MESOS-7440:
-----------------------------------
Found another instance of flaky DefaultExecutorCheckTest.CommandCheckDeliveredAndReconciled
{code}
[ RUN ] DefaultExecutorCheckTest.CommandCheckDeliveredAndReconciled
I0629 10:37:56.535794 5916 cluster.cpp:162] Creating default 'local' authorizer
I0629 10:37:56.538604 5939 master.cpp:438] Master 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d (d89378cfb216) started on 172.17.0.6:43517
I0629 10:37:56.538645 5939 master.cpp:440] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate_agents="true" --authenticate_frameworks="true" --authenticate_http_frameworks="true" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/IU3oeZ/credentials" --filter_gpu_resources="true" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_framework_authenticators="basic" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_agent_ping_timeouts="5" --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --max_unreachable_tasks_per_framework="1000" --port="5050" --quiet="false" --recovery_agent_removal_limit="100%" --registry="in_memory" --registry_fetch_timeout="1mins" --registry_gc_interval="15mins" --registry_max_agent_age="2weeks" --registry_max_agent_count="102400" --registry_store_timeout="100secs" --registry_strict="false" --root_submissions="true" --user_sorter="drf" --version="false" --webui_dir="/mesos/mesos-1.4.0/_inst/share/mesos/webui" --work_dir="/tmp/IU3oeZ/master" --zk_session_timeout="10secs"
I0629 10:37:56.539139 5939 master.cpp:490] Master only allowing authenticated frameworks to register
I0629 10:37:56.539165 5939 master.cpp:504] Master only allowing authenticated agents to register
I0629 10:37:56.539183 5939 master.cpp:517] Master only allowing authenticated HTTP frameworks to register
I0629 10:37:56.539275 5939 credentials.hpp:37] Loading credentials for authentication from '/tmp/IU3oeZ/credentials'
I0629 10:37:56.539800 5939 master.cpp:562] Using default 'crammd5' authenticator
I0629 10:37:56.540105 5939 http.cpp:974] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
I0629 10:37:56.540325 5939 http.cpp:974] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
I0629 10:37:56.540459 5939 http.cpp:974] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
I0629 10:37:56.540586 5939 master.cpp:642] Authorization enabled
I0629 10:37:56.540778 5943 hierarchical.cpp:169] Initialized hierarchical allocator process
I0629 10:37:56.540849 5936 whitelist_watcher.cpp:77] No whitelist given
I0629 10:37:56.544589 5939 master.cpp:2161] Elected as the leading master!
I0629 10:37:56.544646 5939 master.cpp:1700] Recovering from registrar
I0629 10:37:56.544828 5938 registrar.cpp:345] Recovering registrar
I0629 10:37:56.545671 5938 registrar.cpp:389] Successfully fetched the registry (0B) in 765952ns
I0629 10:37:56.545820 5938 registrar.cpp:493] Applied 1 operations in 37541ns; attempting to update the registry
I0629 10:37:56.546499 5938 registrar.cpp:550] Successfully updated the registry in 605184ns
I0629 10:37:56.546636 5938 registrar.cpp:422] Successfully recovered registrar
I0629 10:37:56.547792 5944 hierarchical.cpp:207] Skipping recovery of hierarchical allocator: nothing to recover
I0629 10:37:56.547785 5939 master.cpp:1799] Recovered 0 agents from the registry (129B); allowing 10mins for agents to re-register
I0629 10:37:56.551240 5916 containerizer.cpp:230] Using isolation: posix/cpu,posix/mem,filesystem/posix,network/cni,environment_secret
W0629 10:37:56.551805 5916 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges
W0629 10:37:56.551903 5916 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
I0629 10:37:56.551941 5916 provisioner.cpp:255] Using default backend 'copy'
I0629 10:37:56.556195 5916 cluster.cpp:448] Creating default 'local' authorizer
I0629 10:37:56.558038 5942 slave.cpp:249] Mesos agent started on (20)@172.17.0.6:43517
I0629 10:37:56.558071 5942 slave.cpp:250] Flags at startup: --acls="permissive: true
" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_LL4ThO/store/appc" --authenticate_http_readonly="true" --authenticate_http_readwrite="false" --authenticatee="crammd5" --authentication_backoff_factor="1secs" --authorizer="local" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_LL4ThO/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io" --docker_remove_delay="6hrs" --docker_socket="/var/run/dock:
er.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_LL4ThO/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_reregistration_timeout="2secs" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_LL4ThO/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --http_command_executor="false" --http_credentials="/tmp/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_LL4ThO/http_credentials" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/mesos/mesos-1.4.0/_build/src" --logbufsecs="0" --logging_level="INFO" --max_completed_executors_per_framework="150" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --port="5051" --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_LL4ThO" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_enable_support="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_oYU8Ko"
I0629 10:37:56.558816 5942 credentials.hpp:86] Loading credential for authentication from '/tmp/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_LL4ThO/credential'
I0629 10:37:56.559062 5942 slave.cpp:282] Agent using credential for: test-principal
I0629 10:37:56.559111 5916 scheduler.cpp:184] Version: 1.4.0
I0629 10:37:56.559167 5942 credentials.hpp:37] Loading credentials for authentication from '/tmp/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_LL4ThO/http_credentials'
I0629 10:37:56.559512 5942 http.cpp:974] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
I0629 10:37:56.559820 5935 scheduler.cpp:470] New master detected at master@172.17.0.6:43517
I0629 10:37:56.559921 5935 scheduler.cpp:479] Waiting for 0ns before initiating a re-(connection) attempt with the master
I0629 10:37:56.561468 5942 slave.cpp:553] Agent resources: [{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
I0629 10:37:56.561776 5942 slave.cpp:561] Agent attributes: [ ]
I0629 10:37:56.561816 5942 slave.cpp:566] Agent hostname: d89378cfb216
I0629 10:37:56.562044 5935 status_update_manager.cpp:177] Pausing sending status updates
I0629 10:37:56.562963 5943 scheduler.cpp:361] Connected with the master at http://172.17.0.6:43517/master/api/v1/scheduler
I0629 10:37:56.564517 5942 state.cpp:64] Recovering state from '/tmp/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_oYU8Ko/meta'
I0629 10:37:56.564842 5949 status_update_manager.cpp:203] Recovering status update manager
I0629 10:37:56.565170 5938 containerizer.cpp:582] Recovering containerizer
I0629 10:37:56.565457 5940 scheduler.cpp:243] Sending SUBSCRIBE call to http://172.17.0.6:43517/master/api/v1/scheduler
I0629 10:37:56.566975 5947 process.cpp:3779] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I0629 10:37:56.567172 5940 provisioner.cpp:416] Provisioner recovery complete
I0629 10:37:56.567775 5953 slave.cpp:6168] Finished recovery
I0629 10:37:56.568343 5953 slave.cpp:6350] Querying resource estimator for oversubscribable resources
I0629 10:37:56.568580 5957 status_update_manager.cpp:177] Pausing sending status updates
I0629 10:37:56.568578 5953 slave.cpp:946] New master detected at master@172.17.0.6:43517
I0629 10:37:56.568747 5953 slave.cpp:981] Detecting new master
I0629 10:37:56.569025 5953 slave.cpp:6364] Received oversubscribable resources {} from the resource estimator
I0629 10:37:56.569737 5953 http.cpp:1114] HTTP POST for /master/api/v1/scheduler from 172.17.0.6:55768
I0629 10:37:56.570030 5953 master.cpp:2514] Received subscription request for HTTP framework 'default'
I0629 10:37:56.570144 5953 master.cpp:2197] Authorizing framework principal 'test-principal' to receive offers for roles '{ * }'
I0629 10:37:56.570601 5953 slave.cpp:1008] Authenticating with master master@172.17.0.6:43517
I0629 10:37:56.570700 5953 slave.cpp:1019] Using default CRAM-MD5 authenticatee
I0629 10:37:56.570991 5953 master.cpp:2650] Subscribing framework 'default' with checkpointing disabled and capabilities [ RESERVATION_REFINEMENT ]
I0629 10:37:56.571182 5950 authenticatee.cpp:121] Creating new client SASL connection
I0629 10:37:56.571815 5953 master.cpp:7640] Authenticating slave(20)@172.17.0.6:43517
I0629 10:37:56.572028 5950 hierarchical.cpp:301] Added framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000
I0629 10:37:56.572882 5957 master.hpp:2216] Sending heartbeat to 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000
I0629 10:37:56.573420 5950 hierarchical.cpp:1938] No allocations performed
I0629 10:37:56.573412 5953 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(42)@172.17.0.6:43517
I0629 10:37:56.573457 5940 scheduler.cpp:676] Enqueuing event SUBSCRIBED received from http://172.17.0.6:43517/master/api/v1/scheduler
I0629 10:37:56.573537 5950 hierarchical.cpp:2028] No inverse offers to send out!
I0629 10:37:56.573647 5950 hierarchical.cpp:1493] Performed allocation for 0 agents in 269377ns
I0629 10:37:56.573994 5940 authenticator.cpp:98] Creating new server SASL connection
I0629 10:37:56.574262 5940 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0629 10:37:56.574293 5940 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0629 10:37:56.574887 5953 authenticator.cpp:204] Received SASL authentication start
I0629 10:37:56.575124 5953 authenticator.cpp:326] Authentication requires more steps
I0629 10:37:56.575273 5944 scheduler.cpp:676] Enqueuing event HEARTBEAT received from http://172.17.0.6:43517/master/api/v1/scheduler
I0629 10:37:56.575423 5948 authenticatee.cpp:259] Received SASL authentication step
I0629 10:37:56.575650 5951 authenticator.cpp:232] Received SASL authentication step
I0629 10:37:56.576012 5951 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'd89378cfb216' server FQDN: 'd89378cfb216' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0629 10:37:56.576042 5951 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0629 10:37:56.576097 5951 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0629 10:37:56.576192 5951 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'd89378cfb216' server FQDN: 'd89378cfb216' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0629 10:37:56.576277 5951 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0629 10:37:56.576361 5951 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0629 10:37:56.576395 5951 authenticator.cpp:318] Authentication success
I0629 10:37:56.576661 5951 authenticatee.cpp:299] Authentication success
I0629 10:37:56.576772 5951 master.cpp:7670] Successfully authenticated principal 'test-principal' at slave(20)@172.17.0.6:43517
I0629 10:37:56.576884 5951 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(42)@172.17.0.6:43517
I0629 10:37:56.577378 5951 slave.cpp:1103] Successfully authenticated with master master@172.17.0.6:43517
I0629 10:37:56.577657 5951 slave.cpp:1545] Will retry registration in 1.071821ms if necessary
I0629 10:37:56.577850 5945 master.cpp:5602] Received register agent message from slave(20)@172.17.0.6:43517 (d89378cfb216)
I0629 10:37:56.578140 5945 master.cpp:3742] Authorizing agent with principal 'test-principal'
I0629 10:37:56.578622 5952 master.cpp:5662] Authorized registration of agent at slave(20)@172.17.0.6:43517 (d89378cfb216)
I0629 10:37:56.578742 5952 master.cpp:5741] Registering agent at slave(20)@172.17.0.6:43517 (d89378cfb216) with id 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0
I0629 10:37:56.579205 5935 registrar.cpp:493] Applied 1 operations in 66254ns; attempting to update the registry
I0629 10:37:56.579371 5952 slave.cpp:1545] Will retry registration in 2.26489ms if necessary
I0629 10:37:56.579653 5952 master.cpp:5596] Ignoring register agent message from slave(20)@172.17.0.6:43517 (d89378cfb216) as registration is already in progress
I0629 10:37:56.580101 5955 registrar.cpp:550] Successfully updated the registry in 824064ns
I0629 10:37:56.580361 5937 master.cpp:5788] Admitted agent 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0 at slave(20)@172.17.0.6:43517 (d89378cfb216)
I0629 10:37:56.581025 5943 slave.cpp:4866] Received ping from slave-observer(17)@172.17.0.6:43517
I0629 10:37:56.581434 5943 slave.cpp:1149] Registered with master master@172.17.0.6:43517; given agent ID 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0
I0629 10:37:56.581182 5937 master.cpp:5819] Registered agent 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0 at slave(20)@172.17.0.6:43517 (d89378cfb216) with [{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
I0629 10:37:56.581557 5949 status_update_manager.cpp:184] Resuming sending status updates
I0629 10:37:56.581873 5943 slave.cpp:1169] Checkpointing SlaveInfo to '/tmp/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_oYU8Ko/meta/slaves/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0/slave.info'
I0629 10:37:56.581851 5957 hierarchical.cpp:587] Added agent 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0 (d89378cfb216) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (allocated: {})
I0629 10:37:56.582304 5943 slave.cpp:1207] Forwarding total oversubscribed resources {}
I0629 10:37:56.582496 5950 master.cpp:6508] Received update of agent 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0 at slave(20)@172.17.0.6:43517 (d89378cfb216) with total oversubscribed resources {}
I0629 10:37:56.584228 5957 hierarchical.cpp:2028] No inverse offers to send out!
I0629 10:37:56.584538 5957 hierarchical.cpp:1493] Performed allocation for 1 agents in 2.322379ms
I0629 10:37:56.584758 5955 master.cpp:7470] Sending 1 offers to framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000 (default)
I0629 10:37:56.587064 5955 scheduler.cpp:676] Enqueuing event OFFERS received from http://172.17.0.6:43517/master/api/v1/scheduler
I0629 10:37:56.589366 5955 scheduler.cpp:243] Sending ACCEPT call to http://172.17.0.6:43517/master/api/v1/scheduler
I0629 10:37:56.590898 5950 process.cpp:3779] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I0629 10:37:56.593143 5954 http.cpp:1114] HTTP POST for /master/api/v1/scheduler from 172.17.0.6:55766
I0629 10:37:56.595094 5954 master.cpp:3957] Processing ACCEPT call for offers: [ 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-O0 ] on agent 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0 at slave(20)@172.17.0.6:43517 (d89378cfb216) for framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000 (default)
I0629 10:37:56.595290 5954 master.cpp:3469] Authorizing framework principal 'test-principal' to launch task 4014e448-96a8-4d54-a860-dfd42f6234cf
I0629 10:37:56.601023 5954 master.cpp:9521] Adding task 4014e448-96a8-4d54-a860-dfd42f6234cf with resources [{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":32.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"disk","scalar":{"value":32.0},"type":"SCALAR"}] on agent 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0 at slave(20)@172.17.0.6:43517 (d89378cfb216)
I0629 10:37:56.601722 5954 master.cpp:4909] Launching task group { 4014e448-96a8-4d54-a860-dfd42f6234cf } of framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000 (default) with resources cpus(allocated: *):0.1; mem(allocated: *):32; disk(allocated: *):32 on agent 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0 at slave(20)@172.17.0.6:43517 (d89378cfb216)
I0629 10:37:56.602710 5949 slave.cpp:1670] Got assigned task group containing tasks [ 4014e448-96a8-4d54-a860-dfd42f6234cf ] for framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000
I0629 10:37:56.603030 5953 hierarchical.cpp:1177] Recovered cpus(allocated: *):1.8; mem(allocated: *):960; disk(allocated: *):960; ports(allocated: *):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000], allocated: cpus(allocated: *):0.2; mem(allocated: *):64; disk(allocated: *):64) on agent 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0 from framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000
I0629 10:37:56.603104 5953 hierarchical.cpp:1214] Framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000 filtered agent 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0 for 5secs
I0629 10:37:56.604100 5949 slave.cpp:1951] Authorizing task group containing tasks [ 4014e448-96a8-4d54-a860-dfd42f6234cf ] for framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000
I0629 10:37:56.604197 5949 slave.cpp:6667] Authorizing framework principal 'test-principal' to launch task 4014e448-96a8-4d54-a860-dfd42f6234cf
I0629 10:37:56.605517 5958 slave.cpp:2138] Launching task group containing tasks [ 4014e448-96a8-4d54-a860-dfd42f6234cf ] for framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000
I0629 10:37:56.606405 5958 paths.cpp:577] Trying to chown '/tmp/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_oYU8Ko/slaves/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0/frameworks/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000/executors/default/runs/97360a94-110c-43dc-87fe-c67fcd86606f' to user 'mesos'
I0629 10:37:56.606791 5958 slave.cpp:7127] Launching executor 'default' of framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000 with resources [{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":32.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"disk","scalar":{"value":32.0},"type":"SCALAR"}] in work directory '/tmp/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_oYU8Ko/slaves/17dc2:
f22-3e22-438d-a2f3-63bb6ce22f6d-S0/frameworks/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000/executors/default/runs/97360a94-110c-43dc-87fe-c67fcd86606f'
I0629 10:37:56.607640 5958 slave.cpp:2833] Launching container 97360a94-110c-43dc-87fe-c67fcd86606f for executor 'default' of framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000
I0629 10:37:56.608019 5942 containerizer.cpp:1056] Starting container 97360a94-110c-43dc-87fe-c67fcd86606f
I0629 10:37:56.608322 5958 slave.cpp:2367] Queued task group containing tasks [ 4014e448-96a8-4d54-a860-dfd42f6234cf ] for executor 'default' of framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000
I0629 10:37:56.608624 5958 slave.cpp:899] Successfully attached file '/tmp/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_oYU8Ko/slaves/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0/frameworks/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000/executors/default/runs/97360a94-110c-43dc-87fe-c67fcd86606f'
I0629 10:37:56.608795 5958 slave.cpp:899] Successfully attached file '/tmp/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_oYU8Ko/slaves/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0/frameworks/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000/executors/default/runs/97360a94-110c-43dc-87fe-c67fcd86606f'
I0629 10:37:56.615267 5936 containerizer.cpp:1630] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"arguments":["mesos-default-executor","--launcher_dir=\/mesos\/mesos-1.4.0\/_build\/src"],"shell":false,"value":"\/mesos\/mesos-1.4.0\/_build\/src\/mesos-default-executor"},"environment":{"variables":[{"name":"LIBPROCESS_PORT","type":"VALUE","value":"0"},{"name":"MESOS_AGENT_ENDPOINT","type":"VALUE","value":"172.17.0.6:43517"},{"name":"MESOS_CHECKPOINT","type":"VALUE","value":"0"},{"name":"MESOS_DIRECTORY","type":"VALUE","value":"\/tmp\/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_oYU8Ko\/slaves\/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0\/frameworks\/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000\/executors\/default\/runs\/97360a94-110c-43dc-87fe-c67fcd86606f"},{"name":"MESOS_EXECUTOR_ID","type":"VALUE","value":"default"},{"name":"MESOS_EXECUTOR_SHUTDOWN_GRACE_PERIOD","type":"VALUE","value":"10secs"},{"name":"MESOS_FRAMEWORK_ID","type":"VALUE","value":"17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000"},{"name":"MESOS_HTTP_COMMAND_EXECUTOR","type":"VALUE","value":"0"},{"name":"MESOS_SLAVE_ID","type":"VALUE","value":"17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0"},{"name":"MESOS_SLAVE_PID","type":"VALUE","value":"slave(20)@172.17.0.6:43517"},{"name":"MESOS_SANDBOX","type":"VALUE","value":"\/tmp\/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_oYU8Ko\/slaves\/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0\/frameworks\/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000\/executors\/default\/runs\/97360a94-110c-43dc-87fe-c67fcd86606f"}]},"task_environment":{},"user":"mesos","working_directory":"\/tmp\/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_oYU8Ko\/slaves\/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0\/frameworks\/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000\/executors\/default\/runs\/97360a94-110c-43dc-87fe-c67fcd86606f"}" --pipe_read="10" --pipe_write="11" --runtime_directory="/tmp/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_LL4ThO/containers/97360a94-110c-43dc-87fe-c67fcd86606f" --unshare_namespace_mnt="false"'
I0629 10:37:56.618368 5936 launcher.cpp:140] Forked child with pid '6739' for container '97360a94-110c-43dc-87fe-c67fcd86606f'
I0629 10:37:56.621235 5937 fetcher.cpp:343] Starting to fetch URIs for container: 97360a94-110c-43dc-87fe-c67fcd86606f, directory: /tmp/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_oYU8Ko/slaves/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0/frameworks/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000/executors/default/runs/97360a94-110c-43dc-87fe-c67fcd86606f
I0629 10:37:57.543084 5956 hierarchical.cpp:2186] Filtered offer with cpus:1.8; mem:960; disk:960; ports:[31000-32000] on agent 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0 for role * of framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000
I0629 10:37:57.543476 5956 hierarchical.cpp:1938] No allocations performed
I0629 10:37:57.543823 5956 hierarchical.cpp:2028] No inverse offers to send out!
I0629 10:37:57.544139 5956 hierarchical.cpp:1493] Performed allocation for 1 agents in 1.786468ms
I0629 10:37:58.546476 5954 hierarchical.cpp:2186] Filtered offer with cpus:1.8; mem:960; disk:960; ports:[31000-32000] on agent 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0 for role * of framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000
I0629 10:37:58.546972 5954 hierarchical.cpp:1938] No allocations performed
I0629 10:37:58.547267 5954 hierarchical.cpp:2028] No inverse offers to send out!
I0629 10:37:58.547579 5954 hierarchical.cpp:1493] Performed allocation for 1 agents in 1.783349ms
I0629 10:37:59.550412 5941 hierarchical.cpp:2186] Filtered offer with cpus:1.8; mem:960; disk:960; ports:[31000-32000] on agent 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0 for role * of framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000
I0629 10:37:59.550873 5941 hierarchical.cpp:1938] No allocations performed
I0629 10:37:59.551081 5941 hierarchical.cpp:2028] No inverse offers to send out!
I0629 10:37:59.551265 5941 hierarchical.cpp:1493] Performed allocation for 1 agents in 1.461317ms
I0629 10:38:00.553781 5939 hierarchical.cpp:2186] Filtered offer with cpus:1.8; mem:960; disk:960; ports:[31000-32000] on agent 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0 :
for role * of framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000
I0629 10:38:00.554148 5939 hierarchical.cpp:1938] No allocations performed
I0629 10:38:00.554342 5939 hierarchical.cpp:2028] No inverse offers to send out!
I0629 10:38:00.554532 5939 hierarchical.cpp:1493] Performed allocation for 1 agents in 1.270881ms
I0629 10:38:01.556476 5950 hierarchical.cpp:2186] Filtered offer with cpus:1.8; mem:960; disk:960; ports:[31000-32000] on agent 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0 for role * of framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000
I0629 10:38:01.556562 5950 hierarchical.cpp:1938] No allocations performed
I0629 10:38:01.556602 5950 hierarchical.cpp:2028] No inverse offers to send out!
I0629 10:38:01.556653 5950 hierarchical.cpp:1493] Performed allocation for 1 agents in 613340ns
I0629 10:38:02.559478 5951 hierarchical.cpp:2028] No inverse offers to send out!
I0629 10:38:02.560645 5945 master.cpp:7470] Sending 1 offers to framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000 (default)
I0629 10:38:02.563029 5951 hierarchical.cpp:1493] Performed allocation for 1 agents in 4.840017ms
I0629 10:38:02.566540 5937 scheduler.cpp:676] Enqueuing event OFFERS received from http://172.17.0.6:43517/master/api/v1/scheduler
I0629 10:38:03.564743 5939 hierarchical.cpp:1938] No allocations performed
I0629 10:38:03.564821 5939 hierarchical.cpp:2028] No inverse offers to send out!
I0629 10:38:03.564873 5939 hierarchical.cpp:1493] Performed allocation for 1 agents in 275872ns
I0629 10:38:03.777819 5940 process.cpp:3779] Handling HTTP event for process 'slave(20)' with path: '/slave(20)/api/v1/executor'
I0629 10:38:03.779791 5948 http.cpp:1114] HTTP POST for /slave(20)/api/v1/executor from 172.17.0.6:55914
I0629 10:38:03.780200 5948 slave.cpp:3650] Received Subscribe request for HTTP executor 'default' of framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000
I0629 10:38:03.782759 5945 slave.cpp:2609] Sending queued task group task group containing tasks [ 4014e448-96a8-4d54-a860-dfd42f6234cf ] to executor 'default' of framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000 (via HTTP)
I0629 10:38:03.793095 5957 process.cpp:3779] Handling HTTP event for process 'slave(20)' with path: '/slave(20)/api/v1'
I0629 10:38:03.794051 5938 http.cpp:1114] HTTP POST for /slave(20)/api/v1 from 172.17.0.6:55918
I0629 10:38:03.794661 5938 http.cpp:532] Processing call LAUNCH_NESTED_CONTAINER
I0629 10:38:03.795662 5935 containerizer.cpp:1027] Trying to chown '/tmp/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_oYU8Ko/slaves/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0/frameworks/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000/executors/default/runs/97360a94-110c-43dc-87fe-c67fcd86606f/containers/2efe2fc8-dd4a-42ad-b387-4015f764f241' to user 'mesos'
I0629 10:38:03.795894 5935 containerizer.cpp:1056] Starting container 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241
I0629 10:38:03.799402 5957 containerizer.cpp:1630] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"shell":true,"value":"sleep 10000"},"environment":{"variables":[{"name":"MESOS_SANDBOX","type":"VALUE","value":"\/tmp\/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_oYU8Ko\/slaves\/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0\/frameworks\/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000\/executors\/default\/runs\/97360a94-110c-43dc-87fe-c67fcd86606f\/containers\/2efe2fc8-dd4a-42ad-b387-4015f764f241"},{"name":"MESOS_CONTAINER_IP","type":"VALUE","value":"172.17.0.6"}]},"task_environment":{},"user":"mesos","working_directory":"\/tmp\/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_oYU8Ko\/slaves\/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0\/frameworks\/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000\/executors\/default\/runs\/97360a94-110c-43dc-87fe-c67fcd86606f\/containers\/2efe2fc8-dd4a-42ad-b387-4015f764f241"}" --pipe_read="13" --pipe_write="14" --runtime_directory="/tmp/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_LL4ThO/containers/97360a94-110c-43dc-87fe-c67fcd86606f/containers/2efe2fc8-dd4a-42ad-b387-4015f764f241" --unshare_namespace_mnt="false"'
I0629 10:38:03.801327 5957 launcher.cpp:140] Forked child with pid '6797' for container '97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241'
I0629 10:38:03.803362 5957 fetcher.cpp:343] Starting to fetch URIs for container: 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241, directory: /tmp/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_oYU8Ko/slaves/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0/frameworks/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000/executors/default/runs/97360a94-110c-43dc-87fe-c67fcd86606f/containers/2efe2fc8-dd4a-42ad-b387-4015f764f241
I0629 10:38:03.837800 5948 process.cpp:3779] Handling HTTP event for process 'slave(20)' with path: '/slave(20)/api/v1/executor'
I0629 10:38:03.841096 5951 http.cpp:1114] HTTP POST for /slave(20)/api/v1/executor from 172.17.0.6:55916
I0629 10:38:03.842005 5951 slave.cpp:4336] Handling status update TASK_RUNNING (UUID: 4c1d3a0d-1a98-46c4-9f65-e9811d90a425) for task 4014e448-96a8-4d54-a860-dfd42f6234c:
f of framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000
I0629 10:38:03.843168 5951 process.cpp:3779] Handling HTTP event for process 'slave(20)' with path: '/slave(20)/api/v1'
I0629 10:38:03.843955 5951 process.cpp:3779] Handling HTTP event for process 'slave(20)' with path: '/slave(20)/api/v1'
I0629 10:38:03.847407 5940 status_update_manager.cpp:323] Received status update TASK_RUNNING (UUID: 4c1d3a0d-1a98-46c4-9f65-e9811d90a425) for task 4014e448-96a8-4d54-a860-dfd42f6234cf of framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000
I0629 10:38:03.847748 5940 status_update_manager.cpp:500] Creating StatusUpdate stream for task 4014e448-96a8-4d54-a860-dfd42f6234cf of framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000
I0629 10:38:03.848827 5940 status_update_manager.cpp:377] Forwarding update TASK_RUNNING (UUID: 4c1d3a0d-1a98-46c4-9f65-e9811d90a425) for task 4014e448-96a8-4d54-a860-dfd42f6234cf of framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000 to the agent
I0629 10:38:03.849149 5946 http.cpp:1114] HTTP POST for /slave(20)/api/v1 from 172.17.0.6:55920
I0629 10:38:03.850397 5946 http.cpp:1114] HTTP POST for /slave(20)/api/v1 from 172.17.0.6:55922
I0629 10:38:03.851187 5946 slave.cpp:4776] Forwarding the update TASK_RUNNING (UUID: 4c1d3a0d-1a98-46c4-9f65-e9811d90a425) for task 4014e448-96a8-4d54-a860-dfd42f6234cf of framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000 to master@172.17.0.6:43517
I0629 10:38:03.851827 5946 slave.cpp:4670] Status update manager successfully handled status update TASK_RUNNING (UUID: 4c1d3a0d-1a98-46c4-9f65-e9811d90a425) for task 4014e448-96a8-4d54-a860-dfd42f6234cf of framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000
I0629 10:38:03.852742 5946 http.cpp:532] Processing call WAIT_NESTED_CONTAINER
I0629 10:38:03.853574 5958 master.cpp:6653] Status update TASK_RUNNING (UUID: 4c1d3a0d-1a98-46c4-9f65-e9811d90a425) for task 4014e448-96a8-4d54-a860-dfd42f6234cf of framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000 from agent 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0 at slave(20)@172.17.0.6:43517 (d89378cfb216)
I0629 10:38:03.853694 5958 master.cpp:6715] Forwarding status update TASK_RUNNING (UUID: 4c1d3a0d-1a98-46c4-9f65-e9811d90a425) for task 4014e448-96a8-4d54-a860-dfd42f6234cf of framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000
I0629 10:38:03.853741 5946 http.cpp:532] Processing call LAUNCH_NESTED_CONTAINER_SESSION
I0629 10:38:03.854262 5958 master.cpp:8731] Updating the state of task 4014e448-96a8-4d54-a860-dfd42f6234cf of framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
I0629 10:38:03.856237 5946 containerizer.cpp:1027] Trying to chown '/tmp/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_oYU8Ko/slaves/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0/frameworks/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000/executors/default/runs/97360a94-110c-43dc-87fe-c67fcd86606f/containers/2efe2fc8-dd4a-42ad-b387-4015f764f241/containers/check-cbabae1c-e7e9-4123-afe8-b13700f46b26' to user 'mesos'
I0629 10:38:03.856966 5946 containerizer.cpp:1056] Starting container 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-cbabae1c-e7e9-4123-afe8-b13700f46b26
I0629 10:38:03.862500 5945 switchboard.cpp:545] Launching 'mesos-io-switchboard' with flags '--heartbeat_interval="30secs" --help="false" --socket_address="/tmp/mesos-io-switchboard-9f093556-5e17-43b4-b467-588592db9419" --stderr_from_fd="18" --stderr_to_fd="2" --stdin_to_fd="15" --stdout_from_fd="16" --stdout_to_fd="1" --tty="false" --wait_for_connection="true"' for container 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-cbabae1c-e7e9-4123-afe8-b13700f46b26
I0629 10:38:03.862782 5958 scheduler.cpp:676] Enqueuing event UPDATE received from http://172.17.0.6:43517/master/api/v1/scheduler
I0629 10:38:03.865759 5945 switchboard.cpp:575] Created I/O switchboard server (pid: 6811) listening on socket file '/tmp/mesos-io-switchboard-9f093556-5e17-43b4-b467-588592db9419' for container 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-cbabae1c-e7e9-4123-afe8-b13700f46b26
I0629 10:38:03.869324 5958 scheduler.cpp:243] Sending ACKNOWLEDGE call to http://172.17.0.6:43517/master/api/v1/scheduler
I0629 10:38:03.870548 5942 containerizer.cpp:1630] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"shell":true,"value":"exit $STATUS"},"environment":{"variables":[{"name":"MESOS_SANDBOX","type":"VALUE","value":"\/tmp\/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_oYU8Ko\/slaves\/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0\/frameworks\/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000\/executors\/default\/runs\/97360a94-110c-43dc-87fe-c67fcd86606f\/containers\/2efe2fc8-dd4a-42ad-b387-4015f764f241"},{"name":"MESOS_CONTAINER_IP","type":"VALUE","value":"172.17.0.6"},{"name":"STATUS","type":"VALUE","value":"1"}]},"task_environment":{},"user":"mesos","working_directory":"\/tmp\/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_oYU8Ko\/slaves\/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0\/frameworks\/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000\/executors\/default\/runs\/97360a94-110c-43dc-87fe-c67fcd86606f\/containers\/2efe2fc8-dd4a-42ad-b387-4015f764f241"}" --pipe_read="15" --pipe_write="16" --runtime_directory="/tmp/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_LL4ThO/containers/97360a94-110c-43dc-87fe-c67fcd86606f/containers/2efe2fc8-dd4a-42ad-b387-4015f764f241/containers/check-cbabae1c-e7e9-4123-afe8-b13700f46b26" --unshare_namespace_mnt="false"'
I0629 10:38:03.873306 5942 launcher.cpp:140] Forked child with pid '6812' for container '97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-cbabae1c-e7e9-4123-afe8-b13700f46b26'
I0629 10:38:03.874006 5945 process.cpp:3779] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I0629 10:38:03.875838 5954 fetcher.cpp:343] Starting to fetch URIs for container: 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-cbabae1c-e7e9-4123-afe8-b13700f46b26, directory: /tmp/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_oYU8Ko/slaves/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0/frameworks/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000/executors/default/runs/97360a94-110c-43dc-87fe-c67fcd86606f/containers/2efe2fc8-dd4a-42ad-b387-4015f764f241/containers/check-cbabae1c-e7e9-4123-afe8-b13700f46b26
I0629 10:38:03.919044 5942 http.cpp:1114] HTTP POST for /master/api/v1/scheduler from 172.17.0.6:55766
I0629 10:38:03.919531 5942 master.cpp:5367] Processing ACKNOWLEDGE call 4c1d3a0d-1a98-46c4-9f65-e9811d90a425 for task 4014e448-96a8-4d54-a860-dfd42f6234cf of framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000 (default) on agent 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0
I0629 10:38:03.920841 5942 status_update_manager.cpp:395] Received status update acknowledgement (UUID: 4c1d3a0d-1a98-46c4-9f65-e9811d90a425) for task 4014e448-96a8-4d54-a860-dfd42f6234cf of framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000
I0629 10:38:03.922408 5942 slave.cpp:3586] Status update manager successfully handled status update acknowledgement (UUID: 4c1d3a0d-1a98-46c4-9f65-e9811d90a425) for task 4014e448-96a8-4d54-a860-dfd42f6234cf of framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000
I0629 10:38:04.110831 5951 containerizer.cpp:2507] Container 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-cbabae1c-e7e9-4123-afe8-b13700f46b26 has exited
I0629 10:38:04.110906 5951 containerizer.cpp:2101] Destroying container 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-cbabae1c-e7e9-4123-afe8-b13700f46b26 in RUNNING state
I0629 10:38:04.111295 5951 launcher.cpp:156] Asked to destroy container 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-cbabae1c-e7e9-4123-afe8-b13700f46b26
I0629 10:38:04.570248 5941 hierarchical.cpp:1938] No allocations performed
I0629 10:38:04.570363 5941 hierarchical.cpp:2028] No inverse offers to send out!
I0629 10:38:04.570423 5941 hierarchical.cpp:1493] Performed allocation for 1 agents in 412686ns
I0629 10:38:05.572249 5951 hierarchical.cpp:1938] No allocations performed
I0629 10:38:05.572832 5951 hierarchical.cpp:2028] No inverse offers to send out!
I0629 10:38:05.573194 5951 hierarchical.cpp:1493] Performed allocation for 1 agents in 1.114126ms
I0629 10:38:06.574689 5951 hierarchical.cpp:1938] No allocations performed
I0629 10:38:06.574782 5951 hierarchical.cpp:2028] No inverse offers to send out!
I0629 10:38:06.574836 5951 hierarchical.cpp:1493] Performed allocation for 1 agents in 329025ns
I0629 10:38:07.575736 5948 hierarchical.cpp:1938] No allocations performed
I0629 10:38:07.575825 5948 hierarchical.cpp:2028] No inverse offers to send out!
I0629 10:38:07.575883 5948 hierarchical.cpp:1493] Performed allocation for 1 agents in 310978ns
I0629 10:38:08.578474 5954 hierarchical.cpp:1938] No allocations performed
I0629 10:38:08.578562 5954 hierarchical.cpp:2028] No inverse offers to send out!
I0629 10:38:08.578606 5954 hierarchical.cpp:1493] Performed allocation for 1 agents in 292037ns
I0629 10:38:09.117090 5959 switchboard.cpp:789] Sending SIGTERM to I/O switchboard server (pid: 6811) since container 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-cbabae1c-e7e9-4123-afe8-b13700f46b26 is being destroyed
E0629 10:38:09.194401 5943 switchboard.cpp:904] Unexpected termination of I/O switchboard server: 'IOSwitchboard' terminated with signal Terminated for container 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-cbabae1c-e7e9-4123-afe8-b13700f46b26
E0629 10:38:09.195289 5943 switchboard.cpp:834] Failed to remove unix domain socket file '/tmp/mesos-io-switchboard-9f093556-5e17-43b4-b467-588592db9419' for container '97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-cbabae1c-e7e9-4123-afe8-b13700f46b26': No such file or directory
I0629 10:38:09.200191 5939 provisioner.cpp:490] Ignoring destroy request for unknown container 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-cbabae1c-e7e9-4123-afe8-b13700f46b26
I0629 10:38:09.200700 5939 containerizer.cpp:2380] Checkpointing termination state to nested container's runtime directory '/tmp/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_LL4ThO/containers/97360a94-110c-43dc-87fe-c67fcd86606f/containers/2efe2fc8-dd4a-42ad-b387-4015f764f241/containers/check-cbabae1c-e7e9-4123-afe8-b13700f46b26/termination'
I0629 10:38:09.202594 5945 process.cpp:3836] Failed to process request for '/slave(20)/api/v1': I/O switchboard has shutdown
W0629 10:38:09.202816 5951 http.cpp:2861] Failed to attach to nested container 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-cbabae1c-e7e9-4123-afe8-b13700f46b26: I/O switchboard has shutdown
I0629 10:38:09.202914 5938 process.cpp:1495] Returning '500 Internal Server Error' for '/slave(20)/api/v1' (I/O switchboard has shutdown)
W0629 10:38:09.203783 5951 containerizer.cpp:2089] Attempted to destroy unknown container 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-cbabae1c-e7e9-4123-afe8-b13700f46b26
I0629 10:38:09.232076 5940 process.cpp:3779] Handling HTTP event for process 'slave(20)' with path: '/slave(20)/api/v1'
I0629 10:38:09.234323 5940 http.cpp:1114] HTTP POST for /slave(20)/api/v1 from 172.17.0.6:56036
I0629 10:38:09.235673 5957 http.cpp:532] Processing call REMOVE_NESTED_CONTAINER
I0629 10:38:09.255259 5941 process.cpp:3779] Handling HTTP event for process 'slave(20)' with path: '/slave(20)/api/v1'
I0629 10:38:09.257501 5941 http.cpp:1114] HTTP POST for /slave(20)/api/v1 from 172.17.0.6:56038
I0629 10:38:09.258684 5941 http.cpp:532] Processing call LAUNCH_NESTED_CONTAINER_SESSION
I0629 10:38:09.260548 5955 containerizer.cpp:1027] Trying to chown '/tmp/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_oYU8Ko/slaves/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0/frameworks/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000/executors/default/runs/97360a94-110c-43dc-87fe-c67fcd86606f/containers/2efe2fc8-dd4a-42ad-b387-4015f764f241/containers/check-2b2237de-8eb8-4a40-b2d3-4b887987b7f8' to user 'mesos'
I0629 10:38:09.260996 5955 containerizer.cpp:1056] Starting container 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-2b2237de-8eb8-4a40-b2d3-4b887987b7f8
I0629 10:38:09.266542 5944 switchboard.cpp:545] Launching 'mesos-io-switchboard' with flags '--heartbeat_interval="30secs" --help="false" --socket_address="/tmp/mesos-io-switchboard-dc599c93-092a-4fe0-b07f-e061da726a97" --stderr_from_fd="19" --stderr_to_fd="2" --stdin_to_fd="16" --stdout_from_fd="17" --stdout_to_fd="1" --tty="false" --wait_for_connection="true"' for container 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-2b2237de-8eb8-4a40-b2d3-4b887987b7f8
I0629 10:38:09.269999 5944 switchboard.cpp:575] Created I/O switchboard server (pid: 6844) listening on socket file '/tmp/mesos-io-switchboard-dc599c93-092a-4fe0-b07f-e061da726a97' for container 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-2b2237de-8eb8-4a40-b2d3-4b887987b7f8
I0629 10:38:09.273778 5955 containerizer.cpp:1630] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"shell":true,"value":"exit $STATUS"},"environment":{"variables":[{"name":"MESOS_SANDBOX","type":"VALUE","value":"\/tmp\/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_oYU8Ko\/slaves\/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0\/frameworks\/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000\/executors\/default\/runs\/97360a94-110c-43dc-87fe-c67fcd86606f\/containers\/2efe2fc8-dd4a-42ad-b387-4015f764f241"},{"name":"MESOS_CONTAINER_IP","type":"VALUE","value":"172.17.0.6"},{"name":"STATUS","type":"VALUE","value":"1"}]},"task_environment":{},"user":"mesos","working_directory":"\/tmp\/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_oYU8Ko\/slaves\/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0\/frameworks\/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000\/executors\/default\/runs\/97360a94-110c-43dc-87fe-c67fcd86606f\/containers\/2efe2fc8-dd4a-42ad-b387-4015f764f241"}" --pipe_read="16" --pipe_write="17" --runtime_directory="/tmp/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_LL4ThO/containers/97360a94-110c-43dc-87fe-c67fcd86606f/containers/2efe2fc8-dd4a-42ad-b387-4015f764f241/containers/check-2b2237de-8eb8-4a40-b2d3-4b887987b7f8" --unshare_namespace_mnt="false"'
I0629 10:38:09.276953 5955 launcher.cpp:140] Forked child with pid '6847' for container '97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-2b2237de-8eb8-4a40-b2d3-4b887987b7f8'
I0629 10:38:09.281071 5958 fetcher.cpp:343] Starting to fetch URIs for container: 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-2b2237de-8eb8-4a40-b2d3-4b887987b7f8, directory: /tmp/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_oYU8Ko/slaves/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0/frameworks/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000/executors/default/runs/97360a94-110c-43dc-87fe-c67fcd86606f/containers/2efe2fc8-dd4a-42ad-b387-4015f764f241/containers/check-2b2237de-8eb8-4a40-b2d3-4b887987b7f8
I0629 10:38:09.510234 5947 containerizer.cpp:2507] Container 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-2b2237de-8eb8-4a40-b2d3-4b887987b7f8 has exited
I0629 10:38:09.510857 5947 containerizer.cpp:2101] Destroying container 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-2b2237de-8eb8-4a40-b2d3-4b887987b7f8 in RUNNING state
I0629 10:38:09.511555 5947 launcher.cpp:156] Asked to destroy container 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-2b2237de-8eb8-4a40-b2d3-4b887987b7f8
I0629 10:38:09.579416 5936 hierarchical.cpp:1938] No allocations performed
I0629 10:38:09.579509 5936 hierarchical.cpp:2028] No inverse offers to send out!
I0629 10:38:09.579599 5936 hierarchical.cpp:1493] Performed allocation for 1 agents in 384807ns
I0629 10:38:10.585616 5951 hierarchical.cpp:1938] No allocations performed
I0629 10:38:10.585708 5951 hierarchical.cpp:2028] No inverse offers to send out!
I0629 10:38:10.585753 5951 hierarchical.cpp:1493] Performed allocation for 1 agents in 317061ns
I0629 10:38:11.570235 5939 slave.cpp:6350] Querying resource estimator for oversubscribable resources
I0629 10:38:11.570555 5939 slave.cpp:6364] Received oversubscribable resources {} from the resource estimator
I0629 10:38:11.574453 5952 master.hpp:2216] Sending heartbeat to 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000
I0629 10:38:11.576776 5942 scheduler.cpp:676] Enqueuing event HEARTBEAT received from http://172.17.0.6:43517/master/api/v1/scheduler
I0629 10:38:11.582347 5951 slave.cpp:4866] Received ping from slave-observer(17)@172.17.0.6:43517
I0629 10:38:11.587069 5935 hierarchical.cpp:1938] No allocations performed
I0629 10:38:11.587507 5935 hierarchical.cpp:2028] No inverse offers to send out!
I0629 10:38:11.587674 5935 hierarchical.cpp:1493] Performed allocation for 1 agents in 767970ns
I0629 10:38:12.589851 5947 hierarchical.cpp:1938] No allocations performed
I0629 10:38:12.589942 5947 hierarchical.cpp:2028] No inverse offers to send out!
I0629 10:38:12.589987 5947 hierarchical.cpp:1493] Performed allocation for 1 agents in 316274ns
I0629 10:38:13.591883 5954 hierarchical.cpp:1938] No allocations performed
I0629 10:38:13.592947 5954 hierarchical.cpp:2028] No inverse offers to send out!
I0629 10:38:13.593427 5954 hierarchical.cpp:1493] Performed allocation for 1 agents in 1.754311ms
I0629 10:38:14.518102 5959 switchboard.cpp:789] Sending SIGTERM to I/O switchboard server (pid: 6844) since container 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-2b2237de-8eb8-4a40-b2d3-4b887987b7f8 is being destroyed
E0629 10:38:14.581822 5937 switchboard.cpp:904] Unexpected termination of I/O switchboard server: 'IOSwitchboard' terminated with signal Terminated for container 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-2b2237de-8eb8-4a40-b2d3-4b887987b7f8
E0629 10:38:14.582137 5937 switchboard.cpp:834] Failed to remove unix domain socket file '/tmp/mesos-io-switchboard-dc599c93-092a-4fe0-b07f-e061da726a97' for container '97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-2b2237de-8eb8-4a40-b2d3-4b887987b7f8': No such file or directory
I0629 10:38:14.583308 5944 provisioner.cpp:490] Ignoring destroy request for unknown container 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-2b2237de-8eb8-4a40-b2d3-4b887987b7f8
I0629 10:38:14.583513 5935 containerizer.cpp:2380] Checkpointing termination state to nested container's runtime directory '/tmp/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_LL4ThO/containers/97360a94-110c-43dc-87fe-c67fcd86606f/containers/2efe2fc8-dd4a-42ad-b387-4015f764f241/containers/check-2b2237de-8eb8-4a40-b2d3-4b887987b7f8/termination'
W0629 10:38:14.585533 5956 http.cpp:2861] Failed to attach to nested container 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-2b2237de-8eb8-4a40-b2d3-4b887987b7f8: I/O switchboard has shutdown
I0629 10:38:14.585636 5947 process.cpp:1495] Returning '500 Internal Server Error' for '/slave(20)/api/v1' (I/O switchboard has shutdown)
I0629 10:38:14.585597 5955 process.cpp:3836] Failed to process request for '/slave(20)/api/v1': I/O switchboard has shutdown
W0629 10:38:14.585911 5956 containerizer.cpp:2089] Attempted to destroy unknown container 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-2b2237de-8eb8-4a40-b2d3-4b887987b7f8
I0629 10:38:14.590529 5951 process.cpp:3779] Handling HTTP event for process 'slave(20)' with path: '/slave(20)/api/v1'
I0629 10:38:14.591440 5958 http.cpp:1114] HTTP POST for /slave(20)/api/v1 from 172.17.0.6:56158
I0629 10:38:14.591850 5958 http.cpp:532] Processing call REMOVE_NESTED_CONTAINER
I0629 10:38:14.595965 5942 hierarchical.cpp:1938] No allocations performed
I0629 10:38:14.596029 5942 hierarchical.cpp:2028] No inverse offers to send out!
I0629 10:38:14.596074 5942 hierarchical.cpp:1493] Performed allocation for 1 agents in 253602ns
I0629 10:38:14.599545 5956 process.cpp:3779] Handling HTTP event for process 'slave(20)' with path: '/slave(20)/api/v1'
I0629 10:38:14.600294 5946 http.cpp:1114] HTTP POST for /slave(20)/api/v1 from 172.17.0.6:56160
I0629 10:38:14.600817 5946 http.cpp:532] Processing call LAUNCH_NESTED_CONTAINER_SESSION
I0629 10:38:14.601532 5957 containerizer.cpp:1027] Trying to chown '/tmp/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_oYU8Ko/slaves/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0/frameworks/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000/executors/default/runs/97360a94-110c-43dc-87fe-c67fcd86606f/containers/2efe2fc8-dd4a-42ad-b387-4015f764f241/containers/check-7c07cf95-3b72-46bf-9675-48976851353b' to user 'mesos'
I0629 10:38:14.601760 5957 containerizer.cpp:1056] Starting container 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-7c07cf95-3b72-46bf-9675-48976851353b
I0629 10:38:14.604198 5935 switchboard.cpp:545] Launching 'mesos-io-switchboard' with flags '--heartbeat_interval="30secs" --help="false" --socket_address="/tmp/mesos-io-switchboard-a090036e-ba73-487d-91ed-614a353e92d7" --stderr_from_fd="18" --stderr_to_fd="2" --stdin_to_fd="15" --stdout_from_fd="16" --stdout_to_fd="1" --tty="false" --wait_for_connection="true"' for container 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-7c07cf95-3b72-46bf-9675-48976851353b
I0629 10:38:14.605885 5935 switchboard.cpp:575] Created I/O switchboard server (pid: 6876) listening on socket file '/tmp/mesos-io-switchboard-a090036e-ba73-487d-91ed-614a353e92d7' for container 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-7c07cf95-3b72-46bf-9675-48976851353b
I0629 10:38:14.608336 5956 containerizer.cpp:1630] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"shell":true,"value":"exit $STATUS"},"environment":{"variables":[{"name":"MESOS_SANDBOX","type":"VALUE","value":"\/tmp\/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_oYU8Ko\/slaves\/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0\/frameworks\/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000\/executors\/default\/runs\/97360a94-110c-43dc-87fe-c67fcd86606f\/containers\/2efe2fc8-dd4a-42ad-b387-4015f764f241"},{"name":"MESOS_CONTAINER_IP","type":"VALUE","value":"172.17.0.6"},{"name":"STATUS","type":"VALUE","value":"1"}]},"task_environment":{},"user":"mesos","working_directory":"\/tmp\/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_oYU8Ko\/slaves\/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0\/frameworks\/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000\/executors\/default\/runs\/97360a94-110c-43dc-87fe-c67fcd86606f\/containers\/2efe2fc8-dd4a-42ad-b387-4015f764f241"}" --pipe_read="15" --pipe_write="16" --runtime_directory="/tmp/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_LL4ThO/containers/97360a94-110c-43dc-87fe-c67fcd86606f/containers/2efe2fc8-dd4a-42ad-b387-4015f764f241/containers/check-7c07cf95-3b72-46bf-9675-48976851353b" --unshare_namespace_mnt="false"'
I0629 10:38:14.610085 5956 launcher.cpp:140] Forked child with pid '6878' for container '97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-7c07cf95-3b72-46bf-9675-48976851353b'
I0629 10:38:14.611842 5958 fetcher.cpp:343] Starting to fetch URIs for container: 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-7c07cf95-3b72-46bf-9675-48976851353b, directory: /tmp/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_oYU8Ko/slaves/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0/frameworks/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000/executors/default/runs/97360a94-110c-43dc-87fe-c67fcd86606f/containers/2efe2fc8-dd4a-42ad-b387-4015f764f241/containers/check-7c07cf95-3b72-46bf-9675-48976851353b
I0629 10:38:14.784044 5955 containerizer.cpp:2507] Container 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-7c07cf95-3b72-46bf-9675-48976851353b has exited
I0629 10:38:14.784101 5955 containerizer.cpp:2101] Destroying container 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-7c07cf95-3b72-46bf-9675-48976851353b in RUNNING state
I0629 10:38:14.784418 5955 launcher.cpp:156] Asked to destroy container 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-7c07cf95-3b72-46bf-9675-48976851353b
I0629 10:38:15.597908 5945 hierarchical.cpp:1938] No allocations performed
I0629 10:38:15.597997 5945 hierarchical.cpp:2028] No inverse offers to send out!
I0629 10:38:15.598047 5945 hierarchical.cpp:1493] Performed allocation for 1 agents in 312482ns
I0629 10:38:16.599727 5941 hierarchical.cpp:1938] No allocations performed
I0629 10:38:16.599807 5941 hierarchical.cpp:2028] No inverse offers to send out!
I0629 10:38:16.599848 5941 hierarchical.cpp:1493] Performed allocation for 1 agents in 284137ns
I0629 10:38:17.601797 5945 hierarchical.cpp:1938] No allocations performed
I0629 10:38:17.602231 5945 hierarchical.cpp:2028] No inverse offers to send out!
I0629 10:38:17.602474 5945 hierarchical.cpp:1493] Performed allocation for 1 agents in 839836ns
I0629 10:38:18.604341 5935 hierarchical.cpp:1938] No allocations performed
I0629 10:38:18.604427 5935 hierarchical.cpp:2028] No inverse offers to send out!
I0629 10:38:18.604470 5935 hierarchical.cpp:1493] Performed allocation for 1 agents in 293064ns
../../src/tests/check_tests.cpp:1429: Failure
Failed to wait 15secs for updateCheckResult
../../src/tests/check_tests.cpp:1389: Failure
Actual function call count doesn't match EXPECT_CALL(*scheduler, update(_, _))...
Expected: to be called at least 4 times
Actual: called once - unsatisfied and active
I0629 10:38:18.890370 5947 containerizer.cpp:2101] Destroying container 97360a94-110c-43dc-87fe-c67fcd86606f in RUNNING state
I0629 10:38:18.890708 5941 master.cpp:1430] Framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000 (default) disconnected
I0629 10:38:18.891165 5941 master.cpp:3203] Deactivating framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000 (default)
I0629 10:38:18.891563 5939 hierarchical.cpp:410] Deactivated framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000
W0629 10:38:18.892401 5941 master.hpp:2377] Unable to send event to framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000 (default): connection closed
I0629 10:38:18.892494 5941 master.cpp:3180] Disconnecting framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000 (default)
I0629 10:38:18.892535 5941 master.cpp:1445] Giving framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000 (default) 0ns to failover
I0629 10:38:18.892709 5947 containerizer.cpp:2101] Destroying container 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241 in RUNNING state
I0629 10:38:18.892680 5957 hierarchical.cpp:1177] Recovered cpus(allocated: *):1.8; mem(allocated: *):960; disk(allocated: *):960; ports(allocated: *):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000], allocated: cpus(allocated: *):0.2; mem(allocated: *):64; disk(allocated: *):64) on agent 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0 from framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000
I0629 10:38:18.893929 5951 master.cpp:7306] Framework failover timeout, removing framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000 (default)
I0629 10:38:18.894135 5951 master.cpp:8163] Removing framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000 (default)
I0629 10:38:18.894557 5951 master.cpp:8731] Updating the state of task 4014e448-96a8-4d54-a860-dfd42f6234cf of framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000 (latest state: TASK_KILLED, status update state: TASK_KILLED)
I0629 10:38:18.894575 5944 slave.cpp:3136] Asked to shut down framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000 by master@172.17.0.6:43517
I0629 10:38:18.894795 5944 slave.cpp:3161] Shutting down framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000
I0629 10:38:18.894870 5944 slave.cpp:5631] Shutting down executor 'default' of framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000 (via HTTP)
I0629 10:38:18.895306 5951 master.cpp:8825] Removing task 4014e448-96a8-4d54-a860-dfd42f6234cf with resources [{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":32.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"disk","scalar":{"value":32.0},"type":"SCALAR"}] of framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000 on agent 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0 at slave(20)@172.17.0.6:43517 (d89378cfb216)
I0629 10:38:18.895622 5936 hierarchical.cpp:1177] Recovered cpus(allocated: *):0.1; mem(allocated: *):32; disk(allocated: *):32 (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000], allocated: cpus(allocated: *):0.1; mem(allocated: *):32; disk(allocated: *):32) on agent 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0 from framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000
I0629 10:38:18.895954 5951 master.cpp:8854] Removing executor 'default' with resources [{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":32.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"disk","scalar":{"value":32.0},"type":"SCALAR"}] of framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000 on agent 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0 at slave(20)@172.17.0.6:43517 (d89378cfb216)
I0629 10:38:18.896715 5945 hierarchical.cpp:1177] Recovered cpus(allocated: *):0.1; mem(allocated: *):32; disk(allocated: *):32 (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000], allocated: {}) on agent 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0 from framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000
I0629 10:38:18.897039 5945 hierarchical.cpp:353] Removed framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000
I0629 10:38:18.900172 5947 process.cpp:3779] Handling HTTP event for process 'slave(20)' with path: '/slave(20)/api/v1'
I0629 10:38:18.901003 5955 http.cpp:1114] HTTP POST for /slave(20)/api/v1 from 172.17.0.6:56250
I0629 10:38:18.901542 5955 http.cpp:532] Processing call KILL_NESTED_CONTAINER
I0629 10:38:19.605898 5945 hierarchical.cpp:1938] No allocations performed
I0629 10:38:19.606009 5945 hierarchical.cpp:1493] Performed allocation for 1 agents in 294202ns
I0629 10:38:19.787919 5959 switchboard.cpp:789] Sending SIGTERM to I/O switchboard server (pid: 6876) since container 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-7c07cf95-3b72-46bf-9675-48976851353b is being destroyed
E0629 10:38:19.872403 5942 switchboard.cpp:904] Unexpected termination of I/O switchboard server: 'IOSwitchboard' terminated with signal Terminated for container 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-7c07cf95-3b72-46bf-9675-48976851353b
E0629 10:38:19.873018 5942 switchboard.cpp:834] Failed to remove unix domain socket file '/tmp/mesos-io-switchboard-a090036e-ba73-487d-91ed-614a353e92d7' for container '97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-7c07cf95-3b72-46bf-9675-48976851353b': No such file or directory
I0629 10:38:19.874934 5942 provisioner.cpp:490] Ignoring destroy request for unknown container 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-7c07cf95-3b72-46bf-9675-48976851353b
I0629 10:38:19.875092 5942 containerizer.cpp:2380] Checkpointing termination state to nested container's runtime directory '/tmp/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_LL4ThO/containers/97360a94-110c-43dc-87fe-c67fcd86606f/containers/2efe2fc8-dd4a-42ad-b387-4015f764f241/containers/check-7c07cf95-3b72-46bf-9675-48976851353b/termination'
I0629 10:38:19.876178 5942 launcher.cpp:156] Asked to destroy container 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241
I0629 10:38:19.882293 5937 process.cpp:3836] Failed to process request for '/slave(20)/api/v1': I/O switchboard has shutdown
W0629 10:38:19.882519 5937 http.cpp:2861] Failed to attach to nested container 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-7c07cf95-3b72-46bf-9675-48976851353b: I/O switchboard has shutdown
I0629 10:38:19.882694 5937 process.cpp:1495] Returning '500 Internal Server Error' for '/slave(20)/api/v1' (I/O switchboard has shutdown)
W0629 10:38:19.893316 5942 containerizer.cpp:2089] Attempted to destroy unknown container 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-7c07cf95-3b72-46bf-9675-48976851353b
I0629 10:38:19.974308 5957 containerizer.cpp:2507] Container 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241 has exited
I0629 10:38:19.975914 5946 provisioner.cpp:490] Ignoring destroy request for unknown container 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241
I0629 10:38:19.976106 5941 containerizer.cpp:2380] Checkpointing termination state to nested container's runtime directory '/tmp/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_LL4ThO/containers/97360a94-110c-43dc-87fe-c67fcd86606f/containers/2efe2fc8-dd4a-42ad-b387-4015f764f241/termination'
I0629 10:38:19.978129 5941 launcher.cpp:156] Asked to destroy container 97360a94-110c-43dc-87fe-c67fcd86606f
I0629 10:38:20.076380 5937 containerizer.cpp:2507] Container 97360a94-110c-43dc-87fe-c67fcd86606f has exited
I0629 10:38:20.080268 5937 provisioner.cpp:490] Ignoring destroy request for unknown container 97360a94-110c-43dc-87fe-c67fcd86606f
I0629 10:38:20.082012 5937 slave.cpp:5309] Executor 'default' of framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000 terminated with signal Killed
I0629 10:38:20.082166 5937 slave.cpp:5409] Cleaning up executor 'default' of framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000 (via HTTP)
I0629 10:38:20.082592 5937 slave.cpp:5505] Cleaning up framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000
W0629 10:38:20.082988 5937 master.cpp:6770] Ignoring unknown exited executor 'default' of framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000 on agent 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0 at slave(20)@172.17.0.6:43517 (d89378cfb216)
I0629 10:38:20.083050 5937 gc.cpp:55] Scheduling '/tmp/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_oYU8Ko/slaves/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0/frameworks/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000/executors/default/runs/97360a94-110c-43dc-87fe-c67fcd86606f' for gc 6.99999904726815days in the future
I0629 10:38:20.083209 5937 gc.cpp:55] Scheduling '/tmp/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_oYU8Ko/slaves/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0/frameworks/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000/executors/default' for gc 6.99999904497778days in the future
I0629 10:38:20.083329 5937 gc.cpp:55] Scheduling '/tmp/DefaultExecutorCheckTest_CommandCheckDeliveredAndReconciled_oYU8Ko/slaves/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0/frameworks/17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000' for gc 6.99999904293926days in the future
I0629 10:38:20.083444 5937 status_update_manager.cpp:285] Closing status update streams for framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000
I0629 10:38:20.083487 5937 status_update_manager.cpp:531] Cleaning up status update stream for task 4014e448-96a8-4d54-a860-dfd42f6234cf of framework 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-0000
W0629 10:38:20.084676 5940 containerizer.cpp:2089] Attempted to destroy unknown container 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241
W0629 10:38:20.085372 5940 containerizer.cpp:2089] Attempted to destroy unknown container 97360a94-110c-43dc-87fe-c67fcd86606f.2efe2fc8-dd4a-42ad-b387-4015f764f241.check-7c07cf95-3b72-46bf-9675-48976851353b
I0629 10:38:20.086882 5916 slave.cpp:818] Agent terminating
I0629 10:38:20.091439 5916 master.cpp:1158] Master terminating
I0629 10:38:20.093300 5946 hierarchical.cpp:620] Removed agent 17dc2f22-3e22-438d-a2f3-63bb6ce22f6d-S0
[ FAILED ] DefaultExecutorCheckTest.CommandCheckDeliveredAndReconciled (23566 ms)
{code}
> Various DefaultExecutorCheckTest* tests flaky on ASF CI
> -------------------------------------------------------
>
> Key: MESOS-7440
> URL: https://issues.apache.org/jira/browse/MESOS-7440
> Project: Mesos
> Issue Type: Bug
> Components: test
> Environment: ASF CI: Configuration autotools,gcc,--verbose --enable-libevent --enable-ssl,GLOG_v=1 MESOS_VERBOSE=1,ubuntu:14.04,(docker||Hadoop)&&(!ubuntu-us1)&&(!ubuntu-eu2)
> Reporter: Yan Xu
> Labels: flaky
> Attachments: log.txt
>
>
> {noformat:title=}
> [ FAILED ] DefaultExecutorCheckTest.CommandCheckDeliveredAndReconciled
> [ FAILED ] DefaultExecutorCheckTest.CommandCheckStatusChange
> [ FAILED ] DefaultExecutorCheckTest.CommandCheckTimeout
> [ FAILED ] DefaultExecutorCheckTest.HTTPCheckDelivered
> {noformat}
> See [jenkins|https://builds.apache.org/job/Mesos-Buildbot/BUILDTOOL=autotools,COMPILER=gcc,CONFIGURATION=--verbose%20--enable-libevent%20--enable-ssl,ENVIRONMENT=GLOG_v=1%20MESOS_VERBOSE=1,OS=ubuntu:14.04,label_exp=(docker%7C%7CHadoop)&&(!ubuntu-us1)&&(!ubuntu-eu2)/3585/consoleFull] or attached logs.
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)