On Tue, May 30, 2017 at 2:36 PM, Vinod Kone <vinodk...@apache.org> wrote: > Ran on ASF CI. > > Found following issues. > > Failed test: CommandExecutorCheckTest.CommandCheckDeliveredAndReconciled > <https://builds.apache.org/view/M-R/view/Mesos/job/Mesos-Release/36/BUILDTOOL=autotools,COMPILER=gcc,CONFIGURATION=--verbose%20--enable-libevent%20--enable-ssl,ENVIRONMENT=GLOG_v=1%20MESOS_VERBOSE=1,OS=centos:7,label_exp=(docker%7C%7CHadoop)&&(!ubuntu-us1)&&(!ubuntu-eu2)/console>
Attached is the test log for this failure. From a quick look, seems as though the agent starts to launch the task, including forking the child process, but no subsequent task status updates or error messages are observed. Gaston, have you seen this before? I filed https://issues.apache.org/jira/browse/MESOS-7589 to track this. > Failed test: OneWayPartitionTest.MasterToSlave > <https://builds.apache.org/view/M-R/view/Mesos/job/Mesos-Release/36/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)/console> Looking into this now. Neil
[ RUN ] CommandExecutorCheckTest.CommandCheckDeliveredAndReconciled I0525 16:55:27.473031 2250 cluster.cpp:162] Creating default 'local' authorizer I0525 16:55:27.475637 2280 master.cpp:436] Master b97c30ee-bdab-4879-ba55-5d32f822c038 (305d67e5598a) started on 172.17.0.2:40622 I0525 16:55:27.475666 2280 master.cpp:438] 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/UqWhgS/credentials" --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.3.0/_inst/share/mesos/webui" --work_dir="/tmp/UqWhgS/master" --zk_session_timeout="10secs" I0525 16:55:27.475993 2280 master.cpp:488] Master only allowing authenticated frameworks to register I0525 16:55:27.476006 2280 master.cpp:502] Master only allowing authenticated agents to register I0525 16:55:27.476013 2280 master.cpp:515] Master only allowing authenticated HTTP frameworks to register I0525 16:55:27.476022 2280 credentials.hpp:37] Loading credentials for authentication from '/tmp/UqWhgS/credentials' I0525 16:55:27.476297 2280 master.cpp:560] Using default 'crammd5' authenticator I0525 16:55:27.476441 2280 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly' I0525 16:55:27.476702 2280 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite' I0525 16:55:27.476845 2280 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler' I0525 16:55:27.476972 2280 master.cpp:640] Authorization enabled I0525 16:55:27.477180 2272 whitelist_watcher.cpp:77] No whitelist given I0525 16:55:27.477191 2270 hierarchical.cpp:158] Initialized hierarchical allocator process I0525 16:55:27.480708 2284 master.cpp:2161] Elected as the leading master! I0525 16:55:27.480739 2284 master.cpp:1700] Recovering from registrar I0525 16:55:27.480864 2285 registrar.cpp:345] Recovering registrar I0525 16:55:27.481547 2285 registrar.cpp:389] Successfully fetched the registry (0B) in 645888ns I0525 16:55:27.481663 2285 registrar.cpp:493] Applied 1 operations in 22833ns; attempting to update the registry I0525 16:55:27.482271 2285 registrar.cpp:550] Successfully updated the registry in 556032ns I0525 16:55:27.482409 2285 registrar.cpp:422] Successfully recovered registrar I0525 16:55:27.482946 2277 hierarchical.cpp:185] Skipping recovery of hierarchical allocator: nothing to recover I0525 16:55:27.482945 2286 master.cpp:1799] Recovered 0 agents from the registry (129B); allowing 10mins for agents to re-register I0525 16:55:27.487871 2250 containerizer.cpp:221] Using isolation: posix/cpu,posix/mem,filesystem/posix,network/cni W0525 16:55:27.488440 2250 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges W0525 16:55:27.488562 2250 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges I0525 16:55:27.488612 2250 provisioner.cpp:249] Using default backend 'copy' I0525 16:55:27.490339 2250 cluster.cpp:448] Creating default 'local' authorizer I0525 16:55:27.492072 2283 slave.cpp:225] Mesos agent started on (12)@172.17.0.2:40622 I0525 16:55:27.492094 2283 slave.cpp:226] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://"; --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http_executors="true" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --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/CommandExecutorCheckTest_CommandCheckDeliveredAndReconciled_0pyiCR/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/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_secret_key="/tmp/CommandExecutorCheckTest_CommandCheckDeliveredAndReconciled_0pyiCR/executor_secret_key" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/CommandExecutorCheckTest_CommandCheckDeliveredAndReconciled_0pyiCR/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/CommandExecutorCheckTest_CommandCheckDeliveredAndReconciled_0pyiCR/http_credentials" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/mesos/mesos-1.3.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/CommandExecutorCheckTest_CommandCheckDeliveredAndReconciled_0pyiCR" --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/CommandExecutorCheckTest_CommandCheckDeliveredAndReconciled_W0LhWR" I0525 16:55:27.492513 2283 credentials.hpp:86] Loading credential for authentication from '/tmp/CommandExecutorCheckTest_CommandCheckDeliveredAndReconciled_0pyiCR/credential' I0525 16:55:27.492696 2283 slave.cpp:258] Agent using credential for: test-principal I0525 16:55:27.492718 2283 credentials.hpp:37] Loading credentials for authentication from '/tmp/CommandExecutorCheckTest_CommandCheckDeliveredAndReconciled_0pyiCR/http_credentials' I0525 16:55:27.493023 2283 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-executor' I0525 16:55:27.493059 2250 scheduler.cpp:184] Version: 1.3.0 I0525 16:55:27.493160 2283 http.cpp:996] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-executor' I0525 16:55:27.493470 2283 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly' I0525 16:55:27.493571 2283 http.cpp:996] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-readonly' I0525 16:55:27.493700 2269 scheduler.cpp:470] New master detected at master@172.17.0.2:40622 I0525 16:55:27.493772 2283 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite' I0525 16:55:27.493882 2283 http.cpp:996] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-readwrite' I0525 16:55:27.495227 2269 scheduler.cpp:479] Waiting for 0ns before initiating a re-(connection) attempt with the master I0525 16:55:27.495391 2283 slave.cpp:525] Agent resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I0525 16:55:27.495488 2283 slave.cpp:533] Agent attributes: [ ] I0525 16:55:27.495503 2283 slave.cpp:538] Agent hostname: 305d67e5598a I0525 16:55:27.495632 2277 status_update_manager.cpp:177] Pausing sending status updates I0525 16:55:27.497735 2287 state.cpp:62] Recovering state from '/tmp/CommandExecutorCheckTest_CommandCheckDeliveredAndReconciled_W0LhWR/meta' I0525 16:55:27.498019 2270 status_update_manager.cpp:203] Recovering status update manager I0525 16:55:27.498220 2279 containerizer.cpp:608] Recovering containerizer I0525 16:55:27.498343 2270 scheduler.cpp:361] Connected with the master at http://172.17.0.2:40622/master/api/v1/scheduler I0525 16:55:27.500072 2289 provisioner.cpp:410] Provisioner recovery complete I0525 16:55:27.500449 2277 slave.cpp:5970] Finished recovery I0525 16:55:27.500931 2277 slave.cpp:6152] Querying resource estimator for oversubscribable resources I0525 16:55:27.501181 2273 status_update_manager.cpp:177] Pausing sending status updates I0525 16:55:27.501183 2277 slave.cpp:918] New master detected at master@172.17.0.2:40622 I0525 16:55:27.501293 2277 slave.cpp:953] Detecting new master I0525 16:55:27.501430 2277 slave.cpp:6166] Received oversubscribable resources {} from the resource estimator I0525 16:55:27.507483 2282 slave.cpp:980] Authenticating with master master@172.17.0.2:40622 I0525 16:55:27.507571 2282 slave.cpp:991] Using default CRAM-MD5 authenticatee I0525 16:55:27.507817 2289 authenticatee.cpp:121] Creating new client SASL connection I0525 16:55:27.508098 2288 master.cpp:7475] Authenticating slave(12)@172.17.0.2:40622 I0525 16:55:27.508242 2278 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(34)@172.17.0.2:40622 I0525 16:55:27.508467 2287 authenticator.cpp:98] Creating new server SASL connection I0525 16:55:27.508692 2273 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 I0525 16:55:27.508730 2273 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' I0525 16:55:27.508836 2285 authenticator.cpp:204] Received SASL authentication start I0525 16:55:27.508896 2285 authenticator.cpp:326] Authentication requires more steps I0525 16:55:27.508988 2273 authenticatee.cpp:259] Received SASL authentication step I0525 16:55:27.509156 2271 authenticator.cpp:232] Received SASL authentication step I0525 16:55:27.509194 2271 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '305d67e5598a' server FQDN: '305d67e5598a' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0525 16:55:27.509209 2271 auxprop.cpp:181] Looking up auxiliary property '*userPassword' I0525 16:55:27.509253 2271 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0525 16:55:27.509276 2271 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '305d67e5598a' server FQDN: '305d67e5598a' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0525 16:55:27.509289 2271 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0525 16:55:27.509296 2271 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0525 16:55:27.509313 2271 authenticator.cpp:318] Authentication success I0525 16:55:27.509388 2285 authenticatee.cpp:299] Authentication success I0525 16:55:27.509544 2270 master.cpp:7505] Successfully authenticated principal 'test-principal' at slave(12)@172.17.0.2:40622 I0525 16:55:27.509660 2277 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(34)@172.17.0.2:40622 I0525 16:55:27.509722 2275 slave.cpp:1075] Successfully authenticated with master master@172.17.0.2:40622 I0525 16:55:27.509948 2275 slave.cpp:1503] Will retry registration in 11.150028ms if necessary I0525 16:55:27.510116 2284 master.cpp:5429] Received register agent message from slave(12)@172.17.0.2:40622 (305d67e5598a) I0525 16:55:27.510247 2284 master.cpp:3659] Authorizing agent with principal 'test-principal' I0525 16:55:27.510843 2286 master.cpp:5564] Registering agent at slave(12)@172.17.0.2:40622 (305d67e5598a) with id b97c30ee-bdab-4879-ba55-5d32f822c038-S0 I0525 16:55:27.511317 2273 registrar.cpp:493] Applied 1 operations in 67935ns; attempting to update the registry I0525 16:55:27.511989 2273 registrar.cpp:550] Successfully updated the registry in 608us I0525 16:55:27.512789 2271 slave.cpp:4745] Received ping from slave-observer(9)@172.17.0.2:40622 I0525 16:55:27.513079 2279 slave.cpp:1121] Registered with master master@172.17.0.2:40622; given agent ID b97c30ee-bdab-4879-ba55-5d32f822c038-S0 I0525 16:55:27.513108 2279 fetcher.cpp:94] Clearing fetcher cache I0525 16:55:27.513006 2287 master.cpp:5639] Registered agent b97c30ee-bdab-4879-ba55-5d32f822c038-S0 at slave(12)@172.17.0.2:40622 (305d67e5598a) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I0525 16:55:27.513247 2271 status_update_manager.cpp:184] Resuming sending status updates I0525 16:55:27.513339 2291 hierarchical.cpp:525] Added agent b97c30ee-bdab-4879-ba55-5d32f822c038-S0 (305d67e5598a) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: {}) I0525 16:55:27.513483 2279 slave.cpp:1149] Checkpointing SlaveInfo to '/tmp/CommandExecutorCheckTest_CommandCheckDeliveredAndReconciled_W0LhWR/meta/slaves/b97c30ee-bdab-4879-ba55-5d32f822c038-S0/slave.info' I0525 16:55:27.513586 2291 hierarchical.cpp:1850] No allocations performed I0525 16:55:27.513638 2291 hierarchical.cpp:1434] Performed allocation for 1 agents in 166218ns I0525 16:55:27.513805 2279 slave.cpp:1187] Forwarding total oversubscribed resources {} I0525 16:55:27.513974 2285 master.cpp:6324] Received update of agent b97c30ee-bdab-4879-ba55-5d32f822c038-S0 at slave(12)@172.17.0.2:40622 (305d67e5598a) with total oversubscribed resources {} I0525 16:55:27.500349 2292 scheduler.cpp:243] Sending SUBSCRIBE call to http://172.17.0.2:40622/master/api/v1/scheduler I0525 16:55:27.515352 2287 process.cpp:3731] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler' I0525 16:55:27.517225 2292 http.cpp:1115] HTTP POST for /master/api/v1/scheduler from 172.17.0.2:37592 I0525 16:55:27.517470 2292 master.cpp:2513] Received subscription request for HTTP framework 'default' I0525 16:55:27.517668 2292 master.cpp:2197] Authorizing framework principal 'test-principal' to receive offers for roles '{ * }' I0525 16:55:27.518112 2277 master.cpp:2628] Subscribing framework 'default' with checkpointing disabled and capabilities [ ] I0525 16:55:27.519039 2278 hierarchical.cpp:273] Added framework b97c30ee-bdab-4879-ba55-5d32f822c038-0000 I0525 16:55:27.519259 2273 master.hpp:2194] Sending heartbeat to b97c30ee-bdab-4879-ba55-5d32f822c038-0000 I0525 16:55:27.520114 2271 scheduler.cpp:676] Enqueuing event SUBSCRIBED received from http://172.17.0.2:40622/master/api/v1/scheduler I0525 16:55:27.520591 2278 hierarchical.cpp:1940] No inverse offers to send out! I0525 16:55:27.520654 2278 hierarchical.cpp:1434] Performed allocation for 1 agents in 1.463701ms I0525 16:55:27.520817 2271 scheduler.cpp:676] Enqueuing event HEARTBEAT received from http://172.17.0.2:40622/master/api/v1/scheduler I0525 16:55:27.521289 2270 master.cpp:7305] Sending 1 offers to framework b97c30ee-bdab-4879-ba55-5d32f822c038-0000 (default) I0525 16:55:27.523448 2279 scheduler.cpp:676] Enqueuing event OFFERS received from http://172.17.0.2:40622/master/api/v1/scheduler I0525 16:55:27.526424 2277 scheduler.cpp:243] Sending ACCEPT call to http://172.17.0.2:40622/master/api/v1/scheduler I0525 16:55:27.527422 2290 process.cpp:3731] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler' I0525 16:55:27.528816 2292 http.cpp:1115] HTTP POST for /master/api/v1/scheduler from 172.17.0.2:37590 I0525 16:55:27.529896 2292 master.cpp:3875] Processing ACCEPT call for offers: [ b97c30ee-bdab-4879-ba55-5d32f822c038-O0 ] on agent b97c30ee-bdab-4879-ba55-5d32f822c038-S0 at slave(12)@172.17.0.2:40622 (305d67e5598a) for framework b97c30ee-bdab-4879-ba55-5d32f822c038-0000 (default) I0525 16:55:27.529996 2292 master.cpp:3426] Authorizing framework principal 'test-principal' to launch task 36b26131-1b47-40f6-ae71-983bf92607e8 I0525 16:55:27.532521 2292 master.cpp:9320] Adding task 36b26131-1b47-40f6-ae71-983bf92607e8 with resources cpus(*)(allocated: *):0.1; mem(*)(allocated: *):32; disk(*)(allocated: *):32 on agent b97c30ee-bdab-4879-ba55-5d32f822c038-S0 at slave(12)@172.17.0.2:40622 (305d67e5598a) I0525 16:55:27.532763 2292 master.cpp:4531] Launching task 36b26131-1b47-40f6-ae71-983bf92607e8 of framework b97c30ee-bdab-4879-ba55-5d32f822c038-0000 (default) with resources cpus(*)(allocated: *):0.1; mem(*)(allocated: *):32; disk(*)(allocated: *):32 on agent b97c30ee-bdab-4879-ba55-5d32f822c038-S0 at slave(12)@172.17.0.2:40622 (305d67e5598a) I0525 16:55:27.533684 2272 slave.cpp:1613] Got assigned task '36b26131-1b47-40f6-ae71-983bf92607e8' for framework b97c30ee-bdab-4879-ba55-5d32f822c038-0000 I0525 16:55:27.534471 2272 slave.cpp:1894] Authorizing task '36b26131-1b47-40f6-ae71-983bf92607e8' for framework b97c30ee-bdab-4879-ba55-5d32f822c038-0000 I0525 16:55:27.534545 2272 slave.cpp:6589] Authorizing framework principal 'test-principal' to launch task 36b26131-1b47-40f6-ae71-983bf92607e8 I0525 16:55:27.535441 2273 slave.cpp:2081] Launching task '36b26131-1b47-40f6-ae71-983bf92607e8' for framework b97c30ee-bdab-4879-ba55-5d32f822c038-0000 I0525 16:55:27.535605 2280 hierarchical.cpp:850] Updated allocation of framework b97c30ee-bdab-4879-ba55-5d32f822c038-0000 on agent b97c30ee-bdab-4879-ba55-5d32f822c038-S0 from cpus(*)(allocated: *):2; mem(*)(allocated: *):1024; disk(*)(allocated: *):1024; ports(*)(allocated: *):[31000-32000] to cpus(*)(allocated: *):2; mem(*)(allocated: *):1024; disk(*)(allocated: *):1024; ports(*)(allocated: *):[31000-32000] I0525 16:55:27.536135 2273 paths.cpp:573] Trying to chown '/tmp/CommandExecutorCheckTest_CommandCheckDeliveredAndReconciled_W0LhWR/slaves/b97c30ee-bdab-4879-ba55-5d32f822c038-S0/frameworks/b97c30ee-bdab-4879-ba55-5d32f822c038-0000/executors/36b26131-1b47-40f6-ae71-983bf92607e8/runs/0e478f45-a711-4b74-b801-43a1733628ba' to user 'mesos' I0525 16:55:27.536381 2280 hierarchical.cpp:1114] Recovered cpus(*)(allocated: *):1.9; mem(*)(allocated: *):992; disk(*)(allocated: *):992; ports(*)(allocated: *):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*)(allocated: *):0.1; mem(*)(allocated: *):32; disk(*)(allocated: *):32) on agent b97c30ee-bdab-4879-ba55-5d32f822c038-S0 from framework b97c30ee-bdab-4879-ba55-5d32f822c038-0000 I0525 16:55:27.536453 2280 hierarchical.cpp:1151] Framework b97c30ee-bdab-4879-ba55-5d32f822c038-0000 filtered agent b97c30ee-bdab-4879-ba55-5d32f822c038-S0 for 5secs I0525 16:55:27.536437 2273 slave.cpp:6933] Launching executor '36b26131-1b47-40f6-ae71-983bf92607e8' of framework b97c30ee-bdab-4879-ba55-5d32f822c038-0000 with resources cpus(*)(allocated: *):0.1; mem(*)(allocated: *):32 in work directory '/tmp/CommandExecutorCheckTest_CommandCheckDeliveredAndReconciled_W0LhWR/slaves/b97c30ee-bdab-4879-ba55-5d32f822c038-S0/frameworks/b97c30ee-bdab-4879-ba55-5d32f822c038-0000/executors/36b26131-1b47-40f6-ae71-983bf92607e8/runs/0e478f45-a711-4b74-b801-43a1733628ba' I0525 16:55:27.537381 2273 slave.cpp:2310] Queued task '36b26131-1b47-40f6-ae71-983bf92607e8' for executor '36b26131-1b47-40f6-ae71-983bf92607e8' of framework b97c30ee-bdab-4879-ba55-5d32f822c038-0000 I0525 16:55:27.537457 2273 slave.cpp:871] Successfully attached file '/tmp/CommandExecutorCheckTest_CommandCheckDeliveredAndReconciled_W0LhWR/slaves/b97c30ee-bdab-4879-ba55-5d32f822c038-S0/frameworks/b97c30ee-bdab-4879-ba55-5d32f822c038-0000/executors/36b26131-1b47-40f6-ae71-983bf92607e8/runs/0e478f45-a711-4b74-b801-43a1733628ba' I0525 16:55:27.538044 2290 containerizer.cpp:1001] Starting container 0e478f45-a711-4b74-b801-43a1733628ba for executor '36b26131-1b47-40f6-ae71-983bf92607e8' of framework b97c30ee-bdab-4879-ba55-5d32f822c038-0000 I0525 16:55:27.546634 2290 containerizer.cpp:1524] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"arguments":["mesos-executor","--launcher_dir=\/mesos\/mesos-1.3.0\/_build\/src"],"shell":false,"value":"\/mesos\/mesos-1.3.0\/_build\/src\/mesos-executor"},"environment":{"variables":[{"name":"LIBPROCESS_PORT","type":"VALUE","value":"0"},{"name":"MESOS_AGENT_ENDPOINT","type":"VALUE","value":"172.17.0.2:40622"},{"name":"MESOS_CHECKPOINT","type":"VALUE","value":"0"},{"name":"MESOS_DIRECTORY","type":"VALUE","value":"\/tmp\/CommandExecutorCheckTest_CommandCheckDeliveredAndReconciled_W0LhWR\/slaves\/b97c30ee-bdab-4879-ba55-5d32f822c038-S0\/frameworks\/b97c30ee-bdab-4879-ba55-5d32f822c038-0000\/executors\/36b26131-1b47-40f6-ae71-983bf92607e8\/runs\/0e478f45-a711-4b74-b801-43a1733628ba"},{"name":"MESOS_EXECUTOR_AUTHENTICATION_TOKEN","type":"VALUE","value":"eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJjaWQiOiIwZTQ3OGY0NS1hNzExLTRiNzQtYjgwMS00M2ExNzMzNjI4YmEiLCJlaWQiOiIzNmIyNjEzMS0xYjQ3LTQwZjYtYWU3MS05ODNiZjkyNjA3ZTgiLCJmaWQiOiJiOTdjMzBlZS1iZGFiLTQ4NzktYmE1NS01ZDMyZjgyMmMwMzgtMDAwMCJ9.y9E9nJ2oSp8X4m9xNlcIKwgJXT9g93qiA7HAPdeOZTA"},{"name":"MESOS_EXECUTOR_ID","type":"VALUE","value":"36b26131-1b47-40f6-ae71-983bf92607e8"},{"name":"MESOS_EXECUTOR_SHUTDOWN_GRACE_PERIOD","type":"VALUE","value":"5secs"},{"name":"MESOS_FRAMEWORK_ID","type":"VALUE","value":"b97c30ee-bdab-4879-ba55-5d32f822c038-0000"},{"name":"MESOS_HTTP_COMMAND_EXECUTOR","type":"VALUE","value":"0"},{"name":"MESOS_SLAVE_ID","type":"VALUE","value":"b97c30ee-bdab-4879-ba55-5d32f822c038-S0"},{"name":"MESOS_SLAVE_PID","type":"VALUE","value":"slave(12)@172.17.0.2:40622"},{"name":"MESOS_SANDBOX","type":"VALUE","value":"\/tmp\/CommandExecutorCheckTest_CommandCheckDeliveredAndReconciled_W0LhWR\/slaves\/b97c30ee-bdab-4879-ba55-5d32f822c038-S0\/frameworks\/b97c30ee-bdab-4879-ba55-5d32f822c038-0000\/executors\/36b26131-1b47-40f6-ae71-983bf92607e8\/runs\/0e478f45-a711-4b74-b801-43a1733628ba"}]},"user":"mesos","working_directory":"\/tmp\/CommandExecutorCheckTest_CommandCheckDeliveredAndReconciled_W0LhWR\/slaves\/b97c30ee-bdab-4879-ba55-5d32f822c038-S0\/frameworks\/b97c30ee-bdab-4879-ba55-5d32f822c038-0000\/executors\/36b26131-1b47-40f6-ae71-983bf92607e8\/runs\/0e478f45-a711-4b74-b801-43a1733628ba"}" --pipe_read="11" --pipe_write="12" --runtime_directory="/tmp/CommandExecutorCheckTest_CommandCheckDeliveredAndReconciled_0pyiCR/containers/0e478f45-a711-4b74-b801-43a1733628ba" --unshare_namespace_mnt="false"' I0525 16:55:27.549115 2290 launcher.cpp:140] Forked child with pid '2305' for container '0e478f45-a711-4b74-b801-43a1733628ba' I0525 16:55:27.554666 2277 fetcher.cpp:353] Starting to fetch URIs for container: 0e478f45-a711-4b74-b801-43a1733628ba, directory: /tmp/CommandExecutorCheckTest_CommandCheckDeliveredAndReconciled_W0LhWR/slaves/b97c30ee-bdab-4879-ba55-5d32f822c038-S0/frameworks/b97c30ee-bdab-4879-ba55-5d32f822c038-0000/executors/36b26131-1b47-40f6-ae71-983bf92607e8/runs/0e478f45-a711-4b74-b801-43a1733628ba I0525 16:55:28.479254 2278 hierarchical.cpp:2084] Filtered offer with cpus(*):1.9; mem(*):992; disk(*):992; ports(*):[31000-32000] on agent b97c30ee-bdab-4879-ba55-5d32f822c038-S0 for role * of framework b97c30ee-bdab-4879-ba55-5d32f822c038-0000 I0525 16:55:28.479354 2278 hierarchical.cpp:1850] No allocations performed I0525 16:55:28.479432 2278 hierarchical.cpp:1940] No inverse offers to send out! I0525 16:55:28.479534 2278 hierarchical.cpp:1434] Performed allocation for 1 agents in 1.327639ms I0525 16:55:29.481426 2270 hierarchical.cpp:2084] Filtered offer with cpus(*):1.9; mem(*):992; disk(*):992; ports(*):[31000-32000] on agent b97c30ee-bdab-4879-ba55-5d32f822c038-S0 for role * of framework b97c30ee-bdab-4879-ba55-5d32f822c038-0000 I0525 16:55:29.481513 2270 hierarchical.cpp:1850] No allocations performed I0525 16:55:29.481570 2270 hierarchical.cpp:1940] No inverse offers to send out! I0525 16:55:29.481638 2270 hierarchical.cpp:1434] Performed allocation for 1 agents in 936616ns I0525 16:55:30.482831 2289 hierarchical.cpp:2084] Filtered offer with cpus(*):1.9; mem(*):992; disk(*):992; ports(*):[31000-32000] on agent b97c30ee-bdab-4879-ba55-5d32f822c038-S0 for role * of framework b97c30ee-bdab-4879-ba55-5d32f822c038-0000 I0525 16:55:30.482940 2289 hierarchical.cpp:1850] No allocations performed I0525 16:55:30.483003 2289 hierarchical.cpp:1940] No inverse offers to send out! I0525 16:55:30.483084 2289 hierarchical.cpp:1434] Performed allocation for 1 agents in 964699ns I0525 16:55:31.484776 2281 hierarchical.cpp:2084] Filtered offer with cpus(*):1.9; mem(*):992; disk(*):992; ports(*):[31000-32000] on agent b97c30ee-bdab-4879-ba55-5d32f822c038-S0 for role * of framework b97c30ee-bdab-4879-ba55-5d32f822c038-0000 I0525 16:55:31.484884 2281 hierarchical.cpp:1850] No allocations performed I0525 16:55:31.484949 2281 hierarchical.cpp:1940] No inverse offers to send out! I0525 16:55:31.485034 2281 hierarchical.cpp:1434] Performed allocation for 1 agents in 973084ns I0525 16:55:32.487136 2289 hierarchical.cpp:2084] Filtered offer with cpus(*):1.9; mem(*):992; disk(*):992; ports(*):[31000-32000] on agent b97c30ee-bdab-4879-ba55-5d32f822c038-S0 for role * of framework b97c30ee-bdab-4879-ba55-5d32f822c038-0000 I0525 16:55:32.487232 2289 hierarchical.cpp:1850] No allocations performed I0525 16:55:32.487304 2289 hierarchical.cpp:1940] No inverse offers to send out! I0525 16:55:32.487399 2289 hierarchical.cpp:1434] Performed allocation for 1 agents in 998902ns I0525 16:55:33.489687 2279 hierarchical.cpp:1940] No inverse offers to send out! I0525 16:55:33.489789 2279 hierarchical.cpp:1434] Performed allocation for 1 agents in 1.667498ms I0525 16:55:33.490720 2291 master.cpp:7305] Sending 1 offers to framework b97c30ee-bdab-4879-ba55-5d32f822c038-0000 (default) I0525 16:55:33.494283 2284 scheduler.cpp:676] Enqueuing event OFFERS received from http://172.17.0.2:40622/master/api/v1/scheduler I0525 16:55:34.490906 2269 hierarchical.cpp:1850] No allocations performed I0525 16:55:34.491021 2269 hierarchical.cpp:1940] No inverse offers to send out! I0525 16:55:34.491116 2269 hierarchical.cpp:1434] Performed allocation for 1 agents in 425063ns I0525 16:55:35.492594 2271 hierarchical.cpp:1850] No allocations performed I0525 16:55:35.492681 2271 hierarchical.cpp:1940] No inverse offers to send out! I0525 16:55:35.492766 2271 hierarchical.cpp:1434] Performed allocation for 1 agents in 379419ns I0525 16:55:36.494427 2270 hierarchical.cpp:1850] No allocations performed I0525 16:55:36.494618 2270 hierarchical.cpp:1940] No inverse offers to send out! I0525 16:55:36.494734 2270 hierarchical.cpp:1434] Performed allocation for 1 agents in 625711ns I0525 16:55:37.496234 2275 hierarchical.cpp:1850] No allocations performed I0525 16:55:37.496340 2275 hierarchical.cpp:1940] No inverse offers to send out! I0525 16:55:37.496454 2275 hierarchical.cpp:1434] Performed allocation for 1 agents in 394130ns I0525 16:55:38.497721 2274 hierarchical.cpp:1850] No allocations performed I0525 16:55:38.497834 2274 hierarchical.cpp:1940] No inverse offers to send out! I0525 16:55:38.497952 2274 hierarchical.cpp:1434] Performed allocation for 1 agents in 419us I0525 16:55:39.499193 2290 hierarchical.cpp:1850] No allocations performed I0525 16:55:39.499295 2290 hierarchical.cpp:1940] No inverse offers to send out! I0525 16:55:39.499377 2290 hierarchical.cpp:1434] Performed allocation for 1 agents in 441722ns I0525 16:55:40.500267 2278 hierarchical.cpp:1850] No allocations performed I0525 16:55:40.500411 2278 hierarchical.cpp:1940] No inverse offers to send out! I0525 16:55:40.500524 2278 hierarchical.cpp:1434] Performed allocation for 1 agents in 551752ns I0525 16:55:41.501482 2281 hierarchical.cpp:1850] No allocations performed I0525 16:55:41.501566 2281 hierarchical.cpp:1940] No inverse offers to send out! I0525 16:55:41.501641 2281 hierarchical.cpp:1434] Performed allocation for 1 agents in 296106ns I0525 16:55:42.501719 2290 slave.cpp:6152] Querying resource estimator for oversubscribable resources I0525 16:55:42.502305 2292 slave.cpp:6166] Received oversubscribable resources {} from the resource estimator I0525 16:55:42.503197 2275 hierarchical.cpp:1850] No allocations performed I0525 16:55:42.503281 2275 hierarchical.cpp:1940] No inverse offers to send out! I0525 16:55:42.503365 2275 hierarchical.cpp:1434] Performed allocation for 1 agents in 340650ns I0525 16:55:42.513365 2269 slave.cpp:4745] Received ping from slave-observer(9)@172.17.0.2:40622 I0525 16:55:42.520403 2279 master.hpp:2194] Sending heartbeat to b97c30ee-bdab-4879-ba55-5d32f822c038-0000 I0525 16:55:42.522338 2276 scheduler.cpp:676] Enqueuing event HEARTBEAT received from http://172.17.0.2:40622/master/api/v1/scheduler ../../src/tests/check_tests.cpp:324: Failure Failed to wait 15secs for updateTaskRunning ../../src/tests/check_tests.cpp:295: Failure Actual function call count doesn't match EXPECT_CALL(*scheduler, update(_, _))... Expected: to be called at least 4 times Actual: never called - unsatisfied and active I0525 16:55:42.529412 2279 master.cpp:1430] Framework b97c30ee-bdab-4879-ba55-5d32f822c038-0000 (default) disconnected I0525 16:55:42.529513 2279 master.cpp:3160] Deactivating framework b97c30ee-bdab-4879-ba55-5d32f822c038-0000 (default) I0525 16:55:42.529976 2283 hierarchical.cpp:374] Deactivated framework b97c30ee-bdab-4879-ba55-5d32f822c038-0000 W0525 16:55:42.530922 2279 master.hpp:2355] Unable to send event to framework b97c30ee-bdab-4879-ba55-5d32f822c038-0000 (default): connection closed I0525 16:55:42.531030 2271 containerizer.cpp:2102] Destroying container 0e478f45-a711-4b74-b801-43a1733628ba in RUNNING state I0525 16:55:42.531049 2279 master.cpp:3137] Disconnecting framework b97c30ee-bdab-4879-ba55-5d32f822c038-0000 (default) I0525 16:55:42.531390 2279 master.cpp:1445] Giving framework b97c30ee-bdab-4879-ba55-5d32f822c038-0000 (default) 0ns to failover I0525 16:55:42.531786 2269 hierarchical.cpp:1114] Recovered cpus(*)(allocated: *):1.9; mem(*)(allocated: *):992; disk(*)(allocated: *):992; ports(*)(allocated: *):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*)(allocated: *):0.1; mem(*)(allocated: *):32; disk(*)(allocated: *):32) on agent b97c30ee-bdab-4879-ba55-5d32f822c038-S0 from framework b97c30ee-bdab-4879-ba55-5d32f822c038-0000 I0525 16:55:42.531868 2283 master.cpp:7146] Framework failover timeout, removing framework b97c30ee-bdab-4879-ba55-5d32f822c038-0000 (default) I0525 16:55:42.531910 2283 master.cpp:8000] Removing framework b97c30ee-bdab-4879-ba55-5d32f822c038-0000 (default) I0525 16:55:42.532184 2277 slave.cpp:3057] Asked to shut down framework b97c30ee-bdab-4879-ba55-5d32f822c038-0000 by master@172.17.0.2:40622 I0525 16:55:42.532220 2283 master.cpp:8568] Updating the state of task 36b26131-1b47-40f6-ae71-983bf92607e8 of framework b97c30ee-bdab-4879-ba55-5d32f822c038-0000 (latest state: TASK_KILLED, status update state: TASK_KILLED) I0525 16:55:42.532263 2277 slave.cpp:3082] Shutting down framework b97c30ee-bdab-4879-ba55-5d32f822c038-0000 I0525 16:55:42.532353 2277 slave.cpp:5482] Shutting down executor '36b26131-1b47-40f6-ae71-983bf92607e8' of framework b97c30ee-bdab-4879-ba55-5d32f822c038-0000 I0525 16:55:42.532382 2271 launcher.cpp:156] Asked to destroy container 0e478f45-a711-4b74-b801-43a1733628ba W0525 16:55:42.532389 2277 slave.hpp:986] Unable to send event to executor '36b26131-1b47-40f6-ae71-983bf92607e8' of framework b97c30ee-bdab-4879-ba55-5d32f822c038-0000: unknown connection type I0525 16:55:42.533179 2283 master.cpp:8662] Removing task 36b26131-1b47-40f6-ae71-983bf92607e8 with resources cpus(*)(allocated: *):0.1; mem(*)(allocated: *):32; disk(*)(allocated: *):32 of framework b97c30ee-bdab-4879-ba55-5d32f822c038-0000 on agent b97c30ee-bdab-4879-ba55-5d32f822c038-S0 at slave(12)@172.17.0.2:40622 (305d67e5598a) I0525 16:55:42.534639 2290 hierarchical.cpp:1114] Recovered cpus(*)(allocated: *):0.1; mem(*)(allocated: *):32; disk(*)(allocated: *):32 (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: {}) on agent b97c30ee-bdab-4879-ba55-5d32f822c038-S0 from framework b97c30ee-bdab-4879-ba55-5d32f822c038-0000 I0525 16:55:42.535161 2290 hierarchical.cpp:325] Removed framework b97c30ee-bdab-4879-ba55-5d32f822c038-0000 I0525 16:55:42.573261 2291 containerizer.cpp:2508] Container 0e478f45-a711-4b74-b801-43a1733628ba has exited I0525 16:55:42.577396 2292 provisioner.cpp:484] Ignoring destroy request for unknown container 0e478f45-a711-4b74-b801-43a1733628ba I0525 16:55:42.578270 2289 slave.cpp:5168] Executor '36b26131-1b47-40f6-ae71-983bf92607e8' of framework b97c30ee-bdab-4879-ba55-5d32f822c038-0000 terminated with signal Killed I0525 16:55:42.578342 2289 slave.cpp:5268] Cleaning up executor '36b26131-1b47-40f6-ae71-983bf92607e8' of framework b97c30ee-bdab-4879-ba55-5d32f822c038-0000 I0525 16:55:42.578761 2280 gc.cpp:55] Scheduling '/tmp/CommandExecutorCheckTest_CommandCheckDeliveredAndReconciled_W0LhWR/slaves/b97c30ee-bdab-4879-ba55-5d32f822c038-S0/frameworks/b97c30ee-bdab-4879-ba55-5d32f822c038-0000/executors/36b26131-1b47-40f6-ae71-983bf92607e8/runs/0e478f45-a711-4b74-b801-43a1733628ba' for gc 6.9999933036563days in the future I0525 16:55:42.578927 2289 slave.cpp:5356] Cleaning up framework b97c30ee-bdab-4879-ba55-5d32f822c038-0000 I0525 16:55:42.579002 2280 gc.cpp:55] Scheduling '/tmp/CommandExecutorCheckTest_CommandCheckDeliveredAndReconciled_W0LhWR/slaves/b97c30ee-bdab-4879-ba55-5d32f822c038-S0/frameworks/b97c30ee-bdab-4879-ba55-5d32f822c038-0000/executors/36b26131-1b47-40f6-ae71-983bf92607e8' for gc 6.99999330035852days in the future I0525 16:55:42.579095 2276 status_update_manager.cpp:285] Closing status update streams for framework b97c30ee-bdab-4879-ba55-5d32f822c038-0000 I0525 16:55:42.582744 2279 gc.cpp:55] Scheduling '/tmp/CommandExecutorCheckTest_CommandCheckDeliveredAndReconciled_W0LhWR/slaves/b97c30ee-bdab-4879-ba55-5d32f822c038-S0/frameworks/b97c30ee-bdab-4879-ba55-5d32f822c038-0000' for gc 6.99999329575111days in the future I0525 16:55:42.582983 2284 slave.cpp:790] Agent terminating I0525 16:55:42.583328 2273 master.cpp:1313] Agent b97c30ee-bdab-4879-ba55-5d32f822c038-S0 at slave(12)@172.17.0.2:40622 (305d67e5598a) disconnected I0525 16:55:42.583376 2273 master.cpp:3197] Disconnecting agent b97c30ee-bdab-4879-ba55-5d32f822c038-S0 at slave(12)@172.17.0.2:40622 (305d67e5598a) I0525 16:55:42.583506 2273 master.cpp:3216] Deactivating agent b97c30ee-bdab-4879-ba55-5d32f822c038-S0 at slave(12)@172.17.0.2:40622 (305d67e5598a) I0525 16:55:42.583782 2271 hierarchical.cpp:653] Agent b97c30ee-bdab-4879-ba55-5d32f822c038-S0 deactivated I0525 16:55:42.588577 2280 master.cpp:1155] Master terminating I0525 16:55:42.589231 2269 hierarchical.cpp:558] Removed agent b97c30ee-bdab-4879-ba55-5d32f822c038-S0 [ FAILED ] CommandExecutorCheckTest.CommandCheckDeliveredAndReconciled (15122 ms)
