[
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
[email protected]: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
[email protected]: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
[email protected]: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 [email protected]: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
[email protected]: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 [email protected]: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 [email protected]: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)
