[
https://issues.apache.org/jira/browse/MESOS-8983?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16918041#comment-16918041
]
Vinod Kone commented on MESOS-8983:
-----------------------------------
Seen this again when testing 1.9.0-RC2.
{code}
13:32:33 3: [ RUN ] SlaveRecoveryTest/0.PingTimeoutDuringRecovery
13:32:33 3: I0828 18:32:33.580678 20801 cluster.cpp:177] Creating default
'local' authorizer
13:32:33 3: I0828 18:32:33.587858 20824 master.cpp:440] Master
3de64da7-619c-4652-9d33-3fe2ca2a3d5f (b766865f9da3) started on 172.17.0.2:42011
13:32:33 3: I0828 18:32:33.587904 20824 master.cpp:443] 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/sIRhDp/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_operator_event_stream_subscribers="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/sIRhDp/master" --zk_session_timeout="10secs"
13:32:33 3: I0828 18:32:33.588558 20824 master.cpp:492] Master only allowing
authenticated frameworks to register
13:32:33 3: I0828 18:32:33.588574 20824 master.cpp:498] Master only allowing
authenticated agents to register
13:32:33 3: I0828 18:32:33.588587 20824 master.cpp:504] Master only allowing
authenticated HTTP frameworks to register
13:32:33 3: I0828 18:32:33.588599 20824 credentials.hpp:37] Loading credentials
for authentication from '/tmp/sIRhDp/credentials'
13:32:33 3: I0828 18:32:33.588999 20824 master.cpp:548] Using default 'crammd5'
authenticator
13:32:33 3: I0828 18:32:33.589262 20824 http.cpp:975] Creating default 'basic'
HTTP authenticator for realm 'mesos-master-readonly'
13:32:33 3: I0828 18:32:33.589529 20824 http.cpp:975] Creating default 'basic'
HTTP authenticator for realm 'mesos-master-readwrite'
13:32:33 3: I0828 18:32:33.589697 20824 http.cpp:975] Creating default 'basic'
HTTP authenticator for realm 'mesos-master-scheduler'
13:32:33 3: I0828 18:32:33.589866 20824 master.cpp:629] Authorization enabled
13:32:33 3: I0828 18:32:33.590817 20823 whitelist_watcher.cpp:77] No whitelist
given
13:32:33 3: I0828 18:32:33.594827 20816 master.cpp:2170] Elected as the leading
master!
13:32:33 3: I0828 18:32:33.594887 20816 master.cpp:1666] Recovering from
registrar
13:32:33 3: I0828 18:32:33.595124 20808 hierarchical.cpp:474] Initialized
hierarchical allocator process
13:32:33 3: I0828 18:32:33.595382 20808 registrar.cpp:339] Recovering registrar
13:32:33 3: I0828 18:32:33.596575 20808 registrar.cpp:383] Successfully fetched
the registry (0B) in 1.14688ms
13:32:33 3: I0828 18:32:33.596779 20808 registrar.cpp:487] Applied 1 operations
in 63194ns; attempting to update the registry
13:32:33 3: I0828 18:32:33.597638 20819 registrar.cpp:544] Successfully updated
the registry in 788224ns
13:32:33 3: I0828 18:32:33.597805 20819 registrar.cpp:416] Successfully
recovered registrar
13:32:33 3: I0828 18:32:33.598423 20819 master.cpp:1819] Recovered 0 agents
from the registry (144B); allowing 10mins for agents to reregister
13:32:33 3: I0828 18:32:33.598599 20813 hierarchical.cpp:513] Skipping recovery
of hierarchical allocator: nothing to recover
13:32:33 3: I0828 18:32:33.614511 20801 containerizer.cpp:318] Using isolation
{ environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni }
13:32:33 3: W0828 18:32:33.615756 20801 backend.cpp:76] Failed to create
'overlay' backend: OverlayBackend requires root privileges
13:32:33 3: W0828 18:32:33.615855 20801 backend.cpp:76] Failed to create 'aufs'
backend: AufsBackend requires root privileges
13:32:33 3: W0828 18:32:33.615934 20801 backend.cpp:76] Failed to create 'bind'
backend: BindBackend requires root privileges
13:32:33 3: I0828 18:32:33.616178 20801 provisioner.cpp:300] Using default
backend 'copy'
13:32:33 3: W0828 18:32:33.626040 20801 process.cpp:2877] Attempted to spawn
already running process files@172.17.0.2:42011
13:32:33 3: I0828 18:32:33.628049 20801 cluster.cpp:518] Creating default
'local' authorizer
13:32:33 3: I0828 18:32:33.632318 20823 slave.cpp:267] Mesos agent started on
@172.17.0.2:42011
13:32:33 3: I0828 18:32:33.632380 20823 slave.cpp:268] Flags at startup:
--acls="" --appc_simple_discovery_uri_prefix="http://";
--appc_store_dir="/tmp/sIRhDp/Cdd6uy/store/appc"
--authenticate_http_readonly="true" --authenticate_http_readwrite="false"
--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/sIRhDp/Cdd6uy/credential"
--default_role="*" --disallow_sharing_agent_ipc_namespace="false"
--disallow_sharing_agent_pid_namespace="false" --disk_watch_interval="1mins"
--docker="docker" --docker_ignore_runtime="false" --docker_kill_orphans="true"
--docker_registry="https://registry-1.docker.io"; --docker_remove_delay="6hrs"
--docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns"
--docker_store_dir="/tmp/sIRhDp/Cdd6uy/store/docker"
--docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume"
--docker_volume_chown="false" --enforce_container_disk_quota="false"
--executor_registration_timeout="1mins"
--executor_reregistration_timeout="1mins"
--executor_shutdown_grace_period="5secs"
--fetcher_cache_dir="/tmp/sIRhDp/Cdd6uy/fetch" --fetcher_cache_size="2GB"
--fetcher_stall_timeout="1mins"
--frameworks_home="/tmp/sIRhDp/Cdd6uy/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/sIRhDp/Cdd6uy/http_credentials"
--http_heartbeat_interval="30secs" --initialize_driver_logging="true"
--isolation="posix/cpu,posix/mem" --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" --network_cni_root_dir_persist="false"
--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_Va3Nxv"
--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_QsMwAs"
--zk_session_timeout="10secs"
13:32:33 3: I0828 18:32:33.633353 20823 credentials.hpp:86] Loading credential
for authentication from '/tmp/sIRhDp/Cdd6uy/credential'
13:32:33 3: W0828 18:32:33.633366 20801 process.cpp:2877] Attempted to spawn
already running process version@172.17.0.2:42011
13:32:33 3: I0828 18:32:33.633718 20823 slave.cpp:300] Agent using credential
for: test-principal
13:32:33 3: I0828 18:32:33.633744 20823 credentials.hpp:37] Loading credentials
for authentication from '/tmp/sIRhDp/Cdd6uy/http_credentials'
13:32:33 3: I0828 18:32:33.634088 20823 http.cpp:975] Creating default 'basic'
HTTP authenticator for realm 'mesos-agent-readonly'
13:32:33 3: I0828 18:32:33.634706 20823 disk_profile_adaptor.cpp:78] Creating
default disk profile adaptor module
13:32:33 3: I0828 18:32:33.636852 20823 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"}]
13:32:33 3: I0828 18:32:33.637275 20823 slave.cpp:623] Agent attributes: [ ]
13:32:33 3: I0828 18:32:33.637341 20823 slave.cpp:632] Agent hostname:
b766865f9da3
13:32:33 3: I0828 18:32:33.638134 20801 sched.cpp:239] Version: 1.10.0
13:32:33 3: I0828 18:32:33.638346 20810 task_status_update_manager.cpp:181]
Pausing sending task status updates
13:32:33 3: I0828 18:32:33.638454 20810 status_update_manager_process.hpp:379]
Pausing operation status update manager
13:32:33 3: I0828 18:32:33.639616 20806 sched.cpp:343] New master detected at
master@172.17.0.2:42011
13:32:33 3: I0828 18:32:33.639814 20806 sched.cpp:408] Authenticating with
master master@172.17.0.2:42011
13:32:33 3: I0828 18:32:33.639833 20806 sched.cpp:415] Using default CRAM-MD5
authenticatee
13:32:33 3: I0828 18:32:33.640564 20806 authenticatee.cpp:121] Creating new
client SASL connection
13:32:33 3: I0828 18:32:33.640940 20806 state.cpp:67] Recovering state from
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_QsMwAs/meta'
13:32:33 3: I0828 18:32:33.641163 20819 master.cpp:10617] Authenticating
scheduler-963d7ebc-7ef5-4a23-8e9c-5f9e58528f67@172.17.0.2:42011
13:32:33 3: I0828 18:32:33.641198 20818 slave.cpp:7491] Finished recovering
checkpointed state from
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_QsMwAs/meta', beginning
agent recovery
13:32:33 3: I0828 18:32:33.642060 20811 authenticator.cpp:414] Starting
authentication session for crammd5-authenticatee(593)@172.17.0.2:42011
13:32:33 3: I0828 18:32:33.642184 20818 task_status_update_manager.cpp:207]
Recovering task status update manager
13:32:33 3: I0828 18:32:33.642686 20811 authenticator.cpp:98] Creating new
server SASL connection
13:32:33 3: I0828 18:32:33.643050 20811 containerizer.cpp:821] Recovering Mesos
containers
13:32:33 3: I0828 18:32:33.643180 20818 authenticatee.cpp:213] Received SASL
authentication mechanisms: CRAM-MD5
13:32:33 3: I0828 18:32:33.643216 20818 authenticatee.cpp:239] Attempting to
authenticate with mechanism 'CRAM-MD5'
13:32:33 3: I0828 18:32:33.643419 20818 authenticator.cpp:204] Received SASL
authentication start
13:32:33 3: I0828 18:32:33.643483 20811 containerizer.cpp:1161] Recovering
isolators
13:32:33 3: I0828 18:32:33.643524 20818 authenticator.cpp:326] Authentication
requires more steps
13:32:33 3: I0828 18:32:33.643796 20820 authenticatee.cpp:259] Received SASL
authentication step
13:32:33 3: I0828 18:32:33.643991 20810 authenticator.cpp:232] Received SASL
authentication step
13:32:33 3: I0828 18:32:33.644129 20810 auxprop.cpp:109] Request to lookup
properties for user: 'test-principal' realm: 'b766865f9da3' server FQDN:
'b766865f9da3' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE:
false SASL_AUXPROP_AUTHZID: false
13:32:33 3: I0828 18:32:33.644152 20810 auxprop.cpp:181] Looking up auxiliary
property '*userPassword'
13:32:33 3: I0828 18:32:33.644228 20810 auxprop.cpp:181] Looking up auxiliary
property '*cmusaslsecretCRAM-MD5'
13:32:33 3: I0828 18:32:33.644268 20810 auxprop.cpp:109] Request to lookup
properties for user: 'test-principal' realm: 'b766865f9da3' server FQDN:
'b766865f9da3' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE:
false SASL_AUXPROP_AUTHZID: true
13:32:33 3: I0828 18:32:33.644285 20810 auxprop.cpp:131] Skipping auxiliary
property '*userPassword' since SASL_AUXPROP_AUTHZID == true
13:32:33 3: I0828 18:32:33.644297 20810 auxprop.cpp:131] Skipping auxiliary
property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
13:32:33 3: I0828 18:32:33.644320 20810 authenticator.cpp:318] Authentication
success
13:32:33 3: I0828 18:32:33.644472 20804 authenticatee.cpp:299] Authentication
success
13:32:33 3: I0828 18:32:33.644709 20810 master.cpp:10649] Successfully
authenticated principal 'test-principal' at
scheduler-963d7ebc-7ef5-4a23-8e9c-5f9e58528f67@172.17.0.2:42011
13:32:33 3: I0828 18:32:33.644847 20804 containerizer.cpp:1200] Recovering
provisioner
13:32:33 3: I0828 18:32:33.645210 20813 sched.cpp:520] Successfully
authenticated with master master@172.17.0.2:42011
13:32:33 3: I0828 18:32:33.645241 20813 sched.cpp:835] Sending SUBSCRIBE call
to master@172.17.0.2:42011
13:32:33 3: I0828 18:32:33.645488 20813 sched.cpp:870] Will retry registration
in 989.436808ms if necessary
13:32:33 3: I0828 18:32:33.645747 20818 master.cpp:2910] Received SUBSCRIBE
call for framework 'default' at
scheduler-963d7ebc-7ef5-4a23-8e9c-5f9e58528f67@172.17.0.2:42011
13:32:33 3: I0828 18:32:33.645789 20818 master.cpp:2242] Authorizing framework
principal 'test-principal' to receive offers for roles '{ * }'
13:32:33 3: I0828 18:32:33.645834 20813 provisioner.cpp:500] Provisioner
recovery complete
13:32:33 3: I0828 18:32:33.647011 20804 master.cpp:2997] Subscribing framework
default with checkpointing enabled and capabilities [ MULTI_ROLE,
RESERVATION_REFINEMENT ]
13:32:33 3: I0828 18:32:33.647253 20818 composing.cpp:339] Finished recovering
all containerizers
13:32:33 3: I0828 18:32:33.647601 20809 slave.cpp:7972] Recovering executors
13:32:33 3: I0828 18:32:33.647738 20809 slave.cpp:8125] Finished recovery
13:32:33 3: I0828 18:32:33.649415 20818 task_status_update_manager.cpp:181]
Pausing sending task status updates
13:32:33 3: I0828 18:32:33.649453 20820 status_update_manager_process.hpp:379]
Pausing operation status update manager
13:32:33 3: I0828 18:32:33.649520 20809 slave.cpp:1351] New master detected at
master@172.17.0.2:42011
13:32:33 3: I0828 18:32:33.649801 20809 slave.cpp:1416] Detecting new master
13:32:33 3: I0828 18:32:33.649876 20811 authenticator.cpp:432] Authentication
session cleanup for crammd5-authenticatee(593)@172.17.0.2:42011
13:32:33 3: I0828 18:32:33.655400 20804 master.cpp:10847] Adding framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000 (default) at
scheduler-963d7ebc-7ef5-4a23-8e9c-5f9e58528f67@172.17.0.2:42011 with roles { }
suppressed
13:32:33 3: I0828 18:32:33.658586 20804 sched.cpp:751] Framework registered
with 3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000
13:32:33 3: I0828 18:32:33.658758 20804 sched.cpp:770] Scheduler::registered
took 37674ns
13:32:33 3: I0828 18:32:33.659413 20820 hierarchical.cpp:605] Added framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000
13:32:33 3: I0828 18:32:33.659899 20820 hierarchical.cpp:1724] Performed
allocation for 0 agents in 205698ns
13:32:33 3: I0828 18:32:33.663064 20815 slave.cpp:1443] Authenticating with
master master@172.17.0.2:42011
13:32:33 3: I0828 18:32:33.663345 20815 slave.cpp:1452] Using default CRAM-MD5
authenticatee
13:32:33 3: I0828 18:32:33.664279 20815 authenticatee.cpp:121] Creating new
client SASL connection
13:32:33 3: I0828 18:32:33.664853 20813 master.cpp:10617] Authenticating
slave@172.17.0.2:42011
13:32:33 3: I0828 18:32:33.665170 20813 authenticator.cpp:414] Starting
authentication session for crammd5-authenticatee(594)@172.17.0.2:42011
13:32:33 3: I0828 18:32:33.665807 20813 authenticator.cpp:98] Creating new
server SASL connection
13:32:33 3: I0828 18:32:33.666249 20813 authenticatee.cpp:213] Received SASL
authentication mechanisms: CRAM-MD5
13:32:33 3: I0828 18:32:33.666281 20813 authenticatee.cpp:239] Attempting to
authenticate with mechanism 'CRAM-MD5'
13:32:33 3: I0828 18:32:33.666425 20813 authenticator.cpp:204] Received SASL
authentication start
13:32:33 3: I0828 18:32:33.666508 20813 authenticator.cpp:326] Authentication
requires more steps
13:32:33 3: I0828 18:32:33.666656 20825 authenticatee.cpp:259] Received SASL
authentication step
13:32:33 3: I0828 18:32:33.666833 20825 authenticator.cpp:232] Received SASL
authentication step
13:32:33 3: I0828 18:32:33.666919 20825 auxprop.cpp:109] Request to lookup
properties for user: 'test-principal' realm: 'b766865f9da3' server FQDN:
'b766865f9da3' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE:
false SASL_AUXPROP_AUTHZID: false
13:32:33 3: I0828 18:32:33.666949 20825 auxprop.cpp:181] Looking up auxiliary
property '*userPassword'
13:32:33 3: I0828 18:32:33.667029 20825 auxprop.cpp:181] Looking up auxiliary
property '*cmusaslsecretCRAM-MD5'
13:32:33 3: I0828 18:32:33.667073 20825 auxprop.cpp:109] Request to lookup
properties for user: 'test-principal' realm: 'b766865f9da3' server FQDN:
'b766865f9da3' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE:
false SASL_AUXPROP_AUTHZID: true
13:32:33 3: I0828 18:32:33.667089 20825 auxprop.cpp:131] Skipping auxiliary
property '*userPassword' since SASL_AUXPROP_AUTHZID == true
13:32:33 3: I0828 18:32:33.667102 20825 auxprop.cpp:131] Skipping auxiliary
property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
13:32:33 3: I0828 18:32:33.667122 20825 authenticator.cpp:318] Authentication
success
13:32:33 3: I0828 18:32:33.667440 20825 authenticatee.cpp:299] Authentication
success
13:32:33 3: I0828 18:32:33.667814 20825 master.cpp:10649] Successfully
authenticated principal 'test-principal' at slave@172.17.0.2:42011
13:32:33 3: I0828 18:32:33.667980 20825 authenticator.cpp:432] Authentication
session cleanup for crammd5-authenticatee(594)@172.17.0.2:42011
13:32:33 3: I0828 18:32:33.668539 20825 slave.cpp:1543] Successfully
authenticated with master master@172.17.0.2:42011
13:32:33 3: I0828 18:32:33.669265 20825 slave.cpp:1993] Will retry registration
in 18.453705ms if necessary
13:32:33 3: I0828 18:32:33.669775 20822 master.cpp:7088] Received register
agent message from slave@172.17.0.2:42011 (b766865f9da3)
13:32:33 3: I0828 18:32:33.670429 20822 master.cpp:4204] Authorizing agent
providing resources 'cpus:2; mem:1024; disk:1024; ports:[31000-32000]' with
principal 'test-principal'
13:32:33 3: I0828 18:32:33.671587 20820 master.cpp:7155] Authorized
registration of agent at slave@172.17.0.2:42011 (b766865f9da3)
13:32:33 3: I0828 18:32:33.671730 20820 master.cpp:7267] Registering agent at
slave@172.17.0.2:42011 (b766865f9da3) with id
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-S0
13:32:33 3: I0828 18:32:33.672840 20820 registrar.cpp:487] Applied 1 operations
in 451223ns; attempting to update the registry
13:32:33 3: I0828 18:32:33.673902 20820 registrar.cpp:544] Successfully updated
the registry in 954112ns
13:32:33 3: I0828 18:32:33.674212 20820 master.cpp:7315] Admitted agent
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-S0 at slave@172.17.0.2:42011 (b766865f9da3)
13:32:33 3: I0828 18:32:33.675454 20820 master.cpp:7360] Registered agent
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-S0 at slave@172.17.0.2:42011
(b766865f9da3) with cpus:2; mem:1024; disk:1024; ports:[31000-32000]
13:32:33 3: I0828 18:32:33.676136 20820 hierarchical.cpp:854] Added agent
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-S0 (b766865f9da3) with cpus:2; mem:1024;
disk:1024; ports:[31000-32000] (allocated: {})
13:32:33 3: I0828 18:32:33.677968 20820 hierarchical.cpp:1724] Performed
allocation for 1 agents in 1.581327ms
13:32:33 3: I0828 18:32:33.678031 20819 slave.cpp:1576] Registered with master
master@172.17.0.2:42011; given agent ID 3de64da7-619c-4652-9d33-3fe2ca2a3d5f-S0
13:32:33 3: I0828 18:32:33.678885 20819 slave.cpp:1611] Checkpointing SlaveInfo
to
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_QsMwAs/meta/slaves/3de64da7-619c-4652-9d33-3fe2ca2a3d5f-S0/slave.info'
13:32:33 3: I0828 18:32:33.678905 20804 task_status_update_manager.cpp:188]
Resuming sending task status updates
13:32:33 3: I0828 18:32:33.679065 20823 status_update_manager_process.hpp:385]
Resuming operation status update manager
13:32:33 3: I0828 18:32:33.679260 20820 master.cpp:10432] Sending offers [
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-O0 ] to framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000 (default) at
scheduler-963d7ebc-7ef5-4a23-8e9c-5f9e58528f67@172.17.0.2:42011
13:32:33 3: I0828 18:32:33.680179 20816 sched.cpp:934]
Scheduler::resourceOffers took 127677ns
13:32:33 3: I0828 18:32:33.680932 20819 slave.cpp:1663] Forwarding agent update
{"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"+D7D09JzQgWugVrmbS8xdA=="},"slave_id":{"value":"3de64da7-619c-4652-9d33-3fe2ca2a3d5f-S0"},"update_oversubscribed_resources":false}
13:32:33 3: I0828 18:32:33.682183 20820 master.cpp:8487] Ignoring update on
agent 3de64da7-619c-4652-9d33-3fe2ca2a3d5f-S0 at slave@172.17.0.2:42011
(b766865f9da3) as it reports no changes
13:32:33 3: I0828 18:32:33.685616 20824 master.cpp:12724] Removing offer
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-O0
13:32:33 3: I0828 18:32:33.686409 20824 master.cpp:4741] Processing ACCEPT call
for offers: [ 3de64da7-619c-4652-9d33-3fe2ca2a3d5f-O0 ] on agent
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-S0 at slave@172.17.0.2:42011
(b766865f9da3) for framework 3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000
(default) at scheduler-963d7ebc-7ef5-4a23-8e9c-5f9e58528f67@172.17.0.2:42011
13:32:33 3: I0828 18:32:33.686590 20824 master.cpp:3758] Authorizing framework
principal 'test-principal' to launch task 1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6
13:32:33 3: I0828 18:32:33.691210 20823 master.cpp:4302] Adding task
1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6 with resources ports(allocated:
*):[31000-32000]; cpus(allocated: *):2; mem(allocated: *):1024; disk(allocated:
*):1024 of framework 3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000 (default) at
scheduler-963d7ebc-7ef5-4a23-8e9c-5f9e58528f67@172.17.0.2:42011 on agent
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-S0 at slave@172.17.0.2:42011 (b766865f9da3)
13:32:33 3: I0828 18:32:33.692509 20823 master.cpp:5720] Launching task
1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6 of framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000 (default) at
scheduler-963d7ebc-7ef5-4a23-8e9c-5f9e58528f67@172.17.0.2:42011 with resources
[{"allocation_info":{"role":"*"},"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"},{"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"}]
on agent 3de64da7-619c-4652-9d33-3fe2ca2a3d5f-S0 at slave@172.17.0.2:42011
(b766865f9da3) on new executor
13:32:33 3: I0828 18:32:33.694851 20825 hierarchical.cpp:1648] Allocation paused
13:32:33 3: I0828 18:32:33.694914 20825 hierarchical.cpp:1658] Allocation
resumed
13:32:33 3: I0828 18:32:33.695554 20823 slave.cpp:2130] Got assigned task
'1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6' for framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000
13:32:33 3: I0828 18:32:33.695917 20823 slave.cpp:9916] Checkpointing
FrameworkInfo to
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_QsMwAs/meta/slaves/3de64da7-619c-4652-9d33-3fe2ca2a3d5f-S0/frameworks/3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000/framework.info'
13:32:33 3: I0828 18:32:33.696831 20823 slave.cpp:9927] Checkpointing framework
pid 'scheduler-963d7ebc-7ef5-4a23-8e9c-5f9e58528f67@172.17.0.2:42011' to
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_QsMwAs/meta/slaves/3de64da7-619c-4652-9d33-3fe2ca2a3d5f-S0/frameworks/3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000/framework.pid'
13:32:33 3: I0828 18:32:33.704190 20823 slave.cpp:2504] Authorizing task
'1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6' for framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000
13:32:33 3: I0828 18:32:33.704349 20823 slave.cpp:9464] Authorizing framework
principal 'test-principal' to launch task 1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6
13:32:33 3: I0828 18:32:33.709846 20823 slave.cpp:2977] Launching task
'1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6' for framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000
13:32:33 3: I0828 18:32:33.710022 20823 paths.cpp:817] Creating sandbox
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_QsMwAs/slaves/3de64da7-619c-4652-9d33-3fe2ca2a3d5f-S0/frameworks/3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000/executors/1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6/runs/12ac0ef5-82bc-4c8e-912c-44343aaf10ab'
for user 'mesos'
13:32:33 3: I0828 18:32:33.711552 20823 slave.cpp:10714] Checkpointing
ExecutorInfo to
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_QsMwAs/meta/slaves/3de64da7-619c-4652-9d33-3fe2ca2a3d5f-S0/frameworks/3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000/executors/1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6/executor.info'
13:32:33 3: I0828 18:32:33.712919 20823 paths.cpp:820] Creating sandbox
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_QsMwAs/meta/slaves/3de64da7-619c-4652-9d33-3fe2ca2a3d5f-S0/frameworks/3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000/executors/1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6/runs/12ac0ef5-82bc-4c8e-912c-44343aaf10ab'
13:32:33 3: I0828 18:32:33.713439 20823 slave.cpp:10002] Launching executor
'1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6' of framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-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_QsMwAs/slaves/3de64da7-619c-4652-9d33-3fe2ca2a3d5f-S0/frameworks/3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000/executors/1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6/runs/12ac0ef5-82bc-4c8e-912c-44343aaf10ab'
13:32:33 3: I0828 18:32:33.715871 20823 slave.cpp:10745] Checkpointing TaskInfo
to
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_QsMwAs/meta/slaves/3de64da7-619c-4652-9d33-3fe2ca2a3d5f-S0/frameworks/3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000/executors/1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6/runs/12ac0ef5-82bc-4c8e-912c-44343aaf10ab/tasks/1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6/task.info'
13:32:33 3: I0828 18:32:33.717613 20823 slave.cpp:3209] Queued task
'1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6' for executor
'1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6' of framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000
13:32:33 3: I0828 18:32:33.717806 20823 slave.cpp:1084] Successfully attached
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_QsMwAs/slaves/3de64da7-619c-4652-9d33-3fe2ca2a3d5f-S0/frameworks/3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000/executors/1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6/runs/12ac0ef5-82bc-4c8e-912c-44343aaf10ab'
to virtual path
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_QsMwAs/slaves/3de64da7-619c-4652-9d33-3fe2ca2a3d5f-S0/frameworks/3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000/executors/1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6/runs/latest'
13:32:33 3: I0828 18:32:33.718402 20823 slave.cpp:1084] Successfully attached
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_QsMwAs/slaves/3de64da7-619c-4652-9d33-3fe2ca2a3d5f-S0/frameworks/3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000/executors/1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6/runs/12ac0ef5-82bc-4c8e-912c-44343aaf10ab'
to virtual path
'/frameworks/3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000/executors/1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6/runs/latest'
13:32:33 3: I0828 18:32:33.718467 20823 slave.cpp:1084] Successfully attached
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_QsMwAs/slaves/3de64da7-619c-4652-9d33-3fe2ca2a3d5f-S0/frameworks/3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000/executors/1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6/runs/12ac0ef5-82bc-4c8e-912c-44343aaf10ab'
to virtual path
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_QsMwAs/slaves/3de64da7-619c-4652-9d33-3fe2ca2a3d5f-S0/frameworks/3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000/executors/1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6/runs/12ac0ef5-82bc-4c8e-912c-44343aaf10ab'
13:32:33 3: I0828 18:32:33.719085 20823 slave.cpp:3657] Launching container
12ac0ef5-82bc-4c8e-912c-44343aaf10ab for executor
'1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6' of framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000
13:32:33 3: I0828 18:32:33.720368 20823 containerizer.cpp:1396] Starting
container 12ac0ef5-82bc-4c8e-912c-44343aaf10ab
13:32:33 3: I0828 18:32:33.721280 20823 containerizer.cpp:3323] Transitioning
the state of container 12ac0ef5-82bc-4c8e-912c-44343aaf10ab from STARTING to
PROVISIONING after 587008ns
13:32:33 3: I0828 18:32:33.724167 20823 containerizer.cpp:1574] Checkpointed
ContainerConfig at
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_Va3Nxv/containers/12ac0ef5-82bc-4c8e-912c-44343aaf10ab/config'
13:32:33 3: I0828 18:32:33.724247 20823 containerizer.cpp:3323] Transitioning
the state of container 12ac0ef5-82bc-4c8e-912c-44343aaf10ab from PROVISIONING
to PREPARING after 2.960896ms
13:32:33 3: I0828 18:32:33.736675 20824 containerizer.cpp:2100] 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.2:42011"},{"name":"MESOS_CHECKPOINT","type":"VALUE","value":"1"},{"name":"MESOS_DIRECTORY","type":"VALUE","value":"/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_QsMwAs/slaves/3de64da7-619c-4652-9d33-3fe2ca2a3d5f-S0/frameworks/3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000/executors/1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6/runs/12ac0ef5-82bc-4c8e-912c-44343aaf10ab"},{"name":"MESOS_EXECUTOR_ID","type":"VALUE","value":"1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6"},{"name":"MESOS_EXECUTOR_SHUTDOWN_GRACE_PERIOD","type":"VALUE","value":"5secs"},{"name":"MESOS_FRAMEWORK_ID","type":"VALUE","value":"3de64da7-619c-4652-9d33-3fe2ca2a3d5f-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":"3de64da7-619c-4652-9d33-3fe2ca2a3d5f-S0"},{"name":"MESOS_SLAVE_PID","type":"VALUE","value":"slave@172.17.0.2:42011"},{"name":"MESOS_SUBSCRIPTION_BACKOFF_MAX","type":"VALUE","value":"1mins"},{"name":"MESOS_SANDBOX","type":"VALUE","value":"/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_QsMwAs/slaves/3de64da7-619c-4652-9d33-3fe2ca2a3d5f-S0/frameworks/3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000/executors/1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6/runs/12ac0ef5-82bc-4c8e-912c-44343aaf10ab"}]},"task_environment":{},"user":"mesos","working_directory":"/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_QsMwAs/slaves/3de64da7-619c-4652-9d33-3fe2ca2a3d5f-S0/frameworks/3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000/executors/1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6/runs/12ac0ef5-82bc-4c8e-912c-44343aaf10ab"}"
--pipe_read="13" --pipe_write="14"
--runtime_directory="/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_Va3Nxv/containers/12ac0ef5-82bc-4c8e-912c-44343aaf10ab"
--unshare_namespace_mnt="false"'
13:32:33 3: I0828 18:32:33.741381 20824 launcher.cpp:145] Forked child with pid
'23818' for container '12ac0ef5-82bc-4c8e-912c-44343aaf10ab'
13:32:33 3: I0828 18:32:33.741645 20824 containerizer.cpp:2209] Checkpointing
container's forked pid 23818 to
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_QsMwAs/meta/slaves/3de64da7-619c-4652-9d33-3fe2ca2a3d5f-S0/frameworks/3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000/executors/1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6/runs/12ac0ef5-82bc-4c8e-912c-44343aaf10ab/pids/forked.pid'
13:32:33 3: I0828 18:32:33.756260 20824 containerizer.cpp:3323] Transitioning
the state of container 12ac0ef5-82bc-4c8e-912c-44343aaf10ab from PREPARING to
ISOLATING after 31.997184ms
13:32:33 3: I0828 18:32:33.767547 20802 containerizer.cpp:3323] Transitioning
the state of container 12ac0ef5-82bc-4c8e-912c-44343aaf10ab from ISOLATING to
FETCHING after 11.29472ms
13:32:33 3: I0828 18:32:33.768169 20802 fetcher.cpp:369] Starting to fetch URIs
for container: 12ac0ef5-82bc-4c8e-912c-44343aaf10ab, directory:
/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_QsMwAs/slaves/3de64da7-619c-4652-9d33-3fe2ca2a3d5f-S0/frameworks/3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000/executors/1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6/runs/12ac0ef5-82bc-4c8e-912c-44343aaf10ab
13:32:33 3: I0828 18:32:33.770155 20802 containerizer.cpp:3323] Transitioning
the state of container 12ac0ef5-82bc-4c8e-912c-44343aaf10ab from FETCHING to
RUNNING after 2.621184ms
13:32:34 3: I0828 18:32:34.470085 23819 exec.cpp:164] Version: 1.10.0
13:32:34 3: I0828 18:32:34.492386 20813 slave.cpp:5256] Got registration for
executor '1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6' of framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000 from executor(1)@172.17.0.2:37229
13:32:34 3: I0828 18:32:34.493299 20813 slave.cpp:5342] Checkpointing executor
pid 'executor(1)@172.17.0.2:37229' to
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_QsMwAs/meta/slaves/3de64da7-619c-4652-9d33-3fe2ca2a3d5f-S0/frameworks/3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000/executors/1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6/runs/12ac0ef5-82bc-4c8e-912c-44343aaf10ab/pids/libprocess.pid'
13:32:34 3: I0828 18:32:34.509138 20811 slave.cpp:3427] Sending queued task
'1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6' to executor
'1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6' of framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000 at executor(1)@172.17.0.2:37229
13:32:34 3: I0828 18:32:34.528692 23841 exec.cpp:237] Executor registered on
agent 3de64da7-619c-4652-9d33-3fe2ca2a3d5f-S0
13:32:34 3: I0828 18:32:34.545915 23841 executor.cpp:190] Received SUBSCRIBED
event
13:32:34 3: I0828 18:32:34.552199 23841 executor.cpp:194] Subscribed executor
on b766865f9da3
13:32:34 3: I0828 18:32:34.552727 23841 executor.cpp:190] Received LAUNCH event
13:32:34 3: I0828 18:32:34.553709 23841 executor.cpp:722] Starting task
1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6
13:32:34 3: I0828 18:32:34.567251 20808 slave.cpp:5737] Handling status update
TASK_STARTING (Status UUID: 450d2963-e050-474e-bd85-1e724fbd0502) for task
1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6 of framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000 from executor(1)@172.17.0.2:37229
13:32:34 3: I0828 18:32:34.572708 20805 task_status_update_manager.cpp:328]
Received task status update TASK_STARTING (Status UUID:
450d2963-e050-474e-bd85-1e724fbd0502) for task
1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6 of framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000
13:32:34 3: I0828 18:32:34.572814 20805 task_status_update_manager.cpp:507]
Creating StatusUpdate stream for task 1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6 of
framework 3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000
13:32:34 3: I0828 18:32:34.574477 20805 task_status_update_manager.cpp:842]
Checkpointing UPDATE for task status update TASK_STARTING (Status UUID:
450d2963-e050-474e-bd85-1e724fbd0502) for task
1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6 of framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000
13:32:34 3: I0828 18:32:34.574904 20805 task_status_update_manager.cpp:383]
Forwarding task status update TASK_STARTING (Status UUID:
450d2963-e050-474e-bd85-1e724fbd0502) for task
1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6 of framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000 to the agent
13:32:34 3: I0828 18:32:34.575500 20805 slave.cpp:6276] Forwarding the update
TASK_STARTING (Status UUID: 450d2963-e050-474e-bd85-1e724fbd0502) for task
1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6 of framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000 to master@172.17.0.2:42011
13:32:34 3: I0828 18:32:34.576138 20806 master.cpp:8985] Status update
TASK_STARTING (Status UUID: 450d2963-e050-474e-bd85-1e724fbd0502) for task
1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6 of framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000 from agent
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-S0 at slave@172.17.0.2:42011 (b766865f9da3)
13:32:34 3: I0828 18:32:34.576220 20806 master.cpp:9042] Forwarding status
update TASK_STARTING (Status UUID: 450d2963-e050-474e-bd85-1e724fbd0502) for
task 1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6 of framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000
13:32:34 3: I0828 18:32:34.576606 20806 master.cpp:12073] Updating the state of
task 1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6 of framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000 (latest state: TASK_STARTING, status
update state: TASK_STARTING)
13:32:34 3: I0828 18:32:34.577132 20806 sched.cpp:1042] Scheduler::statusUpdate
took 142946ns
13:32:34 3: I0828 18:32:34.577327 20805 slave.cpp:6160] Task status update
manager successfully handled status update TASK_STARTING (Status UUID:
450d2963-e050-474e-bd85-1e724fbd0502) for task
1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6 of framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000
13:32:34 3: I0828 18:32:34.577527 20805 slave.cpp:6187] Sending acknowledgement
for status update TASK_STARTING (Status UUID:
450d2963-e050-474e-bd85-1e724fbd0502) for task
1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6 of framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000 to executor(1)@172.17.0.2:37229
13:32:34 3: I0828 18:32:34.579707 20818 master.cpp:6695] Processing ACKNOWLEDGE
call for status 450d2963-e050-474e-bd85-1e724fbd0502 for task
1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6 of framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000 (default) at
scheduler-963d7ebc-7ef5-4a23-8e9c-5f9e58528f67@172.17.0.2:42011 on agent
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-S0
13:32:34 3: I0828 18:32:34.580312 20818 task_status_update_manager.cpp:401]
Received task status update acknowledgement (UUID:
450d2963-e050-474e-bd85-1e724fbd0502) for task
1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6 of framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000
13:32:34 3: I0828 18:32:34.580471 20818 task_status_update_manager.cpp:842]
Checkpointing ACK for task status update TASK_STARTING (Status UUID:
450d2963-e050-474e-bd85-1e724fbd0502) for task
1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6 of framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000
13:32:34 3: I0828 18:32:34.580912 20818 slave.cpp:4866] Task status update
manager successfully handled status update acknowledgement (UUID:
450d2963-e050-474e-bd85-1e724fbd0502) for task
1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6 of framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000
13:32:34 3: I0828 18:32:34.599927 20807 hierarchical.cpp:1724] Performed
allocation for 1 agents in 453188ns
13:32:34 3: I0828 18:32:34.612114 23841 executor.cpp:738] Forked command at
23845
13:32:34 3: I0828 18:32:34.636667 20802 slave.cpp:5737] Handling status update
TASK_RUNNING (Status UUID: e71cf9d2-36f0-4523-91fb-ea9ef6190e65) for task
1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6 of framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000 from executor(1)@172.17.0.2:37229
13:32:34 3: I0828 18:32:34.642412 20818 task_status_update_manager.cpp:328]
Received task status update TASK_RUNNING (Status UUID:
e71cf9d2-36f0-4523-91fb-ea9ef6190e65) for task
1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6 of framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000
13:32:34 3: I0828 18:32:34.642567 20818 task_status_update_manager.cpp:842]
Checkpointing UPDATE for task status update TASK_RUNNING (Status UUID:
e71cf9d2-36f0-4523-91fb-ea9ef6190e65) for task
1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6 of framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000
13:32:34 3: I0828 18:32:34.643005 20818 task_status_update_manager.cpp:383]
Forwarding task status update TASK_RUNNING (Status UUID:
e71cf9d2-36f0-4523-91fb-ea9ef6190e65) for task
1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6 of framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000 to the agent
13:32:34 3: I0828 18:32:34.644069 20803 slave.cpp:6276] Forwarding the update
TASK_RUNNING (Status UUID: e71cf9d2-36f0-4523-91fb-ea9ef6190e65) for task
1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6 of framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000 to master@172.17.0.2:42011
13:32:34 3: I0828 18:32:34.644883 20815 master.cpp:8985] Status update
TASK_RUNNING (Status UUID: e71cf9d2-36f0-4523-91fb-ea9ef6190e65) for task
1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6 of framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000 from agent
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-S0 at slave@172.17.0.2:42011 (b766865f9da3)
13:32:34 3: I0828 18:32:34.644975 20815 master.cpp:9042] Forwarding status
update TASK_RUNNING (Status UUID: e71cf9d2-36f0-4523-91fb-ea9ef6190e65) for
task 1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6 of framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000
13:32:34 3: I0828 18:32:34.645359 20815 master.cpp:12073] Updating the state of
task 1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6 of framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000 (latest state: TASK_RUNNING, status
update state: TASK_RUNNING)
13:32:34 3: I0828 18:32:34.645851 20815 sched.cpp:1042] Scheduler::statusUpdate
took 122122ns
13:32:34 3: I0828 18:32:34.647410 20816 master.cpp:6695] Processing ACKNOWLEDGE
call for status e71cf9d2-36f0-4523-91fb-ea9ef6190e65 for task
1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6 of framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000 (default) at
scheduler-963d7ebc-7ef5-4a23-8e9c-5f9e58528f67@172.17.0.2:42011 on agent
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-S0
13:32:34 3: I0828 18:32:34.647778 20803 slave.cpp:6160] Task status update
manager successfully handled status update TASK_RUNNING (Status UUID:
e71cf9d2-36f0-4523-91fb-ea9ef6190e65) for task
1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6 of framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000
13:32:34 3: I0828 18:32:34.648123 20803 slave.cpp:6187] Sending acknowledgement
for status update TASK_RUNNING (Status UUID:
e71cf9d2-36f0-4523-91fb-ea9ef6190e65) for task
1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6 of framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000 to executor(1)@172.17.0.2:37229
13:32:34 3: I0828 18:32:34.649669 20813 task_status_update_manager.cpp:401]
Received task status update acknowledgement (UUID:
e71cf9d2-36f0-4523-91fb-ea9ef6190e65) for task
1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6 of framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000
13:32:34 3: I0828 18:32:34.649842 20813 task_status_update_manager.cpp:842]
Checkpointing ACK for task status update TASK_RUNNING (Status UUID:
e71cf9d2-36f0-4523-91fb-ea9ef6190e65) for task
1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6 of framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000
13:32:34 3: I0828 18:32:34.656613 20803 slave.cpp:4866] Task status update
manager successfully handled status update acknowledgement (UUID:
e71cf9d2-36f0-4523-91fb-ea9ef6190e65) for task
1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6 of framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000
13:32:34 3: I0828 18:32:34.657055 20803 slave.cpp:924] Agent terminating
13:32:34 3: I0828 18:32:34.667977 20815 master.cpp:1297] Agent
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-S0 at slave@172.17.0.2:42011
(b766865f9da3) disconnected
13:32:34 3: I0828 18:32:34.668049 20815 master.cpp:3399] Disconnecting agent
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-S0 at slave@172.17.0.2:42011 (b766865f9da3)
13:32:34 3: I0828 18:32:34.668161 20815 master.cpp:3418] Deactivating agent
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-S0 at slave@172.17.0.2:42011 (b766865f9da3)
13:32:34 3: I0828 18:32:34.668669 20815 hierarchical.cpp:1037] Agent
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-S0 deactivated
13:32:34 3: I0828 18:32:34.669589 20801 containerizer.cpp:318] Using isolation
{ environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni }
13:32:34 3: W0828 18:32:34.670797 20801 backend.cpp:76] Failed to create
'overlay' backend: OverlayBackend requires root privileges
13:32:34 3: W0828 18:32:34.670835 20801 backend.cpp:76] Failed to create 'aufs'
backend: AufsBackend requires root privileges
13:32:34 3: W0828 18:32:34.670862 20801 backend.cpp:76] Failed to create 'bind'
backend: BindBackend requires root privileges
13:32:34 3: I0828 18:32:34.670912 20801 provisioner.cpp:300] Using default
backend 'copy'
13:32:34 3: W0828 18:32:34.742063 20801 process.cpp:2877] Attempted to spawn
already running process files@172.17.0.2:42011
13:32:34 3: I0828 18:32:34.743468 20801 cluster.cpp:518] Creating default
'local' authorizer
13:32:34 3: I0828 18:32:34.748119 20811 slave.cpp:267] Mesos agent started on
@172.17.0.2:42011
13:32:34 3: I0828 18:32:34.748172 20811 slave.cpp:268] Flags at startup:
--acls="" --appc_simple_discovery_uri_prefix="http://";
--appc_store_dir="/tmp/sIRhDp/Cdd6uy/store/appc"
--authenticate_http_readonly="true" --authenticate_http_readwrite="false"
--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/sIRhDp/Cdd6uy/credential"
--default_role="*" --disallow_sharing_agent_ipc_namespace="false"
--disallow_sharing_agent_pid_namespace="false" --disk_watch_interval="1mins"
--docker="docker" --docker_ignore_runtime="false" --docker_kill_orphans="true"
--docker_registry="https://registry-1.docker.io"; --docker_remove_delay="6hrs"
--docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns"
--docker_store_dir="/tmp/sIRhDp/Cdd6uy/store/docker"
--docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume"
--docker_volume_chown="false" --enforce_container_disk_quota="false"
--executor_registration_timeout="1mins"
--executor_reregistration_timeout="1mins"
--executor_shutdown_grace_period="5secs"
--fetcher_cache_dir="/tmp/sIRhDp/Cdd6uy/fetch" --fetcher_cache_size="2GB"
--fetcher_stall_timeout="1mins"
--frameworks_home="/tmp/sIRhDp/Cdd6uy/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/sIRhDp/Cdd6uy/http_credentials"
--http_heartbeat_interval="30secs" --initialize_driver_logging="true"
--isolation="posix/cpu,posix/mem" --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" --network_cni_root_dir_persist="false"
--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_Va3Nxv"
--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_QsMwAs"
--zk_session_timeout="10secs"
13:32:34 3: I0828 18:32:34.749047 20811 credentials.hpp:86] Loading credential
for authentication from '/tmp/sIRhDp/Cdd6uy/credential'
13:32:34 3: I0828 18:32:34.749388 20811 slave.cpp:300] Agent using credential
for: test-principal
13:32:34 3: I0828 18:32:34.749414 20811 credentials.hpp:37] Loading credentials
for authentication from '/tmp/sIRhDp/Cdd6uy/http_credentials'
13:32:34 3: I0828 18:32:34.749752 20811 http.cpp:975] Creating default 'basic'
HTTP authenticator for realm 'mesos-agent-readonly'
13:32:34 3: I0828 18:32:34.750783 20811 disk_profile_adaptor.cpp:78] Creating
default disk profile adaptor module
13:32:34 3: I0828 18:32:34.753080 20811 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"}]
13:32:34 3: I0828 18:32:34.753450 20811 slave.cpp:623] Agent attributes: [ ]
13:32:34 3: I0828 18:32:34.753471 20811 slave.cpp:632] Agent hostname:
b766865f9da3
13:32:34 3: I0828 18:32:34.755028 20824 status_update_manager_process.hpp:379]
Pausing operation status update manager
13:32:34 3: I0828 18:32:34.762432 20815 state.cpp:67] Recovering state from
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_QsMwAs/meta'
13:32:34 3: I0828 18:32:34.762630 20823 task_status_update_manager.cpp:181]
Pausing sending task status updates
13:32:34 3: I0828 18:32:34.762642 20815 state.cpp:874] No committed
checkpointed resources and operations found at
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_QsMwAs/meta/resources/resources_and_operations.state'
13:32:34 3: I0828 18:32:34.762836 20815 state.cpp:880] No committed
checkpointed resources found at
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_QsMwAs/meta/resources/resources.info'
13:32:34 3: I0828 18:32:34.798907 20810 slave.cpp:7491] Finished recovering
checkpointed state from
'/tmp/SlaveRecoveryTest_0_PingTimeoutDuringRecovery_QsMwAs/meta', beginning
agent recovery
13:32:34 3: I0828 18:32:34.800797 20810 slave.cpp:8222] Recovering framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000
13:32:34 3: I0828 18:32:34.800999 20810 slave.cpp:10120] Recovering executor
'1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6' of framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000
13:32:34 3: I0828 18:32:34.804620 20810 task_status_update_manager.cpp:207]
Recovering task status update manager
13:32:34 3: I0828 18:32:34.804755 20810 task_status_update_manager.cpp:215]
Recovering executor '1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6' of framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000
13:32:34 3: I0828 18:32:34.804939 20810 task_status_update_manager.cpp:507]
Creating StatusUpdate stream for task 1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6 of
framework 3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000
13:32:34 3: I0828 18:32:34.806234 20810 task_status_update_manager.cpp:818]
Replaying task status update stream for task
1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6
13:32:34 3: I0828 18:32:34.809662 20809 containerizer.cpp:821] Recovering Mesos
containers
13:32:34 3: I0828 18:32:34.809826 20809 containerizer.cpp:878] Recovering
container 12ac0ef5-82bc-4c8e-912c-44343aaf10ab for executor
'1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6' of framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000
13:32:34 3: I0828 18:32:34.812481 20809 containerizer.cpp:1161] Recovering
isolators
13:32:34 3: I0828 18:32:34.815238 20825 containerizer.cpp:1200] Recovering
provisioner
13:32:34 3: I0828 18:32:34.816676 20812 provisioner.cpp:500] Provisioner
recovery complete
13:32:34 3: I0828 18:32:34.821009 20823 composing.cpp:339] Finished recovering
all containerizers
13:32:34 3: I0828 18:32:34.822939 20807 status_update_manager_process.hpp:314]
Recovering operation status update manager
13:32:34 3: I0828 18:32:34.823730 20807 slave.cpp:7972] Recovering executors
13:32:34 3: I0828 18:32:34.823928 20807 slave.cpp:7996] Sending reconnect
request to executor '1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6' of framework
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000 at executor(1)@172.17.0.2:37229
13:32:34 3: I0828 18:32:34.831092 23826 exec.cpp:283] Received reconnect
request from agent 3de64da7-619c-4652-9d33-3fe2ca2a3d5f-S0
13:32:34 3: I0828 18:32:34.839380 20808 slave.cpp:5424] Received
re-registration message from executor '1ca63c79-a8a3-4771-9c5b-38bfdcf66ed6' of
framework 3de64da7-619c-4652-9d33-3fe2ca2a3d5f-0000
13:32:34 3: I0828 18:32:34.847268 23824 exec.cpp:260] Executor reregistered on
agent 3de64da7-619c-4652-9d33-3fe2ca2a3d5f-S0
13:32:34 3: I0828 18:32:34.853519 23823 executor.cpp:190] Received SUBSCRIBED
event
13:32:34 3: I0828 18:32:34.853653 23823 executor.cpp:194] Subscribed executor
on b766865f9da3
13:32:34 3: I0828 18:32:34.858855 20807 slave.cpp:6446] No pings from master
received within 75secs
13:32:34 3: I0828 18:32:34.858897 20814 hierarchical.cpp:1724] Performed
allocation for 1 agents in 425627ns
13:32:34 3: F0828 18:32:34.862807 20806 slave.cpp:1323] Check failed: state ==
DISCONNECTED || state == RUNNING || state == TERMINATING RECOVERING
13:32:35 3: *** Check failure stack trace: ***
13:32:35 3: @ 0x7f227998629c google::LogMessage::Fail()
13:32:35 3: @ 0x7f22799861e0 google::LogMessage::SendToLog()
13:32:35 3: @ 0x7f2279985afe google::LogMessage::Flush()
13:32:35 3: @ 0x7f227998964b
google::LogMessageFatal::~LogMessageFatal()
13:32:35 3: @ 0x7f2288f50ecb mesos::internal::slave::Slave::detected()
13:32:35 3: @ 0x7f2289021b6f
_ZZN7process8dispatchIN5mesos8internal5slave5SlaveERKNS_6FutureI6OptionINS1_10MasterInfoEEEESB_EEvRKNS_3PIDIT_EEMSD_FvT0_EOT1_ENKUlOS9_PNS_11ProcessBaseEE_clESM_SO_
13:32:35 3: @ 0x7f2289173df3
_ZN5cpp176invokeIZN7process8dispatchIN5mesos8internal5slave5SlaveERKNS1_6FutureI6OptionINS3_10MasterInfoEEEESD_EEvRKNS1_3PIDIT_EEMSF_FvT0_EOT1_EUlOSB_PNS1_11ProcessBaseEE_ISB_SQ_EEEDTclcl7forwardISF_Efp_Espcl7forwardIT0_Efp0_EEEOSF_DpOSS_
13:32:35 3: @ 0x7f2289161b8c
_ZN6lambda8internal7PartialIZN7process8dispatchIN5mesos8internal5slave5SlaveERKNS2_6FutureI6OptionINS4_10MasterInfoEEEESE_EEvRKNS2_3PIDIT_EEMSG_FvT0_EOT1_EUlOSC_PNS2_11ProcessBaseEE_JSC_St12_PlaceholderILi1EEEE13invoke_expandISS_St5tupleIJSC_SU_EESX_IJOSR_EEJLm0ELm1EEEEDTcl6invokecl7forwardISG_Efp_Espcl6expandcl3getIXT2_EEcl7forwardISK_Efp0_EEcl7forwardISN_Efp2_EEEEOSG_OSK_N5cpp1416integer_sequenceImJXspT2_EEEESO_
13:32:35 3: @ 0x7f228914e32a
_ZNO6lambda8internal7PartialIZN7process8dispatchIN5mesos8internal5slave5SlaveERKNS2_6FutureI6OptionINS4_10MasterInfoEEEESE_EEvRKNS2_3PIDIT_EEMSG_FvT0_EOT1_EUlOSC_PNS2_11ProcessBaseEE_JSC_St12_PlaceholderILi1EEEEclIJSR_EEEDTcl13invoke_expandcl4movedtdefpT1fEcl4movedtdefpT10bound_argsEcvN5cpp1416integer_sequenceImJLm0ELm1EEEE_Ecl16forward_as_tuplespcl7forwardIT_Efp_EEEEDpOS10_
13:32:35 3: @ 0x7f22891451a7
_ZN5cpp176invokeIN6lambda8internal7PartialIZN7process8dispatchIN5mesos8internal5slave5SlaveERKNS4_6FutureI6OptionINS6_10MasterInfoEEEESG_EEvRKNS4_3PIDIT_EEMSI_FvT0_EOT1_EUlOSE_PNS4_11ProcessBaseEE_ISE_St12_PlaceholderILi1EEEEEIST_EEEDTclcl7forwardISI_Efp_Espcl7forwardIT0_Efp0_EEEOSI_DpOSY_
13:32:35 3: @ 0x7f22891408a7
_ZN6lambda8internal6InvokeIvEclINS0_7PartialIZN7process8dispatchIN5mesos8internal5slave5SlaveERKNS5_6FutureI6OptionINS7_10MasterInfoEEEESH_EEvRKNS5_3PIDIT_EEMSJ_FvT0_EOT1_EUlOSF_PNS5_11ProcessBaseEE_JSF_St12_PlaceholderILi1EEEEEJSU_EEEvOSJ_DpOT0_
13:32:35 3: @ 0x7f228913c538
_ZNO6lambda12CallableOnceIFvPN7process11ProcessBaseEEE10CallableFnINS_8internal7PartialIZNS1_8dispatchIN5mesos8internal5slave5SlaveERKNS1_6FutureI6OptionINSA_10MasterInfoEEEESK_EEvRKNS1_3PIDIT_EEMSM_FvT0_EOT1_EUlOSI_S3_E_ISI_St12_PlaceholderILi1EEEEEEclEOS3_
13:32:35 3: @ 0x7f227b005810
_ZNO6lambda12CallableOnceIFvPN7process11ProcessBaseEEEclES3_
13:32:35 3: @ 0x7f227afbc836 process::ProcessBase::consume()
13:32:35 3: @ 0x7f227afe6d22
_ZNO7process13DispatchEvent7consumeEPNS_13EventConsumerE
13:32:35 3: @ 0x18e4ba4 process::ProcessBase::serve()
13:32:35 3: @ 0x7f227afb9013 process::ProcessManager::resume()
13:32:35 3: @ 0x7f227afb5216
_ZZN7process14ProcessManager12init_threadsEvENKUlvE_clEv
13:32:35 3: @ 0x7f227afdea4a
_ZNSt12_Bind_simpleIFZN7process14ProcessManager12init_threadsEvEUlvE_vEE9_M_invokeIJEEEvSt12_Index_tupleIJXspT_EEE
13:32:35 3: @ 0x7f227afddaac
_ZNSt12_Bind_simpleIFZN7process14ProcessManager12init_threadsEvEUlvE_vEEclEv
13:32:35 3: @ 0x7f227afdc8f0
_ZNSt6thread5_ImplISt12_Bind_simpleIFZN7process14ProcessManager12init_threadsEvEUlvE_vEEE6_M_runEv
13:32:35 3: @ 0x7f2275fa8c80 (unknown)
13:32:35 3: @ 0x7f22797596ba start_thread
13:32:35 3: @ 0x7f227570e41d clone
13:32:35 3: @ (nil) (unknown)
13:32:35 3: I0828 18:32:35.840852 23837 exec.cpp:532] Agent exited, but
framework has checkpointing enabled. Waiting 15mins to reconnect with agent
3de64da7-619c-4652-9d33-3fe2ca2a3d5f-S0
13:47:35 3: I0828 18:47:35.842643 23834 exec.cpp:513] Recovery timeout of
15mins exceeded; Shutting down
13:47:35 3: I0828 18:47:35.842794 23834 exec.cpp:459] Executor asked to shutdown
13:47:35 3: I0828 18:47:35.844286 23841 executor.cpp:190] Received SHUTDOWN
event
13:47:35 3: I0828 18:47:35.844352 23841 executor.cpp:841] Shutting down
13:47:35 3: I0828 18:47:35.844424 23841 executor.cpp:954] Sending SIGTERM to
process tree at pid 23845
13:47:35 3: I0828 18:47:35.850082 23841 executor.cpp:967] Sent SIGTERM to the
following process trees:
13:47:35 3: [
13:47:35 3: -+- 23845 sh -c sleep 1000
13:47:35 3: \--- 23847 sleep 1000
13:47:35 3: ]
13:47:35 3: I0828 18:47:35.850103 23841 executor.cpp:971] Scheduling escalation
to SIGKILL in 3secs from now
13:47:36 3: I0828 18:47:35.937669 23839 executor.cpp:1039] Command terminated
with signal Terminated (pid: 23845)
13:47:36 3: W0828 18:47:35.949383 23844 process.cpp:1917] Failed to send
'mesos.internal.StatusUpdateMessage' to '172.17.0.2:42011', connect: Failed to
connect to 172.17.0.2:42011: Connection refused
13:47:37 3: I0828 18:47:36.945973 23844 process.cpp:935] Stopped the socket
accept loop
13:47:37 3/3 Test #3: MesosTests .......................***Exception:
Other1170.31 sec
13:47:37
13:47:37 67% tests passed, 1 tests failed out of 3
13:47:37
13:47:37 Total Test time (real) = 1204.34 sec
13:47:37
13:47:37 The following tests FAILED:
13:47:37 3 - MesosTests (OTHER_FAULT)
13:47:37 Errors while running CTest
13:47:37 CMakeFiles/check.dir/build.make:60: recipe for target
'CMakeFiles/check' failed
13:47:37 make[3]: *** [CMakeFiles/check] Error 8
13:47:37 make[3]: Leaving directory '/tmp/SRC/build'
13:47:37 CMakeFiles/Makefile2:181: recipe for target 'CMakeFiles/check.dir/all'
failed
13:47:37 make[2]: *** [CMakeFiles/check.dir/all] Error 2
{code}
> SlaveRecoveryTest/0.PingTimeoutDuringRecovery is flaky
> ------------------------------------------------------
>
> Key: MESOS-8983
> URL: https://issues.apache.org/jira/browse/MESOS-8983
> Project: Mesos
> Issue Type: Bug
> Affects Versions: 1.7.0, 1.8.0
> Reporter: Alexander Rojas
> Assignee: Joseph Wu
> Priority: Major
> Labels: flaky-test, foundations
>
> 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
(v8.3.2#803003)
