You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "Benjamin Mahler (JIRA)" <ji...@apache.org> on 2015/12/04 04:44:10 UTC
[jira] [Updated] (MESOS-4024) HealthCheckTest.CheckCommandTimeout
is flaky.
[ https://issues.apache.org/jira/browse/MESOS-4024?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Benjamin Mahler updated MESOS-4024:
-----------------------------------
Labels: flaky-test (was: )
Description:
{noformat: title=Failed Run}
[ RUN ] HealthCheckTest.CheckCommandTimeout
I1201 13:03:15.211911 30288 leveldb.cpp:174] Opened db in 126.548747ms
I1201 13:03:15.254041 30288 leveldb.cpp:181] Compacted db in 42.053948ms
I1201 13:03:15.254226 30288 leveldb.cpp:196] Created db iterator in 25588ns
I1201 13:03:15.254281 30288 leveldb.cpp:202] Seeked to beginning of db in 3231ns
I1201 13:03:15.254294 30288 leveldb.cpp:271] Iterated through 0 keys in the db in 256ns
I1201 13:03:15.254348 30288 replica.cpp:778] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I1201 13:03:15.255162 30311 recover.cpp:447] Starting replica recovery
I1201 13:03:15.255502 30311 recover.cpp:473] Replica is in EMPTY status
I1201 13:03:15.257158 30311 replica.cpp:674] Replica in EMPTY status received a broadcasted recover request from (1898)@172.17.21.0:52024
I1201 13:03:15.258224 30318 recover.cpp:193] Received a recover response from a replica in EMPTY status
I1201 13:03:15.259735 30310 recover.cpp:564] Updating replica status to STARTING
I1201 13:03:15.265080 30322 master.cpp:365] Master dd5bff66-362f-4efc-963a-54756b2edcce (fa812f474cf4) started on 172.17.21.0:52024
I1201 13:03:15.265121 30322 master.cpp:367] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="true" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/IaRntP/credentials" --framework_sorter="drf" --help="false" --hostname_lookup="true" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_slave_ping_timeouts="5" --quiet="false" --recovery_slave_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_store_timeout="25secs" --registry_strict="true" --root_submissions="true" --slave_ping_timeout="15secs" --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false" --webui_dir="/mesos/mesos-0.27.0/_inst/share/mesos/webui" --work_dir="/tmp/IaRntP/master" --zk_session_timeout="10secs"
I1201 13:03:15.265487 30322 master.cpp:412] Master only allowing authenticated frameworks to register
I1201 13:03:15.265504 30322 master.cpp:417] Master only allowing authenticated slaves to register
I1201 13:03:15.265513 30322 credentials.hpp:35] Loading credentials for authentication from '/tmp/IaRntP/credentials'
I1201 13:03:15.265842 30322 master.cpp:456] Using default 'crammd5' authenticator
I1201 13:03:15.266006 30322 master.cpp:493] Authorization enabled
I1201 13:03:15.266464 30308 hierarchical.cpp:162] Initialized hierarchical allocator process
I1201 13:03:15.267225 30321 whitelist_watcher.cpp:77] No whitelist given
I1201 13:03:15.268847 30322 master.cpp:1637] The newly elected leader is master@172.17.21.0:52024 with id dd5bff66-362f-4efc-963a-54756b2edcce
I1201 13:03:15.268887 30322 master.cpp:1650] Elected as the leading master!
I1201 13:03:15.268905 30322 master.cpp:1395] Recovering from registrar
I1201 13:03:15.270830 30322 registrar.cpp:307] Recovering registrar
I1201 13:03:15.291272 30318 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 31.410668ms
I1201 13:03:15.291363 30318 replica.cpp:321] Persisted replica status to STARTING
I1201 13:03:15.291733 30318 recover.cpp:473] Replica is in STARTING status
I1201 13:03:15.293392 30318 replica.cpp:674] Replica in STARTING status received a broadcasted recover request from (1900)@172.17.21.0:52024
I1201 13:03:15.294251 30307 recover.cpp:193] Received a recover response from a replica in STARTING status
I1201 13:03:15.294756 30307 recover.cpp:564] Updating replica status to VOTING
I1201 13:03:15.338260 30307 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 43.256127ms
I1201 13:03:15.338348 30307 replica.cpp:321] Persisted replica status to VOTING
I1201 13:03:15.338601 30307 recover.cpp:578] Successfully joined the Paxos group
I1201 13:03:15.338803 30307 recover.cpp:462] Recover process terminated
I1201 13:03:15.339624 30307 log.cpp:659] Attempting to start the writer
I1201 13:03:15.342535 30316 replica.cpp:494] Replica received implicit promise request from (1901)@172.17.21.0:52024 with proposal 1
I1201 13:03:15.383368 30316 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 40.616854ms
I1201 13:03:15.383433 30316 replica.cpp:343] Persisted promised to 1
I1201 13:03:15.389814 30312 coordinator.cpp:238] Coordinator attempting to fill missing positions
I1201 13:03:15.391582 30316 replica.cpp:389] Replica received explicit promise request from (1902)@172.17.21.0:52024 for position 0 with proposal 2
I1201 13:03:15.434260 30316 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 42.530151ms
I1201 13:03:15.434340 30316 replica.cpp:713] Persisted action at 0
I1201 13:03:15.438995 30315 replica.cpp:538] Replica received write request for position 0 from (1903)@172.17.21.0:52024
I1201 13:03:15.439116 30315 leveldb.cpp:436] Reading position from leveldb took 52656ns
I1201 13:03:15.468266 30315 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 29.058804ms
I1201 13:03:15.468354 30315 replica.cpp:713] Persisted action at 0
I1201 13:03:15.469364 30308 replica.cpp:692] Replica received learned notice for position 0 from @0.0.0.0:0
I1201 13:03:15.500910 30308 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 31.499794ms
I1201 13:03:15.500991 30308 replica.cpp:713] Persisted action at 0
I1201 13:03:15.501029 30308 replica.cpp:698] Replica learned NOP action at position 0
I1201 13:03:15.502320 30308 log.cpp:675] Writer started with ending position 0
I1201 13:03:15.503906 30308 leveldb.cpp:436] Reading position from leveldb took 58333ns
I1201 13:03:15.505216 30321 registrar.cpp:340] Successfully fetched the registry (0B) in 234.329856ms
I1201 13:03:15.505354 30321 registrar.cpp:439] Applied 1 operations in 37858ns; attempting to update the 'registry'
I1201 13:03:15.506649 30321 log.cpp:683] Attempting to append 171 bytes to the log
I1201 13:03:15.506898 30321 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
I1201 13:03:15.508052 30308 replica.cpp:538] Replica received write request for position 1 from (1904)@172.17.21.0:52024
I1201 13:03:15.571291 30308 leveldb.cpp:341] Persisting action (190 bytes) to leveldb took 63.17935ms
I1201 13:03:15.571372 30308 replica.cpp:713] Persisted action at 1
I1201 13:03:15.572895 30308 replica.cpp:692] Replica received learned notice for position 1 from @0.0.0.0:0
I1201 13:03:15.605268 30308 leveldb.cpp:341] Persisting action (192 bytes) to leveldb took 32.320829ms
I1201 13:03:15.605357 30308 replica.cpp:713] Persisted action at 1
I1201 13:03:15.605394 30308 replica.cpp:698] Replica learned APPEND action at position 1
I1201 13:03:15.611315 30318 registrar.cpp:484] Successfully updated the 'registry' in 105.864192ms
I1201 13:03:15.611776 30318 registrar.cpp:370] Successfully recovered registrar
I1201 13:03:15.612607 30322 master.cpp:1447] Recovered 0 slaves from the Registry (132B) ; allowing 10mins for slaves to re-register
I1201 13:03:15.613045 30322 hierarchical.cpp:174] Allocator recovery is not supported yet
I1201 13:03:15.614012 30308 log.cpp:702] Attempting to truncate the log to 1
I1201 13:03:15.614817 30307 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
I1201 13:03:15.616644 30307 replica.cpp:538] Replica received write request for position 2 from (1905)@172.17.21.0:52024
I1201 13:03:15.630637 30307 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 13.701643ms
I1201 13:03:15.630728 30307 replica.cpp:713] Persisted action at 2
I1201 13:03:15.632129 30307 replica.cpp:692] Replica received learned notice for position 2 from @0.0.0.0:0
I1201 13:03:15.677260 30307 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 45.085356ms
I1201 13:03:15.677404 30307 leveldb.cpp:399] Deleting ~1 keys from leveldb took 64881ns
I1201 13:03:15.677433 30307 replica.cpp:713] Persisted action at 2
I1201 13:03:15.677469 30307 replica.cpp:698] Replica learned TRUNCATE action at position 2
I1201 13:03:15.680896 30288 containerizer.cpp:141] Using isolation: posix/cpu,posix/mem,filesystem/posix
W1201 13:03:15.681568 30288 backend.cpp:48] Failed to create 'bind' backend: BindBackend requires root privileges
I1201 13:03:15.717629 30317 slave.cpp:189] Slave started on 61)@172.17.21.0:52024
I1201 13:03:15.717674 30317 slave.cpp:190] Flags at startup: --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" --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/HealthCheckTest_CheckCommandTimeout_6kGYjg/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_auth_server="auth.docker.io" --docker_auth_server_port="443" --docker_kill_orphans="true" --docker_local_archives_dir="/tmp/mesos/images/docker" --docker_puller="local" --docker_puller_timeout="60" --docker_registry="registry-1.docker.io" --docker_registry_port="443" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/HealthCheckTest_CheckCommandTimeout_6kGYjg/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/mesos/mesos-0.27.0/_build/src" --logbufsecs="0" --logging_level="INFO" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:2;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/HealthCheckTest_CheckCommandTimeout_6kGYjg"
I1201 13:03:15.718204 30317 credentials.hpp:83] Loading credential for authentication from '/tmp/HealthCheckTest_CheckCommandTimeout_6kGYjg/credential'
I1201 13:03:15.718427 30317 slave.cpp:320] Slave using credential for: test-principal
I1201 13:03:15.718590 30317 resources.cpp:478] Parsing resources as JSON failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000]
Trying semicolon-delimited string format instead
I1201 13:03:15.719068 30317 slave.cpp:390] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I1201 13:03:15.719142 30317 slave.cpp:398] Slave attributes: [ ]
I1201 13:03:15.719156 30317 slave.cpp:403] Slave hostname: fa812f474cf4
I1201 13:03:15.719182 30317 slave.cpp:408] Slave checkpoint: true
I1201 13:03:15.720470 30308 state.cpp:52] Recovering state from '/tmp/HealthCheckTest_CheckCommandTimeout_6kGYjg/meta'
I1201 13:03:15.721117 30319 status_update_manager.cpp:200] Recovering status update manager
I1201 13:03:15.721451 30319 containerizer.cpp:383] Recovering containerizer
I1201 13:03:15.722421 30288 sched.cpp:164] Version: 0.27.0
I1201 13:03:15.723305 30307 slave.cpp:4258] Finished recovery
I1201 13:03:15.723848 30307 slave.cpp:4430] Querying resource estimator for oversubscribable resources
I1201 13:03:15.724340 30308 slave.cpp:727] New master detected at master@172.17.21.0:52024
I1201 13:03:15.724370 30311 status_update_manager.cpp:174] Pausing sending status updates
I1201 13:03:15.724428 30308 slave.cpp:790] Authenticating with master master@172.17.21.0:52024
I1201 13:03:15.724447 30308 slave.cpp:795] Using default CRAM-MD5 authenticatee
I1201 13:03:15.724616 30308 slave.cpp:763] Detecting new master
I1201 13:03:15.724714 30319 authenticatee.cpp:121] Creating new client SASL connection
I1201 13:03:15.724731 30308 slave.cpp:4444] Received oversubscribable resources from the resource estimator
I1201 13:03:15.724836 30308 sched.cpp:262] New master detected at master@172.17.21.0:52024
I1201 13:03:15.724911 30308 sched.cpp:318] Authenticating with master master@172.17.21.0:52024
I1201 13:03:15.724928 30308 sched.cpp:325] Using default CRAM-MD5 authenticatee
I1201 13:03:15.725319 30308 authenticatee.cpp:121] Creating new client SASL connection
I1201 13:03:15.725348 30319 master.cpp:5181] Authenticating slave(61)@172.17.21.0:52024
I1201 13:03:15.725872 30319 master.cpp:5181] Authenticating scheduler-05ae72c3-af75-4cab-b2df-764ef7c26d35@172.17.21.0:52024
I1201 13:03:15.725978 30321 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(169)@172.17.21.0:52024
I1201 13:03:15.726480 30321 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(170)@172.17.21.0:52024
I1201 13:03:15.726966 30321 authenticator.cpp:98] Creating new server SASL connection
I1201 13:03:15.726670 30316 authenticator.cpp:98] Creating new server SASL connection
I1201 13:03:15.727452 30316 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
I1201 13:03:15.727605 30316 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
I1201 13:03:15.727756 30316 authenticator.cpp:203] Received SASL authentication start
I1201 13:03:15.727913 30316 authenticator.cpp:325] Authentication requires more steps
I1201 13:03:15.728073 30316 authenticatee.cpp:258] Received SASL authentication step
I1201 13:03:15.728250 30316 authenticator.cpp:231] Received SASL authentication step
I1201 13:03:15.728638 30316 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'fa812f474cf4' server FQDN: 'fa812f474cf4' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1201 13:03:15.728721 30316 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
I1201 13:03:15.728854 30316 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1201 13:03:15.728977 30316 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'fa812f474cf4' server FQDN: 'fa812f474cf4' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1201 13:03:15.729069 30316 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1201 13:03:15.729154 30316 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1201 13:03:15.729269 30316 authenticator.cpp:317] Authentication success
I1201 13:03:15.729555 30316 authenticatee.cpp:298] Authentication success
I1201 13:03:15.730110 30316 slave.cpp:858] Successfully authenticated with master master@172.17.21.0:52024
I1201 13:03:15.730420 30316 slave.cpp:1252] Will retry registration in 9.588533ms if necessary
I1201 13:03:15.728505 30321 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
I1201 13:03:15.730845 30321 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
I1201 13:03:15.731009 30321 authenticator.cpp:203] Received SASL authentication start
I1201 13:03:15.729656 30314 master.cpp:5211] Successfully authenticated principal 'test-principal' at slave(61)@172.17.21.0:52024
I1201 13:03:15.731493 30314 master.cpp:3890] Registering slave at slave(61)@172.17.21.0:52024 (fa812f474cf4) with id dd5bff66-362f-4efc-963a-54756b2edcce-S0
I1201 13:03:15.729717 30311 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(169)@172.17.21.0:52024
I1201 13:03:15.732597 30314 registrar.cpp:439] Applied 1 operations in 486128ns; attempting to update the 'registry'
I1201 13:03:15.733901 30311 log.cpp:683] Attempting to append 340 bytes to the log
I1201 13:03:15.734225 30310 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3
I1201 13:03:15.735477 30318 replica.cpp:538] Replica received write request for position 3 from (1917)@172.17.21.0:52024
I1201 13:03:15.734043 30321 authenticator.cpp:325] Authentication requires more steps
I1201 13:03:15.735970 30321 authenticatee.cpp:258] Received SASL authentication step
I1201 13:03:15.736068 30321 authenticator.cpp:231] Received SASL authentication step
I1201 13:03:15.736107 30321 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'fa812f474cf4' server FQDN: 'fa812f474cf4' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1201 13:03:15.736120 30321 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
I1201 13:03:15.736423 30321 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1201 13:03:15.736464 30321 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'fa812f474cf4' server FQDN: 'fa812f474cf4' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1201 13:03:15.736480 30321 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1201 13:03:15.736490 30321 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1201 13:03:15.736508 30321 authenticator.cpp:317] Authentication success
I1201 13:03:15.736748 30310 authenticatee.cpp:298] Authentication success
I1201 13:03:15.736846 30310 master.cpp:5211] Successfully authenticated principal 'test-principal' at scheduler-05ae72c3-af75-4cab-b2df-764ef7c26d35@172.17.21.0:52024
I1201 13:03:15.737114 30310 sched.cpp:407] Successfully authenticated with master master@172.17.21.0:52024
I1201 13:03:15.737138 30310 sched.cpp:714] Sending SUBSCRIBE call to master@172.17.21.0:52024
I1201 13:03:15.737776 30310 sched.cpp:747] Will retry registration in 175.278268ms if necessary
I1201 13:03:15.737962 30310 master.cpp:2207] Received SUBSCRIBE call for framework 'default' at scheduler-05ae72c3-af75-4cab-b2df-764ef7c26d35@172.17.21.0:52024
I1201 13:03:15.738026 30310 master.cpp:1676] Authorizing framework principal 'test-principal' to receive offers for role '*'
I1201 13:03:15.738289 30321 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(170)@172.17.21.0:52024
I1201 13:03:15.738601 30310 master.cpp:2278] Subscribing framework default with checkpointing disabled and capabilities [ ]
I1201 13:03:15.739156 30310 hierarchical.cpp:220] Added framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
I1201 13:03:15.739486 30310 hierarchical.cpp:1062] No resources available to allocate!
I1201 13:03:15.739528 30310 hierarchical.cpp:1155] No inverse offers to send out!
I1201 13:03:15.739559 30310 hierarchical.cpp:957] Performed allocation for 0 slaves in 113362ns
I1201 13:03:15.739363 30321 sched.cpp:641] Framework registered with dd5bff66-362f-4efc-963a-54756b2edcce-0000
I1201 13:03:15.739622 30321 sched.cpp:655] Scheduler::registered took 25557ns
I1201 13:03:15.741346 30312 master.cpp:3878] Ignoring register slave message from slave(61)@172.17.21.0:52024 (fa812f474cf4) as admission is already in progress
I1201 13:03:15.741147 30316 slave.cpp:1252] Will retry registration in 9.901407ms if necessary
I1201 13:03:15.752579 30322 slave.cpp:1252] Will retry registration in 54.177145ms if necessary
I1201 13:03:15.752959 30320 master.cpp:3878] Ignoring register slave message from slave(61)@172.17.21.0:52024 (fa812f474cf4) as admission is already in progress
I1201 13:03:15.756857 30318 leveldb.cpp:341] Persisting action (359 bytes) to leveldb took 21.322978ms
I1201 13:03:15.757028 30318 replica.cpp:713] Persisted action at 3
I1201 13:03:15.758445 30309 replica.cpp:692] Replica received learned notice for position 3 from @0.0.0.0:0
I1201 13:03:15.809561 30315 slave.cpp:1252] Will retry registration in 90.392215ms if necessary
I1201 13:03:15.809877 30315 master.cpp:3878] Ignoring register slave message from slave(61)@172.17.21.0:52024 (fa812f474cf4) as admission is already in progress
I1201 13:03:15.811102 30309 leveldb.cpp:341] Persisting action (361 bytes) to leveldb took 52.532272ms
I1201 13:03:15.811142 30309 replica.cpp:713] Persisted action at 3
I1201 13:03:15.811187 30309 replica.cpp:698] Replica learned APPEND action at position 3
I1201 13:03:15.813498 30315 registrar.cpp:484] Successfully updated the 'registry' in 80.742912ms
I1201 13:03:15.814883 30315 master.cpp:3958] Registered slave dd5bff66-362f-4efc-963a-54756b2edcce-S0 at slave(61)@172.17.21.0:52024 (fa812f474cf4) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I1201 13:03:15.815547 30320 hierarchical.cpp:380] Added slave dd5bff66-362f-4efc-963a-54756b2edcce-S0 (fa812f474cf4) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
I1201 13:03:15.817054 30320 hierarchical.cpp:1155] No inverse offers to send out!
I1201 13:03:15.817100 30320 hierarchical.cpp:973] Performed allocation for slave dd5bff66-362f-4efc-963a-54756b2edcce-S0 in 989520ns
I1201 13:03:15.815670 30318 slave.cpp:902] Registered with master master@172.17.21.0:52024; given slave ID dd5bff66-362f-4efc-963a-54756b2edcce-S0
I1201 13:03:15.817320 30318 fetcher.cpp:79] Clearing fetcher cache
I1201 13:03:15.818097 30320 master.cpp:5010] Sending 1 offers to framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 (default) at scheduler-05ae72c3-af75-4cab-b2df-764ef7c26d35@172.17.21.0:52024
I1201 13:03:15.818240 30314 status_update_manager.cpp:181] Resuming sending status updates
I1201 13:03:15.818553 30318 slave.cpp:925] Checkpointing SlaveInfo to '/tmp/HealthCheckTest_CheckCommandTimeout_6kGYjg/meta/slaves/dd5bff66-362f-4efc-963a-54756b2edcce-S0/slave.info'
I1201 13:03:15.818996 30318 slave.cpp:961] Forwarding total oversubscribed resources
I1201 13:03:15.819099 30318 slave.cpp:3197] Received ping from slave-observer(58)@172.17.21.0:52024
I1201 13:03:15.819594 30320 master.cpp:4300] Received update of slave dd5bff66-362f-4efc-963a-54756b2edcce-S0 at slave(61)@172.17.21.0:52024 (fa812f474cf4) with total oversubscribed resources
I1201 13:03:15.820132 30320 sched.cpp:811] Scheduler::resourceOffers took 130339ns
I1201 13:03:15.820576 30314 hierarchical.cpp:434] Slave dd5bff66-362f-4efc-963a-54756b2edcce-S0 (fa812f474cf4) updated with oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000])
I1201 13:03:15.821035 30314 hierarchical.cpp:1062] No resources available to allocate!
I1201 13:03:15.821076 30314 hierarchical.cpp:1155] No inverse offers to send out!
I1201 13:03:15.821096 30314 hierarchical.cpp:973] Performed allocation for slave dd5bff66-362f-4efc-963a-54756b2edcce-S0 in 469026ns
I1201 13:03:15.822010 30309 log.cpp:702] Attempting to truncate the log to 3
I1201 13:03:15.822232 30318 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 4
I1201 13:03:15.823371 30310 replica.cpp:538] Replica received write request for position 4 from (1918)@172.17.21.0:52024
I1201 13:03:15.824892 30316 master.cpp:2946] Processing ACCEPT call for offers: [ dd5bff66-362f-4efc-963a-54756b2edcce-O0 ] on slave dd5bff66-362f-4efc-963a-54756b2edcce-S0 at slave(61)@172.17.21.0:52024 (fa812f474cf4) for framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 (default) at scheduler-05ae72c3-af75-4cab-b2df-764ef7c26d35@172.17.21.0:52024
I1201 13:03:15.824942 30316 master.cpp:2742] Authorizing framework principal 'test-principal' to launch task 1 as user 'mesos'
I1201 13:03:15.826663 30316 master.hpp:176] Adding task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave dd5bff66-362f-4efc-963a-54756b2edcce-S0 (fa812f474cf4)
I1201 13:03:15.826897 30316 master.cpp:3276] Launching task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 (default) at scheduler-05ae72c3-af75-4cab-b2df-764ef7c26d35@172.17.21.0:52024 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave dd5bff66-362f-4efc-963a-54756b2edcce-S0 at slave(61)@172.17.21.0:52024 (fa812f474cf4)
I1201 13:03:15.827376 30322 slave.cpp:1292] Got assigned task 1 for framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
I1201 13:03:15.827641 30322 resources.cpp:478] Parsing resources as JSON failed: cpus:0.1;mem:32
Trying semicolon-delimited string format instead
I1201 13:03:15.828306 30322 slave.cpp:1411] Launching task 1 for framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
I1201 13:03:15.828402 30322 resources.cpp:478] Parsing resources as JSON failed: cpus:0.1;mem:32
Trying semicolon-delimited string format instead
I1201 13:03:15.851069 30322 paths.cpp:434] Trying to chown '/tmp/HealthCheckTest_CheckCommandTimeout_6kGYjg/slaves/dd5bff66-362f-4efc-963a-54756b2edcce-S0/frameworks/dd5bff66-362f-4efc-963a-54756b2edcce-0000/executors/1/runs/8d8aa0bb-fad5-4715-a14f-62783b07da81' to user 'mesos'
I1201 13:03:15.856019 30310 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 32.584609ms
I1201 13:03:15.856098 30310 replica.cpp:713] Persisted action at 4
I1201 13:03:15.856991 30322 slave.cpp:5042] Launching executor 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/HealthCheckTest_CheckCommandTimeout_6kGYjg/slaves/dd5bff66-362f-4efc-963a-54756b2edcce-S0/frameworks/dd5bff66-362f-4efc-963a-54756b2edcce-0000/executors/1/runs/8d8aa0bb-fad5-4715-a14f-62783b07da81'
I1201 13:03:15.857708 30322 slave.cpp:1629] Queuing task '1' for executor '1' of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
I1201 13:03:15.857856 30322 slave.cpp:680] Successfully attached file '/tmp/HealthCheckTest_CheckCommandTimeout_6kGYjg/slaves/dd5bff66-362f-4efc-963a-54756b2edcce-S0/frameworks/dd5bff66-362f-4efc-963a-54756b2edcce-0000/executors/1/runs/8d8aa0bb-fad5-4715-a14f-62783b07da81'
I1201 13:03:15.857945 30322 replica.cpp:692] Replica received learned notice for position 4 from @0.0.0.0:0
I1201 13:03:15.857978 30310 containerizer.cpp:617] Starting container '8d8aa0bb-fad5-4715-a14f-62783b07da81' for executor '1' of framework 'dd5bff66-362f-4efc-963a-54756b2edcce-0000'
I1201 13:03:15.862118 30312 launcher.cpp:132] Forked child with pid '3131' for container '8d8aa0bb-fad5-4715-a14f-62783b07da81'
I1201 13:03:15.891278 30322 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 33.273317ms
I1201 13:03:15.891428 30322 leveldb.cpp:399] Deleting ~2 keys from leveldb took 84833ns
I1201 13:03:15.891456 30322 replica.cpp:713] Persisted action at 4
I1201 13:03:15.891494 30322 replica.cpp:698] Replica learned TRUNCATE action at position 4
I1201 13:03:16.100318 30322 slave.cpp:2406] Got registration for executor '1' of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 from executor(1)@172.17.21.0:58381
I1201 13:03:16.104367 30317 slave.cpp:1794] Sending queued task '1' to executor '1' of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 at executor(1)@172.17.21.0:58381
I1201 13:03:16.142390 30311 slave.cpp:2763] Handling status update TASK_RUNNING (UUID: cfdb8408-a2e8-441b-836c-3368e93ac6e2) for task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 from executor(1)@172.17.21.0:58381
I1201 13:03:16.142907 30311 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: cfdb8408-a2e8-441b-836c-3368e93ac6e2) for task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
I1201 13:03:16.142951 30311 status_update_manager.cpp:497] Creating StatusUpdate stream for task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
I1201 13:03:16.143543 30311 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: cfdb8408-a2e8-441b-836c-3368e93ac6e2) for task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 to the slave
I1201 13:03:16.144052 30311 slave.cpp:3115] Forwarding the update TASK_RUNNING (UUID: cfdb8408-a2e8-441b-836c-3368e93ac6e2) for task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 to master@172.17.21.0:52024
I1201 13:03:16.145408 30311 slave.cpp:3009] Status update manager successfully handled status update TASK_RUNNING (UUID: cfdb8408-a2e8-441b-836c-3368e93ac6e2) for task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
I1201 13:03:16.145467 30311 slave.cpp:3025] Sending acknowledgement for status update TASK_RUNNING (UUID: cfdb8408-a2e8-441b-836c-3368e93ac6e2) for task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 to executor(1)@172.17.21.0:58381
I1201 13:03:16.147138 30311 master.cpp:4445] Status update TASK_RUNNING (UUID: cfdb8408-a2e8-441b-836c-3368e93ac6e2) for task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 from slave dd5bff66-362f-4efc-963a-54756b2edcce-S0 at slave(61)@172.17.21.0:52024 (fa812f474cf4)
I1201 13:03:16.147233 30311 master.cpp:4493] Forwarding status update TASK_RUNNING (UUID: cfdb8408-a2e8-441b-836c-3368e93ac6e2) for task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
I1201 13:03:16.147439 30311 master.cpp:6097] Updating the state of task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
I1201 13:03:16.147747 30311 sched.cpp:919] Scheduler::statusUpdate took 122865ns
I1201 13:03:16.148129 30311 master.cpp:3602] Processing ACKNOWLEDGE call cfdb8408-a2e8-441b-836c-3368e93ac6e2 for task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 (default) at scheduler-05ae72c3-af75-4cab-b2df-764ef7c26d35@172.17.21.0:52024 on slave dd5bff66-362f-4efc-963a-54756b2edcce-S0
I1201 13:03:16.148674 30311 status_update_manager.cpp:392] Received status update acknowledgement (UUID: cfdb8408-a2e8-441b-836c-3368e93ac6e2) for task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
I1201 13:03:16.149813 30320 slave.cpp:2346] Status update manager successfully handled status update acknowledgement (UUID: cfdb8408-a2e8-441b-836c-3368e93ac6e2) for task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
I1201 13:03:16.269222 30322 hierarchical.cpp:1062] No resources available to allocate!
I1201 13:03:16.269312 30322 hierarchical.cpp:1155] No inverse offers to send out!
I1201 13:03:16.269347 30322 hierarchical.cpp:957] Performed allocation for 1 slaves in 777937ns
I1201 13:03:17.270767 30322 hierarchical.cpp:1062] No resources available to allocate!
I1201 13:03:17.270853 30322 hierarchical.cpp:1155] No inverse offers to send out!
I1201 13:03:17.270884 30322 hierarchical.cpp:957] Performed allocation for 1 slaves in 793428ns
I1201 13:03:18.273021 30318 hierarchical.cpp:1062] No resources available to allocate!
I1201 13:03:18.273107 30318 hierarchical.cpp:1155] No inverse offers to send out!
I1201 13:03:18.273138 30318 hierarchical.cpp:957] Performed allocation for 1 slaves in 668062ns
I1201 13:03:19.274287 30321 hierarchical.cpp:1062] No resources available to allocate!
I1201 13:03:19.274371 30321 hierarchical.cpp:1155] No inverse offers to send out!
I1201 13:03:19.274402 30321 hierarchical.cpp:957] Performed allocation for 1 slaves in 705640ns
I1201 13:03:20.276296 30313 hierarchical.cpp:1062] No resources available to allocate!
I1201 13:03:20.276381 30313 hierarchical.cpp:1155] No inverse offers to send out!
I1201 13:03:20.276412 30313 hierarchical.cpp:957] Performed allocation for 1 slaves in 681486ns
I1201 13:03:21.277920 30320 hierarchical.cpp:1062] No resources available to allocate!
I1201 13:03:21.278004 30320 hierarchical.cpp:1155] No inverse offers to send out!
I1201 13:03:21.278034 30320 hierarchical.cpp:957] Performed allocation for 1 slaves in 673270ns
I1201 13:03:21.281448 30312 slave.cpp:2763] Handling status update TASK_RUNNING (UUID: a820acb1-a9ed-46f5-83c2-1a6504f5c584) for task 1 in health state unhealthy of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 from executor(1)@172.17.21.0:58381
I1201 13:03:21.282423 30312 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: a820acb1-a9ed-46f5-83c2-1a6504f5c584) for task 1 in health state unhealthy of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
I1201 13:03:21.283000 30312 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: a820acb1-a9ed-46f5-83c2-1a6504f5c584) for task 1 in health state unhealthy of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 to the slave
I1201 13:03:21.283670 30312 slave.cpp:3115] Forwarding the update TASK_RUNNING (UUID: a820acb1-a9ed-46f5-83c2-1a6504f5c584) for task 1 in health state unhealthy of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 to master@172.17.21.0:52024
I1201 13:03:21.284276 30312 slave.cpp:3009] Status update manager successfully handled status update TASK_RUNNING (UUID: a820acb1-a9ed-46f5-83c2-1a6504f5c584) for task 1 in health state unhealthy of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
I1201 13:03:21.284979 30312 slave.cpp:3025] Sending acknowledgement for status update TASK_RUNNING (UUID: a820acb1-a9ed-46f5-83c2-1a6504f5c584) for task 1 in health state unhealthy of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 to executor(1)@172.17.21.0:58381
I1201 13:03:21.284695 30317 master.cpp:4445] Status update TASK_RUNNING (UUID: a820acb1-a9ed-46f5-83c2-1a6504f5c584) for task 1 in health state unhealthy of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 from slave dd5bff66-362f-4efc-963a-54756b2edcce-S0 at slave(61)@172.17.21.0:52024 (fa812f474cf4)
I1201 13:03:21.285204 30317 master.cpp:4493] Forwarding status update TASK_RUNNING (UUID: a820acb1-a9ed-46f5-83c2-1a6504f5c584) for task 1 in health state unhealthy of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
I1201 13:03:21.285403 30317 master.cpp:6097] Updating the state of task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
I1201 13:03:21.285719 30317 sched.cpp:919] Scheduler::statusUpdate took 124592ns
I1201 13:03:21.286097 30317 master.cpp:3602] Processing ACKNOWLEDGE call a820acb1-a9ed-46f5-83c2-1a6504f5c584 for task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 (default) at scheduler-05ae72c3-af75-4cab-b2df-764ef7c26d35@172.17.21.0:52024 on slave dd5bff66-362f-4efc-963a-54756b2edcce-S0
I1201 13:03:21.287281 30317 status_update_manager.cpp:392] Received status update acknowledgement (UUID: a820acb1-a9ed-46f5-83c2-1a6504f5c584) for task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
I1201 13:03:21.287904 30322 slave.cpp:2346] Status update manager successfully handled status update acknowledgement (UUID: a820acb1-a9ed-46f5-83c2-1a6504f5c584) for task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
I1201 13:03:22.279230 30311 hierarchical.cpp:1062] No resources available to allocate!
I1201 13:03:22.279326 30311 hierarchical.cpp:1155] No inverse offers to send out!
I1201 13:03:22.279361 30311 hierarchical.cpp:957] Performed allocation for 1 slaves in 718578ns
I1201 13:03:23.281947 30309 hierarchical.cpp:1062] No resources available to allocate!
I1201 13:03:23.282080 30309 hierarchical.cpp:1155] No inverse offers to send out!
I1201 13:03:23.282142 30309 hierarchical.cpp:957] Performed allocation for 1 slaves in 830902ns
I1201 13:03:24.283694 30316 hierarchical.cpp:1062] No resources available to allocate!
I1201 13:03:24.283906 30316 hierarchical.cpp:1155] No inverse offers to send out!
I1201 13:03:24.284049 30316 hierarchical.cpp:957] Performed allocation for 1 slaves in 980771ns
I1201 13:03:25.285796 30310 hierarchical.cpp:1062] No resources available to allocate!
I1201 13:03:25.285877 30310 hierarchical.cpp:1155] No inverse offers to send out!
I1201 13:03:25.285908 30310 hierarchical.cpp:957] Performed allocation for 1 slaves in 671191ns
I1201 13:03:26.287158 30314 hierarchical.cpp:1062] No resources available to allocate!
I1201 13:03:26.287240 30314 hierarchical.cpp:1155] No inverse offers to send out!
I1201 13:03:26.287271 30314 hierarchical.cpp:957] Performed allocation for 1 slaves in 650436ns
I1201 13:03:26.292038 30316 slave.cpp:2763] Handling status update TASK_RUNNING (UUID: 7b7c6e1a-d3b1-4b7c-8113-f9eeb6d7e5dd) for task 1 in health state unhealthy of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 from executor(1)@172.17.21.0:58381
I1201 13:03:26.292533 30316 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 7b7c6e1a-d3b1-4b7c-8113-f9eeb6d7e5dd) for task 1 in health state unhealthy of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
I1201 13:03:26.292721 30316 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: 7b7c6e1a-d3b1-4b7c-8113-f9eeb6d7e5dd) for task 1 in health state unhealthy of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 to the slave
I1201 13:03:26.293148 30316 slave.cpp:3115] Forwarding the update TASK_RUNNING (UUID: 7b7c6e1a-d3b1-4b7c-8113-f9eeb6d7e5dd) for task 1 in health state unhealthy of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 to master@172.17.21.0:52024
I1201 13:03:26.293442 30316 slave.cpp:3009] Status update manager successfully handled status update TASK_RUNNING (UUID: 7b7c6e1a-d3b1-4b7c-8113-f9eeb6d7e5dd) for task 1 in health state unhealthy of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
I1201 13:03:26.293485 30316 slave.cpp:3025] Sending acknowledgement for status update TASK_RUNNING (UUID: 7b7c6e1a-d3b1-4b7c-8113-f9eeb6d7e5dd) for task 1 in health state unhealthy of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 to executor(1)@172.17.21.0:58381
I1201 13:03:26.294077 30316 master.cpp:4445] Status update TASK_RUNNING (UUID: 7b7c6e1a-d3b1-4b7c-8113-f9eeb6d7e5dd) for task 1 in health state unhealthy of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 from slave dd5bff66-362f-4efc-963a-54756b2edcce-S0 at slave(61)@172.17.21.0:52024 (fa812f474cf4)
I1201 13:03:26.294124 30316 master.cpp:4493] Forwarding status update TASK_RUNNING (UUID: 7b7c6e1a-d3b1-4b7c-8113-f9eeb6d7e5dd) for task 1 in health state unhealthy of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
I1201 13:03:26.294373 30316 master.cpp:6097] Updating the state of task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
I1201 13:03:26.294651 30316 sched.cpp:919] Scheduler::statusUpdate took 114245ns
I1201 13:03:26.295001 30316 master.cpp:3602] Processing ACKNOWLEDGE call 7b7c6e1a-d3b1-4b7c-8113-f9eeb6d7e5dd for task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 (default) at scheduler-05ae72c3-af75-4cab-b2df-764ef7c26d35@172.17.21.0:52024 on slave dd5bff66-362f-4efc-963a-54756b2edcce-S0
I1201 13:03:26.295910 30318 status_update_manager.cpp:392] Received status update acknowledgement (UUID: 7b7c6e1a-d3b1-4b7c-8113-f9eeb6d7e5dd) for task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
I1201 13:03:26.296237 30322 slave.cpp:2346] Status update manager successfully handled status update acknowledgement (UUID: 7b7c6e1a-d3b1-4b7c-8113-f9eeb6d7e5dd) for task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
I1201 13:03:27.289466 30316 hierarchical.cpp:1062] No resources available to allocate!
I1201 13:03:27.289551 30316 hierarchical.cpp:1155] No inverse offers to send out!
I1201 13:03:27.289582 30316 hierarchical.cpp:957] Performed allocation for 1 slaves in 692419ns
I1201 13:03:28.291142 30312 hierarchical.cpp:1062] No resources available to allocate!
I1201 13:03:28.291239 30312 hierarchical.cpp:1155] No inverse offers to send out!
I1201 13:03:28.291270 30312 hierarchical.cpp:957] Performed allocation for 1 slaves in 659702ns
I1201 13:03:29.293304 30312 hierarchical.cpp:1062] No resources available to allocate!
I1201 13:03:29.293390 30312 hierarchical.cpp:1155] No inverse offers to send out!
I1201 13:03:29.293421 30312 hierarchical.cpp:957] Performed allocation for 1 slaves in 665396ns
I1201 13:03:30.294711 30320 hierarchical.cpp:1062] No resources available to allocate!
I1201 13:03:30.294805 30320 hierarchical.cpp:1155] No inverse offers to send out!
I1201 13:03:30.294842 30320 hierarchical.cpp:957] Performed allocation for 1 slaves in 710415ns
I1201 13:03:30.725651 30322 slave.cpp:4430] Querying resource estimator for oversubscribable resources
I1201 13:03:30.725958 30322 slave.cpp:4444] Received oversubscribable resources from the resource estimator
I1201 13:03:30.817693 30312 slave.cpp:3197] Received ping from slave-observer(58)@172.17.21.0:52024
I1201 13:03:31.296576 30316 hierarchical.cpp:1062] No resources available to allocate!
I1201 13:03:31.296658 30316 hierarchical.cpp:1155] No inverse offers to send out!
I1201 13:03:31.296687 30316 hierarchical.cpp:957] Performed allocation for 1 slaves in 652455ns
I1201 13:03:32.298235 30314 hierarchical.cpp:1062] No resources available to allocate!
I1201 13:03:32.298336 30314 hierarchical.cpp:1155] No inverse offers to send out!
I1201 13:03:32.298370 30314 hierarchical.cpp:957] Performed allocation for 1 slaves in 729548ns
I1201 13:03:33.301245 30308 hierarchical.cpp:1062] No resources available to allocate!
I1201 13:03:33.301337 30308 hierarchical.cpp:1155] No inverse offers to send out!
I1201 13:03:33.301372 30308 hierarchical.cpp:957] Performed allocation for 1 slaves in 745296ns
I1201 13:03:34.303215 30311 hierarchical.cpp:1062] No resources available to allocate!
I1201 13:03:34.303298 30311 hierarchical.cpp:1155] No inverse offers to send out!
I1201 13:03:34.303329 30311 hierarchical.cpp:957] Performed allocation for 1 slaves in 652065ns
I1201 13:03:35.304294 30315 hierarchical.cpp:1062] No resources available to allocate!
I1201 13:03:35.304369 30315 hierarchical.cpp:1155] No inverse offers to send out!
I1201 13:03:35.304400 30315 hierarchical.cpp:957] Performed allocation for 1 slaves in 652578ns
I1201 13:03:36.305637 30310 hierarchical.cpp:1062] No resources available to allocate!
I1201 13:03:36.305721 30310 hierarchical.cpp:1155] No inverse offers to send out!
I1201 13:03:36.305757 30310 hierarchical.cpp:957] Performed allocation for 1 slaves in 571872ns
I1201 13:03:37.307134 30311 hierarchical.cpp:1062] No resources available to allocate!
I1201 13:03:37.307222 30311 hierarchical.cpp:1155] No inverse offers to send out!
I1201 13:03:37.307257 30311 hierarchical.cpp:957] Performed allocation for 1 slaves in 685927ns
I1201 13:03:38.310041 30315 hierarchical.cpp:1062] No resources available to allocate!
I1201 13:03:38.310129 30315 hierarchical.cpp:1155] No inverse offers to send out!
I1201 13:03:38.310173 30315 hierarchical.cpp:957] Performed allocation for 1 slaves in 668279ns
I1201 13:03:39.311493 30312 hierarchical.cpp:1062] No resources available to allocate!
I1201 13:03:39.311586 30312 hierarchical.cpp:1155] No inverse offers to send out!
I1201 13:03:39.311621 30312 hierarchical.cpp:957] Performed allocation for 1 slaves in 728179ns
I1201 13:03:40.312849 30319 hierarchical.cpp:1062] No resources available to allocate!
I1201 13:03:40.312922 30319 hierarchical.cpp:1155] No inverse offers to send out!
I1201 13:03:40.312954 30319 hierarchical.cpp:957] Performed allocation for 1 slaves in 637308ns
../../src/tests/health_check_tests.cpp:919: Failure
Failed to wait 15secs for status3
../../src/tests/health_check_tests.cpp:899: Failure
Actual function call count doesn't match EXPECT_CALL(sched, statusUpdate(&driver, _))...
Expected: to be called 5 times
Actual: called 3 times - unsatisfied and active
I1201 13:03:41.312536 30309 master.cpp:1138] Framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 (default) at scheduler-05ae72c3-af75-4cab-b2df-764ef7c26d35@172.17.21.0:52024 disconnected
I1201 13:03:41.312664 30309 master.cpp:2503] Disconnecting framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 (default) at scheduler-05ae72c3-af75-4cab-b2df-764ef7c26d35@172.17.21.0:52024
I1201 13:03:41.312759 30309 master.cpp:2527] Deactivating framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 (default) at scheduler-05ae72c3-af75-4cab-b2df-764ef7c26d35@172.17.21.0:52024
I1201 13:03:41.312952 30309 master.cpp:1162] Giving framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 (default) at scheduler-05ae72c3-af75-4cab-b2df-764ef7c26d35@172.17.21.0:52024 0ns to failover
I1201 13:03:41.313508 30316 hierarchical.cpp:303] Deactivated framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
I1201 13:03:41.314739 30316 hierarchical.cpp:1062] No resources available to allocate!
I1201 13:03:41.314862 30316 hierarchical.cpp:1155] No inverse offers to send out!
I1201 13:03:41.314971 30316 hierarchical.cpp:957] Performed allocation for 1 slaves in 619616ns
I1201 13:03:41.314245 30320 master.cpp:4858] Framework failover timeout, removing framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 (default) at scheduler-05ae72c3-af75-4cab-b2df-764ef7c26d35@172.17.21.0:52024
I1201 13:03:41.315183 30320 master.cpp:5590] Removing framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 (default) at scheduler-05ae72c3-af75-4cab-b2df-764ef7c26d35@172.17.21.0:52024
I1201 13:03:41.315469 30320 master.cpp:6097] Updating the state of task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 (latest state: TASK_KILLED, status update state: TASK_KILLED)
I1201 13:03:41.315685 30318 slave.cpp:2010] Asked to shut down framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 by master@172.17.21.0:52024
I1201 13:03:41.316105 30320 master.cpp:6163] Removing task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 on slave dd5bff66-362f-4efc-963a-54756b2edcce-S0 at slave(61)@172.17.21.0:52024 (fa812f474cf4)
I1201 13:03:41.316380 30314 hierarchical.cpp:791] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on slave dd5bff66-362f-4efc-963a-54756b2edcce-S0 from framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
I1201 13:03:41.316309 30318 slave.cpp:2035] Shutting down framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
I1201 13:03:41.316668 30318 slave.cpp:3891] Shutting down executor '1' of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 at executor(1)@172.17.21.0:58381
I1201 13:03:41.317257 30319 hierarchical.cpp:260] Removed framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
I1201 13:03:41.316704 30320 master.cpp:938] Master terminating
I1201 13:03:41.318066 30312 hierarchical.cpp:410] Removed slave dd5bff66-362f-4efc-963a-54756b2edcce-S0
I1201 13:03:41.318724 30320 slave.cpp:3243] master@172.17.21.0:52024 exited
W1201 13:03:41.318749 30320 slave.cpp:3246] Master disconnected! Waiting for a new master to be elected
I1201 13:03:41.324950 30308 containerizer.cpp:1073] Destroying container '8d8aa0bb-fad5-4715-a14f-62783b07da81'
I1201 13:03:41.425364 30310 containerizer.cpp:1256] Executor for container '8d8aa0bb-fad5-4715-a14f-62783b07da81' has exited
I1201 13:03:41.427952 30312 slave.cpp:3581] Executor '1' of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 terminated with signal Killed
I1201 13:03:41.428019 30312 slave.cpp:3685] Cleaning up executor '1' of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 at executor(1)@172.17.21.0:58381
I1201 13:03:41.428724 30312 slave.cpp:3773] Cleaning up framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
I1201 13:03:41.428715 30307 gc.cpp:54] Scheduling '/tmp/HealthCheckTest_CheckCommandTimeout_6kGYjg/slaves/dd5bff66-362f-4efc-963a-54756b2edcce-S0/frameworks/dd5bff66-362f-4efc-963a-54756b2edcce-0000/executors/1/runs/8d8aa0bb-fad5-4715-a14f-62783b07da81' for gc 6.99999504180444days in the future
I1201 13:03:41.428894 30307 gc.cpp:54] Scheduling '/tmp/HealthCheckTest_CheckCommandTimeout_6kGYjg/slaves/dd5bff66-362f-4efc-963a-54756b2edcce-S0/frameworks/dd5bff66-362f-4efc-963a-54756b2edcce-0000/executors/1' for gc 6.99999503861037days in the future
I1201 13:03:41.428920 30312 status_update_manager.cpp:282] Closing status update streams for framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
I1201 13:03:41.428980 30312 status_update_manager.cpp:528] Cleaning up status update stream for task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
I1201 13:03:41.429021 30307 gc.cpp:54] Scheduling '/tmp/HealthCheckTest_CheckCommandTimeout_6kGYjg/slaves/dd5bff66-362f-4efc-963a-54756b2edcce-S0/frameworks/dd5bff66-362f-4efc-963a-54756b2edcce-0000' for gc 6.99999503674963days in the future
I1201 13:03:41.429925 30315 slave.cpp:599] Slave terminating
[ FAILED ] HealthCheckTest.CheckCommandTimeout (26359 ms)
{noformat}
{noformat: title=Good Run}
[ RUN ] HealthCheckTest.CheckCommandTimeout
I1201 14:14:26.562675 30295 leveldb.cpp:174] Opened db in 128.451766ms
I1201 14:14:26.589201 30295 leveldb.cpp:181] Compacted db in 26.446367ms
I1201 14:14:26.589298 30295 leveldb.cpp:196] Created db iterator in 27631ns
I1201 14:14:26.589318 30295 leveldb.cpp:202] Seeked to beginning of db in 3097ns
I1201 14:14:26.589329 30295 leveldb.cpp:271] Iterated through 0 keys in the db in 210ns
I1201 14:14:26.589382 30295 replica.cpp:778] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I1201 14:14:26.590701 30321 recover.cpp:447] Starting replica recovery
I1201 14:14:26.591117 30321 recover.cpp:473] Replica is in EMPTY status
I1201 14:14:26.592706 30317 replica.cpp:674] Replica in EMPTY status received a broadcasted recover request from (1903)@172.17.21.7:43732
I1201 14:14:26.593225 30328 recover.cpp:193] Received a recover response from a replica in EMPTY status
I1201 14:14:26.593907 30328 recover.cpp:564] Updating replica status to STARTING
I1201 14:14:26.604007 30316 master.cpp:365] Master 587d1fd5-db6b-4af4-9267-ce84ac458470 (ca6f16e00db6) started on 172.17.21.7:43732
I1201 14:14:26.604156 30316 master.cpp:367] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="true" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/9rplBs/credentials" --framework_sorter="drf" --help="false" --hostname_lookup="true" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_slave_ping_timeouts="5" --quiet="false" --recovery_slave_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_store_timeout="25secs" --registry_strict="true" --root_submissions="true" --slave_ping_timeout="15secs" --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false" --webui_dir="/mesos/mesos-0.27.0/_inst/share/mesos/webui" --work_dir="/tmp/9rplBs/master" --zk_session_timeout="10secs"
I1201 14:14:26.604524 30316 master.cpp:412] Master only allowing authenticated frameworks to register
I1201 14:14:26.604540 30316 master.cpp:417] Master only allowing authenticated slaves to register
I1201 14:14:26.604550 30316 credentials.hpp:35] Loading credentials for authentication from '/tmp/9rplBs/credentials'
I1201 14:14:26.613284 30316 master.cpp:456] Using default 'crammd5' authenticator
I1201 14:14:26.613517 30316 master.cpp:493] Authorization enabled
I1201 14:14:26.614346 30324 hierarchical.cpp:162] Initialized hierarchical allocator process
I1201 14:14:26.614435 30324 whitelist_watcher.cpp:77] No whitelist given
I1201 14:14:26.616992 30316 master.cpp:1637] The newly elected leader is master@172.17.21.7:43732 with id 587d1fd5-db6b-4af4-9267-ce84ac458470
I1201 14:14:26.617038 30316 master.cpp:1650] Elected as the leading master!
I1201 14:14:26.617058 30316 master.cpp:1395] Recovering from registrar
I1201 14:14:26.617224 30324 registrar.cpp:307] Recovering registrar
I1201 14:14:26.621055 30319 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 26.839241ms
I1201 14:14:26.621105 30319 replica.cpp:321] Persisted replica status to STARTING
I1201 14:14:26.621538 30319 recover.cpp:473] Replica is in STARTING status
I1201 14:14:26.623247 30315 replica.cpp:674] Replica in STARTING status received a broadcasted recover request from (1904)@172.17.21.7:43732
I1201 14:14:26.623631 30315 recover.cpp:193] Received a recover response from a replica in STARTING status
I1201 14:14:26.624241 30322 recover.cpp:564] Updating replica status to VOTING
I1201 14:14:26.657734 30315 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 33.355865ms
I1201 14:14:26.657809 30315 replica.cpp:321] Persisted replica status to VOTING
I1201 14:14:26.658102 30315 recover.cpp:578] Successfully joined the Paxos group
I1201 14:14:26.658396 30315 recover.cpp:462] Recover process terminated
I1201 14:14:26.659047 30315 log.cpp:659] Attempting to start the writer
I1201 14:14:26.660820 30323 replica.cpp:494] Replica received implicit promise request from (1905)@172.17.21.7:43732 with proposal 1
I1201 14:14:26.724722 30323 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 63.712877ms
I1201 14:14:26.725214 30323 replica.cpp:343] Persisted promised to 1
I1201 14:14:26.726558 30322 coordinator.cpp:238] Coordinator attempting to fill missing positions
I1201 14:14:26.728757 30316 replica.cpp:389] Replica received explicit promise request from (1906)@172.17.21.7:43732 for position 0 with proposal 2
I1201 14:14:26.783602 30316 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 54.554561ms
I1201 14:14:26.783695 30316 replica.cpp:713] Persisted action at 0
I1201 14:14:26.785193 30321 replica.cpp:538] Replica received write request for position 0 from (1907)@172.17.21.7:43732
I1201 14:14:26.785289 30321 leveldb.cpp:436] Reading position from leveldb took 49720ns
I1201 14:14:26.830451 30321 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 45.082632ms
I1201 14:14:26.830551 30321 replica.cpp:713] Persisted action at 0
I1201 14:14:26.831938 30317 replica.cpp:692] Replica received learned notice for position 0 from @0.0.0.0:0
I1201 14:14:26.881292 30317 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 49.170442ms
I1201 14:14:26.881369 30317 replica.cpp:713] Persisted action at 0
I1201 14:14:26.881402 30317 replica.cpp:698] Replica learned NOP action at position 0
I1201 14:14:26.882609 30323 log.cpp:675] Writer started with ending position 0
I1201 14:14:26.884533 30324 leveldb.cpp:436] Reading position from leveldb took 76333ns
I1201 14:14:26.886106 30324 registrar.cpp:340] Successfully fetched the registry (0B) in 268.833024ms
I1201 14:14:26.886435 30324 registrar.cpp:439] Applied 1 operations in 42802ns; attempting to update the 'registry'
I1201 14:14:26.888010 30318 log.cpp:683] Attempting to append 173 bytes to the log
I1201 14:14:26.888236 30326 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
I1201 14:14:26.890637 30328 replica.cpp:538] Replica received write request for position 1 from (1908)@172.17.21.7:43732
I1201 14:14:26.921727 30328 leveldb.cpp:341] Persisting action (192 bytes) to leveldb took 30.998029ms
I1201 14:14:26.922299 30328 replica.cpp:713] Persisted action at 1
I1201 14:14:26.924146 30315 replica.cpp:692] Replica received learned notice for position 1 from @0.0.0.0:0
I1201 14:14:26.956274 30315 leveldb.cpp:341] Persisting action (194 bytes) to leveldb took 31.633545ms
I1201 14:14:26.956370 30315 replica.cpp:713] Persisted action at 1
I1201 14:14:26.956411 30315 replica.cpp:698] Replica learned APPEND action at position 1
I1201 14:14:26.958438 30317 registrar.cpp:484] Successfully updated the 'registry' in 71.918848ms
I1201 14:14:26.958627 30317 registrar.cpp:370] Successfully recovered registrar
I1201 14:14:26.959338 30320 hierarchical.cpp:174] Allocator recovery is not supported yet
I1201 14:14:26.959838 30323 log.cpp:702] Attempting to truncate the log to 1
I1201 14:14:26.960106 30323 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
I1201 14:14:26.959147 30317 master.cpp:1447] Recovered 0 slaves from the Registry (134B) ; allowing 10mins for slaves to re-register
I1201 14:14:26.961684 30323 replica.cpp:538] Replica received write request for position 2 from (1909)@172.17.21.7:43732
I1201 14:14:27.055438 30323 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 93.663564ms
I1201 14:14:27.055536 30323 replica.cpp:713] Persisted action at 2
I1201 14:14:27.056959 30320 replica.cpp:692] Replica received learned notice for position 2 from @0.0.0.0:0
I1201 14:14:27.118288 30320 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 60.990962ms
I1201 14:14:27.118451 30320 leveldb.cpp:399] Deleting ~1 keys from leveldb took 77007ns
I1201 14:14:27.118479 30320 replica.cpp:713] Persisted action at 2
I1201 14:14:27.118516 30320 replica.cpp:698] Replica learned TRUNCATE action at position 2
I1201 14:14:27.131505 30295 containerizer.cpp:141] Using isolation: posix/cpu,posix/mem,filesystem/posix
W1201 14:14:27.131902 30295 backend.cpp:48] Failed to create 'bind' backend: BindBackend requires root privileges
I1201 14:14:27.143996 30327 slave.cpp:189] Slave started on 61)@172.17.21.7:43732
I1201 14:14:27.144155 30327 slave.cpp:190] Flags at startup: --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" --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/HealthCheckTest_CheckCommandTimeout_DODrUR/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_auth_server="auth.docker.io" --docker_auth_server_port="443" --docker_kill_orphans="true" --docker_local_archives_dir="/tmp/mesos/images/docker" --docker_puller="local" --docker_puller_timeout="60" --docker_registry="registry-1.docker.io" --docker_registry_port="443" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/HealthCheckTest_CheckCommandTimeout_DODrUR/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/mesos/mesos-0.27.0/_build/src" --logbufsecs="0" --logging_level="INFO" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:2;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/HealthCheckTest_CheckCommandTimeout_DODrUR"
I1201 14:14:27.144866 30327 credentials.hpp:83] Loading credential for authentication from '/tmp/HealthCheckTest_CheckCommandTimeout_DODrUR/credential'
I1201 14:14:27.145210 30327 slave.cpp:320] Slave using credential for: test-principal
I1201 14:14:27.145454 30327 resources.cpp:478] Parsing resources as JSON failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000]
Trying semicolon-delimited string format instead
I1201 14:14:27.146003 30327 slave.cpp:390] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I1201 14:14:27.146389 30327 slave.cpp:398] Slave attributes: [ ]
I1201 14:14:27.146450 30327 slave.cpp:403] Slave hostname: ca6f16e00db6
I1201 14:14:27.146512 30327 slave.cpp:408] Slave checkpoint: true
I1201 14:14:27.148231 30326 state.cpp:52] Recovering state from '/tmp/HealthCheckTest_CheckCommandTimeout_DODrUR/meta'
I1201 14:14:27.153398 30295 sched.cpp:164] Version: 0.27.0
I1201 14:14:27.153487 30327 status_update_manager.cpp:200] Recovering status update manager
I1201 14:14:27.154454 30327 containerizer.cpp:383] Recovering containerizer
I1201 14:14:27.155915 30321 slave.cpp:4258] Finished recovery
I1201 14:14:27.156283 30315 sched.cpp:262] New master detected at master@172.17.21.7:43732
I1201 14:14:27.156508 30315 sched.cpp:318] Authenticating with master master@172.17.21.7:43732
I1201 14:14:27.156584 30315 sched.cpp:325] Using default CRAM-MD5 authenticatee
I1201 14:14:27.157011 30315 authenticatee.cpp:121] Creating new client SASL connection
I1201 14:14:27.157587 30325 master.cpp:5181] Authenticating scheduler-90969aaa-c756-4602-8e8a-c07acb10fcfb@172.17.21.7:43732
I1201 14:14:27.157835 30325 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(168)@172.17.21.7:43732
I1201 14:14:27.158241 30325 authenticator.cpp:98] Creating new server SASL connection
I1201 14:14:27.158654 30315 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
I1201 14:14:27.158753 30315 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
I1201 14:14:27.158895 30315 authenticator.cpp:203] Received SASL authentication start
I1201 14:14:27.159062 30315 authenticator.cpp:325] Authentication requires more steps
I1201 14:14:27.159219 30325 authenticatee.cpp:258] Received SASL authentication step
I1201 14:14:27.159415 30315 authenticator.cpp:231] Received SASL authentication step
I1201 14:14:27.159498 30315 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ca6f16e00db6' server FQDN: 'ca6f16e00db6' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1201 14:14:27.159566 30315 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
I1201 14:14:27.159669 30315 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1201 14:14:27.159757 30315 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ca6f16e00db6' server FQDN: 'ca6f16e00db6' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1201 14:14:27.159826 30315 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1201 14:14:27.159883 30315 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1201 14:14:27.159953 30315 authenticator.cpp:317] Authentication success
I1201 14:14:27.160225 30318 master.cpp:5211] Successfully authenticated principal 'test-principal' at scheduler-90969aaa-c756-4602-8e8a-c07acb10fcfb@172.17.21.7:43732
I1201 14:14:27.160372 30318 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(168)@172.17.21.7:43732
I1201 14:14:27.160688 30315 authenticatee.cpp:298] Authentication success
I1201 14:14:27.161622 30315 sched.cpp:407] Successfully authenticated with master master@172.17.21.7:43732
I1201 14:14:27.162294 30315 sched.cpp:714] Sending SUBSCRIBE call to master@172.17.21.7:43732
I1201 14:14:27.162508 30315 sched.cpp:747] Will retry registration in 1.129902694secs if necessary
I1201 14:14:27.162696 30318 master.cpp:2207] Received SUBSCRIBE call for framework 'default' at scheduler-90969aaa-c756-4602-8e8a-c07acb10fcfb@172.17.21.7:43732
I1201 14:14:27.163007 30318 master.cpp:1676] Authorizing framework principal 'test-principal' to receive offers for role '*'
I1201 14:14:27.161137 30321 slave.cpp:4430] Querying resource estimator for oversubscribable resources
I1201 14:14:27.164012 30321 slave.cpp:727] New master detected at master@172.17.21.7:43732
I1201 14:14:27.164070 30328 status_update_manager.cpp:174] Pausing sending status updates
I1201 14:14:27.164103 30321 slave.cpp:790] Authenticating with master master@172.17.21.7:43732
I1201 14:14:27.164119 30321 slave.cpp:795] Using default CRAM-MD5 authenticatee
I1201 14:14:27.164353 30321 slave.cpp:763] Detecting new master
I1201 14:14:27.164423 30317 authenticatee.cpp:121] Creating new client SASL connection
I1201 14:14:27.164472 30321 slave.cpp:4444] Received oversubscribable resources from the resource estimator
I1201 14:14:27.164697 30318 master.cpp:5181] Authenticating slave(61)@172.17.21.7:43732
I1201 14:14:27.165030 30328 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(169)@172.17.21.7:43732
I1201 14:14:27.165266 30324 authenticator.cpp:98] Creating new server SASL connection
I1201 14:14:27.165489 30321 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
I1201 14:14:27.165514 30321 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
I1201 14:14:27.165596 30321 authenticator.cpp:203] Received SASL authentication start
I1201 14:14:27.166223 30321 authenticator.cpp:325] Authentication requires more steps
I1201 14:14:27.166311 30321 authenticatee.cpp:258] Received SASL authentication step
I1201 14:14:27.166394 30321 authenticator.cpp:231] Received SASL authentication step
I1201 14:14:27.166424 30321 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ca6f16e00db6' server FQDN: 'ca6f16e00db6' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1201 14:14:27.166435 30321 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
I1201 14:14:27.166481 30321 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1201 14:14:27.166504 30321 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ca6f16e00db6' server FQDN: 'ca6f16e00db6' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1201 14:14:27.166514 30321 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1201 14:14:27.166522 30321 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1201 14:14:27.166538 30321 authenticator.cpp:317] Authentication success
I1201 14:14:27.166679 30321 authenticatee.cpp:298] Authentication success
I1201 14:14:27.166760 30321 master.cpp:5211] Successfully authenticated principal 'test-principal' at slave(61)@172.17.21.7:43732
I1201 14:14:27.166833 30321 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(169)@172.17.21.7:43732
I1201 14:14:27.167089 30321 slave.cpp:858] Successfully authenticated with master master@172.17.21.7:43732
I1201 14:14:27.167477 30322 master.cpp:3890] Registering slave at slave(61)@172.17.21.7:43732 (ca6f16e00db6) with id 587d1fd5-db6b-4af4-9267-ce84ac458470-S0
I1201 14:14:27.167721 30321 slave.cpp:1252] Will retry registration in 2.161007ms if necessary
I1201 14:14:27.168022 30316 registrar.cpp:439] Applied 1 operations in 80369ns; attempting to update the 'registry'
I1201 14:14:27.168381 30323 master.cpp:2278] Subscribing framework default with checkpointing disabled and capabilities [ ]
I1201 14:14:27.169057 30316 hierarchical.cpp:220] Added framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
I1201 14:14:27.169118 30316 hierarchical.cpp:1062] No resources available to allocate!
I1201 14:14:27.169164 30316 hierarchical.cpp:1155] No inverse offers to send out!
I1201 14:14:27.169214 30316 hierarchical.cpp:957] Performed allocation for 0 slaves in 129635ns
I1201 14:14:27.169347 30321 sched.cpp:641] Framework registered with 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
I1201 14:14:27.169394 30321 sched.cpp:655] Scheduler::registered took 23910ns
I1201 14:14:27.169589 30322 log.cpp:683] Attempting to append 342 bytes to the log
I1201 14:14:27.170240 30319 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3
I1201 14:14:27.170464 30329 slave.cpp:1252] Will retry registration in 33.87185ms if necessary
I1201 14:14:27.170650 30319 master.cpp:3878] Ignoring register slave message from slave(61)@172.17.21.7:43732 (ca6f16e00db6) as admission is already in progress
I1201 14:14:27.171053 30322 replica.cpp:538] Replica received write request for position 3 from (1921)@172.17.21.7:43732
I1201 14:14:27.185808 30322 leveldb.cpp:341] Persisting action (361 bytes) to leveldb took 14.695502ms
I1201 14:14:27.185899 30322 replica.cpp:713] Persisted action at 3
I1201 14:14:27.187346 30314 replica.cpp:692] Replica received learned notice for position 3 from @0.0.0.0:0
I1201 14:14:27.206691 30322 slave.cpp:1252] Will retry registration in 21.161456ms if necessary
I1201 14:14:27.207093 30322 master.cpp:3878] Ignoring register slave message from slave(61)@172.17.21.7:43732 (ca6f16e00db6) as admission is already in progress
I1201 14:14:27.215098 30314 leveldb.cpp:341] Persisting action (363 bytes) to leveldb took 27.696174ms
I1201 14:14:27.215196 30314 replica.cpp:713] Persisted action at 3
I1201 14:14:27.215239 30314 replica.cpp:698] Replica learned APPEND action at position 3
I1201 14:14:27.218340 30314 registrar.cpp:484] Successfully updated the 'registry' in 50.230016ms
I1201 14:14:27.218909 30314 log.cpp:702] Attempting to truncate the log to 3
I1201 14:14:27.220247 30322 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 4
I1201 14:14:27.220552 30328 hierarchical.cpp:380] Added slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0 (ca6f16e00db6) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
I1201 14:14:27.220841 30322 slave.cpp:902] Registered with master master@172.17.21.7:43732; given slave ID 587d1fd5-db6b-4af4-9267-ce84ac458470-S0
I1201 14:14:27.220865 30322 fetcher.cpp:79] Clearing fetcher cache
I1201 14:14:27.220121 30314 master.cpp:3958] Registered slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0 at slave(61)@172.17.21.7:43732 (ca6f16e00db6) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I1201 14:14:27.221568 30328 hierarchical.cpp:1155] No inverse offers to send out!
I1201 14:14:27.221766 30322 slave.cpp:925] Checkpointing SlaveInfo to '/tmp/HealthCheckTest_CheckCommandTimeout_DODrUR/meta/slaves/587d1fd5-db6b-4af4-9267-ce84ac458470-S0/slave.info'
I1201 14:14:27.221575 30314 status_update_manager.cpp:181] Resuming sending status updates
I1201 14:14:27.221885 30328 hierarchical.cpp:973] Performed allocation for slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0 in 1.185334ms
I1201 14:14:27.222190 30317 master.cpp:5010] Sending 1 offers to framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 (default) at scheduler-90969aaa-c756-4602-8e8a-c07acb10fcfb@172.17.21.7:43732
I1201 14:14:27.222575 30322 slave.cpp:961] Forwarding total oversubscribed resources
I1201 14:14:27.222957 30317 sched.cpp:811] Scheduler::resourceOffers took 146960ns
I1201 14:14:27.223748 30319 replica.cpp:538] Replica received write request for position 4 from (1922)@172.17.21.7:43732
I1201 14:14:27.223976 30322 slave.cpp:3197] Received ping from slave-observer(58)@172.17.21.7:43732
I1201 14:14:27.224243 30325 master.cpp:4300] Received update of slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0 at slave(61)@172.17.21.7:43732 (ca6f16e00db6) with total oversubscribed resources
I1201 14:14:27.225162 30325 hierarchical.cpp:434] Slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0 (ca6f16e00db6) updated with oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000])
I1201 14:14:27.225759 30325 hierarchical.cpp:1062] No resources available to allocate!
I1201 14:14:27.226012 30325 hierarchical.cpp:1155] No inverse offers to send out!
I1201 14:14:27.226039 30325 hierarchical.cpp:973] Performed allocation for slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0 in 751766ns
I1201 14:14:27.228044 30321 master.cpp:2946] Processing ACCEPT call for offers: [ 587d1fd5-db6b-4af4-9267-ce84ac458470-O0 ] on slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0 at slave(61)@172.17.21.7:43732 (ca6f16e00db6) for framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 (default) at scheduler-90969aaa-c756-4602-8e8a-c07acb10fcfb@172.17.21.7:43732
I1201 14:14:27.228107 30321 master.cpp:2742] Authorizing framework principal 'test-principal' to launch task 1 as user 'mesos'
I1201 14:14:27.230907 30323 master.hpp:176] Adding task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0 (ca6f16e00db6)
I1201 14:14:27.231200 30323 master.cpp:3276] Launching task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 (default) at scheduler-90969aaa-c756-4602-8e8a-c07acb10fcfb@172.17.21.7:43732 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0 at slave(61)@172.17.21.7:43732 (ca6f16e00db6)
I1201 14:14:27.231850 30323 slave.cpp:1292] Got assigned task 1 for framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
I1201 14:14:27.232142 30323 resources.cpp:478] Parsing resources as JSON failed: cpus:0.1;mem:32
Trying semicolon-delimited string format instead
I1201 14:14:27.233273 30323 slave.cpp:1411] Launching task 1 for framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
I1201 14:14:27.233381 30323 resources.cpp:478] Parsing resources as JSON failed: cpus:0.1;mem:32
Trying semicolon-delimited string format instead
I1201 14:14:27.249552 30323 paths.cpp:434] Trying to chown '/tmp/HealthCheckTest_CheckCommandTimeout_DODrUR/slaves/587d1fd5-db6b-4af4-9267-ce84ac458470-S0/frameworks/587d1fd5-db6b-4af4-9267-ce84ac458470-0000/executors/1/runs/e5213230-3cf6-4e8c-b7cd-f4e2615df70f' to user 'mesos'
I1201 14:14:27.255273 30323 slave.cpp:5042] Launching executor 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/HealthCheckTest_CheckCommandTimeout_DODrUR/slaves/587d1fd5-db6b-4af4-9267-ce84ac458470-S0/frameworks/587d1fd5-db6b-4af4-9267-ce84ac458470-0000/executors/1/runs/e5213230-3cf6-4e8c-b7cd-f4e2615df70f'
I1201 14:14:27.256011 30323 slave.cpp:1629] Queuing task '1' for executor '1' of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
I1201 14:14:27.256116 30327 containerizer.cpp:617] Starting container 'e5213230-3cf6-4e8c-b7cd-f4e2615df70f' for executor '1' of framework '587d1fd5-db6b-4af4-9267-ce84ac458470-0000'
I1201 14:14:27.257302 30319 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 33.493331ms
I1201 14:14:27.257356 30319 replica.cpp:713] Persisted action at 4
I1201 14:14:27.258471 30325 replica.cpp:692] Replica received learned notice for position 4 from @0.0.0.0:0
I1201 14:14:27.261706 30321 slave.cpp:680] Successfully attached file '/tmp/HealthCheckTest_CheckCommandTimeout_DODrUR/slaves/587d1fd5-db6b-4af4-9267-ce84ac458470-S0/frameworks/587d1fd5-db6b-4af4-9267-ce84ac458470-0000/executors/1/runs/e5213230-3cf6-4e8c-b7cd-f4e2615df70f'
I1201 14:14:27.268529 30327 launcher.cpp:132] Forked child with pid '3184' for container 'e5213230-3cf6-4e8c-b7cd-f4e2615df70f'
I1201 14:14:27.291683 30325 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 33.038313ms
I1201 14:14:27.292078 30325 leveldb.cpp:399] Deleting ~2 keys from leveldb took 87529ns
I1201 14:14:27.292244 30325 replica.cpp:713] Persisted action at 4
I1201 14:14:27.292456 30325 replica.cpp:698] Replica learned TRUNCATE action at position 4
I1201 14:14:27.507856 30325 slave.cpp:2406] Got registration for executor '1' of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 from executor(1)@172.17.21.7:46225
I1201 14:14:27.512398 30314 slave.cpp:1794] Sending queued task '1' to executor '1' of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 at executor(1)@172.17.21.7:46225
I1201 14:14:27.539080 30322 slave.cpp:2763] Handling status update TASK_RUNNING (UUID: f6c38987-fb13-4ce6-af7f-7839ce3b8ecb) for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 from executor(1)@172.17.21.7:46225
I1201 14:14:27.540004 30318 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: f6c38987-fb13-4ce6-af7f-7839ce3b8ecb) for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
I1201 14:14:27.540385 30318 status_update_manager.cpp:497] Creating StatusUpdate stream for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
I1201 14:14:27.541409 30318 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: f6c38987-fb13-4ce6-af7f-7839ce3b8ecb) for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 to the slave
I1201 14:14:27.542279 30322 slave.cpp:3115] Forwarding the update TASK_RUNNING (UUID: f6c38987-fb13-4ce6-af7f-7839ce3b8ecb) for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 to master@172.17.21.7:43732
I1201 14:14:27.542510 30322 slave.cpp:3009] Status update manager successfully handled status update TASK_RUNNING (UUID: f6c38987-fb13-4ce6-af7f-7839ce3b8ecb) for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
I1201 14:14:27.542562 30322 slave.cpp:3025] Sending acknowledgement for status update TASK_RUNNING (UUID: f6c38987-fb13-4ce6-af7f-7839ce3b8ecb) for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 to executor(1)@172.17.21.7:46225
I1201 14:14:27.543005 30318 master.cpp:4445] Status update TASK_RUNNING (UUID: f6c38987-fb13-4ce6-af7f-7839ce3b8ecb) for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 from slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0 at slave(61)@172.17.21.7:43732 (ca6f16e00db6)
I1201 14:14:27.543375 30318 master.cpp:4493] Forwarding status update TASK_RUNNING (UUID: f6c38987-fb13-4ce6-af7f-7839ce3b8ecb) for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
I1201 14:14:27.543947 30318 master.cpp:6097] Updating the state of task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
I1201 14:14:27.544643 30318 sched.cpp:919] Scheduler::statusUpdate took 137099ns
I1201 14:14:27.545348 30322 master.cpp:3602] Processing ACKNOWLEDGE call f6c38987-fb13-4ce6-af7f-7839ce3b8ecb for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 (default) at scheduler-90969aaa-c756-4602-8e8a-c07acb10fcfb@172.17.21.7:43732 on slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0
I1201 14:14:27.545892 30329 status_update_manager.cpp:392] Received status update acknowledgement (UUID: f6c38987-fb13-4ce6-af7f-7839ce3b8ecb) for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
I1201 14:14:27.546821 30329 slave.cpp:2346] Status update manager successfully handled status update acknowledgement (UUID: f6c38987-fb13-4ce6-af7f-7839ce3b8ecb) for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
I1201 14:14:27.615839 30322 hierarchical.cpp:1062] No resources available to allocate!
I1201 14:14:27.615924 30322 hierarchical.cpp:1155] No inverse offers to send out!
I1201 14:14:27.615954 30322 hierarchical.cpp:957] Performed allocation for 1 slaves in 826681ns
I1201 14:14:28.617543 30326 hierarchical.cpp:1062] No resources available to allocate!
I1201 14:14:28.617914 30326 hierarchical.cpp:1155] No inverse offers to send out!
I1201 14:14:28.618074 30326 hierarchical.cpp:957] Performed allocation for 1 slaves in 1.123832ms
I1201 14:14:29.619159 30314 hierarchical.cpp:1062] No resources available to allocate!
I1201 14:14:29.619263 30314 hierarchical.cpp:1155] No inverse offers to send out!
I1201 14:14:29.619300 30314 hierarchical.cpp:957] Performed allocation for 1 slaves in 726672ns
I1201 14:14:30.622232 30329 hierarchical.cpp:1062] No resources available to allocate!
I1201 14:14:30.622321 30329 hierarchical.cpp:1155] No inverse offers to send out!
I1201 14:14:30.622359 30329 hierarchical.cpp:957] Performed allocation for 1 slaves in 719341ns
I1201 14:14:31.625255 30314 hierarchical.cpp:1062] No resources available to allocate!
I1201 14:14:31.625346 30314 hierarchical.cpp:1155] No inverse offers to send out!
I1201 14:14:31.625383 30314 hierarchical.cpp:957] Performed allocation for 1 slaves in 743648ns
I1201 14:14:32.628315 30318 hierarchical.cpp:1062] No resources available to allocate!
I1201 14:14:32.628419 30318 hierarchical.cpp:1155] No inverse offers to send out!
I1201 14:14:32.628478 30318 hierarchical.cpp:957] Performed allocation for 1 slaves in 809723ns
I1201 14:14:32.744158 30321 slave.cpp:2763] Handling status update TASK_RUNNING (UUID: a20337d6-2301-44ba-bd7e-60cd5c7ac014) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 from executor(1)@172.17.21.7:46225
I1201 14:14:32.744817 30319 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: a20337d6-2301-44ba-bd7e-60cd5c7ac014) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
I1201 14:14:32.745187 30319 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: a20337d6-2301-44ba-bd7e-60cd5c7ac014) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 to the slave
I1201 14:14:32.745558 30325 slave.cpp:3115] Forwarding the update TASK_RUNNING (UUID: a20337d6-2301-44ba-bd7e-60cd5c7ac014) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 to master@172.17.21.7:43732
I1201 14:14:32.745990 30325 slave.cpp:3009] Status update manager successfully handled status update TASK_RUNNING (UUID: a20337d6-2301-44ba-bd7e-60cd5c7ac014) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
I1201 14:14:32.746037 30325 slave.cpp:3025] Sending acknowledgement for status update TASK_RUNNING (UUID: a20337d6-2301-44ba-bd7e-60cd5c7ac014) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 to executor(1)@172.17.21.7:46225
I1201 14:14:32.746395 30320 master.cpp:4445] Status update TASK_RUNNING (UUID: a20337d6-2301-44ba-bd7e-60cd5c7ac014) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 from slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0 at slave(61)@172.17.21.7:43732 (ca6f16e00db6)
I1201 14:14:32.747027 30320 master.cpp:4493] Forwarding status update TASK_RUNNING (UUID: a20337d6-2301-44ba-bd7e-60cd5c7ac014) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
I1201 14:14:32.747349 30320 master.cpp:6097] Updating the state of task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
I1201 14:14:32.747804 30315 sched.cpp:919] Scheduler::statusUpdate took 115298ns
I1201 14:14:32.748492 30315 master.cpp:3602] Processing ACKNOWLEDGE call a20337d6-2301-44ba-bd7e-60cd5c7ac014 for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 (default) at scheduler-90969aaa-c756-4602-8e8a-c07acb10fcfb@172.17.21.7:43732 on slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0
I1201 14:14:32.748931 30324 status_update_manager.cpp:392] Received status update acknowledgement (UUID: a20337d6-2301-44ba-bd7e-60cd5c7ac014) for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
I1201 14:14:32.749595 30324 slave.cpp:2346] Status update manager successfully handled status update acknowledgement (UUID: a20337d6-2301-44ba-bd7e-60cd5c7ac014) for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
I1201 14:14:33.630220 30321 hierarchical.cpp:1062] No resources available to allocate!
I1201 14:14:33.630412 30321 hierarchical.cpp:1155] No inverse offers to send out!
I1201 14:14:33.630549 30321 hierarchical.cpp:957] Performed allocation for 1 slaves in 908929ns
I1201 14:14:34.631630 30324 hierarchical.cpp:1062] No resources available to allocate!
I1201 14:14:34.631721 30324 hierarchical.cpp:1155] No inverse offers to send out!
I1201 14:14:34.631757 30324 hierarchical.cpp:957] Performed allocation for 1 slaves in 697251ns
I1201 14:14:35.632884 30322 hierarchical.cpp:1062] No resources available to allocate!
I1201 14:14:35.632969 30322 hierarchical.cpp:1155] No inverse offers to send out!
I1201 14:14:35.633003 30322 hierarchical.cpp:957] Performed allocation for 1 slaves in 676552ns
I1201 14:14:36.634296 30315 hierarchical.cpp:1062] No resources available to allocate!
I1201 14:14:36.634392 30315 hierarchical.cpp:1155] No inverse offers to send out!
I1201 14:14:36.634426 30315 hierarchical.cpp:957] Performed allocation for 1 slaves in 758855ns
I1201 14:14:37.637233 30323 hierarchical.cpp:1062] No resources available to allocate!
I1201 14:14:37.637323 30323 hierarchical.cpp:1155] No inverse offers to send out!
I1201 14:14:37.637359 30323 hierarchical.cpp:957] Performed allocation for 1 slaves in 726275ns
I1201 14:14:37.764578 30326 slave.cpp:2763] Handling status update TASK_RUNNING (UUID: 01be2c68-5336-411a-aa1e-84a46d11c688) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 from executor(1)@172.17.21.7:46225
I1201 14:14:37.765316 30326 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 01be2c68-5336-411a-aa1e-84a46d11c688) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
I1201 14:14:37.765745 30326 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: 01be2c68-5336-411a-aa1e-84a46d11c688) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 to the slave
I1201 14:14:37.766261 30318 slave.cpp:3115] Forwarding the update TASK_RUNNING (UUID: 01be2c68-5336-411a-aa1e-84a46d11c688) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 to master@172.17.21.7:43732
I1201 14:14:37.766813 30316 master.cpp:4445] Status update TASK_RUNNING (UUID: 01be2c68-5336-411a-aa1e-84a46d11c688) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 from slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0 at slave(61)@172.17.21.7:43732 (ca6f16e00db6)
I1201 14:14:37.767022 30316 master.cpp:4493] Forwarding status update TASK_RUNNING (UUID: 01be2c68-5336-411a-aa1e-84a46d11c688) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
I1201 14:14:37.767364 30316 master.cpp:6097] Updating the state of task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
I1201 14:14:37.767786 30327 sched.cpp:919] Scheduler::statusUpdate took 123386ns
I1201 14:14:37.771409 30316 master.cpp:3602] Processing ACKNOWLEDGE call 01be2c68-5336-411a-aa1e-84a46d11c688 for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 (default) at scheduler-90969aaa-c756-4602-8e8a-c07acb10fcfb@172.17.21.7:43732 on slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0
I1201 14:14:37.772351 30326 status_update_manager.cpp:392] Received status update acknowledgement (UUID: 01be2c68-5336-411a-aa1e-84a46d11c688) for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
I1201 14:14:37.772438 30316 slave.cpp:3009] Status update manager successfully handled status update TASK_RUNNING (UUID: 01be2c68-5336-411a-aa1e-84a46d11c688) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
I1201 14:14:37.772816 30316 slave.cpp:3025] Sending acknowledgement for status update TASK_RUNNING (UUID: 01be2c68-5336-411a-aa1e-84a46d11c688) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 to executor(1)@172.17.21.7:46225
I1201 14:14:37.773659 30326 slave.cpp:2346] Status update manager successfully handled status update acknowledgement (UUID: 01be2c68-5336-411a-aa1e-84a46d11c688) for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
I1201 14:14:38.639390 30325 hierarchical.cpp:1062] No resources available to allocate!
I1201 14:14:38.639753 30325 hierarchical.cpp:1155] No inverse offers to send out!
I1201 14:14:38.640020 30325 hierarchical.cpp:957] Performed allocation for 1 slaves in 1.435634ms
I1201 14:14:39.641808 30329 hierarchical.cpp:1062] No resources available to allocate!
I1201 14:14:39.641896 30329 hierarchical.cpp:1155] No inverse offers to send out!
I1201 14:14:39.641926 30329 hierarchical.cpp:957] Performed allocation for 1 slaves in 729812ns
I1201 14:14:40.643889 30320 hierarchical.cpp:1062] No resources available to allocate!
I1201 14:14:40.643978 30320 hierarchical.cpp:1155] No inverse offers to send out!
I1201 14:14:40.644009 30320 hierarchical.cpp:957] Performed allocation for 1 slaves in 741824ns
I1201 14:14:41.645243 30327 hierarchical.cpp:1062] No resources available to allocate!
I1201 14:14:41.645352 30327 hierarchical.cpp:1155] No inverse offers to send out!
I1201 14:14:41.645400 30327 hierarchical.cpp:957] Performed allocation for 1 slaves in 751314ns
I1201 14:14:42.165752 30329 slave.cpp:4430] Querying resource estimator for oversubscribable resources
I1201 14:14:42.166100 30329 slave.cpp:4444] Received oversubscribable resources from the resource estimator
I1201 14:14:42.222800 30317 slave.cpp:3197] Received ping from slave-observer(58)@172.17.21.7:43732
I1201 14:14:42.648282 30323 hierarchical.cpp:1062] No resources available to allocate!
I1201 14:14:42.648391 30323 hierarchical.cpp:1155] No inverse offers to send out!
I1201 14:14:42.648435 30323 hierarchical.cpp:957] Performed allocation for 1 slaves in 765531ns
I1201 14:14:42.800969 30320 slave.cpp:2763] Handling status update TASK_RUNNING (UUID: d6a4f449-13f7-49ec-8e58-ee693cea55b7) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 from executor(1)@172.17.21.7:46225
I1201 14:14:42.801570 30320 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: d6a4f449-13f7-49ec-8e58-ee693cea55b7) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
I1201 14:14:42.801789 30320 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: d6a4f449-13f7-49ec-8e58-ee693cea55b7) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 to the slave
I1201 14:14:42.802266 30327 slave.cpp:3115] Forwarding the update TASK_RUNNING (UUID: d6a4f449-13f7-49ec-8e58-ee693cea55b7) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 to master@172.17.21.7:43732
I1201 14:14:42.802454 30327 slave.cpp:3009] Status update manager successfully handled status update TASK_RUNNING (UUID: d6a4f449-13f7-49ec-8e58-ee693cea55b7) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
I1201 14:14:42.802500 30327 slave.cpp:3025] Sending acknowledgement for status update TASK_RUNNING (UUID: d6a4f449-13f7-49ec-8e58-ee693cea55b7) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 to executor(1)@172.17.21.7:46225
I1201 14:14:42.804724 30327 master.cpp:4445] Status update TASK_RUNNING (UUID: d6a4f449-13f7-49ec-8e58-ee693cea55b7) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 from slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0 at slave(61)@172.17.21.7:43732 (ca6f16e00db6)
I1201 14:14:42.804810 30327 master.cpp:4493] Forwarding status update TASK_RUNNING (UUID: d6a4f449-13f7-49ec-8e58-ee693cea55b7) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
I1201 14:14:42.805073 30327 master.cpp:6097] Updating the state of task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
I1201 14:14:42.805578 30327 sched.cpp:919] Scheduler::statusUpdate took 173590ns
I1201 14:14:42.806002 30327 master.cpp:3602] Processing ACKNOWLEDGE call d6a4f449-13f7-49ec-8e58-ee693cea55b7 for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 (default) at scheduler-90969aaa-c756-4602-8e8a-c07acb10fcfb@172.17.21.7:43732 on slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0
I1201 14:14:42.806567 30326 status_update_manager.cpp:392] Received status update acknowledgement (UUID: d6a4f449-13f7-49ec-8e58-ee693cea55b7) for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
I1201 14:14:42.806990 30326 slave.cpp:2346] Status update manager successfully handled status update acknowledgement (UUID: d6a4f449-13f7-49ec-8e58-ee693cea55b7) for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
I1201 14:14:42.853611 30321 slave.cpp:2763] Handling status update TASK_KILLED (UUID: bc631a7f-8b8a-4dd8-a1bb-7a28016108dc) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 from executor(1)@172.17.21.7:46225
I1201 14:14:42.853857 30321 slave.cpp:5341] Terminating task 1
I1201 14:14:42.855967 30321 status_update_manager.cpp:320] Received status update TASK_KILLED (UUID: bc631a7f-8b8a-4dd8-a1bb-7a28016108dc) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
I1201 14:14:42.856298 30321 status_update_manager.cpp:374] Forwarding update TASK_KILLED (UUID: bc631a7f-8b8a-4dd8-a1bb-7a28016108dc) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 to the slave
I1201 14:14:42.856757 30321 slave.cpp:3115] Forwarding the update TASK_KILLED (UUID: bc631a7f-8b8a-4dd8-a1bb-7a28016108dc) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 to master@172.17.21.7:43732
I1201 14:14:42.856945 30321 slave.cpp:3009] Status update manager successfully handled status update TASK_KILLED (UUID: bc631a7f-8b8a-4dd8-a1bb-7a28016108dc) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
I1201 14:14:42.856992 30321 slave.cpp:3025] Sending acknowledgement for status update TASK_KILLED (UUID: bc631a7f-8b8a-4dd8-a1bb-7a28016108dc) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 to executor(1)@172.17.21.7:46225
I1201 14:14:42.857553 30319 master.cpp:4445] Status update TASK_KILLED (UUID: bc631a7f-8b8a-4dd8-a1bb-7a28016108dc) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 from slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0 at slave(61)@172.17.21.7:43732 (ca6f16e00db6)
I1201 14:14:42.857599 30319 master.cpp:4493] Forwarding status update TASK_KILLED (UUID: bc631a7f-8b8a-4dd8-a1bb-7a28016108dc) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
I1201 14:14:42.857770 30319 master.cpp:6097] Updating the state of task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 (latest state: TASK_KILLED, status update state: TASK_KILLED)
I1201 14:14:42.858459 30325 sched.cpp:919] Scheduler::statusUpdate took 130918ns
I1201 14:14:42.859022 30325 hierarchical.cpp:791] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0 from framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
I1201 14:14:42.859416 30319 master.cpp:3602] Processing ACKNOWLEDGE call bc631a7f-8b8a-4dd8-a1bb-7a28016108dc for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 (default) at scheduler-90969aaa-c756-4602-8e8a-c07acb10fcfb@172.17.21.7:43732 on slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0
I1201 14:14:42.859482 30319 master.cpp:6163] Removing task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 on slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0 at slave(61)@172.17.21.7:43732 (ca6f16e00db6)
I1201 14:14:42.860584 30319 status_update_manager.cpp:392] Received status update acknowledgement (UUID: bc631a7f-8b8a-4dd8-a1bb-7a28016108dc) for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
I1201 14:14:42.860781 30319 status_update_manager.cpp:528] Cleaning up status update stream for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
I1201 14:14:42.861460 30319 slave.cpp:2346] Status update manager successfully handled status update acknowledgement (UUID: bc631a7f-8b8a-4dd8-a1bb-7a28016108dc) for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
I1201 14:14:42.861522 30319 slave.cpp:5382] Completing task 1
I1201 14:14:42.861721 30295 sched.cpp:1803] Asked to stop the driver
I1201 14:14:42.861811 30319 sched.cpp:1041] Stopping framework '587d1fd5-db6b-4af4-9267-ce84ac458470-0000'
I1201 14:14:42.861917 30315 master.cpp:938] Master terminating
I1201 14:14:42.862610 30323 hierarchical.cpp:410] Removed slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0
I1201 14:14:42.863286 30322 hierarchical.cpp:260] Removed framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
I1201 14:14:42.863615 30326 slave.cpp:3243] master@172.17.21.7:43732 exited
W1201 14:14:42.863641 30326 slave.cpp:3246] Master disconnected! Waiting for a new master to be elected
I1201 14:14:42.877462 30318 containerizer.cpp:1073] Destroying container 'e5213230-3cf6-4e8c-b7cd-f4e2615df70f'
I1201 14:14:42.942379 30314 containerizer.cpp:1256] Executor for container 'e5213230-3cf6-4e8c-b7cd-f4e2615df70f' has exited
I1201 14:14:42.945029 30329 slave.cpp:3581] Executor '1' of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 terminated with signal Killed
I1201 14:14:42.945142 30329 slave.cpp:3685] Cleaning up executor '1' of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 at executor(1)@172.17.21.7:46225
I1201 14:14:42.945504 30326 gc.cpp:54] Scheduling '/tmp/HealthCheckTest_CheckCommandTimeout_DODrUR/slaves/587d1fd5-db6b-4af4-9267-ce84ac458470-S0/frameworks/587d1fd5-db6b-4af4-9267-ce84ac458470-0000/executors/1/runs/e5213230-3cf6-4e8c-b7cd-f4e2615df70f' for gc 6.9999890582637days in the future
I1201 14:14:42.945605 30329 slave.cpp:3773] Cleaning up framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
I1201 14:14:42.945726 30317 status_update_manager.cpp:282] Closing status update streams for framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
I1201 14:14:42.945765 30326 gc.cpp:54] Scheduling '/tmp/HealthCheckTest_CheckCommandTimeout_DODrUR/slaves/587d1fd5-db6b-4af4-9267-ce84ac458470-S0/frameworks/587d1fd5-db6b-4af4-9267-ce84ac458470-0000/executors/1' for gc 6.99998905620444days in the future
I1201 14:14:42.945861 30326 gc.cpp:54] Scheduling '/tmp/HealthCheckTest_CheckCommandTimeout_DODrUR/slaves/587d1fd5-db6b-4af4-9267-ce84ac458470-S0/frameworks/587d1fd5-db6b-4af4-9267-ce84ac458470-0000' for gc 6.99998905409778days in the future
I1201 14:14:42.946763 30295 slave.cpp:599] Slave terminating
[ OK ] HealthCheckTest.CheckCommandTimeout (16537 ms)
{noformat}
Also, this test takes 16 seconds to succeed? :(
was:https://builds.apache.org/job/Mesos/1288/COMPILER=gcc,CONFIGURATION=--verbose,OS=ubuntu:14.04,label_exp=docker%7C%7CHadoop/consoleText
Summary: HealthCheckTest.CheckCommandTimeout is flaky. (was: HealthCheckTest.CheckCommandTimeout flaky)
> HealthCheckTest.CheckCommandTimeout is flaky.
> ---------------------------------------------
>
> Key: MESOS-4024
> URL: https://issues.apache.org/jira/browse/MESOS-4024
> Project: Mesos
> Issue Type: Bug
> Reporter: haosdent
> Assignee: haosdent
> Labels: flaky-test
> Attachments: HealthCheckTest_CheckCommandTimeout.log
>
>
> {noformat: title=Failed Run}
> [ RUN ] HealthCheckTest.CheckCommandTimeout
> I1201 13:03:15.211911 30288 leveldb.cpp:174] Opened db in 126.548747ms
> I1201 13:03:15.254041 30288 leveldb.cpp:181] Compacted db in 42.053948ms
> I1201 13:03:15.254226 30288 leveldb.cpp:196] Created db iterator in 25588ns
> I1201 13:03:15.254281 30288 leveldb.cpp:202] Seeked to beginning of db in 3231ns
> I1201 13:03:15.254294 30288 leveldb.cpp:271] Iterated through 0 keys in the db in 256ns
> I1201 13:03:15.254348 30288 replica.cpp:778] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> I1201 13:03:15.255162 30311 recover.cpp:447] Starting replica recovery
> I1201 13:03:15.255502 30311 recover.cpp:473] Replica is in EMPTY status
> I1201 13:03:15.257158 30311 replica.cpp:674] Replica in EMPTY status received a broadcasted recover request from (1898)@172.17.21.0:52024
> I1201 13:03:15.258224 30318 recover.cpp:193] Received a recover response from a replica in EMPTY status
> I1201 13:03:15.259735 30310 recover.cpp:564] Updating replica status to STARTING
> I1201 13:03:15.265080 30322 master.cpp:365] Master dd5bff66-362f-4efc-963a-54756b2edcce (fa812f474cf4) started on 172.17.21.0:52024
> I1201 13:03:15.265121 30322 master.cpp:367] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="true" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/IaRntP/credentials" --framework_sorter="drf" --help="false" --hostname_lookup="true" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_slave_ping_timeouts="5" --quiet="false" --recovery_slave_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_store_timeout="25secs" --registry_strict="true" --root_submissions="true" --slave_ping_timeout="15secs" --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false" --webui_dir="/mesos/mesos-0.27.0/_inst/share/mesos/webui" --work_dir="/tmp/IaRntP/master" --zk_session_timeout="10secs"
> I1201 13:03:15.265487 30322 master.cpp:412] Master only allowing authenticated frameworks to register
> I1201 13:03:15.265504 30322 master.cpp:417] Master only allowing authenticated slaves to register
> I1201 13:03:15.265513 30322 credentials.hpp:35] Loading credentials for authentication from '/tmp/IaRntP/credentials'
> I1201 13:03:15.265842 30322 master.cpp:456] Using default 'crammd5' authenticator
> I1201 13:03:15.266006 30322 master.cpp:493] Authorization enabled
> I1201 13:03:15.266464 30308 hierarchical.cpp:162] Initialized hierarchical allocator process
> I1201 13:03:15.267225 30321 whitelist_watcher.cpp:77] No whitelist given
> I1201 13:03:15.268847 30322 master.cpp:1637] The newly elected leader is master@172.17.21.0:52024 with id dd5bff66-362f-4efc-963a-54756b2edcce
> I1201 13:03:15.268887 30322 master.cpp:1650] Elected as the leading master!
> I1201 13:03:15.268905 30322 master.cpp:1395] Recovering from registrar
> I1201 13:03:15.270830 30322 registrar.cpp:307] Recovering registrar
> I1201 13:03:15.291272 30318 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 31.410668ms
> I1201 13:03:15.291363 30318 replica.cpp:321] Persisted replica status to STARTING
> I1201 13:03:15.291733 30318 recover.cpp:473] Replica is in STARTING status
> I1201 13:03:15.293392 30318 replica.cpp:674] Replica in STARTING status received a broadcasted recover request from (1900)@172.17.21.0:52024
> I1201 13:03:15.294251 30307 recover.cpp:193] Received a recover response from a replica in STARTING status
> I1201 13:03:15.294756 30307 recover.cpp:564] Updating replica status to VOTING
> I1201 13:03:15.338260 30307 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 43.256127ms
> I1201 13:03:15.338348 30307 replica.cpp:321] Persisted replica status to VOTING
> I1201 13:03:15.338601 30307 recover.cpp:578] Successfully joined the Paxos group
> I1201 13:03:15.338803 30307 recover.cpp:462] Recover process terminated
> I1201 13:03:15.339624 30307 log.cpp:659] Attempting to start the writer
> I1201 13:03:15.342535 30316 replica.cpp:494] Replica received implicit promise request from (1901)@172.17.21.0:52024 with proposal 1
> I1201 13:03:15.383368 30316 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 40.616854ms
> I1201 13:03:15.383433 30316 replica.cpp:343] Persisted promised to 1
> I1201 13:03:15.389814 30312 coordinator.cpp:238] Coordinator attempting to fill missing positions
> I1201 13:03:15.391582 30316 replica.cpp:389] Replica received explicit promise request from (1902)@172.17.21.0:52024 for position 0 with proposal 2
> I1201 13:03:15.434260 30316 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 42.530151ms
> I1201 13:03:15.434340 30316 replica.cpp:713] Persisted action at 0
> I1201 13:03:15.438995 30315 replica.cpp:538] Replica received write request for position 0 from (1903)@172.17.21.0:52024
> I1201 13:03:15.439116 30315 leveldb.cpp:436] Reading position from leveldb took 52656ns
> I1201 13:03:15.468266 30315 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 29.058804ms
> I1201 13:03:15.468354 30315 replica.cpp:713] Persisted action at 0
> I1201 13:03:15.469364 30308 replica.cpp:692] Replica received learned notice for position 0 from @0.0.0.0:0
> I1201 13:03:15.500910 30308 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 31.499794ms
> I1201 13:03:15.500991 30308 replica.cpp:713] Persisted action at 0
> I1201 13:03:15.501029 30308 replica.cpp:698] Replica learned NOP action at position 0
> I1201 13:03:15.502320 30308 log.cpp:675] Writer started with ending position 0
> I1201 13:03:15.503906 30308 leveldb.cpp:436] Reading position from leveldb took 58333ns
> I1201 13:03:15.505216 30321 registrar.cpp:340] Successfully fetched the registry (0B) in 234.329856ms
> I1201 13:03:15.505354 30321 registrar.cpp:439] Applied 1 operations in 37858ns; attempting to update the 'registry'
> I1201 13:03:15.506649 30321 log.cpp:683] Attempting to append 171 bytes to the log
> I1201 13:03:15.506898 30321 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
> I1201 13:03:15.508052 30308 replica.cpp:538] Replica received write request for position 1 from (1904)@172.17.21.0:52024
> I1201 13:03:15.571291 30308 leveldb.cpp:341] Persisting action (190 bytes) to leveldb took 63.17935ms
> I1201 13:03:15.571372 30308 replica.cpp:713] Persisted action at 1
> I1201 13:03:15.572895 30308 replica.cpp:692] Replica received learned notice for position 1 from @0.0.0.0:0
> I1201 13:03:15.605268 30308 leveldb.cpp:341] Persisting action (192 bytes) to leveldb took 32.320829ms
> I1201 13:03:15.605357 30308 replica.cpp:713] Persisted action at 1
> I1201 13:03:15.605394 30308 replica.cpp:698] Replica learned APPEND action at position 1
> I1201 13:03:15.611315 30318 registrar.cpp:484] Successfully updated the 'registry' in 105.864192ms
> I1201 13:03:15.611776 30318 registrar.cpp:370] Successfully recovered registrar
> I1201 13:03:15.612607 30322 master.cpp:1447] Recovered 0 slaves from the Registry (132B) ; allowing 10mins for slaves to re-register
> I1201 13:03:15.613045 30322 hierarchical.cpp:174] Allocator recovery is not supported yet
> I1201 13:03:15.614012 30308 log.cpp:702] Attempting to truncate the log to 1
> I1201 13:03:15.614817 30307 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
> I1201 13:03:15.616644 30307 replica.cpp:538] Replica received write request for position 2 from (1905)@172.17.21.0:52024
> I1201 13:03:15.630637 30307 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 13.701643ms
> I1201 13:03:15.630728 30307 replica.cpp:713] Persisted action at 2
> I1201 13:03:15.632129 30307 replica.cpp:692] Replica received learned notice for position 2 from @0.0.0.0:0
> I1201 13:03:15.677260 30307 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 45.085356ms
> I1201 13:03:15.677404 30307 leveldb.cpp:399] Deleting ~1 keys from leveldb took 64881ns
> I1201 13:03:15.677433 30307 replica.cpp:713] Persisted action at 2
> I1201 13:03:15.677469 30307 replica.cpp:698] Replica learned TRUNCATE action at position 2
> I1201 13:03:15.680896 30288 containerizer.cpp:141] Using isolation: posix/cpu,posix/mem,filesystem/posix
> W1201 13:03:15.681568 30288 backend.cpp:48] Failed to create 'bind' backend: BindBackend requires root privileges
> I1201 13:03:15.717629 30317 slave.cpp:189] Slave started on 61)@172.17.21.0:52024
> I1201 13:03:15.717674 30317 slave.cpp:190] Flags at startup: --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" --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/HealthCheckTest_CheckCommandTimeout_6kGYjg/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_auth_server="auth.docker.io" --docker_auth_server_port="443" --docker_kill_orphans="true" --docker_local_archives_dir="/tmp/mesos/images/docker" --docker_puller="local" --docker_puller_timeout="60" --docker_registry="registry-1.docker.io" --docker_registry_port="443" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/HealthCheckTest_CheckCommandTimeout_6kGYjg/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/mesos/mesos-0.27.0/_build/src" --logbufsecs="0" --logging_level="INFO" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:2;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/HealthCheckTest_CheckCommandTimeout_6kGYjg"
> I1201 13:03:15.718204 30317 credentials.hpp:83] Loading credential for authentication from '/tmp/HealthCheckTest_CheckCommandTimeout_6kGYjg/credential'
> I1201 13:03:15.718427 30317 slave.cpp:320] Slave using credential for: test-principal
> I1201 13:03:15.718590 30317 resources.cpp:478] Parsing resources as JSON failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000]
> Trying semicolon-delimited string format instead
> I1201 13:03:15.719068 30317 slave.cpp:390] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I1201 13:03:15.719142 30317 slave.cpp:398] Slave attributes: [ ]
> I1201 13:03:15.719156 30317 slave.cpp:403] Slave hostname: fa812f474cf4
> I1201 13:03:15.719182 30317 slave.cpp:408] Slave checkpoint: true
> I1201 13:03:15.720470 30308 state.cpp:52] Recovering state from '/tmp/HealthCheckTest_CheckCommandTimeout_6kGYjg/meta'
> I1201 13:03:15.721117 30319 status_update_manager.cpp:200] Recovering status update manager
> I1201 13:03:15.721451 30319 containerizer.cpp:383] Recovering containerizer
> I1201 13:03:15.722421 30288 sched.cpp:164] Version: 0.27.0
> I1201 13:03:15.723305 30307 slave.cpp:4258] Finished recovery
> I1201 13:03:15.723848 30307 slave.cpp:4430] Querying resource estimator for oversubscribable resources
> I1201 13:03:15.724340 30308 slave.cpp:727] New master detected at master@172.17.21.0:52024
> I1201 13:03:15.724370 30311 status_update_manager.cpp:174] Pausing sending status updates
> I1201 13:03:15.724428 30308 slave.cpp:790] Authenticating with master master@172.17.21.0:52024
> I1201 13:03:15.724447 30308 slave.cpp:795] Using default CRAM-MD5 authenticatee
> I1201 13:03:15.724616 30308 slave.cpp:763] Detecting new master
> I1201 13:03:15.724714 30319 authenticatee.cpp:121] Creating new client SASL connection
> I1201 13:03:15.724731 30308 slave.cpp:4444] Received oversubscribable resources from the resource estimator
> I1201 13:03:15.724836 30308 sched.cpp:262] New master detected at master@172.17.21.0:52024
> I1201 13:03:15.724911 30308 sched.cpp:318] Authenticating with master master@172.17.21.0:52024
> I1201 13:03:15.724928 30308 sched.cpp:325] Using default CRAM-MD5 authenticatee
> I1201 13:03:15.725319 30308 authenticatee.cpp:121] Creating new client SASL connection
> I1201 13:03:15.725348 30319 master.cpp:5181] Authenticating slave(61)@172.17.21.0:52024
> I1201 13:03:15.725872 30319 master.cpp:5181] Authenticating scheduler-05ae72c3-af75-4cab-b2df-764ef7c26d35@172.17.21.0:52024
> I1201 13:03:15.725978 30321 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(169)@172.17.21.0:52024
> I1201 13:03:15.726480 30321 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(170)@172.17.21.0:52024
> I1201 13:03:15.726966 30321 authenticator.cpp:98] Creating new server SASL connection
> I1201 13:03:15.726670 30316 authenticator.cpp:98] Creating new server SASL connection
> I1201 13:03:15.727452 30316 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
> I1201 13:03:15.727605 30316 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
> I1201 13:03:15.727756 30316 authenticator.cpp:203] Received SASL authentication start
> I1201 13:03:15.727913 30316 authenticator.cpp:325] Authentication requires more steps
> I1201 13:03:15.728073 30316 authenticatee.cpp:258] Received SASL authentication step
> I1201 13:03:15.728250 30316 authenticator.cpp:231] Received SASL authentication step
> I1201 13:03:15.728638 30316 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'fa812f474cf4' server FQDN: 'fa812f474cf4' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I1201 13:03:15.728721 30316 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
> I1201 13:03:15.728854 30316 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I1201 13:03:15.728977 30316 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'fa812f474cf4' server FQDN: 'fa812f474cf4' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I1201 13:03:15.729069 30316 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I1201 13:03:15.729154 30316 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I1201 13:03:15.729269 30316 authenticator.cpp:317] Authentication success
> I1201 13:03:15.729555 30316 authenticatee.cpp:298] Authentication success
> I1201 13:03:15.730110 30316 slave.cpp:858] Successfully authenticated with master master@172.17.21.0:52024
> I1201 13:03:15.730420 30316 slave.cpp:1252] Will retry registration in 9.588533ms if necessary
> I1201 13:03:15.728505 30321 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
> I1201 13:03:15.730845 30321 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
> I1201 13:03:15.731009 30321 authenticator.cpp:203] Received SASL authentication start
> I1201 13:03:15.729656 30314 master.cpp:5211] Successfully authenticated principal 'test-principal' at slave(61)@172.17.21.0:52024
> I1201 13:03:15.731493 30314 master.cpp:3890] Registering slave at slave(61)@172.17.21.0:52024 (fa812f474cf4) with id dd5bff66-362f-4efc-963a-54756b2edcce-S0
> I1201 13:03:15.729717 30311 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(169)@172.17.21.0:52024
> I1201 13:03:15.732597 30314 registrar.cpp:439] Applied 1 operations in 486128ns; attempting to update the 'registry'
> I1201 13:03:15.733901 30311 log.cpp:683] Attempting to append 340 bytes to the log
> I1201 13:03:15.734225 30310 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3
> I1201 13:03:15.735477 30318 replica.cpp:538] Replica received write request for position 3 from (1917)@172.17.21.0:52024
> I1201 13:03:15.734043 30321 authenticator.cpp:325] Authentication requires more steps
> I1201 13:03:15.735970 30321 authenticatee.cpp:258] Received SASL authentication step
> I1201 13:03:15.736068 30321 authenticator.cpp:231] Received SASL authentication step
> I1201 13:03:15.736107 30321 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'fa812f474cf4' server FQDN: 'fa812f474cf4' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I1201 13:03:15.736120 30321 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
> I1201 13:03:15.736423 30321 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I1201 13:03:15.736464 30321 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'fa812f474cf4' server FQDN: 'fa812f474cf4' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I1201 13:03:15.736480 30321 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I1201 13:03:15.736490 30321 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I1201 13:03:15.736508 30321 authenticator.cpp:317] Authentication success
> I1201 13:03:15.736748 30310 authenticatee.cpp:298] Authentication success
> I1201 13:03:15.736846 30310 master.cpp:5211] Successfully authenticated principal 'test-principal' at scheduler-05ae72c3-af75-4cab-b2df-764ef7c26d35@172.17.21.0:52024
> I1201 13:03:15.737114 30310 sched.cpp:407] Successfully authenticated with master master@172.17.21.0:52024
> I1201 13:03:15.737138 30310 sched.cpp:714] Sending SUBSCRIBE call to master@172.17.21.0:52024
> I1201 13:03:15.737776 30310 sched.cpp:747] Will retry registration in 175.278268ms if necessary
> I1201 13:03:15.737962 30310 master.cpp:2207] Received SUBSCRIBE call for framework 'default' at scheduler-05ae72c3-af75-4cab-b2df-764ef7c26d35@172.17.21.0:52024
> I1201 13:03:15.738026 30310 master.cpp:1676] Authorizing framework principal 'test-principal' to receive offers for role '*'
> I1201 13:03:15.738289 30321 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(170)@172.17.21.0:52024
> I1201 13:03:15.738601 30310 master.cpp:2278] Subscribing framework default with checkpointing disabled and capabilities [ ]
> I1201 13:03:15.739156 30310 hierarchical.cpp:220] Added framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
> I1201 13:03:15.739486 30310 hierarchical.cpp:1062] No resources available to allocate!
> I1201 13:03:15.739528 30310 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 13:03:15.739559 30310 hierarchical.cpp:957] Performed allocation for 0 slaves in 113362ns
> I1201 13:03:15.739363 30321 sched.cpp:641] Framework registered with dd5bff66-362f-4efc-963a-54756b2edcce-0000
> I1201 13:03:15.739622 30321 sched.cpp:655] Scheduler::registered took 25557ns
> I1201 13:03:15.741346 30312 master.cpp:3878] Ignoring register slave message from slave(61)@172.17.21.0:52024 (fa812f474cf4) as admission is already in progress
> I1201 13:03:15.741147 30316 slave.cpp:1252] Will retry registration in 9.901407ms if necessary
> I1201 13:03:15.752579 30322 slave.cpp:1252] Will retry registration in 54.177145ms if necessary
> I1201 13:03:15.752959 30320 master.cpp:3878] Ignoring register slave message from slave(61)@172.17.21.0:52024 (fa812f474cf4) as admission is already in progress
> I1201 13:03:15.756857 30318 leveldb.cpp:341] Persisting action (359 bytes) to leveldb took 21.322978ms
> I1201 13:03:15.757028 30318 replica.cpp:713] Persisted action at 3
> I1201 13:03:15.758445 30309 replica.cpp:692] Replica received learned notice for position 3 from @0.0.0.0:0
> I1201 13:03:15.809561 30315 slave.cpp:1252] Will retry registration in 90.392215ms if necessary
> I1201 13:03:15.809877 30315 master.cpp:3878] Ignoring register slave message from slave(61)@172.17.21.0:52024 (fa812f474cf4) as admission is already in progress
> I1201 13:03:15.811102 30309 leveldb.cpp:341] Persisting action (361 bytes) to leveldb took 52.532272ms
> I1201 13:03:15.811142 30309 replica.cpp:713] Persisted action at 3
> I1201 13:03:15.811187 30309 replica.cpp:698] Replica learned APPEND action at position 3
> I1201 13:03:15.813498 30315 registrar.cpp:484] Successfully updated the 'registry' in 80.742912ms
> I1201 13:03:15.814883 30315 master.cpp:3958] Registered slave dd5bff66-362f-4efc-963a-54756b2edcce-S0 at slave(61)@172.17.21.0:52024 (fa812f474cf4) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I1201 13:03:15.815547 30320 hierarchical.cpp:380] Added slave dd5bff66-362f-4efc-963a-54756b2edcce-S0 (fa812f474cf4) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
> I1201 13:03:15.817054 30320 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 13:03:15.817100 30320 hierarchical.cpp:973] Performed allocation for slave dd5bff66-362f-4efc-963a-54756b2edcce-S0 in 989520ns
> I1201 13:03:15.815670 30318 slave.cpp:902] Registered with master master@172.17.21.0:52024; given slave ID dd5bff66-362f-4efc-963a-54756b2edcce-S0
> I1201 13:03:15.817320 30318 fetcher.cpp:79] Clearing fetcher cache
> I1201 13:03:15.818097 30320 master.cpp:5010] Sending 1 offers to framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 (default) at scheduler-05ae72c3-af75-4cab-b2df-764ef7c26d35@172.17.21.0:52024
> I1201 13:03:15.818240 30314 status_update_manager.cpp:181] Resuming sending status updates
> I1201 13:03:15.818553 30318 slave.cpp:925] Checkpointing SlaveInfo to '/tmp/HealthCheckTest_CheckCommandTimeout_6kGYjg/meta/slaves/dd5bff66-362f-4efc-963a-54756b2edcce-S0/slave.info'
> I1201 13:03:15.818996 30318 slave.cpp:961] Forwarding total oversubscribed resources
> I1201 13:03:15.819099 30318 slave.cpp:3197] Received ping from slave-observer(58)@172.17.21.0:52024
> I1201 13:03:15.819594 30320 master.cpp:4300] Received update of slave dd5bff66-362f-4efc-963a-54756b2edcce-S0 at slave(61)@172.17.21.0:52024 (fa812f474cf4) with total oversubscribed resources
> I1201 13:03:15.820132 30320 sched.cpp:811] Scheduler::resourceOffers took 130339ns
> I1201 13:03:15.820576 30314 hierarchical.cpp:434] Slave dd5bff66-362f-4efc-963a-54756b2edcce-S0 (fa812f474cf4) updated with oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000])
> I1201 13:03:15.821035 30314 hierarchical.cpp:1062] No resources available to allocate!
> I1201 13:03:15.821076 30314 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 13:03:15.821096 30314 hierarchical.cpp:973] Performed allocation for slave dd5bff66-362f-4efc-963a-54756b2edcce-S0 in 469026ns
> I1201 13:03:15.822010 30309 log.cpp:702] Attempting to truncate the log to 3
> I1201 13:03:15.822232 30318 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 4
> I1201 13:03:15.823371 30310 replica.cpp:538] Replica received write request for position 4 from (1918)@172.17.21.0:52024
> I1201 13:03:15.824892 30316 master.cpp:2946] Processing ACCEPT call for offers: [ dd5bff66-362f-4efc-963a-54756b2edcce-O0 ] on slave dd5bff66-362f-4efc-963a-54756b2edcce-S0 at slave(61)@172.17.21.0:52024 (fa812f474cf4) for framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 (default) at scheduler-05ae72c3-af75-4cab-b2df-764ef7c26d35@172.17.21.0:52024
> I1201 13:03:15.824942 30316 master.cpp:2742] Authorizing framework principal 'test-principal' to launch task 1 as user 'mesos'
> I1201 13:03:15.826663 30316 master.hpp:176] Adding task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave dd5bff66-362f-4efc-963a-54756b2edcce-S0 (fa812f474cf4)
> I1201 13:03:15.826897 30316 master.cpp:3276] Launching task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 (default) at scheduler-05ae72c3-af75-4cab-b2df-764ef7c26d35@172.17.21.0:52024 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave dd5bff66-362f-4efc-963a-54756b2edcce-S0 at slave(61)@172.17.21.0:52024 (fa812f474cf4)
> I1201 13:03:15.827376 30322 slave.cpp:1292] Got assigned task 1 for framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
> I1201 13:03:15.827641 30322 resources.cpp:478] Parsing resources as JSON failed: cpus:0.1;mem:32
> Trying semicolon-delimited string format instead
> I1201 13:03:15.828306 30322 slave.cpp:1411] Launching task 1 for framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
> I1201 13:03:15.828402 30322 resources.cpp:478] Parsing resources as JSON failed: cpus:0.1;mem:32
> Trying semicolon-delimited string format instead
> I1201 13:03:15.851069 30322 paths.cpp:434] Trying to chown '/tmp/HealthCheckTest_CheckCommandTimeout_6kGYjg/slaves/dd5bff66-362f-4efc-963a-54756b2edcce-S0/frameworks/dd5bff66-362f-4efc-963a-54756b2edcce-0000/executors/1/runs/8d8aa0bb-fad5-4715-a14f-62783b07da81' to user 'mesos'
> I1201 13:03:15.856019 30310 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 32.584609ms
> I1201 13:03:15.856098 30310 replica.cpp:713] Persisted action at 4
> I1201 13:03:15.856991 30322 slave.cpp:5042] Launching executor 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/HealthCheckTest_CheckCommandTimeout_6kGYjg/slaves/dd5bff66-362f-4efc-963a-54756b2edcce-S0/frameworks/dd5bff66-362f-4efc-963a-54756b2edcce-0000/executors/1/runs/8d8aa0bb-fad5-4715-a14f-62783b07da81'
> I1201 13:03:15.857708 30322 slave.cpp:1629] Queuing task '1' for executor '1' of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
> I1201 13:03:15.857856 30322 slave.cpp:680] Successfully attached file '/tmp/HealthCheckTest_CheckCommandTimeout_6kGYjg/slaves/dd5bff66-362f-4efc-963a-54756b2edcce-S0/frameworks/dd5bff66-362f-4efc-963a-54756b2edcce-0000/executors/1/runs/8d8aa0bb-fad5-4715-a14f-62783b07da81'
> I1201 13:03:15.857945 30322 replica.cpp:692] Replica received learned notice for position 4 from @0.0.0.0:0
> I1201 13:03:15.857978 30310 containerizer.cpp:617] Starting container '8d8aa0bb-fad5-4715-a14f-62783b07da81' for executor '1' of framework 'dd5bff66-362f-4efc-963a-54756b2edcce-0000'
> I1201 13:03:15.862118 30312 launcher.cpp:132] Forked child with pid '3131' for container '8d8aa0bb-fad5-4715-a14f-62783b07da81'
> I1201 13:03:15.891278 30322 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 33.273317ms
> I1201 13:03:15.891428 30322 leveldb.cpp:399] Deleting ~2 keys from leveldb took 84833ns
> I1201 13:03:15.891456 30322 replica.cpp:713] Persisted action at 4
> I1201 13:03:15.891494 30322 replica.cpp:698] Replica learned TRUNCATE action at position 4
> I1201 13:03:16.100318 30322 slave.cpp:2406] Got registration for executor '1' of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 from executor(1)@172.17.21.0:58381
> I1201 13:03:16.104367 30317 slave.cpp:1794] Sending queued task '1' to executor '1' of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 at executor(1)@172.17.21.0:58381
> I1201 13:03:16.142390 30311 slave.cpp:2763] Handling status update TASK_RUNNING (UUID: cfdb8408-a2e8-441b-836c-3368e93ac6e2) for task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 from executor(1)@172.17.21.0:58381
> I1201 13:03:16.142907 30311 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: cfdb8408-a2e8-441b-836c-3368e93ac6e2) for task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
> I1201 13:03:16.142951 30311 status_update_manager.cpp:497] Creating StatusUpdate stream for task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
> I1201 13:03:16.143543 30311 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: cfdb8408-a2e8-441b-836c-3368e93ac6e2) for task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 to the slave
> I1201 13:03:16.144052 30311 slave.cpp:3115] Forwarding the update TASK_RUNNING (UUID: cfdb8408-a2e8-441b-836c-3368e93ac6e2) for task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 to master@172.17.21.0:52024
> I1201 13:03:16.145408 30311 slave.cpp:3009] Status update manager successfully handled status update TASK_RUNNING (UUID: cfdb8408-a2e8-441b-836c-3368e93ac6e2) for task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
> I1201 13:03:16.145467 30311 slave.cpp:3025] Sending acknowledgement for status update TASK_RUNNING (UUID: cfdb8408-a2e8-441b-836c-3368e93ac6e2) for task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 to executor(1)@172.17.21.0:58381
> I1201 13:03:16.147138 30311 master.cpp:4445] Status update TASK_RUNNING (UUID: cfdb8408-a2e8-441b-836c-3368e93ac6e2) for task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 from slave dd5bff66-362f-4efc-963a-54756b2edcce-S0 at slave(61)@172.17.21.0:52024 (fa812f474cf4)
> I1201 13:03:16.147233 30311 master.cpp:4493] Forwarding status update TASK_RUNNING (UUID: cfdb8408-a2e8-441b-836c-3368e93ac6e2) for task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
> I1201 13:03:16.147439 30311 master.cpp:6097] Updating the state of task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
> I1201 13:03:16.147747 30311 sched.cpp:919] Scheduler::statusUpdate took 122865ns
> I1201 13:03:16.148129 30311 master.cpp:3602] Processing ACKNOWLEDGE call cfdb8408-a2e8-441b-836c-3368e93ac6e2 for task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 (default) at scheduler-05ae72c3-af75-4cab-b2df-764ef7c26d35@172.17.21.0:52024 on slave dd5bff66-362f-4efc-963a-54756b2edcce-S0
> I1201 13:03:16.148674 30311 status_update_manager.cpp:392] Received status update acknowledgement (UUID: cfdb8408-a2e8-441b-836c-3368e93ac6e2) for task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
> I1201 13:03:16.149813 30320 slave.cpp:2346] Status update manager successfully handled status update acknowledgement (UUID: cfdb8408-a2e8-441b-836c-3368e93ac6e2) for task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
> I1201 13:03:16.269222 30322 hierarchical.cpp:1062] No resources available to allocate!
> I1201 13:03:16.269312 30322 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 13:03:16.269347 30322 hierarchical.cpp:957] Performed allocation for 1 slaves in 777937ns
> I1201 13:03:17.270767 30322 hierarchical.cpp:1062] No resources available to allocate!
> I1201 13:03:17.270853 30322 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 13:03:17.270884 30322 hierarchical.cpp:957] Performed allocation for 1 slaves in 793428ns
> I1201 13:03:18.273021 30318 hierarchical.cpp:1062] No resources available to allocate!
> I1201 13:03:18.273107 30318 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 13:03:18.273138 30318 hierarchical.cpp:957] Performed allocation for 1 slaves in 668062ns
> I1201 13:03:19.274287 30321 hierarchical.cpp:1062] No resources available to allocate!
> I1201 13:03:19.274371 30321 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 13:03:19.274402 30321 hierarchical.cpp:957] Performed allocation for 1 slaves in 705640ns
> I1201 13:03:20.276296 30313 hierarchical.cpp:1062] No resources available to allocate!
> I1201 13:03:20.276381 30313 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 13:03:20.276412 30313 hierarchical.cpp:957] Performed allocation for 1 slaves in 681486ns
> I1201 13:03:21.277920 30320 hierarchical.cpp:1062] No resources available to allocate!
> I1201 13:03:21.278004 30320 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 13:03:21.278034 30320 hierarchical.cpp:957] Performed allocation for 1 slaves in 673270ns
> I1201 13:03:21.281448 30312 slave.cpp:2763] Handling status update TASK_RUNNING (UUID: a820acb1-a9ed-46f5-83c2-1a6504f5c584) for task 1 in health state unhealthy of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 from executor(1)@172.17.21.0:58381
> I1201 13:03:21.282423 30312 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: a820acb1-a9ed-46f5-83c2-1a6504f5c584) for task 1 in health state unhealthy of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
> I1201 13:03:21.283000 30312 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: a820acb1-a9ed-46f5-83c2-1a6504f5c584) for task 1 in health state unhealthy of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 to the slave
> I1201 13:03:21.283670 30312 slave.cpp:3115] Forwarding the update TASK_RUNNING (UUID: a820acb1-a9ed-46f5-83c2-1a6504f5c584) for task 1 in health state unhealthy of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 to master@172.17.21.0:52024
> I1201 13:03:21.284276 30312 slave.cpp:3009] Status update manager successfully handled status update TASK_RUNNING (UUID: a820acb1-a9ed-46f5-83c2-1a6504f5c584) for task 1 in health state unhealthy of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
> I1201 13:03:21.284979 30312 slave.cpp:3025] Sending acknowledgement for status update TASK_RUNNING (UUID: a820acb1-a9ed-46f5-83c2-1a6504f5c584) for task 1 in health state unhealthy of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 to executor(1)@172.17.21.0:58381
> I1201 13:03:21.284695 30317 master.cpp:4445] Status update TASK_RUNNING (UUID: a820acb1-a9ed-46f5-83c2-1a6504f5c584) for task 1 in health state unhealthy of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 from slave dd5bff66-362f-4efc-963a-54756b2edcce-S0 at slave(61)@172.17.21.0:52024 (fa812f474cf4)
> I1201 13:03:21.285204 30317 master.cpp:4493] Forwarding status update TASK_RUNNING (UUID: a820acb1-a9ed-46f5-83c2-1a6504f5c584) for task 1 in health state unhealthy of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
> I1201 13:03:21.285403 30317 master.cpp:6097] Updating the state of task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
> I1201 13:03:21.285719 30317 sched.cpp:919] Scheduler::statusUpdate took 124592ns
> I1201 13:03:21.286097 30317 master.cpp:3602] Processing ACKNOWLEDGE call a820acb1-a9ed-46f5-83c2-1a6504f5c584 for task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 (default) at scheduler-05ae72c3-af75-4cab-b2df-764ef7c26d35@172.17.21.0:52024 on slave dd5bff66-362f-4efc-963a-54756b2edcce-S0
> I1201 13:03:21.287281 30317 status_update_manager.cpp:392] Received status update acknowledgement (UUID: a820acb1-a9ed-46f5-83c2-1a6504f5c584) for task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
> I1201 13:03:21.287904 30322 slave.cpp:2346] Status update manager successfully handled status update acknowledgement (UUID: a820acb1-a9ed-46f5-83c2-1a6504f5c584) for task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
> I1201 13:03:22.279230 30311 hierarchical.cpp:1062] No resources available to allocate!
> I1201 13:03:22.279326 30311 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 13:03:22.279361 30311 hierarchical.cpp:957] Performed allocation for 1 slaves in 718578ns
> I1201 13:03:23.281947 30309 hierarchical.cpp:1062] No resources available to allocate!
> I1201 13:03:23.282080 30309 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 13:03:23.282142 30309 hierarchical.cpp:957] Performed allocation for 1 slaves in 830902ns
> I1201 13:03:24.283694 30316 hierarchical.cpp:1062] No resources available to allocate!
> I1201 13:03:24.283906 30316 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 13:03:24.284049 30316 hierarchical.cpp:957] Performed allocation for 1 slaves in 980771ns
> I1201 13:03:25.285796 30310 hierarchical.cpp:1062] No resources available to allocate!
> I1201 13:03:25.285877 30310 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 13:03:25.285908 30310 hierarchical.cpp:957] Performed allocation for 1 slaves in 671191ns
> I1201 13:03:26.287158 30314 hierarchical.cpp:1062] No resources available to allocate!
> I1201 13:03:26.287240 30314 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 13:03:26.287271 30314 hierarchical.cpp:957] Performed allocation for 1 slaves in 650436ns
> I1201 13:03:26.292038 30316 slave.cpp:2763] Handling status update TASK_RUNNING (UUID: 7b7c6e1a-d3b1-4b7c-8113-f9eeb6d7e5dd) for task 1 in health state unhealthy of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 from executor(1)@172.17.21.0:58381
> I1201 13:03:26.292533 30316 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 7b7c6e1a-d3b1-4b7c-8113-f9eeb6d7e5dd) for task 1 in health state unhealthy of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
> I1201 13:03:26.292721 30316 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: 7b7c6e1a-d3b1-4b7c-8113-f9eeb6d7e5dd) for task 1 in health state unhealthy of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 to the slave
> I1201 13:03:26.293148 30316 slave.cpp:3115] Forwarding the update TASK_RUNNING (UUID: 7b7c6e1a-d3b1-4b7c-8113-f9eeb6d7e5dd) for task 1 in health state unhealthy of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 to master@172.17.21.0:52024
> I1201 13:03:26.293442 30316 slave.cpp:3009] Status update manager successfully handled status update TASK_RUNNING (UUID: 7b7c6e1a-d3b1-4b7c-8113-f9eeb6d7e5dd) for task 1 in health state unhealthy of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
> I1201 13:03:26.293485 30316 slave.cpp:3025] Sending acknowledgement for status update TASK_RUNNING (UUID: 7b7c6e1a-d3b1-4b7c-8113-f9eeb6d7e5dd) for task 1 in health state unhealthy of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 to executor(1)@172.17.21.0:58381
> I1201 13:03:26.294077 30316 master.cpp:4445] Status update TASK_RUNNING (UUID: 7b7c6e1a-d3b1-4b7c-8113-f9eeb6d7e5dd) for task 1 in health state unhealthy of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 from slave dd5bff66-362f-4efc-963a-54756b2edcce-S0 at slave(61)@172.17.21.0:52024 (fa812f474cf4)
> I1201 13:03:26.294124 30316 master.cpp:4493] Forwarding status update TASK_RUNNING (UUID: 7b7c6e1a-d3b1-4b7c-8113-f9eeb6d7e5dd) for task 1 in health state unhealthy of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
> I1201 13:03:26.294373 30316 master.cpp:6097] Updating the state of task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
> I1201 13:03:26.294651 30316 sched.cpp:919] Scheduler::statusUpdate took 114245ns
> I1201 13:03:26.295001 30316 master.cpp:3602] Processing ACKNOWLEDGE call 7b7c6e1a-d3b1-4b7c-8113-f9eeb6d7e5dd for task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 (default) at scheduler-05ae72c3-af75-4cab-b2df-764ef7c26d35@172.17.21.0:52024 on slave dd5bff66-362f-4efc-963a-54756b2edcce-S0
> I1201 13:03:26.295910 30318 status_update_manager.cpp:392] Received status update acknowledgement (UUID: 7b7c6e1a-d3b1-4b7c-8113-f9eeb6d7e5dd) for task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
> I1201 13:03:26.296237 30322 slave.cpp:2346] Status update manager successfully handled status update acknowledgement (UUID: 7b7c6e1a-d3b1-4b7c-8113-f9eeb6d7e5dd) for task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
> I1201 13:03:27.289466 30316 hierarchical.cpp:1062] No resources available to allocate!
> I1201 13:03:27.289551 30316 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 13:03:27.289582 30316 hierarchical.cpp:957] Performed allocation for 1 slaves in 692419ns
> I1201 13:03:28.291142 30312 hierarchical.cpp:1062] No resources available to allocate!
> I1201 13:03:28.291239 30312 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 13:03:28.291270 30312 hierarchical.cpp:957] Performed allocation for 1 slaves in 659702ns
> I1201 13:03:29.293304 30312 hierarchical.cpp:1062] No resources available to allocate!
> I1201 13:03:29.293390 30312 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 13:03:29.293421 30312 hierarchical.cpp:957] Performed allocation for 1 slaves in 665396ns
> I1201 13:03:30.294711 30320 hierarchical.cpp:1062] No resources available to allocate!
> I1201 13:03:30.294805 30320 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 13:03:30.294842 30320 hierarchical.cpp:957] Performed allocation for 1 slaves in 710415ns
> I1201 13:03:30.725651 30322 slave.cpp:4430] Querying resource estimator for oversubscribable resources
> I1201 13:03:30.725958 30322 slave.cpp:4444] Received oversubscribable resources from the resource estimator
> I1201 13:03:30.817693 30312 slave.cpp:3197] Received ping from slave-observer(58)@172.17.21.0:52024
> I1201 13:03:31.296576 30316 hierarchical.cpp:1062] No resources available to allocate!
> I1201 13:03:31.296658 30316 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 13:03:31.296687 30316 hierarchical.cpp:957] Performed allocation for 1 slaves in 652455ns
> I1201 13:03:32.298235 30314 hierarchical.cpp:1062] No resources available to allocate!
> I1201 13:03:32.298336 30314 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 13:03:32.298370 30314 hierarchical.cpp:957] Performed allocation for 1 slaves in 729548ns
> I1201 13:03:33.301245 30308 hierarchical.cpp:1062] No resources available to allocate!
> I1201 13:03:33.301337 30308 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 13:03:33.301372 30308 hierarchical.cpp:957] Performed allocation for 1 slaves in 745296ns
> I1201 13:03:34.303215 30311 hierarchical.cpp:1062] No resources available to allocate!
> I1201 13:03:34.303298 30311 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 13:03:34.303329 30311 hierarchical.cpp:957] Performed allocation for 1 slaves in 652065ns
> I1201 13:03:35.304294 30315 hierarchical.cpp:1062] No resources available to allocate!
> I1201 13:03:35.304369 30315 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 13:03:35.304400 30315 hierarchical.cpp:957] Performed allocation for 1 slaves in 652578ns
> I1201 13:03:36.305637 30310 hierarchical.cpp:1062] No resources available to allocate!
> I1201 13:03:36.305721 30310 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 13:03:36.305757 30310 hierarchical.cpp:957] Performed allocation for 1 slaves in 571872ns
> I1201 13:03:37.307134 30311 hierarchical.cpp:1062] No resources available to allocate!
> I1201 13:03:37.307222 30311 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 13:03:37.307257 30311 hierarchical.cpp:957] Performed allocation for 1 slaves in 685927ns
> I1201 13:03:38.310041 30315 hierarchical.cpp:1062] No resources available to allocate!
> I1201 13:03:38.310129 30315 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 13:03:38.310173 30315 hierarchical.cpp:957] Performed allocation for 1 slaves in 668279ns
> I1201 13:03:39.311493 30312 hierarchical.cpp:1062] No resources available to allocate!
> I1201 13:03:39.311586 30312 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 13:03:39.311621 30312 hierarchical.cpp:957] Performed allocation for 1 slaves in 728179ns
> I1201 13:03:40.312849 30319 hierarchical.cpp:1062] No resources available to allocate!
> I1201 13:03:40.312922 30319 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 13:03:40.312954 30319 hierarchical.cpp:957] Performed allocation for 1 slaves in 637308ns
> ../../src/tests/health_check_tests.cpp:919: Failure
> Failed to wait 15secs for status3
> ../../src/tests/health_check_tests.cpp:899: Failure
> Actual function call count doesn't match EXPECT_CALL(sched, statusUpdate(&driver, _))...
> Expected: to be called 5 times
> Actual: called 3 times - unsatisfied and active
> I1201 13:03:41.312536 30309 master.cpp:1138] Framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 (default) at scheduler-05ae72c3-af75-4cab-b2df-764ef7c26d35@172.17.21.0:52024 disconnected
> I1201 13:03:41.312664 30309 master.cpp:2503] Disconnecting framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 (default) at scheduler-05ae72c3-af75-4cab-b2df-764ef7c26d35@172.17.21.0:52024
> I1201 13:03:41.312759 30309 master.cpp:2527] Deactivating framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 (default) at scheduler-05ae72c3-af75-4cab-b2df-764ef7c26d35@172.17.21.0:52024
> I1201 13:03:41.312952 30309 master.cpp:1162] Giving framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 (default) at scheduler-05ae72c3-af75-4cab-b2df-764ef7c26d35@172.17.21.0:52024 0ns to failover
> I1201 13:03:41.313508 30316 hierarchical.cpp:303] Deactivated framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
> I1201 13:03:41.314739 30316 hierarchical.cpp:1062] No resources available to allocate!
> I1201 13:03:41.314862 30316 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 13:03:41.314971 30316 hierarchical.cpp:957] Performed allocation for 1 slaves in 619616ns
> I1201 13:03:41.314245 30320 master.cpp:4858] Framework failover timeout, removing framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 (default) at scheduler-05ae72c3-af75-4cab-b2df-764ef7c26d35@172.17.21.0:52024
> I1201 13:03:41.315183 30320 master.cpp:5590] Removing framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 (default) at scheduler-05ae72c3-af75-4cab-b2df-764ef7c26d35@172.17.21.0:52024
> I1201 13:03:41.315469 30320 master.cpp:6097] Updating the state of task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 (latest state: TASK_KILLED, status update state: TASK_KILLED)
> I1201 13:03:41.315685 30318 slave.cpp:2010] Asked to shut down framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 by master@172.17.21.0:52024
> I1201 13:03:41.316105 30320 master.cpp:6163] Removing task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 on slave dd5bff66-362f-4efc-963a-54756b2edcce-S0 at slave(61)@172.17.21.0:52024 (fa812f474cf4)
> I1201 13:03:41.316380 30314 hierarchical.cpp:791] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on slave dd5bff66-362f-4efc-963a-54756b2edcce-S0 from framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
> I1201 13:03:41.316309 30318 slave.cpp:2035] Shutting down framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
> I1201 13:03:41.316668 30318 slave.cpp:3891] Shutting down executor '1' of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 at executor(1)@172.17.21.0:58381
> I1201 13:03:41.317257 30319 hierarchical.cpp:260] Removed framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
> I1201 13:03:41.316704 30320 master.cpp:938] Master terminating
> I1201 13:03:41.318066 30312 hierarchical.cpp:410] Removed slave dd5bff66-362f-4efc-963a-54756b2edcce-S0
> I1201 13:03:41.318724 30320 slave.cpp:3243] master@172.17.21.0:52024 exited
> W1201 13:03:41.318749 30320 slave.cpp:3246] Master disconnected! Waiting for a new master to be elected
> I1201 13:03:41.324950 30308 containerizer.cpp:1073] Destroying container '8d8aa0bb-fad5-4715-a14f-62783b07da81'
> I1201 13:03:41.425364 30310 containerizer.cpp:1256] Executor for container '8d8aa0bb-fad5-4715-a14f-62783b07da81' has exited
> I1201 13:03:41.427952 30312 slave.cpp:3581] Executor '1' of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 terminated with signal Killed
> I1201 13:03:41.428019 30312 slave.cpp:3685] Cleaning up executor '1' of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000 at executor(1)@172.17.21.0:58381
> I1201 13:03:41.428724 30312 slave.cpp:3773] Cleaning up framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
> I1201 13:03:41.428715 30307 gc.cpp:54] Scheduling '/tmp/HealthCheckTest_CheckCommandTimeout_6kGYjg/slaves/dd5bff66-362f-4efc-963a-54756b2edcce-S0/frameworks/dd5bff66-362f-4efc-963a-54756b2edcce-0000/executors/1/runs/8d8aa0bb-fad5-4715-a14f-62783b07da81' for gc 6.99999504180444days in the future
> I1201 13:03:41.428894 30307 gc.cpp:54] Scheduling '/tmp/HealthCheckTest_CheckCommandTimeout_6kGYjg/slaves/dd5bff66-362f-4efc-963a-54756b2edcce-S0/frameworks/dd5bff66-362f-4efc-963a-54756b2edcce-0000/executors/1' for gc 6.99999503861037days in the future
> I1201 13:03:41.428920 30312 status_update_manager.cpp:282] Closing status update streams for framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
> I1201 13:03:41.428980 30312 status_update_manager.cpp:528] Cleaning up status update stream for task 1 of framework dd5bff66-362f-4efc-963a-54756b2edcce-0000
> I1201 13:03:41.429021 30307 gc.cpp:54] Scheduling '/tmp/HealthCheckTest_CheckCommandTimeout_6kGYjg/slaves/dd5bff66-362f-4efc-963a-54756b2edcce-S0/frameworks/dd5bff66-362f-4efc-963a-54756b2edcce-0000' for gc 6.99999503674963days in the future
> I1201 13:03:41.429925 30315 slave.cpp:599] Slave terminating
> [ FAILED ] HealthCheckTest.CheckCommandTimeout (26359 ms)
> {noformat}
> {noformat: title=Good Run}
> [ RUN ] HealthCheckTest.CheckCommandTimeout
> I1201 14:14:26.562675 30295 leveldb.cpp:174] Opened db in 128.451766ms
> I1201 14:14:26.589201 30295 leveldb.cpp:181] Compacted db in 26.446367ms
> I1201 14:14:26.589298 30295 leveldb.cpp:196] Created db iterator in 27631ns
> I1201 14:14:26.589318 30295 leveldb.cpp:202] Seeked to beginning of db in 3097ns
> I1201 14:14:26.589329 30295 leveldb.cpp:271] Iterated through 0 keys in the db in 210ns
> I1201 14:14:26.589382 30295 replica.cpp:778] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> I1201 14:14:26.590701 30321 recover.cpp:447] Starting replica recovery
> I1201 14:14:26.591117 30321 recover.cpp:473] Replica is in EMPTY status
> I1201 14:14:26.592706 30317 replica.cpp:674] Replica in EMPTY status received a broadcasted recover request from (1903)@172.17.21.7:43732
> I1201 14:14:26.593225 30328 recover.cpp:193] Received a recover response from a replica in EMPTY status
> I1201 14:14:26.593907 30328 recover.cpp:564] Updating replica status to STARTING
> I1201 14:14:26.604007 30316 master.cpp:365] Master 587d1fd5-db6b-4af4-9267-ce84ac458470 (ca6f16e00db6) started on 172.17.21.7:43732
> I1201 14:14:26.604156 30316 master.cpp:367] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="true" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/9rplBs/credentials" --framework_sorter="drf" --help="false" --hostname_lookup="true" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_slave_ping_timeouts="5" --quiet="false" --recovery_slave_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_store_timeout="25secs" --registry_strict="true" --root_submissions="true" --slave_ping_timeout="15secs" --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false" --webui_dir="/mesos/mesos-0.27.0/_inst/share/mesos/webui" --work_dir="/tmp/9rplBs/master" --zk_session_timeout="10secs"
> I1201 14:14:26.604524 30316 master.cpp:412] Master only allowing authenticated frameworks to register
> I1201 14:14:26.604540 30316 master.cpp:417] Master only allowing authenticated slaves to register
> I1201 14:14:26.604550 30316 credentials.hpp:35] Loading credentials for authentication from '/tmp/9rplBs/credentials'
> I1201 14:14:26.613284 30316 master.cpp:456] Using default 'crammd5' authenticator
> I1201 14:14:26.613517 30316 master.cpp:493] Authorization enabled
> I1201 14:14:26.614346 30324 hierarchical.cpp:162] Initialized hierarchical allocator process
> I1201 14:14:26.614435 30324 whitelist_watcher.cpp:77] No whitelist given
> I1201 14:14:26.616992 30316 master.cpp:1637] The newly elected leader is master@172.17.21.7:43732 with id 587d1fd5-db6b-4af4-9267-ce84ac458470
> I1201 14:14:26.617038 30316 master.cpp:1650] Elected as the leading master!
> I1201 14:14:26.617058 30316 master.cpp:1395] Recovering from registrar
> I1201 14:14:26.617224 30324 registrar.cpp:307] Recovering registrar
> I1201 14:14:26.621055 30319 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 26.839241ms
> I1201 14:14:26.621105 30319 replica.cpp:321] Persisted replica status to STARTING
> I1201 14:14:26.621538 30319 recover.cpp:473] Replica is in STARTING status
> I1201 14:14:26.623247 30315 replica.cpp:674] Replica in STARTING status received a broadcasted recover request from (1904)@172.17.21.7:43732
> I1201 14:14:26.623631 30315 recover.cpp:193] Received a recover response from a replica in STARTING status
> I1201 14:14:26.624241 30322 recover.cpp:564] Updating replica status to VOTING
> I1201 14:14:26.657734 30315 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 33.355865ms
> I1201 14:14:26.657809 30315 replica.cpp:321] Persisted replica status to VOTING
> I1201 14:14:26.658102 30315 recover.cpp:578] Successfully joined the Paxos group
> I1201 14:14:26.658396 30315 recover.cpp:462] Recover process terminated
> I1201 14:14:26.659047 30315 log.cpp:659] Attempting to start the writer
> I1201 14:14:26.660820 30323 replica.cpp:494] Replica received implicit promise request from (1905)@172.17.21.7:43732 with proposal 1
> I1201 14:14:26.724722 30323 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 63.712877ms
> I1201 14:14:26.725214 30323 replica.cpp:343] Persisted promised to 1
> I1201 14:14:26.726558 30322 coordinator.cpp:238] Coordinator attempting to fill missing positions
> I1201 14:14:26.728757 30316 replica.cpp:389] Replica received explicit promise request from (1906)@172.17.21.7:43732 for position 0 with proposal 2
> I1201 14:14:26.783602 30316 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 54.554561ms
> I1201 14:14:26.783695 30316 replica.cpp:713] Persisted action at 0
> I1201 14:14:26.785193 30321 replica.cpp:538] Replica received write request for position 0 from (1907)@172.17.21.7:43732
> I1201 14:14:26.785289 30321 leveldb.cpp:436] Reading position from leveldb took 49720ns
> I1201 14:14:26.830451 30321 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 45.082632ms
> I1201 14:14:26.830551 30321 replica.cpp:713] Persisted action at 0
> I1201 14:14:26.831938 30317 replica.cpp:692] Replica received learned notice for position 0 from @0.0.0.0:0
> I1201 14:14:26.881292 30317 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 49.170442ms
> I1201 14:14:26.881369 30317 replica.cpp:713] Persisted action at 0
> I1201 14:14:26.881402 30317 replica.cpp:698] Replica learned NOP action at position 0
> I1201 14:14:26.882609 30323 log.cpp:675] Writer started with ending position 0
> I1201 14:14:26.884533 30324 leveldb.cpp:436] Reading position from leveldb took 76333ns
> I1201 14:14:26.886106 30324 registrar.cpp:340] Successfully fetched the registry (0B) in 268.833024ms
> I1201 14:14:26.886435 30324 registrar.cpp:439] Applied 1 operations in 42802ns; attempting to update the 'registry'
> I1201 14:14:26.888010 30318 log.cpp:683] Attempting to append 173 bytes to the log
> I1201 14:14:26.888236 30326 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
> I1201 14:14:26.890637 30328 replica.cpp:538] Replica received write request for position 1 from (1908)@172.17.21.7:43732
> I1201 14:14:26.921727 30328 leveldb.cpp:341] Persisting action (192 bytes) to leveldb took 30.998029ms
> I1201 14:14:26.922299 30328 replica.cpp:713] Persisted action at 1
> I1201 14:14:26.924146 30315 replica.cpp:692] Replica received learned notice for position 1 from @0.0.0.0:0
> I1201 14:14:26.956274 30315 leveldb.cpp:341] Persisting action (194 bytes) to leveldb took 31.633545ms
> I1201 14:14:26.956370 30315 replica.cpp:713] Persisted action at 1
> I1201 14:14:26.956411 30315 replica.cpp:698] Replica learned APPEND action at position 1
> I1201 14:14:26.958438 30317 registrar.cpp:484] Successfully updated the 'registry' in 71.918848ms
> I1201 14:14:26.958627 30317 registrar.cpp:370] Successfully recovered registrar
> I1201 14:14:26.959338 30320 hierarchical.cpp:174] Allocator recovery is not supported yet
> I1201 14:14:26.959838 30323 log.cpp:702] Attempting to truncate the log to 1
> I1201 14:14:26.960106 30323 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
> I1201 14:14:26.959147 30317 master.cpp:1447] Recovered 0 slaves from the Registry (134B) ; allowing 10mins for slaves to re-register
> I1201 14:14:26.961684 30323 replica.cpp:538] Replica received write request for position 2 from (1909)@172.17.21.7:43732
> I1201 14:14:27.055438 30323 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 93.663564ms
> I1201 14:14:27.055536 30323 replica.cpp:713] Persisted action at 2
> I1201 14:14:27.056959 30320 replica.cpp:692] Replica received learned notice for position 2 from @0.0.0.0:0
> I1201 14:14:27.118288 30320 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 60.990962ms
> I1201 14:14:27.118451 30320 leveldb.cpp:399] Deleting ~1 keys from leveldb took 77007ns
> I1201 14:14:27.118479 30320 replica.cpp:713] Persisted action at 2
> I1201 14:14:27.118516 30320 replica.cpp:698] Replica learned TRUNCATE action at position 2
> I1201 14:14:27.131505 30295 containerizer.cpp:141] Using isolation: posix/cpu,posix/mem,filesystem/posix
> W1201 14:14:27.131902 30295 backend.cpp:48] Failed to create 'bind' backend: BindBackend requires root privileges
> I1201 14:14:27.143996 30327 slave.cpp:189] Slave started on 61)@172.17.21.7:43732
> I1201 14:14:27.144155 30327 slave.cpp:190] Flags at startup: --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" --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/HealthCheckTest_CheckCommandTimeout_DODrUR/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_auth_server="auth.docker.io" --docker_auth_server_port="443" --docker_kill_orphans="true" --docker_local_archives_dir="/tmp/mesos/images/docker" --docker_puller="local" --docker_puller_timeout="60" --docker_registry="registry-1.docker.io" --docker_registry_port="443" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/HealthCheckTest_CheckCommandTimeout_DODrUR/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/mesos/mesos-0.27.0/_build/src" --logbufsecs="0" --logging_level="INFO" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:2;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/HealthCheckTest_CheckCommandTimeout_DODrUR"
> I1201 14:14:27.144866 30327 credentials.hpp:83] Loading credential for authentication from '/tmp/HealthCheckTest_CheckCommandTimeout_DODrUR/credential'
> I1201 14:14:27.145210 30327 slave.cpp:320] Slave using credential for: test-principal
> I1201 14:14:27.145454 30327 resources.cpp:478] Parsing resources as JSON failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000]
> Trying semicolon-delimited string format instead
> I1201 14:14:27.146003 30327 slave.cpp:390] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I1201 14:14:27.146389 30327 slave.cpp:398] Slave attributes: [ ]
> I1201 14:14:27.146450 30327 slave.cpp:403] Slave hostname: ca6f16e00db6
> I1201 14:14:27.146512 30327 slave.cpp:408] Slave checkpoint: true
> I1201 14:14:27.148231 30326 state.cpp:52] Recovering state from '/tmp/HealthCheckTest_CheckCommandTimeout_DODrUR/meta'
> I1201 14:14:27.153398 30295 sched.cpp:164] Version: 0.27.0
> I1201 14:14:27.153487 30327 status_update_manager.cpp:200] Recovering status update manager
> I1201 14:14:27.154454 30327 containerizer.cpp:383] Recovering containerizer
> I1201 14:14:27.155915 30321 slave.cpp:4258] Finished recovery
> I1201 14:14:27.156283 30315 sched.cpp:262] New master detected at master@172.17.21.7:43732
> I1201 14:14:27.156508 30315 sched.cpp:318] Authenticating with master master@172.17.21.7:43732
> I1201 14:14:27.156584 30315 sched.cpp:325] Using default CRAM-MD5 authenticatee
> I1201 14:14:27.157011 30315 authenticatee.cpp:121] Creating new client SASL connection
> I1201 14:14:27.157587 30325 master.cpp:5181] Authenticating scheduler-90969aaa-c756-4602-8e8a-c07acb10fcfb@172.17.21.7:43732
> I1201 14:14:27.157835 30325 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(168)@172.17.21.7:43732
> I1201 14:14:27.158241 30325 authenticator.cpp:98] Creating new server SASL connection
> I1201 14:14:27.158654 30315 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
> I1201 14:14:27.158753 30315 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
> I1201 14:14:27.158895 30315 authenticator.cpp:203] Received SASL authentication start
> I1201 14:14:27.159062 30315 authenticator.cpp:325] Authentication requires more steps
> I1201 14:14:27.159219 30325 authenticatee.cpp:258] Received SASL authentication step
> I1201 14:14:27.159415 30315 authenticator.cpp:231] Received SASL authentication step
> I1201 14:14:27.159498 30315 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ca6f16e00db6' server FQDN: 'ca6f16e00db6' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I1201 14:14:27.159566 30315 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
> I1201 14:14:27.159669 30315 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I1201 14:14:27.159757 30315 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ca6f16e00db6' server FQDN: 'ca6f16e00db6' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I1201 14:14:27.159826 30315 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I1201 14:14:27.159883 30315 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I1201 14:14:27.159953 30315 authenticator.cpp:317] Authentication success
> I1201 14:14:27.160225 30318 master.cpp:5211] Successfully authenticated principal 'test-principal' at scheduler-90969aaa-c756-4602-8e8a-c07acb10fcfb@172.17.21.7:43732
> I1201 14:14:27.160372 30318 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(168)@172.17.21.7:43732
> I1201 14:14:27.160688 30315 authenticatee.cpp:298] Authentication success
> I1201 14:14:27.161622 30315 sched.cpp:407] Successfully authenticated with master master@172.17.21.7:43732
> I1201 14:14:27.162294 30315 sched.cpp:714] Sending SUBSCRIBE call to master@172.17.21.7:43732
> I1201 14:14:27.162508 30315 sched.cpp:747] Will retry registration in 1.129902694secs if necessary
> I1201 14:14:27.162696 30318 master.cpp:2207] Received SUBSCRIBE call for framework 'default' at scheduler-90969aaa-c756-4602-8e8a-c07acb10fcfb@172.17.21.7:43732
> I1201 14:14:27.163007 30318 master.cpp:1676] Authorizing framework principal 'test-principal' to receive offers for role '*'
> I1201 14:14:27.161137 30321 slave.cpp:4430] Querying resource estimator for oversubscribable resources
> I1201 14:14:27.164012 30321 slave.cpp:727] New master detected at master@172.17.21.7:43732
> I1201 14:14:27.164070 30328 status_update_manager.cpp:174] Pausing sending status updates
> I1201 14:14:27.164103 30321 slave.cpp:790] Authenticating with master master@172.17.21.7:43732
> I1201 14:14:27.164119 30321 slave.cpp:795] Using default CRAM-MD5 authenticatee
> I1201 14:14:27.164353 30321 slave.cpp:763] Detecting new master
> I1201 14:14:27.164423 30317 authenticatee.cpp:121] Creating new client SASL connection
> I1201 14:14:27.164472 30321 slave.cpp:4444] Received oversubscribable resources from the resource estimator
> I1201 14:14:27.164697 30318 master.cpp:5181] Authenticating slave(61)@172.17.21.7:43732
> I1201 14:14:27.165030 30328 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(169)@172.17.21.7:43732
> I1201 14:14:27.165266 30324 authenticator.cpp:98] Creating new server SASL connection
> I1201 14:14:27.165489 30321 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
> I1201 14:14:27.165514 30321 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
> I1201 14:14:27.165596 30321 authenticator.cpp:203] Received SASL authentication start
> I1201 14:14:27.166223 30321 authenticator.cpp:325] Authentication requires more steps
> I1201 14:14:27.166311 30321 authenticatee.cpp:258] Received SASL authentication step
> I1201 14:14:27.166394 30321 authenticator.cpp:231] Received SASL authentication step
> I1201 14:14:27.166424 30321 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ca6f16e00db6' server FQDN: 'ca6f16e00db6' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I1201 14:14:27.166435 30321 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
> I1201 14:14:27.166481 30321 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I1201 14:14:27.166504 30321 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ca6f16e00db6' server FQDN: 'ca6f16e00db6' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I1201 14:14:27.166514 30321 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I1201 14:14:27.166522 30321 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I1201 14:14:27.166538 30321 authenticator.cpp:317] Authentication success
> I1201 14:14:27.166679 30321 authenticatee.cpp:298] Authentication success
> I1201 14:14:27.166760 30321 master.cpp:5211] Successfully authenticated principal 'test-principal' at slave(61)@172.17.21.7:43732
> I1201 14:14:27.166833 30321 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(169)@172.17.21.7:43732
> I1201 14:14:27.167089 30321 slave.cpp:858] Successfully authenticated with master master@172.17.21.7:43732
> I1201 14:14:27.167477 30322 master.cpp:3890] Registering slave at slave(61)@172.17.21.7:43732 (ca6f16e00db6) with id 587d1fd5-db6b-4af4-9267-ce84ac458470-S0
> I1201 14:14:27.167721 30321 slave.cpp:1252] Will retry registration in 2.161007ms if necessary
> I1201 14:14:27.168022 30316 registrar.cpp:439] Applied 1 operations in 80369ns; attempting to update the 'registry'
> I1201 14:14:27.168381 30323 master.cpp:2278] Subscribing framework default with checkpointing disabled and capabilities [ ]
> I1201 14:14:27.169057 30316 hierarchical.cpp:220] Added framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
> I1201 14:14:27.169118 30316 hierarchical.cpp:1062] No resources available to allocate!
> I1201 14:14:27.169164 30316 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 14:14:27.169214 30316 hierarchical.cpp:957] Performed allocation for 0 slaves in 129635ns
> I1201 14:14:27.169347 30321 sched.cpp:641] Framework registered with 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
> I1201 14:14:27.169394 30321 sched.cpp:655] Scheduler::registered took 23910ns
> I1201 14:14:27.169589 30322 log.cpp:683] Attempting to append 342 bytes to the log
> I1201 14:14:27.170240 30319 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3
> I1201 14:14:27.170464 30329 slave.cpp:1252] Will retry registration in 33.87185ms if necessary
> I1201 14:14:27.170650 30319 master.cpp:3878] Ignoring register slave message from slave(61)@172.17.21.7:43732 (ca6f16e00db6) as admission is already in progress
> I1201 14:14:27.171053 30322 replica.cpp:538] Replica received write request for position 3 from (1921)@172.17.21.7:43732
> I1201 14:14:27.185808 30322 leveldb.cpp:341] Persisting action (361 bytes) to leveldb took 14.695502ms
> I1201 14:14:27.185899 30322 replica.cpp:713] Persisted action at 3
> I1201 14:14:27.187346 30314 replica.cpp:692] Replica received learned notice for position 3 from @0.0.0.0:0
> I1201 14:14:27.206691 30322 slave.cpp:1252] Will retry registration in 21.161456ms if necessary
> I1201 14:14:27.207093 30322 master.cpp:3878] Ignoring register slave message from slave(61)@172.17.21.7:43732 (ca6f16e00db6) as admission is already in progress
> I1201 14:14:27.215098 30314 leveldb.cpp:341] Persisting action (363 bytes) to leveldb took 27.696174ms
> I1201 14:14:27.215196 30314 replica.cpp:713] Persisted action at 3
> I1201 14:14:27.215239 30314 replica.cpp:698] Replica learned APPEND action at position 3
> I1201 14:14:27.218340 30314 registrar.cpp:484] Successfully updated the 'registry' in 50.230016ms
> I1201 14:14:27.218909 30314 log.cpp:702] Attempting to truncate the log to 3
> I1201 14:14:27.220247 30322 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 4
> I1201 14:14:27.220552 30328 hierarchical.cpp:380] Added slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0 (ca6f16e00db6) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
> I1201 14:14:27.220841 30322 slave.cpp:902] Registered with master master@172.17.21.7:43732; given slave ID 587d1fd5-db6b-4af4-9267-ce84ac458470-S0
> I1201 14:14:27.220865 30322 fetcher.cpp:79] Clearing fetcher cache
> I1201 14:14:27.220121 30314 master.cpp:3958] Registered slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0 at slave(61)@172.17.21.7:43732 (ca6f16e00db6) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I1201 14:14:27.221568 30328 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 14:14:27.221766 30322 slave.cpp:925] Checkpointing SlaveInfo to '/tmp/HealthCheckTest_CheckCommandTimeout_DODrUR/meta/slaves/587d1fd5-db6b-4af4-9267-ce84ac458470-S0/slave.info'
> I1201 14:14:27.221575 30314 status_update_manager.cpp:181] Resuming sending status updates
> I1201 14:14:27.221885 30328 hierarchical.cpp:973] Performed allocation for slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0 in 1.185334ms
> I1201 14:14:27.222190 30317 master.cpp:5010] Sending 1 offers to framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 (default) at scheduler-90969aaa-c756-4602-8e8a-c07acb10fcfb@172.17.21.7:43732
> I1201 14:14:27.222575 30322 slave.cpp:961] Forwarding total oversubscribed resources
> I1201 14:14:27.222957 30317 sched.cpp:811] Scheduler::resourceOffers took 146960ns
> I1201 14:14:27.223748 30319 replica.cpp:538] Replica received write request for position 4 from (1922)@172.17.21.7:43732
> I1201 14:14:27.223976 30322 slave.cpp:3197] Received ping from slave-observer(58)@172.17.21.7:43732
> I1201 14:14:27.224243 30325 master.cpp:4300] Received update of slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0 at slave(61)@172.17.21.7:43732 (ca6f16e00db6) with total oversubscribed resources
> I1201 14:14:27.225162 30325 hierarchical.cpp:434] Slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0 (ca6f16e00db6) updated with oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000])
> I1201 14:14:27.225759 30325 hierarchical.cpp:1062] No resources available to allocate!
> I1201 14:14:27.226012 30325 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 14:14:27.226039 30325 hierarchical.cpp:973] Performed allocation for slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0 in 751766ns
> I1201 14:14:27.228044 30321 master.cpp:2946] Processing ACCEPT call for offers: [ 587d1fd5-db6b-4af4-9267-ce84ac458470-O0 ] on slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0 at slave(61)@172.17.21.7:43732 (ca6f16e00db6) for framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 (default) at scheduler-90969aaa-c756-4602-8e8a-c07acb10fcfb@172.17.21.7:43732
> I1201 14:14:27.228107 30321 master.cpp:2742] Authorizing framework principal 'test-principal' to launch task 1 as user 'mesos'
> I1201 14:14:27.230907 30323 master.hpp:176] Adding task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0 (ca6f16e00db6)
> I1201 14:14:27.231200 30323 master.cpp:3276] Launching task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 (default) at scheduler-90969aaa-c756-4602-8e8a-c07acb10fcfb@172.17.21.7:43732 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0 at slave(61)@172.17.21.7:43732 (ca6f16e00db6)
> I1201 14:14:27.231850 30323 slave.cpp:1292] Got assigned task 1 for framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
> I1201 14:14:27.232142 30323 resources.cpp:478] Parsing resources as JSON failed: cpus:0.1;mem:32
> Trying semicolon-delimited string format instead
> I1201 14:14:27.233273 30323 slave.cpp:1411] Launching task 1 for framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
> I1201 14:14:27.233381 30323 resources.cpp:478] Parsing resources as JSON failed: cpus:0.1;mem:32
> Trying semicolon-delimited string format instead
> I1201 14:14:27.249552 30323 paths.cpp:434] Trying to chown '/tmp/HealthCheckTest_CheckCommandTimeout_DODrUR/slaves/587d1fd5-db6b-4af4-9267-ce84ac458470-S0/frameworks/587d1fd5-db6b-4af4-9267-ce84ac458470-0000/executors/1/runs/e5213230-3cf6-4e8c-b7cd-f4e2615df70f' to user 'mesos'
> I1201 14:14:27.255273 30323 slave.cpp:5042] Launching executor 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/HealthCheckTest_CheckCommandTimeout_DODrUR/slaves/587d1fd5-db6b-4af4-9267-ce84ac458470-S0/frameworks/587d1fd5-db6b-4af4-9267-ce84ac458470-0000/executors/1/runs/e5213230-3cf6-4e8c-b7cd-f4e2615df70f'
> I1201 14:14:27.256011 30323 slave.cpp:1629] Queuing task '1' for executor '1' of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
> I1201 14:14:27.256116 30327 containerizer.cpp:617] Starting container 'e5213230-3cf6-4e8c-b7cd-f4e2615df70f' for executor '1' of framework '587d1fd5-db6b-4af4-9267-ce84ac458470-0000'
> I1201 14:14:27.257302 30319 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 33.493331ms
> I1201 14:14:27.257356 30319 replica.cpp:713] Persisted action at 4
> I1201 14:14:27.258471 30325 replica.cpp:692] Replica received learned notice for position 4 from @0.0.0.0:0
> I1201 14:14:27.261706 30321 slave.cpp:680] Successfully attached file '/tmp/HealthCheckTest_CheckCommandTimeout_DODrUR/slaves/587d1fd5-db6b-4af4-9267-ce84ac458470-S0/frameworks/587d1fd5-db6b-4af4-9267-ce84ac458470-0000/executors/1/runs/e5213230-3cf6-4e8c-b7cd-f4e2615df70f'
> I1201 14:14:27.268529 30327 launcher.cpp:132] Forked child with pid '3184' for container 'e5213230-3cf6-4e8c-b7cd-f4e2615df70f'
> I1201 14:14:27.291683 30325 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 33.038313ms
> I1201 14:14:27.292078 30325 leveldb.cpp:399] Deleting ~2 keys from leveldb took 87529ns
> I1201 14:14:27.292244 30325 replica.cpp:713] Persisted action at 4
> I1201 14:14:27.292456 30325 replica.cpp:698] Replica learned TRUNCATE action at position 4
> I1201 14:14:27.507856 30325 slave.cpp:2406] Got registration for executor '1' of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 from executor(1)@172.17.21.7:46225
> I1201 14:14:27.512398 30314 slave.cpp:1794] Sending queued task '1' to executor '1' of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 at executor(1)@172.17.21.7:46225
> I1201 14:14:27.539080 30322 slave.cpp:2763] Handling status update TASK_RUNNING (UUID: f6c38987-fb13-4ce6-af7f-7839ce3b8ecb) for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 from executor(1)@172.17.21.7:46225
> I1201 14:14:27.540004 30318 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: f6c38987-fb13-4ce6-af7f-7839ce3b8ecb) for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
> I1201 14:14:27.540385 30318 status_update_manager.cpp:497] Creating StatusUpdate stream for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
> I1201 14:14:27.541409 30318 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: f6c38987-fb13-4ce6-af7f-7839ce3b8ecb) for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 to the slave
> I1201 14:14:27.542279 30322 slave.cpp:3115] Forwarding the update TASK_RUNNING (UUID: f6c38987-fb13-4ce6-af7f-7839ce3b8ecb) for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 to master@172.17.21.7:43732
> I1201 14:14:27.542510 30322 slave.cpp:3009] Status update manager successfully handled status update TASK_RUNNING (UUID: f6c38987-fb13-4ce6-af7f-7839ce3b8ecb) for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
> I1201 14:14:27.542562 30322 slave.cpp:3025] Sending acknowledgement for status update TASK_RUNNING (UUID: f6c38987-fb13-4ce6-af7f-7839ce3b8ecb) for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 to executor(1)@172.17.21.7:46225
> I1201 14:14:27.543005 30318 master.cpp:4445] Status update TASK_RUNNING (UUID: f6c38987-fb13-4ce6-af7f-7839ce3b8ecb) for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 from slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0 at slave(61)@172.17.21.7:43732 (ca6f16e00db6)
> I1201 14:14:27.543375 30318 master.cpp:4493] Forwarding status update TASK_RUNNING (UUID: f6c38987-fb13-4ce6-af7f-7839ce3b8ecb) for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
> I1201 14:14:27.543947 30318 master.cpp:6097] Updating the state of task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
> I1201 14:14:27.544643 30318 sched.cpp:919] Scheduler::statusUpdate took 137099ns
> I1201 14:14:27.545348 30322 master.cpp:3602] Processing ACKNOWLEDGE call f6c38987-fb13-4ce6-af7f-7839ce3b8ecb for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 (default) at scheduler-90969aaa-c756-4602-8e8a-c07acb10fcfb@172.17.21.7:43732 on slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0
> I1201 14:14:27.545892 30329 status_update_manager.cpp:392] Received status update acknowledgement (UUID: f6c38987-fb13-4ce6-af7f-7839ce3b8ecb) for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
> I1201 14:14:27.546821 30329 slave.cpp:2346] Status update manager successfully handled status update acknowledgement (UUID: f6c38987-fb13-4ce6-af7f-7839ce3b8ecb) for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
> I1201 14:14:27.615839 30322 hierarchical.cpp:1062] No resources available to allocate!
> I1201 14:14:27.615924 30322 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 14:14:27.615954 30322 hierarchical.cpp:957] Performed allocation for 1 slaves in 826681ns
> I1201 14:14:28.617543 30326 hierarchical.cpp:1062] No resources available to allocate!
> I1201 14:14:28.617914 30326 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 14:14:28.618074 30326 hierarchical.cpp:957] Performed allocation for 1 slaves in 1.123832ms
> I1201 14:14:29.619159 30314 hierarchical.cpp:1062] No resources available to allocate!
> I1201 14:14:29.619263 30314 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 14:14:29.619300 30314 hierarchical.cpp:957] Performed allocation for 1 slaves in 726672ns
> I1201 14:14:30.622232 30329 hierarchical.cpp:1062] No resources available to allocate!
> I1201 14:14:30.622321 30329 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 14:14:30.622359 30329 hierarchical.cpp:957] Performed allocation for 1 slaves in 719341ns
> I1201 14:14:31.625255 30314 hierarchical.cpp:1062] No resources available to allocate!
> I1201 14:14:31.625346 30314 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 14:14:31.625383 30314 hierarchical.cpp:957] Performed allocation for 1 slaves in 743648ns
> I1201 14:14:32.628315 30318 hierarchical.cpp:1062] No resources available to allocate!
> I1201 14:14:32.628419 30318 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 14:14:32.628478 30318 hierarchical.cpp:957] Performed allocation for 1 slaves in 809723ns
> I1201 14:14:32.744158 30321 slave.cpp:2763] Handling status update TASK_RUNNING (UUID: a20337d6-2301-44ba-bd7e-60cd5c7ac014) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 from executor(1)@172.17.21.7:46225
> I1201 14:14:32.744817 30319 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: a20337d6-2301-44ba-bd7e-60cd5c7ac014) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
> I1201 14:14:32.745187 30319 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: a20337d6-2301-44ba-bd7e-60cd5c7ac014) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 to the slave
> I1201 14:14:32.745558 30325 slave.cpp:3115] Forwarding the update TASK_RUNNING (UUID: a20337d6-2301-44ba-bd7e-60cd5c7ac014) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 to master@172.17.21.7:43732
> I1201 14:14:32.745990 30325 slave.cpp:3009] Status update manager successfully handled status update TASK_RUNNING (UUID: a20337d6-2301-44ba-bd7e-60cd5c7ac014) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
> I1201 14:14:32.746037 30325 slave.cpp:3025] Sending acknowledgement for status update TASK_RUNNING (UUID: a20337d6-2301-44ba-bd7e-60cd5c7ac014) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 to executor(1)@172.17.21.7:46225
> I1201 14:14:32.746395 30320 master.cpp:4445] Status update TASK_RUNNING (UUID: a20337d6-2301-44ba-bd7e-60cd5c7ac014) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 from slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0 at slave(61)@172.17.21.7:43732 (ca6f16e00db6)
> I1201 14:14:32.747027 30320 master.cpp:4493] Forwarding status update TASK_RUNNING (UUID: a20337d6-2301-44ba-bd7e-60cd5c7ac014) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
> I1201 14:14:32.747349 30320 master.cpp:6097] Updating the state of task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
> I1201 14:14:32.747804 30315 sched.cpp:919] Scheduler::statusUpdate took 115298ns
> I1201 14:14:32.748492 30315 master.cpp:3602] Processing ACKNOWLEDGE call a20337d6-2301-44ba-bd7e-60cd5c7ac014 for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 (default) at scheduler-90969aaa-c756-4602-8e8a-c07acb10fcfb@172.17.21.7:43732 on slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0
> I1201 14:14:32.748931 30324 status_update_manager.cpp:392] Received status update acknowledgement (UUID: a20337d6-2301-44ba-bd7e-60cd5c7ac014) for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
> I1201 14:14:32.749595 30324 slave.cpp:2346] Status update manager successfully handled status update acknowledgement (UUID: a20337d6-2301-44ba-bd7e-60cd5c7ac014) for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
> I1201 14:14:33.630220 30321 hierarchical.cpp:1062] No resources available to allocate!
> I1201 14:14:33.630412 30321 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 14:14:33.630549 30321 hierarchical.cpp:957] Performed allocation for 1 slaves in 908929ns
> I1201 14:14:34.631630 30324 hierarchical.cpp:1062] No resources available to allocate!
> I1201 14:14:34.631721 30324 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 14:14:34.631757 30324 hierarchical.cpp:957] Performed allocation for 1 slaves in 697251ns
> I1201 14:14:35.632884 30322 hierarchical.cpp:1062] No resources available to allocate!
> I1201 14:14:35.632969 30322 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 14:14:35.633003 30322 hierarchical.cpp:957] Performed allocation for 1 slaves in 676552ns
> I1201 14:14:36.634296 30315 hierarchical.cpp:1062] No resources available to allocate!
> I1201 14:14:36.634392 30315 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 14:14:36.634426 30315 hierarchical.cpp:957] Performed allocation for 1 slaves in 758855ns
> I1201 14:14:37.637233 30323 hierarchical.cpp:1062] No resources available to allocate!
> I1201 14:14:37.637323 30323 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 14:14:37.637359 30323 hierarchical.cpp:957] Performed allocation for 1 slaves in 726275ns
> I1201 14:14:37.764578 30326 slave.cpp:2763] Handling status update TASK_RUNNING (UUID: 01be2c68-5336-411a-aa1e-84a46d11c688) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 from executor(1)@172.17.21.7:46225
> I1201 14:14:37.765316 30326 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 01be2c68-5336-411a-aa1e-84a46d11c688) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
> I1201 14:14:37.765745 30326 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: 01be2c68-5336-411a-aa1e-84a46d11c688) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 to the slave
> I1201 14:14:37.766261 30318 slave.cpp:3115] Forwarding the update TASK_RUNNING (UUID: 01be2c68-5336-411a-aa1e-84a46d11c688) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 to master@172.17.21.7:43732
> I1201 14:14:37.766813 30316 master.cpp:4445] Status update TASK_RUNNING (UUID: 01be2c68-5336-411a-aa1e-84a46d11c688) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 from slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0 at slave(61)@172.17.21.7:43732 (ca6f16e00db6)
> I1201 14:14:37.767022 30316 master.cpp:4493] Forwarding status update TASK_RUNNING (UUID: 01be2c68-5336-411a-aa1e-84a46d11c688) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
> I1201 14:14:37.767364 30316 master.cpp:6097] Updating the state of task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
> I1201 14:14:37.767786 30327 sched.cpp:919] Scheduler::statusUpdate took 123386ns
> I1201 14:14:37.771409 30316 master.cpp:3602] Processing ACKNOWLEDGE call 01be2c68-5336-411a-aa1e-84a46d11c688 for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 (default) at scheduler-90969aaa-c756-4602-8e8a-c07acb10fcfb@172.17.21.7:43732 on slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0
> I1201 14:14:37.772351 30326 status_update_manager.cpp:392] Received status update acknowledgement (UUID: 01be2c68-5336-411a-aa1e-84a46d11c688) for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
> I1201 14:14:37.772438 30316 slave.cpp:3009] Status update manager successfully handled status update TASK_RUNNING (UUID: 01be2c68-5336-411a-aa1e-84a46d11c688) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
> I1201 14:14:37.772816 30316 slave.cpp:3025] Sending acknowledgement for status update TASK_RUNNING (UUID: 01be2c68-5336-411a-aa1e-84a46d11c688) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 to executor(1)@172.17.21.7:46225
> I1201 14:14:37.773659 30326 slave.cpp:2346] Status update manager successfully handled status update acknowledgement (UUID: 01be2c68-5336-411a-aa1e-84a46d11c688) for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
> I1201 14:14:38.639390 30325 hierarchical.cpp:1062] No resources available to allocate!
> I1201 14:14:38.639753 30325 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 14:14:38.640020 30325 hierarchical.cpp:957] Performed allocation for 1 slaves in 1.435634ms
> I1201 14:14:39.641808 30329 hierarchical.cpp:1062] No resources available to allocate!
> I1201 14:14:39.641896 30329 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 14:14:39.641926 30329 hierarchical.cpp:957] Performed allocation for 1 slaves in 729812ns
> I1201 14:14:40.643889 30320 hierarchical.cpp:1062] No resources available to allocate!
> I1201 14:14:40.643978 30320 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 14:14:40.644009 30320 hierarchical.cpp:957] Performed allocation for 1 slaves in 741824ns
> I1201 14:14:41.645243 30327 hierarchical.cpp:1062] No resources available to allocate!
> I1201 14:14:41.645352 30327 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 14:14:41.645400 30327 hierarchical.cpp:957] Performed allocation for 1 slaves in 751314ns
> I1201 14:14:42.165752 30329 slave.cpp:4430] Querying resource estimator for oversubscribable resources
> I1201 14:14:42.166100 30329 slave.cpp:4444] Received oversubscribable resources from the resource estimator
> I1201 14:14:42.222800 30317 slave.cpp:3197] Received ping from slave-observer(58)@172.17.21.7:43732
> I1201 14:14:42.648282 30323 hierarchical.cpp:1062] No resources available to allocate!
> I1201 14:14:42.648391 30323 hierarchical.cpp:1155] No inverse offers to send out!
> I1201 14:14:42.648435 30323 hierarchical.cpp:957] Performed allocation for 1 slaves in 765531ns
> I1201 14:14:42.800969 30320 slave.cpp:2763] Handling status update TASK_RUNNING (UUID: d6a4f449-13f7-49ec-8e58-ee693cea55b7) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 from executor(1)@172.17.21.7:46225
> I1201 14:14:42.801570 30320 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: d6a4f449-13f7-49ec-8e58-ee693cea55b7) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
> I1201 14:14:42.801789 30320 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: d6a4f449-13f7-49ec-8e58-ee693cea55b7) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 to the slave
> I1201 14:14:42.802266 30327 slave.cpp:3115] Forwarding the update TASK_RUNNING (UUID: d6a4f449-13f7-49ec-8e58-ee693cea55b7) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 to master@172.17.21.7:43732
> I1201 14:14:42.802454 30327 slave.cpp:3009] Status update manager successfully handled status update TASK_RUNNING (UUID: d6a4f449-13f7-49ec-8e58-ee693cea55b7) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
> I1201 14:14:42.802500 30327 slave.cpp:3025] Sending acknowledgement for status update TASK_RUNNING (UUID: d6a4f449-13f7-49ec-8e58-ee693cea55b7) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 to executor(1)@172.17.21.7:46225
> I1201 14:14:42.804724 30327 master.cpp:4445] Status update TASK_RUNNING (UUID: d6a4f449-13f7-49ec-8e58-ee693cea55b7) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 from slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0 at slave(61)@172.17.21.7:43732 (ca6f16e00db6)
> I1201 14:14:42.804810 30327 master.cpp:4493] Forwarding status update TASK_RUNNING (UUID: d6a4f449-13f7-49ec-8e58-ee693cea55b7) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
> I1201 14:14:42.805073 30327 master.cpp:6097] Updating the state of task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
> I1201 14:14:42.805578 30327 sched.cpp:919] Scheduler::statusUpdate took 173590ns
> I1201 14:14:42.806002 30327 master.cpp:3602] Processing ACKNOWLEDGE call d6a4f449-13f7-49ec-8e58-ee693cea55b7 for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 (default) at scheduler-90969aaa-c756-4602-8e8a-c07acb10fcfb@172.17.21.7:43732 on slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0
> I1201 14:14:42.806567 30326 status_update_manager.cpp:392] Received status update acknowledgement (UUID: d6a4f449-13f7-49ec-8e58-ee693cea55b7) for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
> I1201 14:14:42.806990 30326 slave.cpp:2346] Status update manager successfully handled status update acknowledgement (UUID: d6a4f449-13f7-49ec-8e58-ee693cea55b7) for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
> I1201 14:14:42.853611 30321 slave.cpp:2763] Handling status update TASK_KILLED (UUID: bc631a7f-8b8a-4dd8-a1bb-7a28016108dc) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 from executor(1)@172.17.21.7:46225
> I1201 14:14:42.853857 30321 slave.cpp:5341] Terminating task 1
> I1201 14:14:42.855967 30321 status_update_manager.cpp:320] Received status update TASK_KILLED (UUID: bc631a7f-8b8a-4dd8-a1bb-7a28016108dc) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
> I1201 14:14:42.856298 30321 status_update_manager.cpp:374] Forwarding update TASK_KILLED (UUID: bc631a7f-8b8a-4dd8-a1bb-7a28016108dc) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 to the slave
> I1201 14:14:42.856757 30321 slave.cpp:3115] Forwarding the update TASK_KILLED (UUID: bc631a7f-8b8a-4dd8-a1bb-7a28016108dc) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 to master@172.17.21.7:43732
> I1201 14:14:42.856945 30321 slave.cpp:3009] Status update manager successfully handled status update TASK_KILLED (UUID: bc631a7f-8b8a-4dd8-a1bb-7a28016108dc) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
> I1201 14:14:42.856992 30321 slave.cpp:3025] Sending acknowledgement for status update TASK_KILLED (UUID: bc631a7f-8b8a-4dd8-a1bb-7a28016108dc) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 to executor(1)@172.17.21.7:46225
> I1201 14:14:42.857553 30319 master.cpp:4445] Status update TASK_KILLED (UUID: bc631a7f-8b8a-4dd8-a1bb-7a28016108dc) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 from slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0 at slave(61)@172.17.21.7:43732 (ca6f16e00db6)
> I1201 14:14:42.857599 30319 master.cpp:4493] Forwarding status update TASK_KILLED (UUID: bc631a7f-8b8a-4dd8-a1bb-7a28016108dc) for task 1 in health state unhealthy of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
> I1201 14:14:42.857770 30319 master.cpp:6097] Updating the state of task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 (latest state: TASK_KILLED, status update state: TASK_KILLED)
> I1201 14:14:42.858459 30325 sched.cpp:919] Scheduler::statusUpdate took 130918ns
> I1201 14:14:42.859022 30325 hierarchical.cpp:791] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0 from framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
> I1201 14:14:42.859416 30319 master.cpp:3602] Processing ACKNOWLEDGE call bc631a7f-8b8a-4dd8-a1bb-7a28016108dc for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 (default) at scheduler-90969aaa-c756-4602-8e8a-c07acb10fcfb@172.17.21.7:43732 on slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0
> I1201 14:14:42.859482 30319 master.cpp:6163] Removing task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 on slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0 at slave(61)@172.17.21.7:43732 (ca6f16e00db6)
> I1201 14:14:42.860584 30319 status_update_manager.cpp:392] Received status update acknowledgement (UUID: bc631a7f-8b8a-4dd8-a1bb-7a28016108dc) for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
> I1201 14:14:42.860781 30319 status_update_manager.cpp:528] Cleaning up status update stream for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
> I1201 14:14:42.861460 30319 slave.cpp:2346] Status update manager successfully handled status update acknowledgement (UUID: bc631a7f-8b8a-4dd8-a1bb-7a28016108dc) for task 1 of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
> I1201 14:14:42.861522 30319 slave.cpp:5382] Completing task 1
> I1201 14:14:42.861721 30295 sched.cpp:1803] Asked to stop the driver
> I1201 14:14:42.861811 30319 sched.cpp:1041] Stopping framework '587d1fd5-db6b-4af4-9267-ce84ac458470-0000'
> I1201 14:14:42.861917 30315 master.cpp:938] Master terminating
> I1201 14:14:42.862610 30323 hierarchical.cpp:410] Removed slave 587d1fd5-db6b-4af4-9267-ce84ac458470-S0
> I1201 14:14:42.863286 30322 hierarchical.cpp:260] Removed framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
> I1201 14:14:42.863615 30326 slave.cpp:3243] master@172.17.21.7:43732 exited
> W1201 14:14:42.863641 30326 slave.cpp:3246] Master disconnected! Waiting for a new master to be elected
> I1201 14:14:42.877462 30318 containerizer.cpp:1073] Destroying container 'e5213230-3cf6-4e8c-b7cd-f4e2615df70f'
> I1201 14:14:42.942379 30314 containerizer.cpp:1256] Executor for container 'e5213230-3cf6-4e8c-b7cd-f4e2615df70f' has exited
> I1201 14:14:42.945029 30329 slave.cpp:3581] Executor '1' of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 terminated with signal Killed
> I1201 14:14:42.945142 30329 slave.cpp:3685] Cleaning up executor '1' of framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000 at executor(1)@172.17.21.7:46225
> I1201 14:14:42.945504 30326 gc.cpp:54] Scheduling '/tmp/HealthCheckTest_CheckCommandTimeout_DODrUR/slaves/587d1fd5-db6b-4af4-9267-ce84ac458470-S0/frameworks/587d1fd5-db6b-4af4-9267-ce84ac458470-0000/executors/1/runs/e5213230-3cf6-4e8c-b7cd-f4e2615df70f' for gc 6.9999890582637days in the future
> I1201 14:14:42.945605 30329 slave.cpp:3773] Cleaning up framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
> I1201 14:14:42.945726 30317 status_update_manager.cpp:282] Closing status update streams for framework 587d1fd5-db6b-4af4-9267-ce84ac458470-0000
> I1201 14:14:42.945765 30326 gc.cpp:54] Scheduling '/tmp/HealthCheckTest_CheckCommandTimeout_DODrUR/slaves/587d1fd5-db6b-4af4-9267-ce84ac458470-S0/frameworks/587d1fd5-db6b-4af4-9267-ce84ac458470-0000/executors/1' for gc 6.99998905620444days in the future
> I1201 14:14:42.945861 30326 gc.cpp:54] Scheduling '/tmp/HealthCheckTest_CheckCommandTimeout_DODrUR/slaves/587d1fd5-db6b-4af4-9267-ce84ac458470-S0/frameworks/587d1fd5-db6b-4af4-9267-ce84ac458470-0000' for gc 6.99998905409778days in the future
> I1201 14:14:42.946763 30295 slave.cpp:599] Slave terminating
> [ OK ] HealthCheckTest.CheckCommandTimeout (16537 ms)
> {noformat}
> Also, this test takes 16 seconds to succeed? :(
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)