[
https://issues.apache.org/jira/browse/MESOS-8983?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16707749#comment-16707749
]
Vinod Kone commented on MESOS-8983:
-----------------------------------
This is happening on ASF CI.
{code}
*15:49:24* 3: [ RUN ]
SlaveRecoveryTest/0.PingTimeoutDuringRecovery*15:49:24* 3: I1203
15:49:24.425719 24686 cluster.cpp:173] Creating default 'local'
authorizer*15:49:24* 3: I1203 15:49:24.430784 24687 master.cpp:413] Master
620b2018-c90f-4b11-bbe3-8fa1c90f204d (5a45e7f918b2) started on
172.17.0.3:42912*15:49:24* 3: I1203 15:49:24.430824 24687 master.cpp:416] Flags
at startup: --acls="" --agent_ping_timeout="1secs"
--agent_reregister_timeout="10mins" --allocation_interval="1secs"
--allocator="hierarchical" --authenticate_agents="true"
--authenticate_frameworks="true" --authenticate_http_frameworks="true"
--authenticate_http_readonly="true" --authenticate_http_readwrite="true"
--authentication_v0_timeout="15secs" --authenticators="crammd5"
--authorizers="local" --credentials="/tmp/PNxXC7/credentials"
--filter_gpu_resources="true" --framework_sorter="drf" --help="false"
--hostname_lookup="true" --http_authenticators="basic"
--http_framework_authenticators="basic" --initialize_driver_logging="true"
--log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO"
--max_agent_ping_timeouts="2" --max_completed_frameworks="50"
--max_completed_tasks_per_framework="1000"
--max_unreachable_tasks_per_framework="1000" --memory_profiling="false"
--min_allocatable_resources="cpus:0.01|mem:32" --port="5050"
--publish_per_framework_metrics="true" --quiet="false"
--recovery_agent_removal_limit="100%" --registry="in_memory"
--registry_fetch_timeout="1mins" --registry_gc_interval="15mins"
--registry_max_agent_age="2weeks" --registry_max_agent_count="102400"
--registry_store_timeout="100secs" --registry_strict="false"
--require_agent_domain="false" --role_sorter="drf" --root_submissions="true"
--version="false" --webui_dir="/usr/local/share/mesos/webui"
--work_dir="/tmp/PNxXC7/master" --zk_session_timeout="10secs"*15:49:24* 3:
I1203 15:49:24.431120 24687 master.cpp:465] Master only allowing authenticated
frameworks to register*15:49:24* 3: I1203 15:49:24.431131 24687 master.cpp:471]
Master only allowing authenticated agents to register*15:49:24* 3: I1203
15:49:24.431139 24687 master.cpp:477] Master only allowing authenticated HTTP
frameworks to register*15:49:24* 3: I1203 15:49:24.431149 24687
credentials.hpp:37] Loading credentials for authentication from
'/tmp/PNxXC7/credentials'*15:49:24* 3: I1203 15:49:24.431355 24687
master.cpp:521] Using default 'crammd5' authenticator*15:49:24* 3: I1203
15:49:24.431514 24687 http.cpp:1042] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-readonly'*15:49:24* 3: I1203
15:49:24.431659 24687 http.cpp:1042] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-readwrite'*15:49:24* 3: I1203
15:49:24.431778 24687 http.cpp:1042] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-scheduler'*15:49:24* 3: I1203
15:49:24.431896 24687 master.cpp:602] Authorization enabled*15:49:24* 3: I1203
15:49:24.432276 24688 hierarchical.cpp:175] Initialized hierarchical allocator
process*15:49:24* 3: I1203 15:49:24.432498 24688 whitelist_watcher.cpp:77] No
whitelist given*15:49:24* 3: I1203 15:49:24.444337 24690 master.cpp:2105]
Elected as the leading master!*15:49:24* 3: I1203 15:49:24.444366 24690
master.cpp:1660] Recovering from registrar*15:49:24* 3: I1203 15:49:24.445142
24687 registrar.cpp:339] Recovering registrar*15:49:24* 3: I1203
15:49:24.445669 24687 registrar.cpp:383] Successfully fetched the registry (0B)
in 472064ns*15:49:24* 3: I1203 15:49:24.445785 24687 registrar.cpp:487] Applied
1 operations in 40517ns; attempting to update the registry*15:49:24* 3: I1203
15:49:24.446497 24687 registrar.cpp:544] Successfully updated the registry in
660992ns*15:49:24* 3: I1203 15:49:24.453212 24687 registrar.cpp:416]
Successfully recovered registrar*15:49:24* 3: I1203 15:49:24.453722 24692
master.cpp:1774] Recovered 0 agents from the registry (135B); allowing 10mins
for agents to reregister*15:49:24* 3: I1203 15:49:24.453984 24692
hierarchical.cpp:215] Skipping recovery of hierarchical allocator: nothing to
recover*15:49:24* 3: I1203 15:49:24.468710 24686 containerizer.cpp:305] Using
isolation \{ environment_secret, posix/cpu, posix/mem, filesystem/posix,
network/cni }*15:49:24* 3: W1203 15:49:24.481513 24686 backend.cpp:76] Failed
to create 'aufs' backend: AufsBackend requires root privileges*15:49:24* 3:
W1203 15:49:24.481549 24686 backend.cpp:76] Failed to create 'bind' backend:
BindBackend requires root privileges*15:49:24* 3: I1203 15:49:24.481591 24686
provisioner.cpp:298] Using default backend 'copy'*15:49:24* 3: W1203
15:49:24.498661 24686 process.cpp:2829] Attempted to spawn already running
process files@172.17.0.3:42912*15:49:24* 3: I1203 15:49:24.499516 24686
cluster.cpp:485] Creating default 'local' authorizer*15:49:24* 3: I1203
15:49:24.501598 24691 slave.cpp:267] Mesos agent started on
@172.17.0.3:42912*15:49:24* 3: I1203 15:49:24.501632 24691 slave.cpp:268] Flags
at startup: --acls="" --appc_simple_discovery_uri_prefix="http://";
--appc_store_dir="/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_qQs4lL/store/appc"
--authenticate_http_executors="true" --authenticate_http_readonly="true"
--authenticate_http_readwrite="true" --authenticatee="crammd5"
--authentication_backoff_factor="1secs" --authentication_timeout_max="1mins"
--authentication_timeout_min="5secs" --authorizer="local"
--cgroups_cpu_enable_pids_and_tids_count="false"
--cgroups_destroy_timeout="1mins" --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/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_qQs4lL/credential"
--default_role="*" --disallow_sharing_agent_pid_namespace="false"
--disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true"
--docker_registry="
[https://registry-1.docker.io|https://registry-1.docker.io/]
" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock"
--docker_stop_timeout="0ns"
--docker_store_dir="/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_qQs4lL/store/docker"
--docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume"
--enforce_container_disk_quota="false" --executor_registration_timeout="1mins"
--executor_reregistration_timeout="1mins"
--executor_shutdown_grace_period="5secs"
--fetcher_cache_dir="/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_qQs4lL/fetch"
--fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins"
--frameworks_home="/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_qQs4lL/frameworks"
--gc_delay="1weeks" --gc_disk_headroom="0.1"
--gc_non_executor_container_sandboxes="false" --help="false"
--hostname_lookup="true" --http_command_executor="false"
--http_credentials="/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_qQs4lL/http_credentials"
--http_heartbeat_interval="30secs" --initialize_driver_logging="true"
--isolation="posix/cpu,posix/mem"
--jwt_secret_key="/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_qQs4lL/jwt_secret_key"
--launcher="posix" --launcher_dir="/tmp/SRC/build/src" --logbufsecs="0"
--logging_level="INFO" --max_completed_executors_per_framework="150"
--memory_profiling="false" --network_cni_metrics="true"
--oversubscribed_resources_interval="15secs" --perf_duration="10secs"
--perf_interval="1mins" --port="5051" --qos_correction_interval_min="0ns"
--quiet="false" --reconfiguration_policy="equal" --recover="reconnect"
--recovery_timeout="15mins" --registration_backoff_factor="10ms"
--resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]"
--revocable_cpu_low_priority="true"
--runtime_dir="/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_qQs4lL"
--sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true"
--systemd_enable_support="true"
--systemd_runtime_directory="/run/systemd/system" --version="false"
--work_dir="/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_mipvuW"
--zk_session_timeout="10secs"*15:49:24* 3: W1203 15:49:24.501935 24686
process.cpp:2829] Attempted to spawn already running process
version@172.17.0.3:42912*15:49:24* 3: I1203 15:49:24.501942 24691
credentials.hpp:86] Loading credential for authentication from
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_qQs4lL/credential'*15:49:24*
3: I1203 15:49:24.502630 24691 slave.cpp:300] Agent using credential for:
test-principal*15:49:24* 3: I1203 15:49:24.502650 24691 credentials.hpp:37]
Loading credentials for authentication from
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_qQs4lL/http_credentials'*15:49:24*
3: I1203 15:49:24.502882 24686 sched.cpp:232] Version: 1.8.0*15:49:24* 3:
I1203 15:49:24.502902 24691 http.cpp:1042] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-executor'*15:49:24* 3: I1203
15:49:24.503082 24691 http.cpp:1063] Creating default 'jwt' HTTP authenticator
for realm 'mesos-agent-executor'*15:49:24* 3: I1203 15:49:24.503306 24691
http.cpp:1042] Creating default 'basic' HTTP authenticator for realm
'mesos-agent-readonly'*15:49:24* 3: I1203 15:49:24.503407 24691 http.cpp:1063]
Creating default 'jwt' HTTP authenticator for realm
'mesos-agent-readonly'*15:49:24* 3: I1203 15:49:24.503582 24691 http.cpp:1042]
Creating default 'basic' HTTP authenticator for realm
'mesos-agent-readwrite'*15:49:24* 3: I1203 15:49:24.503693 24691 http.cpp:1063]
Creating default 'jwt' HTTP authenticator for realm
'mesos-agent-readwrite'*15:49:24* 3: I1203 15:49:24.503868 24688 sched.cpp:336]
New master detected at master@172.17.0.3:42912*15:49:24* 3: I1203
15:49:24.503994 24688 sched.cpp:401] Authenticating with master
master@172.17.0.3:42912*15:49:24* 3: I1203 15:49:24.504014 24688 sched.cpp:408]
Using default CRAM-MD5 authenticatee*15:49:24* 3: I1203 15:49:24.504022 24691
disk_profile_adaptor.cpp:80] Creating default disk profile adaptor
module*15:49:24* 3: I1203 15:49:24.504568 24688 authenticatee.cpp:121] Creating
new client SASL connection*15:49:24* 3: I1203 15:49:24.504958 24692
master.cpp:9699] Authenticating
scheduler-4c1355d8-785d-4e32-950a-abcd46c3fcb9@172.17.0.3:42912*15:49:24* 3:
I1203 15:49:24.505338 24692 authenticator.cpp:414] Starting authentication
session for crammd5-authenticatee(551)@172.17.0.3:42912*15:49:24* 3: I1203
15:49:24.505789 24692 authenticator.cpp:98] Creating new server SASL
connection*15:49:24* 3: I1203 15:49:24.506059 24692 authenticatee.cpp:213]
Received SASL authentication mechanisms: CRAM-MD5*15:49:24* 3: I1203
15:49:24.506083 24692 authenticatee.cpp:239] Attempting to authenticate with
mechanism 'CRAM-MD5'*15:49:24* 3: I1203 15:49:24.506178 24692
authenticator.cpp:204] Received SASL authentication start*15:49:24* 3: I1203
15:49:24.506227 24692 authenticator.cpp:326] Authentication requires more
steps*15:49:24* 3: I1203 15:49:24.506312 24692 authenticatee.cpp:259] Received
SASL authentication step*15:49:24* 3: I1203 15:49:24.506402 24692
authenticator.cpp:232] Received SASL authentication step*15:49:24* 3: I1203
15:49:24.506426 24692 auxprop.cpp:109] Request to lookup properties for user:
'test-principal' realm: '5a45e7f918b2' server FQDN: '5a45e7f918b2'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false *15:49:24* 3: I1203 15:49:24.506439 24692
auxprop.cpp:181] Looking up auxiliary property '*userPassword'*15:49:24* 3:
I1203 15:49:24.506476 24692 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'*15:49:24* 3: I1203 15:49:24.506498 24692
auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm:
'5a45e7f918b2' server FQDN: '5a45e7f918b2' SASL_AUXPROP_VERIFY_AGAINST_HASH:
false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true *15:49:24* 3:
I1203 15:49:24.506510 24692 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true*15:49:24* 3: I1203
15:49:24.506520 24692 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true*15:49:24* 3: I1203
15:49:24.506534 24692 authenticator.cpp:318] Authentication success*15:49:24*
3: I1203 15:49:24.506736 24692 authenticatee.cpp:299] Authentication
success*15:49:24* 3: I1203 15:49:24.506963 24692 master.cpp:9731] Successfully
authenticated principal 'test-principal' at
scheduler-4c1355d8-785d-4e32-950a-abcd46c3fcb9@172.17.0.3:42912*15:49:24* 3:
I1203 15:49:24.507122 24692 authenticator.cpp:432] Authentication session
cleanup for crammd5-authenticatee(551)@172.17.0.3:42912*15:49:24* 3: I1203
15:49:24.507486 24692 sched.cpp:513] Successfully authenticated with master
master@172.17.0.3:42912*15:49:24* 3: I1203 15:49:24.507506 24692 sched.cpp:817]
Sending SUBSCRIBE call to master@172.17.0.3:42912*15:49:24* 3: I1203
15:49:24.507635 24692 sched.cpp:850] Will retry registration in 1.432484435secs
if necessary*15:49:24* 3: I1203 15:49:24.507975 24692 master.cpp:2876] Received
SUBSCRIBE call for framework 'default' at
scheduler-4c1355d8-785d-4e32-950a-abcd46c3fcb9@172.17.0.3:42912*15:49:24* 3:
I1203 15:49:24.507994 24692 master.cpp:2177] Authorizing framework principal
'test-principal' to receive offers for roles '\{ * }'*15:49:24* 3: I1203
15:49:24.508569 24692 master.cpp:2957] Subscribing framework default with
checkpointing enabled and capabilities [ MULTI_ROLE, RESERVATION_REFINEMENT
]*15:49:24* 3: I1203 15:49:24.514458 24692 master.cpp:9929] Adding framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000 (default) at
scheduler-4c1355d8-785d-4e32-950a-abcd46c3fcb9@172.17.0.3:42912 with roles \{
} suppressed*15:49:24* 3: I1203 15:49:24.515206 24689 sched.cpp:744] Framework
registered with 620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000*15:49:24* 3: I1203
15:49:24.515259 24689 sched.cpp:758] Scheduler::registered took
32847ns*15:49:24* 3: I1203 15:49:24.515781 24690 hierarchical.cpp:304] Added
framework 620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000*15:49:24* 3: I1203
15:49:24.515966 24690 hierarchical.cpp:1566] Performed allocation for 0 agents
in 71513ns*15:49:24* 3: I1203 15:49:24.505010 24691 slave.cpp:615] Agent
resources:
[\{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},\{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},\{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},\{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]*15:49:24*
3: I1203 15:49:24.516197 24691 slave.cpp:623] Agent attributes: [ ]*15:49:24*
3: I1203 15:49:24.516212 24691 slave.cpp:632] Agent hostname:
5a45e7f918b2*15:49:24* 3: I1203 15:49:24.517120 24694
task_status_update_manager.cpp:181] Pausing sending task status
updates*15:49:24* 3: I1203 15:49:24.529451 24691 state.cpp:66] Recovering state
from '/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_mipvuW/meta'*15:49:24*
3: I1203 15:49:24.529688 24694 slave.cpp:6915] Finished recovering checkpointed
state from '/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_mipvuW/meta',
beginning agent recovery*15:49:24* 3: I1203 15:49:24.529873 24694
task_status_update_manager.cpp:207] Recovering task status update
manager*15:49:24* 3: I1203 15:49:24.530297 24694 containerizer.cpp:727]
Recovering Mesos containers*15:49:24* 3: I1203 15:49:24.530534 24694
containerizer.cpp:1053] Recovering isolators*15:49:24* 3: I1203 15:49:24.531592
24694 containerizer.cpp:1092] Recovering provisioner*15:49:24* 3: I1203
15:49:24.532214 24694 provisioner.cpp:494] Provisioner recovery
complete*15:49:24* 3: I1203 15:49:24.533071 24688 composing.cpp:339] Finished
recovering all containerizers*15:49:24* 3: I1203 15:49:24.533313 24688
slave.cpp:7144] Recovering executors*15:49:24* 3: I1203 15:49:24.533394 24688
slave.cpp:7297] Finished recovery*15:49:24* 3: I1203 15:49:24.534448 24688
slave.cpp:1260] New master detected at master@172.17.0.3:42912*15:49:24* 3:
I1203 15:49:24.534461 24689 task_status_update_manager.cpp:181] Pausing sending
task status updates*15:49:24* 3: I1203 15:49:24.534575 24688 slave.cpp:1325]
Detecting new master*15:49:24* 3: I1203 15:49:24.553133 24689 slave.cpp:1352]
Authenticating with master master@172.17.0.3:42912*15:49:24* 3: I1203
15:49:24.553277 24689 slave.cpp:1361] Using default CRAM-MD5
authenticatee*15:49:24* 3: I1203 15:49:24.553848 24689 authenticatee.cpp:121]
Creating new client SASL connection*15:49:24* 3: I1203 15:49:24.554237 24689
master.cpp:9699] Authenticating slave@172.17.0.3:42912*15:49:24* 3: I1203
15:49:24.554441 24689 authenticator.cpp:414] Starting authentication session
for crammd5-authenticatee(552)@172.17.0.3:42912*15:49:24* 3: I1203
15:49:24.554893 24689 authenticator.cpp:98] Creating new server SASL
connection*15:49:24* 3: I1203 15:49:24.555191 24693 authenticatee.cpp:213]
Received SASL authentication mechanisms: CRAM-MD5*15:49:24* 3: I1203
15:49:24.555228 24693 authenticatee.cpp:239] Attempting to authenticate with
mechanism 'CRAM-MD5'*15:49:24* 3: I1203 15:49:24.555366 24693
authenticator.cpp:204] Received SASL authentication start*15:49:24* 3: I1203
15:49:24.555418 24693 authenticator.cpp:326] Authentication requires more
steps*15:49:24* 3: I1203 15:49:24.555534 24693 authenticatee.cpp:259] Received
SASL authentication step*15:49:24* 3: I1203 15:49:24.555631 24693
authenticator.cpp:232] Received SASL authentication step*15:49:24* 3: I1203
15:49:24.555656 24693 auxprop.cpp:109] Request to lookup properties for user:
'test-principal' realm: '5a45e7f918b2' server FQDN: '5a45e7f918b2'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false *15:49:24* 3: I1203 15:49:24.555668 24693
auxprop.cpp:181] Looking up auxiliary property '*userPassword'*15:49:24* 3:
I1203 15:49:24.555709 24693 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'*15:49:24* 3: I1203 15:49:24.555730 24693
auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm:
'5a45e7f918b2' server FQDN: '5a45e7f918b2' SASL_AUXPROP_VERIFY_AGAINST_HASH:
false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true *15:49:24* 3:
I1203 15:49:24.555742 24693 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true*15:49:24* 3: I1203
15:49:24.555752 24693 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true*15:49:24* 3: I1203
15:49:24.555766 24693 authenticator.cpp:318] Authentication success*15:49:24*
3: I1203 15:49:24.555968 24693 authenticatee.cpp:299] Authentication
success*15:49:24* 3: I1203 15:49:24.556216 24693 master.cpp:9731] Successfully
authenticated principal 'test-principal' at slave@172.17.0.3:42912*15:49:24* 3:
I1203 15:49:24.556325 24693 authenticator.cpp:432] Authentication session
cleanup for crammd5-authenticatee(552)@172.17.0.3:42912*15:49:24* 3: I1203
15:49:24.556720 24693 slave.cpp:1452] Successfully authenticated with master
master@172.17.0.3:42912*15:49:24* 3: I1203 15:49:24.557538 24687
master.cpp:6650] Received register agent message from slave@172.17.0.3:42912
(5a45e7f918b2)*15:49:24* 3: I1203 15:49:24.557698 24687 master.cpp:3986]
Authorizing agent providing resources 'cpus:2; mem:1024; disk:1024;
ports:[31000-32000]' with principal 'test-principal'*15:49:24* 3: I1203
15:49:24.558728 24687 master.cpp:6717] Authorized registration of agent at
slave@172.17.0.3:42912 (5a45e7f918b2)*15:49:24* 3: I1203 15:49:24.558799 24687
master.cpp:6832] Registering agent at slave@172.17.0.3:42912 (5a45e7f918b2)
with id 620b2018-c90f-4b11-bbe3-8fa1c90f204d-S0*15:49:24* 3: I1203
15:49:24.559409 24687 registrar.cpp:487] Applied 1 operations in 185270ns;
attempting to update the registry*15:49:24* 3: I1203 15:49:24.560205 24687
registrar.cpp:544] Successfully updated the registry in 724992ns*15:49:24* 3:
I1203 15:49:24.560413 24687 master.cpp:6880] Admitted agent
620b2018-c90f-4b11-bbe3-8fa1c90f204d-S0 at slave@172.17.0.3:42912
(5a45e7f918b2)*15:49:24* 3: I1203 15:49:24.561532 24690 hierarchical.cpp:603]
Added agent 620b2018-c90f-4b11-bbe3-8fa1c90f204d-S0 (5a45e7f918b2) with cpus:2;
mem:1024; disk:1024; ports:[31000-32000] (allocated: {})*15:49:24* 3: I1203
15:49:24.562481 24690 hierarchical.cpp:1566] Performed allocation for 1 agents
in 796791ns*15:49:24* 3: I1203 15:49:24.565070 24693 slave.cpp:1883] Will retry
registration in 5.438814ms if necessary*15:49:24* 3: I1203 15:49:24.565280
24693 slave.cpp:1485] Registered with master master@172.17.0.3:42912; given
agent ID 620b2018-c90f-4b11-bbe3-8fa1c90f204d-S0*15:49:24* 3: I1203
15:49:24.565618 24693 slave.cpp:1505] Checkpointing SlaveInfo to
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_mipvuW/meta/slaves/620b2018-c90f-4b11-bbe3-8fa1c90f204d-S0/slave.info'*15:49:24*
3: I1203 15:49:24.566555 24693 slave.cpp:1554] Forwarding agent update
\{"operations":{},"resource_version_uuid":\{"value":"qutn4lYsTa+1PGelXn6DJw=="},"slave_id":\{"value":"620b2018-c90f-4b11-bbe3-8fa1c90f204d-S0"},"update_oversubscribed_resources":false}*15:49:24*
3: I1203 15:49:24.569110 24692 task_status_update_manager.cpp:188] Resuming
sending task status updates*15:49:24* 3: I1203 15:49:24.560948 24687
master.cpp:6925] Registered agent 620b2018-c90f-4b11-bbe3-8fa1c90f204d-S0 at
slave@172.17.0.3:42912 (5a45e7f918b2) with cpus:2; mem:1024; disk:1024;
ports:[31000-32000]*15:49:24* 3: I1203 15:49:24.570235 24687 master.cpp:9514]
Sending offers [ 620b2018-c90f-4b11-bbe3-8fa1c90f204d-O0 ] to framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000 (default) at
scheduler-4c1355d8-785d-4e32-950a-abcd46c3fcb9@172.17.0.3:42912*15:49:24* 3:
I1203 15:49:24.570781 24687 master.cpp:7984] Ignoring update on agent
620b2018-c90f-4b11-bbe3-8fa1c90f204d-S0 at slave@172.17.0.3:42912
(5a45e7f918b2) as it reports no changes*15:49:24* 3: I1203 15:49:24.571557
24688 sched.cpp:914] Scheduler::resourceOffers took 105922ns*15:49:24* 3: I1203
15:49:24.578178 24688 master.cpp:11513] Removing offer
620b2018-c90f-4b11-bbe3-8fa1c90f204d-O0*15:49:24* 3: I1203 15:49:24.578507
24688 master.cpp:4511] Processing ACCEPT call for offers: [
620b2018-c90f-4b11-bbe3-8fa1c90f204d-O0 ] on agent
620b2018-c90f-4b11-bbe3-8fa1c90f204d-S0 at slave@172.17.0.3:42912
(5a45e7f918b2) for framework 620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000
(default) at
scheduler-4c1355d8-785d-4e32-950a-abcd46c3fcb9@172.17.0.3:42912*15:49:24* 3:
I1203 15:49:24.578606 24688 master.cpp:3563] Authorizing framework principal
'test-principal' to launch task b8da8425-1d34-422e-882f-cf16a99db0d5*15:49:24*
3: I1203 15:49:24.580466 24688 master.cpp:4088] Adding task
b8da8425-1d34-422e-882f-cf16a99db0d5 with resources cpus(allocated: *):2;
mem(allocated: *):1024; disk(allocated: *):1024; ports(allocated:
*):[31000-32000] of framework 620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000
(default) at scheduler-4c1355d8-785d-4e32-950a-abcd46c3fcb9@172.17.0.3:42912 on
agent 620b2018-c90f-4b11-bbe3-8fa1c90f204d-S0 at slave@172.17.0.3:42912
(5a45e7f918b2)*15:49:24* 3: I1203 15:49:24.580965 24688 master.cpp:5483]
Launching task b8da8425-1d34-422e-882f-cf16a99db0d5 of framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000 (default) at
scheduler-4c1355d8-785d-4e32-950a-abcd46c3fcb9@172.17.0.3:42912 with resources
[\{"allocation_info":{"role":"*"},"name":"cpus","scalar":\{"value":2.0},"type":"SCALAR"},\{"allocation_info":{"role":"*"},"name":"mem","scalar":\{"value":1024.0},"type":"SCALAR"},\{"allocation_info":{"role":"*"},"name":"disk","scalar":\{"value":1024.0},"type":"SCALAR"},\{"allocation_info":{"role":"*"},"name":"ports","ranges":\{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
on agent 620b2018-c90f-4b11-bbe3-8fa1c90f204d-S0 at slave@172.17.0.3:42912
(5a45e7f918b2) on new executor*15:49:24* 3: I1203 15:49:24.594374 24688
slave.cpp:2020] Got assigned task 'b8da8425-1d34-422e-882f-cf16a99db0d5' for
framework 620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000*15:49:24* 3: I1203
15:49:24.594540 24688 slave.cpp:8914] Checkpointing FrameworkInfo to
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_mipvuW/meta/slaves/620b2018-c90f-4b11-bbe3-8fa1c90f204d-S0/frameworks/620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000/framework.info'*15:49:24*
3: I1203 15:49:24.609599 24688 slave.cpp:8925] Checkpointing framework pid
'scheduler-4c1355d8-785d-4e32-950a-abcd46c3fcb9@172.17.0.3:42912' to
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_mipvuW/meta/slaves/620b2018-c90f-4b11-bbe3-8fa1c90f204d-S0/frameworks/620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000/framework.pid'*15:49:24*
3: I1203 15:49:24.611207 24688 slave.cpp:2394] Authorizing task
'b8da8425-1d34-422e-882f-cf16a99db0d5' for framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000*15:49:24* 3: I1203 15:49:24.611280
24688 slave.cpp:8472] Authorizing framework principal 'test-principal' to
launch task b8da8425-1d34-422e-882f-cf16a99db0d5*15:49:24* 3: I1203
15:49:24.613554 24689 slave.cpp:2837] Launching task
'b8da8425-1d34-422e-882f-cf16a99db0d5' for framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000*15:49:24* 3: I1203 15:49:24.613646
24689 paths.cpp:752] Creating sandbox
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_mipvuW/slaves/620b2018-c90f-4b11-bbe3-8fa1c90f204d-S0/frameworks/620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000/executors/b8da8425-1d34-422e-882f-cf16a99db0d5/runs/28e6e1c7-33a4-42a5-86ba-e2c23d9e039b'
for user 'mesos'*15:49:24* 3: I1203 15:49:24.617535 24689 slave.cpp:9700]
Checkpointing ExecutorInfo to
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_mipvuW/meta/slaves/620b2018-c90f-4b11-bbe3-8fa1c90f204d-S0/frameworks/620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000/executors/b8da8425-1d34-422e-882f-cf16a99db0d5/executor.info'*15:49:24*
3: I1203 15:49:24.618950 24689 paths.cpp:755] Creating sandbox
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_mipvuW/meta/slaves/620b2018-c90f-4b11-bbe3-8fa1c90f204d-S0/frameworks/620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000/executors/b8da8425-1d34-422e-882f-cf16a99db0d5/runs/28e6e1c7-33a4-42a5-86ba-e2c23d9e039b'*15:49:24*
3: I1203 15:49:24.619253 24689 slave.cpp:9000] Launching executor
'b8da8425-1d34-422e-882f-cf16a99db0d5' of framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000 with resources
[\{"allocation_info":{"role":"*"},"name":"cpus","scalar":\{"value":0.1},"type":"SCALAR"},\{"allocation_info":{"role":"*"},"name":"mem","scalar":\{"value":32.0},"type":"SCALAR"}]
in work directory
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_mipvuW/slaves/620b2018-c90f-4b11-bbe3-8fa1c90f204d-S0/frameworks/620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000/executors/b8da8425-1d34-422e-882f-cf16a99db0d5/runs/28e6e1c7-33a4-42a5-86ba-e2c23d9e039b'*15:49:24*
3: I1203 15:49:24.620136 24689 slave.cpp:9731] Checkpointing TaskInfo to
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_mipvuW/meta/slaves/620b2018-c90f-4b11-bbe3-8fa1c90f204d-S0/frameworks/620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000/executors/b8da8425-1d34-422e-882f-cf16a99db0d5/runs/28e6e1c7-33a4-42a5-86ba-e2c23d9e039b/tasks/b8da8425-1d34-422e-882f-cf16a99db0d5/task.info'*15:49:24*
3: I1203 15:49:24.620820 24689 slave.cpp:3034] Queued task
'b8da8425-1d34-422e-882f-cf16a99db0d5' for executor
'b8da8425-1d34-422e-882f-cf16a99db0d5' of framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000*15:49:24* 3: I1203 15:49:24.620916
24689 slave.cpp:994] Successfully attached
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_mipvuW/slaves/620b2018-c90f-4b11-bbe3-8fa1c90f204d-S0/frameworks/620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000/executors/b8da8425-1d34-422e-882f-cf16a99db0d5/runs/28e6e1c7-33a4-42a5-86ba-e2c23d9e039b'
to virtual path
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_mipvuW/slaves/620b2018-c90f-4b11-bbe3-8fa1c90f204d-S0/frameworks/620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000/executors/b8da8425-1d34-422e-882f-cf16a99db0d5/runs/latest'*15:49:24*
3: I1203 15:49:24.633963 24689 slave.cpp:3515] Launching container
28e6e1c7-33a4-42a5-86ba-e2c23d9e039b for executor
'b8da8425-1d34-422e-882f-cf16a99db0d5' of framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000*15:49:24* 3: I1203 15:49:24.634876
24689 slave.cpp:994] Successfully attached
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_mipvuW/slaves/620b2018-c90f-4b11-bbe3-8fa1c90f204d-S0/frameworks/620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000/executors/b8da8425-1d34-422e-882f-cf16a99db0d5/runs/28e6e1c7-33a4-42a5-86ba-e2c23d9e039b'
to virtual path
'/frameworks/620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000/executors/b8da8425-1d34-422e-882f-cf16a99db0d5/runs/latest'*15:49:24*
3: I1203 15:49:24.634920 24689 slave.cpp:994] Successfully attached
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_mipvuW/slaves/620b2018-c90f-4b11-bbe3-8fa1c90f204d-S0/frameworks/620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000/executors/b8da8425-1d34-422e-882f-cf16a99db0d5/runs/28e6e1c7-33a4-42a5-86ba-e2c23d9e039b'
to virtual path
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_mipvuW/slaves/620b2018-c90f-4b11-bbe3-8fa1c90f204d-S0/frameworks/620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000/executors/b8da8425-1d34-422e-882f-cf16a99db0d5/runs/28e6e1c7-33a4-42a5-86ba-e2c23d9e039b'*15:49:24*
3: I1203 15:49:24.635329 24690 containerizer.cpp:1280] Starting container
28e6e1c7-33a4-42a5-86ba-e2c23d9e039b*15:49:24* 3: I1203 15:49:24.636489 24690
containerizer.cpp:1446] Checkpointed ContainerConfig at
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_qQs4lL/containers/28e6e1c7-33a4-42a5-86ba-e2c23d9e039b/config'*15:49:24*
3: I1203 15:49:24.636518 24690 containerizer.cpp:3132] Transitioning the state
of container 28e6e1c7-33a4-42a5-86ba-e2c23d9e039b from PROVISIONING to
PREPARING*15:49:24* 3: I1203 15:49:24.649637 24689 containerizer.cpp:1949]
Launching 'mesos-containerizer' with flags '--help="false"
--launch_info="\{"command":{"arguments":["mesos-executor","--launcher_dir=/tmp/SRC/build/src"],"shell":false,"value":"/tmp/SRC/build/src/mesos-executor"},"environment":\{"variables":[{"name":"LIBPROCESS_PORT","type":"VALUE","value":"0"},\{"name":"MESOS_AGENT_ENDPOINT","type":"VALUE","value":"172.17.0.3:42912"},\{"name":"MESOS_CHECKPOINT","type":"VALUE","value":"1"},\{"name":"MESOS_DIRECTORY","type":"VALUE","value":"/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_mipvuW/slaves/620b2018-c90f-4b11-bbe3-8fa1c90f204d-S0/frameworks/620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000/executors/b8da8425-1d34-422e-882f-cf16a99db0d5/runs/28e6e1c7-33a4-42a5-86ba-e2c23d9e039b"},\{"name":"MESOS_EXECUTOR_AUTHENTICATION_TOKEN","type":"VALUE","value":"eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJjaWQiOiIyOGU2ZTFjNy0zM2E0LTQyYTUtODZiYS1lMmMyM2Q5ZTAzOWIiLCJlaWQiOiJiOGRhODQyNS0xZDM0LTQyMmUtODgyZi1jZjE2YTk5ZGIwZDUiLCJmaWQiOiI2MjBiMjAxOC1jOTBmLTRiMTEtYmJlMy04ZmExYzkwZjIwNGQtMDAwMCJ9.fkSpyn_zZoMAGNaD4uriBUINMnPo-Hz-829xl08NkkA"},\{"name":"MESOS_EXECUTOR_ID","type":"VALUE","value":"b8da8425-1d34-422e-882f-cf16a99db0d5"},\{"name":"MESOS_EXECUTOR_SHUTDOWN_GRACE_PERIOD","type":"VALUE","value":"5secs"},\{"name":"MESOS_FRAMEWORK_ID","type":"VALUE","value":"620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000"},\{"name":"MESOS_HTTP_COMMAND_EXECUTOR","type":"VALUE","value":"0"},\{"name":"MESOS_RECOVERY_TIMEOUT","type":"VALUE","value":"15mins"},\{"name":"MESOS_SLAVE_ID","type":"VALUE","value":"620b2018-c90f-4b11-bbe3-8fa1c90f204d-S0"},\{"name":"MESOS_SLAVE_PID","type":"VALUE","value":"slave@172.17.0.3:42912"},\{"name":"MESOS_SUBSCRIPTION_BACKOFF_MAX","type":"VALUE","value":"1mins"},\{"name":"MESOS_SANDBOX","type":"VALUE","value":"/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_mipvuW/slaves/620b2018-c90f-4b11-bbe3-8fa1c90f204d-S0/frameworks/620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000/executors/b8da8425-1d34-422e-882f-cf16a99db0d5/runs/28e6e1c7-33a4-42a5-86ba-e2c23d9e039b"}]},"task_environment":{},"user":"mesos","working_directory":"/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_mipvuW/slaves/620b2018-c90f-4b11-bbe3-8fa1c90f204d-S0/frameworks/620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000/executors/b8da8425-1d34-422e-882f-cf16a99db0d5/runs/28e6e1c7-33a4-42a5-86ba-e2c23d9e039b"}"
--pipe_read="14" --pipe_write="17"
--runtime_directory="/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_qQs4lL/containers/28e6e1c7-33a4-42a5-86ba-e2c23d9e039b"
--unshare_namespace_mnt="false"'*15:49:24* 3: I1203 15:49:24.657140 24689
launcher.cpp:145] Forked child with pid '26364' for container
'28e6e1c7-33a4-42a5-86ba-e2c23d9e039b'*15:49:24* 3: I1203 15:49:24.657313 24689
containerizer.cpp:2054] Checkpointing container's forked pid 26364 to
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_mipvuW/meta/slaves/620b2018-c90f-4b11-bbe3-8fa1c90f204d-S0/frameworks/620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000/executors/b8da8425-1d34-422e-882f-cf16a99db0d5/runs/28e6e1c7-33a4-42a5-86ba-e2c23d9e039b/pids/forked.pid'*15:49:24*
3: I1203 15:49:24.658131 24689 containerizer.cpp:3132] Transitioning the state
of container 28e6e1c7-33a4-42a5-86ba-e2c23d9e039b from PREPARING to
ISOLATING*15:49:24* 3: I1203 15:49:24.667253 24689 containerizer.cpp:3132]
Transitioning the state of container 28e6e1c7-33a4-42a5-86ba-e2c23d9e039b from
ISOLATING to FETCHING*15:49:24* 3: I1203 15:49:24.667451 24690 fetcher.cpp:369]
Starting to fetch URIs for container: 28e6e1c7-33a4-42a5-86ba-e2c23d9e039b,
directory:
/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_mipvuW/slaves/620b2018-c90f-4b11-bbe3-8fa1c90f204d-S0/frameworks/620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000/executors/b8da8425-1d34-422e-882f-cf16a99db0d5/runs/28e6e1c7-33a4-42a5-86ba-e2c23d9e039b*15:49:24*
3: I1203 15:49:24.677362 24689 containerizer.cpp:3132] Transitioning the state
of container 28e6e1c7-33a4-42a5-86ba-e2c23d9e039b from FETCHING to
RUNNING*15:49:25* 3: I1203 15:49:25.298507 26365 exec.cpp:162] Version:
1.8.0*15:49:25* 3: I1203 15:49:25.350699 24694 slave.cpp:4809] Got registration
for executor 'b8da8425-1d34-422e-882f-cf16a99db0d5' of framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000 from
executor(1)@172.17.0.3:38408*15:49:25* 3: I1203 15:49:25.351094 24694
slave.cpp:4895] Checkpointing executor pid 'executor(1)@172.17.0.3:38408' to
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_mipvuW/meta/slaves/620b2018-c90f-4b11-bbe3-8fa1c90f204d-S0/frameworks/620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000/executors/b8da8425-1d34-422e-882f-cf16a99db0d5/runs/28e6e1c7-33a4-42a5-86ba-e2c23d9e039b/pids/libprocess.pid'*15:49:25*
3: I1203 15:49:25.353680 24687 slave.cpp:3247] Sending queued task
'b8da8425-1d34-422e-882f-cf16a99db0d5' to executor
'b8da8425-1d34-422e-882f-cf16a99db0d5' of framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000 at
executor(1)@172.17.0.3:38408*15:49:25* 3: I1203 15:49:25.377852 26369
exec.cpp:236] Executor registered on agent
620b2018-c90f-4b11-bbe3-8fa1c90f204d-S0*15:49:25* 3: I1203 15:49:25.385691
26369 executor.cpp:184] Received SUBSCRIBED event*15:49:25* 3: I1203
15:49:25.386564 26369 executor.cpp:188] Subscribed executor on
5a45e7f918b2*15:49:25* 3: I1203 15:49:25.402703 26373 executor.cpp:184]
Received LAUNCH event*15:49:25* 3: I1203 15:49:25.408550 26373
executor.cpp:687] Starting task b8da8425-1d34-422e-882f-cf16a99db0d5*15:49:25*
3: I1203 15:49:25.409273 24693 slave.cpp:5275] Handling status update
TASK_STARTING (Status UUID: 2fa16dfd-ebab-4ba9-9038-f5aae9c11391) for task
b8da8425-1d34-422e-882f-cf16a99db0d5 of framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000 from
executor(1)@172.17.0.3:38408*15:49:25* 3: I1203 15:49:25.411695 24687
task_status_update_manager.cpp:328] Received task status update TASK_STARTING
(Status UUID: 2fa16dfd-ebab-4ba9-9038-f5aae9c11391) for task
b8da8425-1d34-422e-882f-cf16a99db0d5 of framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000*15:49:25* 3: I1203 15:49:25.411736
24687 task_status_update_manager.cpp:507] Creating StatusUpdate stream for task
b8da8425-1d34-422e-882f-cf16a99db0d5 of framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000*15:49:25* 3: I1203 15:49:25.412415
24687 task_status_update_manager.cpp:842] Checkpointing UPDATE for task status
update TASK_STARTING (Status UUID: 2fa16dfd-ebab-4ba9-9038-f5aae9c11391) for
task b8da8425-1d34-422e-882f-cf16a99db0d5 of framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000*15:49:25* 3: I1203 15:49:25.412655
24687 task_status_update_manager.cpp:383] Forwarding task status update
TASK_STARTING (Status UUID: 2fa16dfd-ebab-4ba9-9038-f5aae9c11391) for task
b8da8425-1d34-422e-882f-cf16a99db0d5 of framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000 to the agent*15:49:25* 3: I1203
15:49:25.412946 24687 slave.cpp:5767] Forwarding the update TASK_STARTING
(Status UUID: 2fa16dfd-ebab-4ba9-9038-f5aae9c11391) for task
b8da8425-1d34-422e-882f-cf16a99db0d5 of framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000 to master@172.17.0.3:42912*15:49:25*
3: I1203 15:49:25.416335 24687 slave.cpp:5660] Task status update manager
successfully handled status update TASK_STARTING (Status UUID:
2fa16dfd-ebab-4ba9-9038-f5aae9c11391) for task
b8da8425-1d34-422e-882f-cf16a99db0d5 of framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000*15:49:25* 3: I1203 15:49:25.416389
24687 slave.cpp:5676] Sending acknowledgement for status update TASK_STARTING
(Status UUID: 2fa16dfd-ebab-4ba9-9038-f5aae9c11391) for task
b8da8425-1d34-422e-882f-cf16a99db0d5 of framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000 to
executor(1)@172.17.0.3:38408*15:49:25* 3: I1203 15:49:25.419250 24687
master.cpp:8420] Status update TASK_STARTING (Status UUID:
2fa16dfd-ebab-4ba9-9038-f5aae9c11391) for task
b8da8425-1d34-422e-882f-cf16a99db0d5 of framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000 from agent
620b2018-c90f-4b11-bbe3-8fa1c90f204d-S0 at slave@172.17.0.3:42912
(5a45e7f918b2)*15:49:25* 3: I1203 15:49:25.419409 24687 master.cpp:8477]
Forwarding status update TASK_STARTING (Status UUID:
2fa16dfd-ebab-4ba9-9038-f5aae9c11391) for task
b8da8425-1d34-422e-882f-cf16a99db0d5 of framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000*15:49:25* 3: I1203 15:49:25.421360
24687 master.cpp:10978] Updating the state of task
b8da8425-1d34-422e-882f-cf16a99db0d5 of framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000 (latest state: TASK_STARTING, status
update state: TASK_STARTING)*15:49:25* 3: I1203 15:49:25.429525 24691
sched.cpp:1022] Scheduler::statusUpdate took 159919ns*15:49:25* 3: I1203
15:49:25.430727 24694 master.cpp:6286] Processing ACKNOWLEDGE call for status
2fa16dfd-ebab-4ba9-9038-f5aae9c11391 for task
b8da8425-1d34-422e-882f-cf16a99db0d5 of framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000 (default) at
scheduler-4c1355d8-785d-4e32-950a-abcd46c3fcb9@172.17.0.3:42912 on agent
620b2018-c90f-4b11-bbe3-8fa1c90f204d-S0*15:49:25* 3: I1203 15:49:25.431102
24690 task_status_update_manager.cpp:401] Received task status update
acknowledgement (UUID: 2fa16dfd-ebab-4ba9-9038-f5aae9c11391) for task
b8da8425-1d34-422e-882f-cf16a99db0d5 of framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000*15:49:25* 3: I1203 15:49:25.431212
24690 task_status_update_manager.cpp:842] Checkpointing ACK for task status
update TASK_STARTING (Status UUID: 2fa16dfd-ebab-4ba9-9038-f5aae9c11391) for
task b8da8425-1d34-422e-882f-cf16a99db0d5 of framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000*15:49:25* 3: I1203 15:49:25.431476
24694 slave.cpp:4511] Task status update manager successfully handled status
update acknowledgement (UUID: 2fa16dfd-ebab-4ba9-9038-f5aae9c11391) for task
b8da8425-1d34-422e-882f-cf16a99db0d5 of framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000*15:49:25* 3: I1203 15:49:25.434000
24688 hierarchical.cpp:1566] Performed allocation for 1 agents in
416183ns*15:49:25* 3: I1203 15:49:25.455533 26373 executor.cpp:502] Running
'/tmp/SRC/build/src/mesos-containerizer launch
<POSSIBLY-SENSITIVE-DATA>'*15:49:25* 3: I1203 15:49:25.471231 26373
executor.cpp:702] Forked command at 26375*15:49:25* 3: I1203 15:49:25.475173
24690 slave.cpp:5275] Handling status update TASK_RUNNING (Status UUID:
4e22aebd-b911-4f93-9180-2d541d4770fb) for task
b8da8425-1d34-422e-882f-cf16a99db0d5 of framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000 from
executor(1)@172.17.0.3:38408*15:49:25* 3: I1203 15:49:25.477550 24694
task_status_update_manager.cpp:328] Received task status update TASK_RUNNING
(Status UUID: 4e22aebd-b911-4f93-9180-2d541d4770fb) for task
b8da8425-1d34-422e-882f-cf16a99db0d5 of framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000*15:49:25* 3: I1203 15:49:25.477624
24694 task_status_update_manager.cpp:842] Checkpointing UPDATE for task status
update TASK_RUNNING (Status UUID: 4e22aebd-b911-4f93-9180-2d541d4770fb) for
task b8da8425-1d34-422e-882f-cf16a99db0d5 of framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000*15:49:25* 3: I1203 15:49:25.477854
24694 task_status_update_manager.cpp:383] Forwarding task status update
TASK_RUNNING (Status UUID: 4e22aebd-b911-4f93-9180-2d541d4770fb) for task
b8da8425-1d34-422e-882f-cf16a99db0d5 of framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000 to the agent*15:49:25* 3: I1203
15:49:25.478164 24694 slave.cpp:5767] Forwarding the update TASK_RUNNING
(Status UUID: 4e22aebd-b911-4f93-9180-2d541d4770fb) for task
b8da8425-1d34-422e-882f-cf16a99db0d5 of framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000 to master@172.17.0.3:42912*15:49:25*
3: I1203 15:49:25.478336 24694 slave.cpp:5660] Task status update manager
successfully handled status update TASK_RUNNING (Status UUID:
4e22aebd-b911-4f93-9180-2d541d4770fb) for task
b8da8425-1d34-422e-882f-cf16a99db0d5 of framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000*15:49:25* 3: I1203 15:49:25.478381
24694 slave.cpp:5676] Sending acknowledgement for status update TASK_RUNNING
(Status UUID: 4e22aebd-b911-4f93-9180-2d541d4770fb) for task
b8da8425-1d34-422e-882f-cf16a99db0d5 of framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000 to
executor(1)@172.17.0.3:38408*15:49:25* 3: I1203 15:49:25.478873 24694
master.cpp:8420] Status update TASK_RUNNING (Status UUID:
4e22aebd-b911-4f93-9180-2d541d4770fb) for task
b8da8425-1d34-422e-882f-cf16a99db0d5 of framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000 from agent
620b2018-c90f-4b11-bbe3-8fa1c90f204d-S0 at slave@172.17.0.3:42912
(5a45e7f918b2)*15:49:25* 3: I1203 15:49:25.478925 24694 master.cpp:8477]
Forwarding status update TASK_RUNNING (Status UUID:
4e22aebd-b911-4f93-9180-2d541d4770fb) for task
b8da8425-1d34-422e-882f-cf16a99db0d5 of framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000*15:49:25* 3: I1203 15:49:25.479156
24694 master.cpp:10978] Updating the state of task
b8da8425-1d34-422e-882f-cf16a99db0d5 of framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000 (latest state: TASK_RUNNING, status
update state: TASK_RUNNING)*15:49:25* 3: I1203 15:49:25.479528 24694
sched.cpp:1022] Scheduler::statusUpdate took 110237ns*15:49:25* 3: I1203
15:49:25.487766 24692 master.cpp:6286] Processing ACKNOWLEDGE call for status
4e22aebd-b911-4f93-9180-2d541d4770fb for task
b8da8425-1d34-422e-882f-cf16a99db0d5 of framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000 (default) at
scheduler-4c1355d8-785d-4e32-950a-abcd46c3fcb9@172.17.0.3:42912 on agent
620b2018-c90f-4b11-bbe3-8fa1c90f204d-S0*15:49:25* 3: I1203 15:49:25.488126
24692 task_status_update_manager.cpp:401] Received task status update
acknowledgement (UUID: 4e22aebd-b911-4f93-9180-2d541d4770fb) for task
b8da8425-1d34-422e-882f-cf16a99db0d5 of framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000*15:49:25* 3: I1203 15:49:25.488226
24692 task_status_update_manager.cpp:842] Checkpointing ACK for task status
update TASK_RUNNING (Status UUID: 4e22aebd-b911-4f93-9180-2d541d4770fb) for
task b8da8425-1d34-422e-882f-cf16a99db0d5 of framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000*15:49:25* 3: I1203 15:49:25.488538
24692 slave.cpp:4511] Task status update manager successfully handled status
update acknowledgement (UUID: 4e22aebd-b911-4f93-9180-2d541d4770fb) for task
b8da8425-1d34-422e-882f-cf16a99db0d5 of framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000*15:49:25* 3: I1203 15:49:25.488876
24686 slave.cpp:915] Agent terminating*15:49:25* 3: I1203 15:49:25.489737 24686
containerizer.cpp:305] Using isolation \{ environment_secret, posix/cpu,
posix/mem, filesystem/posix, network/cni }*15:49:25* 3: I1203 15:49:25.489923
24688 master.cpp:1273] Agent 620b2018-c90f-4b11-bbe3-8fa1c90f204d-S0 at
slave@172.17.0.3:42912 (5a45e7f918b2) disconnected*15:49:25* 3: I1203
15:49:25.489945 24688 master.cpp:3289] Disconnecting agent
620b2018-c90f-4b11-bbe3-8fa1c90f204d-S0 at slave@172.17.0.3:42912
(5a45e7f918b2)*15:49:25* 3: I1203 15:49:25.490010 24688 master.cpp:3308]
Deactivating agent 620b2018-c90f-4b11-bbe3-8fa1c90f204d-S0 at
slave@172.17.0.3:42912 (5a45e7f918b2)*15:49:25* 3: I1203 15:49:25.490219 24688
hierarchical.cpp:801] Agent 620b2018-c90f-4b11-bbe3-8fa1c90f204d-S0
deactivated*15:49:25* 3: W1203 15:49:25.501610 24686 backend.cpp:76] Failed to
create 'aufs' backend: AufsBackend requires root privileges*15:49:25* 3: W1203
15:49:25.501643 24686 backend.cpp:76] Failed to create 'bind' backend:
BindBackend requires root privileges*15:49:25* 3: I1203 15:49:25.501675 24686
provisioner.cpp:298] Using default backend 'copy'*15:49:25* 3: W1203
15:49:25.596071 24686 process.cpp:2829] Attempted to spawn already running
process files@172.17.0.3:42912*15:49:25* 3: I1203 15:49:25.596592 24686
cluster.cpp:485] Creating default 'local' authorizer*15:49:25* 3: I1203
15:49:25.603407 24692 slave.cpp:267] Mesos agent started on
@172.17.0.3:42912*15:49:25* 3: I1203 15:49:25.607524 24692 slave.cpp:268] Flags
at startup: --acls="" --appc_simple_discovery_uri_prefix="http://";
--appc_store_dir="/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_qQs4lL/store/appc"
--authenticate_http_executors="true" --authenticate_http_readonly="true"
--authenticate_http_readwrite="true" --authenticatee="crammd5"
--authentication_backoff_factor="1secs" --authentication_timeout_max="1mins"
--authentication_timeout_min="5secs" --authorizer="local"
--cgroups_cpu_enable_pids_and_tids_count="false"
--cgroups_destroy_timeout="1mins" --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/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_qQs4lL/credential"
--default_role="*" --disallow_sharing_agent_pid_namespace="false"
--disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true"
--docker_registry="
[https://registry-1.docker.io|https://registry-1.docker.io/]
" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock"
--docker_stop_timeout="0ns"
--docker_store_dir="/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_qQs4lL/store/docker"
--docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume"
--enforce_container_disk_quota="false" --executor_registration_timeout="1mins"
--executor_reregistration_timeout="1mins"
--executor_shutdown_grace_period="5secs"
--fetcher_cache_dir="/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_qQs4lL/fetch"
--fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins"
--frameworks_home="/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_qQs4lL/frameworks"
--gc_delay="1weeks" --gc_disk_headroom="0.1"
--gc_non_executor_container_sandboxes="false" --help="false"
--hostname_lookup="true" --http_command_executor="false"
--http_credentials="/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_qQs4lL/http_credentials"
--http_heartbeat_interval="30secs" --initialize_driver_logging="true"
--isolation="posix/cpu,posix/mem"
--jwt_secret_key="/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_qQs4lL/jwt_secret_key"
--launcher="posix" --launcher_dir="/tmp/SRC/build/src" --logbufsecs="0"
--logging_level="INFO" --max_completed_executors_per_framework="150"
--memory_profiling="false" --network_cni_metrics="true"
--oversubscribed_resources_interval="15secs" --perf_duration="10secs"
--perf_interval="1mins" --port="5051" --qos_correction_interval_min="0ns"
--quiet="false" --reconfiguration_policy="equal" --recover="reconnect"
--recovery_timeout="15mins" --registration_backoff_factor="10ms"
--resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]"
--revocable_cpu_low_priority="true"
--runtime_dir="/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_qQs4lL"
--sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true"
--systemd_enable_support="true"
--systemd_runtime_directory="/run/systemd/system" --version="false"
--work_dir="/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_mipvuW"
--zk_session_timeout="10secs"*15:49:25* 3: I1203 15:49:25.613160 24692
credentials.hpp:86] Loading credential for authentication from
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_qQs4lL/credential'*15:49:25*
3: I1203 15:49:25.613397 24692 slave.cpp:300] Agent using credential for:
test-principal*15:49:25* 3: I1203 15:49:25.615334 24692 credentials.hpp:37]
Loading credentials for authentication from
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_qQs4lL/http_credentials'*15:49:25*
3: I1203 15:49:25.615661 24692 http.cpp:1042] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-executor'*15:49:25* 3: I1203
15:49:25.639093 24692 http.cpp:1063] Creating default 'jwt' HTTP authenticator
for realm 'mesos-agent-executor'*15:49:25* 3: I1203 15:49:25.639654 24692
http.cpp:1042] Creating default 'basic' HTTP authenticator for realm
'mesos-agent-readonly'*15:49:25* 3: I1203 15:49:25.639900 24692 http.cpp:1063]
Creating default 'jwt' HTTP authenticator for realm
'mesos-agent-readonly'*15:49:25* 3: I1203 15:49:25.640169 24692 http.cpp:1042]
Creating default 'basic' HTTP authenticator for realm
'mesos-agent-readwrite'*15:49:25* 3: I1203 15:49:25.642000 24692 http.cpp:1063]
Creating default 'jwt' HTTP authenticator for realm
'mesos-agent-readwrite'*15:49:25* 3: I1203 15:49:25.645750 24692
disk_profile_adaptor.cpp:80] Creating default disk profile adaptor
module*15:49:25* 3: I1203 15:49:25.653551 24692 slave.cpp:615] Agent resources:
[\{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},\{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},\{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},\{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]*15:49:25*
3: I1203 15:49:25.657078 24692 slave.cpp:623] Agent attributes: [ ]*15:49:25*
3: I1203 15:49:25.657135 24692 slave.cpp:632] Agent hostname:
5a45e7f918b2*15:49:25* 3: I1203 15:49:25.664916 24689
task_status_update_manager.cpp:181] Pausing sending task status
updates*15:49:25* 3: I1203 15:49:25.666581 24689 state.cpp:66] Recovering state
from '/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_mipvuW/meta'*15:49:25*
3: I1203 15:49:25.666697 24689 state.cpp:711] No committed checkpointed
resources found at
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_mipvuW/meta/resources/resources.info'*15:49:25*
3: I1203 15:49:25.675501 24689 slave.cpp:6915] Finished recovering
checkpointed state from
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_mipvuW/meta', beginning
agent recovery*15:49:25* 3: I1203 15:49:25.675930 24689 slave.cpp:7394]
Recovering framework 620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000*15:49:25* 3:
I1203 15:49:25.676023 24689 slave.cpp:9118] Recovering executor
'b8da8425-1d34-422e-882f-cf16a99db0d5' of framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000*15:49:25* 3: I1203 15:49:25.676928
24689 task_status_update_manager.cpp:207] Recovering task status update
manager*15:49:25* 3: I1203 15:49:25.676956 24689
task_status_update_manager.cpp:215] Recovering executor
'b8da8425-1d34-422e-882f-cf16a99db0d5' of framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000*15:49:25* 3: I1203 15:49:25.685065
24689 task_status_update_manager.cpp:507] Creating StatusUpdate stream for task
b8da8425-1d34-422e-882f-cf16a99db0d5 of framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000*15:49:25* 3: I1203 15:49:25.685727
24689 task_status_update_manager.cpp:818] Replaying task status update stream
for task b8da8425-1d34-422e-882f-cf16a99db0d5*15:49:25* 3: I1203
15:49:25.686558 24690 containerizer.cpp:727] Recovering Mesos
containers*15:49:25* 3: I1203 15:49:25.686655 24690 containerizer.cpp:784]
Recovering container 28e6e1c7-33a4-42a5-86ba-e2c23d9e039b for executor
'b8da8425-1d34-422e-882f-cf16a99db0d5' of framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000*15:49:25* 3: I1203 15:49:25.688118
24690 containerizer.cpp:1053] Recovering isolators*15:49:25* 3: I1203
15:49:25.697508 24690 containerizer.cpp:1092] Recovering provisioner*15:49:25*
3: I1203 15:49:25.698235 24690 provisioner.cpp:494] Provisioner recovery
complete*15:49:25* 3: I1203 15:49:25.718505 24694 composing.cpp:339] Finished
recovering all containerizers*15:49:25* 3: I1203 15:49:25.718710 24691
slave.cpp:7144] Recovering executors*15:49:25* 3: I1203 15:49:25.718868 24691
slave.cpp:7168] Sending reconnect request to executor
'b8da8425-1d34-422e-882f-cf16a99db0d5' of framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000 at
executor(1)@172.17.0.3:38408*15:49:25* 3: I1203 15:49:25.726879 26368
exec.cpp:282] Received reconnect request from agent
620b2018-c90f-4b11-bbe3-8fa1c90f204d-S0*15:49:25* 3: I1203 15:49:25.737377
24693 slave.cpp:4972] Received re-registration message from executor
'b8da8425-1d34-422e-882f-cf16a99db0d5' of framework
620b2018-c90f-4b11-bbe3-8fa1c90f204d-0000*15:49:25* 3: I1203 15:49:25.750452
26366 exec.cpp:259] Executor reregistered on agent
620b2018-c90f-4b11-bbe3-8fa1c90f204d-S0*15:49:25* 3: I1203 15:49:25.762065
26366 executor.cpp:184] Received SUBSCRIBED event*15:49:25* 3: I1203
15:49:25.762097 26366 executor.cpp:188] Subscribed executor on
5a45e7f918b2*15:49:25* 3: I1203 15:49:25.767073 24687 hierarchical.cpp:1566]
Performed allocation for 1 agents in 290619ns*15:49:25* 3: I1203
15:49:25.767477 24687 slave.cpp:5889] No pings from master received within
75secs*15:49:25* 3: F1203 15:49:25.768113 24687 slave.cpp:1233] Check failed:
state == DISCONNECTED || state == RUNNING || state == TERMINATING
RECOVERING*15:49:25* 3: *** Check failure stack trace: ****15:49:25* 3: @
0x7f143daa664f google::LogMessage::Flush()*15:49:25* 3: @
0x7f143daa98ac google::LogMessageFatal::~LogMessageFatal()*15:49:26* 3: @
0x7f1444bbd673 mesos::internal::slave::Slave::detected()*15:49:26* 3: @
0x7f1444ce0b36
_ZZN7process8dispatchIN5mesos8internal5slave5SlaveERKNS_6FutureI6OptionINS1_10MasterInfoEEEESB_EEvRKNS_3PIDIT_EEMSD_FvT0_EOT1_ENKUlOS9_PNS_11ProcessBaseEE_clESM_SO_*15:49:26*
3: @ 0x7f1444ce0897
_ZN5cpp176invokeIZN7process8dispatchIN5mesos8internal5slave5SlaveERKNS1_6FutureI6OptionINS3_10MasterInfoEEEESD_EEvRKNS1_3PIDIT_EEMSF_FvT0_EOT1_EUlOSB_PNS1_11ProcessBaseEE_JSB_SQ_EEEDTclclsr3stdE7forwardISF_Efp_Espclsr3stdE7forwardIT0_Efp0_EEEOSF_DpOSS_*15:49:26*
3: @ 0x7f1444ce0839
_ZN6lambda8internal7PartialIZN7process8dispatchIN5mesos8internal5slave5SlaveERKNS2_6FutureI6OptionINS4_10MasterInfoEEEESE_EEvRKNS2_3PIDIT_EEMSG_FvT0_EOT1_EUlOSC_PNS2_11ProcessBaseEE_JSC_St12_PlaceholderILi1EEEE13invoke_expandISS_St5tupleIJSC_SU_EESX_IJOSR_EEJLm0ELm1EEEEDTclsr5cpp17E6invokeclsr3stdE7forwardISG_Efp_Espcl6expandclsr3stdE3getIXT2_EEclsr3stdE7forwardISK_Efp0_EEclsr3stdE7forwardISN_Efp2_EEEEOSG_OSK_N5cpp1416integer_sequenceImJXspT2_EEEESO_*15:49:26*
3: @ 0x7f1444ce078b
_ZNO6lambda8internal7PartialIZN7process8dispatchIN5mesos8internal5slave5SlaveERKNS2_6FutureI6OptionINS4_10MasterInfoEEEESE_EEvRKNS2_3PIDIT_EEMSG_FvT0_EOT1_EUlOSC_PNS2_11ProcessBaseEE_JSC_St12_PlaceholderILi1EEEEclIJSR_EEEDTcl13invoke_expandclL_ZSt4moveIRSS_EONSt16remove_referenceISG_E4typeEOSG_EdtdefpT1fEclL_ZSX_IRSt5tupleIJSC_SU_EEES12_S13_EdtdefpT10bound_argsEcvN5cpp1416integer_sequenceImJLm0ELm1EEEE_Eclsr3stdE16forward_as_tuplespclsr3stdE7forwardIT_Efp_EEEEDpOS1A_*15:49:26*
3: @ 0x7f1444ce0712
_ZN5cpp176invokeIN6lambda8internal7PartialIZN7process8dispatchIN5mesos8internal5slave5SlaveERKNS4_6FutureI6OptionINS6_10MasterInfoEEEESG_EEvRKNS4_3PIDIT_EEMSI_FvT0_EOT1_EUlOSE_PNS4_11ProcessBaseEE_JSE_St12_PlaceholderILi1EEEEEJST_EEEDTclclsr3stdE7forwardISI_Efp_Espclsr3stdE7forwardIT0_Efp0_EEEOSI_DpOSY_*15:49:26*
3: @ 0x7f1444ce06d6
_ZN6lambda8internal6InvokeIvEclINS0_7PartialIZN7process8dispatchIN5mesos8internal5slave5SlaveERKNS5_6FutureI6OptionINS7_10MasterInfoEEEESH_EEvRKNS5_3PIDIT_EEMSJ_FvT0_EOT1_EUlOSF_PNS5_11ProcessBaseEE_JSF_St12_PlaceholderILi1EEEEEJSU_EEEvOSJ_DpOT0_*15:49:26*
3: @ 0x7f1444ce045a
_ZNO6lambda12CallableOnceIFvPN7process11ProcessBaseEEE10CallableFnINS_8internal7PartialIZNS1_8dispatchIN5mesos8internal5slave5SlaveERKNS1_6FutureI6OptionINSA_10MasterInfoEEEESK_EEvRKNS1_3PIDIT_EEMSM_FvT0_EOT1_EUlOSI_S3_E_JSI_St12_PlaceholderILi1EEEEEEclEOS3_*15:49:26*
3: @ 0x7f143ecb6fbb
_ZNO6lambda12CallableOnceIFvPN7process11ProcessBaseEEEclES3_*15:49:27* 3: @
0x7f143ec7a0b9 process::ProcessBase::consume()*15:49:27* 3: @
0x7f143ed16ca9
_ZNO7process13DispatchEvent7consumeEPNS_13EventConsumerE*15:49:27* 3: @
0xfb0af4 process::ProcessBase::serve()*15:49:27* 3: @
0x7f143ec76c00 process::ProcessManager::resume()*15:49:27* 3: @
0x7f143ec9f97b
process::ProcessManager::init_threads()::$_16::operator()()*15:49:27* 3: @
0x7f143ec9f825
_ZNSt12_Bind_simpleIFZN7process14ProcessManager12init_threadsEvE4$_16vEE9_M_invokeIJEEEvSt12_Index_tupleIJXspT_EEE*15:49:27*
3: @ 0x7f143ec9f7f5 std::_Bind_simple<>::operator()()*15:49:27* 3:
@ 0x7f143ec9f6e9 std::thread::_Impl<>::_M_run()*15:49:27* 3: @
0x7f143855dc80 (unknown)*15:49:27* 3: @ 0x7f143d6146ba
start_thread*15:49:27* 3: @ 0x7f1437cc341d (unknown)*15:49:27* 3:
I1203 15:49:27.302824 26369 exec.cpp:518] Agent exited, but framework has
checkpointing enabled. Waiting 15mins to reconnect with agent
620b2018-c90f-4b11-bbe3-8fa1c90f204d-S0*16:04:27* 3: I1203 16:04:27.305567
26366 exec.cpp:499] Recovery timeout of 15mins exceeded; Shutting
down*16:04:27* 3: I1203 16:04:27.305616 26366 exec.cpp:445] Executor asked to
shutdown*16:04:27* 3: I1203 16:04:27.306048 26366 executor.cpp:184] Received
SHUTDOWN event*16:04:27* 3: I1203 16:04:27.306074 26366 executor.cpp:805]
Shutting down*16:04:27* 3: I1203 16:04:27.306113 26366 executor.cpp:918]
Sending SIGTERM to process tree at pid 26375*16:04:27* 3: I1203 16:04:27.310303
26366 executor.cpp:931] Sent SIGTERM to the following process trees:*16:04:27*
3: [ *16:04:27* 3: -+- 26375 sh -c sleep 1000 *16:04:27* 3: \--- 26377 sleep
1000 *16:04:27* 3: ]*16:04:27* 3: I1203 16:04:27.310338 26366 executor.cpp:935]
Scheduling escalation to SIGKILL in 3secs from now*16:04:27* 3: I1203
16:04:27.358798 26370 executor.cpp:1003] Command terminated with signal
Terminated (pid: 26375)*16:04:27* 3: W1203 16:04:27.360321 26374
process.cpp:1890] Failed to send 'mesos.internal.StatusUpdateMessage' to
'172.17.0.3:42912', connect: Failed to connect to 172.17.0.3:42912: Connection
refused*16:04:28* 3: I1203 16:04:28.388398 26374 process.cpp:927] Stopped the
socket accept loop*16:04:28* 3/3 Test #3: MesosTests
.......................***Exception: Other1186.70 sec
{code}
> SlaveRecoveryTest/0.PingTimeoutDuringRecovery flaky
> ---------------------------------------------------
>
> Key: MESOS-8983
> URL: https://issues.apache.org/jira/browse/MESOS-8983
> Project: Mesos
> Issue Type: Task
> Affects Versions: 1.7.0, 1.8.0
> Reporter: Alexander Rojas
> Priority: Major
>
> During an unrelated change in a PR, the apache build bot sent the following
> error:
> {noformat}
> @ 00007FF71117D888
> std::invoke<<lambda_9f5bb6c728b761604e288ae85a7b250c>,process::Future<Option<mesos::MasterInfo>
> >,process::ProcessBase *>
> @ 00007FF71119257B
> lambda::internal::Partial<<lambda_9f5bb6c728b761604e288ae85a7b250c>,process::Future<Option<mesos::MasterInfo>
> >,std::_Ph<1>
> >::invoke_expand<<lambda_9f5bb6c728b761604e288ae85a7b250c>,std::tuple<process::Future<Option<mesos::MasterInfo>
> >,std::_Ph<1> >,st
> @ 00007FF7110C08BA )<process::ProcessBase *
> @ 00007FF7110F058C
> std::_Invoker_functor::_Call<lambda::internal::Partial<<lambda_9f5bb6c728b761604e288ae85a7b250c>,process::Future<Option<mesos::MasterInfo>
> >,std::_Ph<1> >,process::ProcessBase *>
> @ 00007FF711183EBC
> std::invoke<lambda::internal::Partial<<lambda_9f5bb6c728b761604e288ae85a7b250c>,process::Future<Option<mesos::MasterInfo>
> >,std::_Ph<1> >,process::ProcessBase *>
> @ 00007FF7110C9F21
> )<lambda::internal::Partial<<lambda_9f5bb6c728b761604e288ae85a7b250c>,process::Future<Option<mesos::MasterInfo>
> >,std::_Ph<1> >,process::ProcessBase *
> @ 00007FF711236416 process::ProcessBase
> *)>::CallableFn<lambda::internal::Partial<<lambda_9f5bb6c728b761604e288ae85a7b250c>,process::Future<Option<mesos::MasterInfo>
> >,std::_Ph<1> > >::operator(
> @ 00007FF712C1A25D process::ProcessBase *)>::operator(
> @ 00007FF712ACB2F9 process::ProcessBase::consume
> @ 00007FF712C738CA process::DispatchEvent::consume
> @ 00007FF70ECE7B07 process::ProcessBase::serve
> @ 00007FF712AD93B0 process::ProcessManager::resume
> @ 00007FF712C07371 ??
> @ 00007FF712B2B130
> std::_Invoker_functor::_Call<<lambda_124422ac022fa041208b80c1460630d7> >
> @ 00007FF712B8B8E0
> std::invoke<<lambda_124422ac022fa041208b80c1460630d7> >
> @ 00007FF712B4076C
> std::_LaunchPad<std::unique_ptr<std::tuple<<lambda_124422ac022fa041208b80c1460630d7>
> >,std::default_delete<std::tuple<<lambda_124422ac022fa041208b80c1460630d7> >
> > > >::_Execute<0>
> @ 00007FF712C5A60A
> std::_LaunchPad<std::unique_ptr<std::tuple<<lambda_124422ac022fa041208b80c1460630d7>
> >,std::default_delete<std::tuple<<lambda_124422ac022fa041208b80c1460630d7> >
> > > >::_Run
> @ 00007FF712C45E78
> std::_LaunchPad<std::unique_ptr<std::tuple<<lambda_124422ac022fa041208b80c1460630d7>
> >,std::default_delete<std::tuple<<lambda_124422ac022fa041208b80c1460630d7> >
> > > >::_Go
> @ 00007FF712C2C3CD std::_Pad::_Call_func
> @ 00007FFF9BE53428 _register_onexit_function
> @ 00007FFF9BE53071 _register_onexit_function
> @ 00007FFFB6391FE4 BaseThreadInitThunk
> @ 00007FFFB69FF061 RtlUserThreadStart
> ll containerizers
> I0606 10:25:26.680230 18356 slave.cpp:7158] Recovering executors
> I0606 10:25:26.680230 18356 slave.cpp:7182] Sending reconnect request to
> executor '3f11d255-bb7b-4e99-967b-055fef95b595' of framework
> 62cf792a-dc69-4e3c-b54f-d83f98fb9451-0000 at executor(1)@192.10.1.5:55652
> I0606 10:25:26.688225 22560 slave.cpp:4984] Received re-registration message
> from executor '3f11d255-bb7b-4e99-967b-055fef95b595' of framework
> 62cf792a-dc69-4e3c-b54f-d83f98fb9451-0000
> I0606 10:25:26.691216 22888 slave.cpp:5901] No pings from master received
> within 75secs
> F0606 10:25:26.692219 22888 slave.cpp:1249] Check failed: state ==
> DISCONNECTED || state == RUNNING || state == TERMINATING RECOVERING
> {noformat}
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
