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)

Reply via email to