Benno Evers created MESOS-9276:
----------------------------------
Summary: SlaveRecoveryTest/0.Reboot is flaky
Key: MESOS-9276
URL: https://issues.apache.org/jira/browse/MESOS-9276
Project: Mesos
Issue Type: Bug
Reporter: Benno Evers
Observed in an internal CI run: (4502)
{noformat}
../../src/tests/slave_recovery_tests.cpp:2746: Failure
Failed to wait 15secs for executorStatus
{noformat}
Full log:
{noformat}
[ RUN ] SlaveRecoveryTest/0.Reboot
I0927 12:33:33.620496 2560127808 cluster.cpp:173] Creating default 'local'
authorizer
I0927 12:33:33.621817 75808768 master.cpp:413] Master
b351e786-2364-4c2e-bb10-1efc3c97e509 (Jenkinss-Mac-mini.local) started on
10.0.49.4:65455
I0927 12:33:33.621845 75808768 master.cpp:416] Flags at startup: --acls=""
--agent_ping_timeout="15secs" --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="/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/DW8BvT/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="5" --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" --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="/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/DW8BvT/master"
--zk_session_timeout="10secs"
I0927 12:33:33.622007 75808768 master.cpp:465] Master only allowing
authenticated frameworks to register
I0927 12:33:33.622015 75808768 master.cpp:471] Master only allowing
authenticated agents to register
I0927 12:33:33.622020 75808768 master.cpp:477] Master only allowing
authenticated HTTP frameworks to register
I0927 12:33:33.622026 75808768 credentials.hpp:37] Loading credentials for
authentication from
'/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/DW8BvT/credentials'
I0927 12:33:33.622184 75808768 master.cpp:521] Using default 'crammd5'
authenticator
I0927 12:33:33.622243 75808768 http.cpp:1037] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-readonly'
I0927 12:33:33.622328 75808768 http.cpp:1037] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-readwrite'
I0927 12:33:33.622391 75808768 http.cpp:1037] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-scheduler'
I0927 12:33:33.622442 75808768 master.cpp:602] Authorization enabled
I0927 12:33:33.622640 74735616 whitelist_watcher.cpp:77] No whitelist given
I0927 12:33:33.622643 75272192 hierarchical.cpp:182] Initialized hierarchical
allocator process
I0927 12:33:33.624191 77418496 master.cpp:2083] Elected as the leading master!
I0927 12:33:33.624217 77418496 master.cpp:1638] Recovering from registrar
I0927 12:33:33.624264 76881920 registrar.cpp:339] Recovering registrar
I0927 12:33:33.624541 76881920 registrar.cpp:383] Successfully fetched the
registry (0B) in 255232ns
I0927 12:33:33.624619 76881920 registrar.cpp:487] Applied 1 operations in
27286ns; attempting to update the registry
I0927 12:33:33.624822 76881920 registrar.cpp:544] Successfully updated the
registry in 172032ns
I0927 12:33:33.624892 76881920 registrar.cpp:416] Successfully recovered
registrar
I0927 12:33:33.625068 75272192 master.cpp:1752] Recovered 0 agents from the
registry (155B); allowing 10mins for agents to reregister
I0927 12:33:33.625089 77955072 hierarchical.cpp:220] Skipping recovery of
hierarchical allocator: nothing to recover
I0927 12:33:33.626883 2560127808 containerizer.cpp:305] Using isolation {
environment_secret, filesystem/posix, posix/mem, posix/cpu }
I0927 12:33:33.627074 2560127808 provisioner.cpp:298] Using default backend
'copy'
W0927 12:33:33.628770 2560127808 process.cpp:2810] Attempted to spawn already
running process files@10.0.49.4:65455
I0927 12:33:33.629148 2560127808 cluster.cpp:485] Creating default 'local'
authorizer
I0927 12:33:33.630077 75272192 slave.cpp:267] Mesos agent started on
(525)@10.0.49.4:65455
I0927 12:33:33.630103 75272192 slave.cpp:268] Flags at startup: --acls=""
--appc_simple_discovery_uri_prefix="http://";
--appc_store_dir="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_Reboot_WZrsCD/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"
--container_disk_watch_interval="15secs" --containerizers="mesos"
--credential="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_Reboot_WZrsCD/credential"
--default_role="*" --disk_watch_interval="1mins" --docker="docker"
--docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io";
--docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock"
--docker_stop_timeout="0ns"
--docker_store_dir="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_Reboot_WZrsCD/store/docker"
--docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume"
--enforce_container_disk_quota="false" --executor_registration_timeout="1mins"
--executor_reregistration_timeout="2secs"
--executor_shutdown_grace_period="5secs"
--fetcher_cache_dir="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_Reboot_WZrsCD/fetch"
--fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins"
--frameworks_home="" --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="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_Reboot_WZrsCD/http_credentials"
--http_heartbeat_interval="30secs" --initialize_driver_logging="true"
--isolation="posix/cpu,posix/mem"
--jwt_secret_key="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_Reboot_WZrsCD/jwt_secret_key"
--launcher="posix"
--launcher_dir="/Users/jenkins/workspace/workspace/mesos/Mesos_CI-build/FLAG/SSL/label/mac/mesos/build/src"
--logbufsecs="0" --logging_level="INFO"
--max_completed_executors_per_framework="150" --memory_profiling="false"
--network_cni_metrics="true" --oversubscribed_resources_interval="15secs"
--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]"
--runtime_dir="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_Reboot_WZrsCD"
--sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true"
--version="false"
--work_dir="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_Reboot_MfmJ3l"
--zk_session_timeout="10secs"
I0927 12:33:33.630363 75272192 credentials.hpp:86] Loading credential for
authentication from
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_Reboot_WZrsCD/credential'
I0927 12:33:33.630489 75272192 slave.cpp:300] Agent using credential for:
test-principal
I0927 12:33:33.630506 75272192 credentials.hpp:37] Loading credentials for
authentication from
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_Reboot_WZrsCD/http_credentials'
W0927 12:33:33.630669 2560127808 process.cpp:2810] Attempted to spawn already
running process version@10.0.49.4:65455
I0927 12:33:33.630726 75272192 http.cpp:1037] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-executor'
I0927 12:33:33.630789 75272192 http.cpp:1058] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-executor'
I0927 12:33:33.630892 75272192 http.cpp:1037] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-readonly'
I0927 12:33:33.630940 75272192 http.cpp:1058] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-readonly'
I0927 12:33:33.631031 75272192 http.cpp:1037] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-readwrite'
I0927 12:33:33.631098 75272192 http.cpp:1058] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-readwrite'
I0927 12:33:33.631279 75272192 disk_profile_adaptor.cpp:80] Creating default
disk profile adaptor module
I0927 12:33:33.631592 75272192 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"}]
I0927 12:33:33.631717 75272192 slave.cpp:623] Agent attributes: [ ]
I0927 12:33:33.631731 75272192 slave.cpp:632] Agent hostname:
Jenkinss-Mac-mini.local
I0927 12:33:33.631795 77955072 task_status_update_manager.cpp:181] Pausing
sending task status updates
I0927 12:33:33.631956 2560127808 sched.cpp:232] Version: 1.8.0
I0927 12:33:33.632251 77955072 sched.cpp:336] New master detected at
master@10.0.49.4:65455
I0927 12:33:33.632302 77955072 sched.cpp:401] Authenticating with master
master@10.0.49.4:65455
I0927 12:33:33.632318 77955072 sched.cpp:408] Using default CRAM-MD5
authenticatee
I0927 12:33:33.632421 76881920 authenticatee.cpp:121] Creating new client SASL
connection
I0927 12:33:33.632567 74199040 state.cpp:66] Recovering state from
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_Reboot_MfmJ3l/meta'
I0927 12:33:33.632625 77418496 master.cpp:9653] Authenticating
scheduler-b7d3e590-e445-4362-83b8-6ac0125c4e84@10.0.49.4:65455
I0927 12:33:33.632676 77955072 slave.cpp:6909] Finished recovering checkpointed
state from
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_Reboot_MfmJ3l/meta',
beginning agent recovery
I0927 12:33:33.632721 74735616 authenticator.cpp:414] Starting authentication
session for crammd5-authenticatee(1064)@10.0.49.4:65455
I0927 12:33:33.632768 76881920 task_status_update_manager.cpp:207] Recovering
task status update manager
I0927 12:33:33.632802 76345344 authenticator.cpp:98] Creating new server SASL
connection
I0927 12:33:33.632894 77418496 authenticatee.cpp:213] Received SASL
authentication mechanisms: CRAM-MD5
I0927 12:33:33.632915 77418496 authenticatee.cpp:239] Attempting to
authenticate with mechanism 'CRAM-MD5'
I0927 12:33:33.632936 77955072 containerizer.cpp:727] Recovering Mesos
containers
I0927 12:33:33.633005 74735616 authenticator.cpp:204] Received SASL
authentication start
I0927 12:33:33.633049 77955072 containerizer.cpp:1053] Recovering isolators
I0927 12:33:33.633083 74735616 authenticator.cpp:326] Authentication requires
more steps
I0927 12:33:33.633263 74199040 authenticatee.cpp:259] Received SASL
authentication step
I0927 12:33:33.633327 76881920 authenticator.cpp:232] Received SASL
authentication step
I0927 12:33:33.633360 76881920 auxprop.cpp:109] Request to lookup properties
for user: 'test-principal' realm: 'Jenkinss-Mac-mini.local' server FQDN:
'Jenkinss-Mac-mini.local' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0927 12:33:33.633373 76881920 auxprop.cpp:181] Looking up auxiliary property
'*userPassword'
I0927 12:33:33.633388 77955072 containerizer.cpp:1092] Recovering provisioner
I0927 12:33:33.633396 76881920 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0927 12:33:33.633437 76881920 auxprop.cpp:109] Request to lookup properties
for user: 'test-principal' realm: 'Jenkinss-Mac-mini.local' server FQDN:
'Jenkinss-Mac-mini.local' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0927 12:33:33.633451 76881920 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0927 12:33:33.633461 76881920 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0927 12:33:33.633481 76881920 authenticator.cpp:318] Authentication success
I0927 12:33:33.633532 77418496 authenticatee.cpp:299] Authentication success
I0927 12:33:33.633599 75272192 master.cpp:9685] Successfully authenticated
principal 'test-principal' at
scheduler-b7d3e590-e445-4362-83b8-6ac0125c4e84@10.0.49.4:65455
I0927 12:33:33.633616 74199040 authenticator.cpp:432] Authentication session
cleanup for crammd5-authenticatee(1064)@10.0.49.4:65455
I0927 12:33:33.633745 74735616 sched.cpp:513] Successfully authenticated with
master master@10.0.49.4:65455
I0927 12:33:33.633764 74735616 sched.cpp:817] Sending SUBSCRIBE call to
master@10.0.49.4:65455
I0927 12:33:33.633797 76345344 provisioner.cpp:494] Provisioner recovery
complete
I0927 12:33:33.633831 74735616 sched.cpp:850] Will retry registration in
308.490562ms if necessary
I0927 12:33:33.633983 75808768 master.cpp:2854] Received SUBSCRIBE call for
framework 'default' at
scheduler-b7d3e590-e445-4362-83b8-6ac0125c4e84@10.0.49.4:65455
I0927 12:33:33.634019 75808768 master.cpp:2155] Authorizing framework principal
'test-principal' to receive offers for roles '{ * }'
I0927 12:33:33.634202 75272192 composing.cpp:339] Finished recovering all
containerizers
I0927 12:33:33.634263 76881920 slave.cpp:7138] Recovering executors
I0927 12:33:33.634340 76881920 slave.cpp:7291] Finished recovery
I0927 12:33:33.634338 75808768 master.cpp:2935] Subscribing framework default
with checkpointing enabled and capabilities [ MULTI_ROLE,
RESERVATION_REFINEMENT ]
I0927 12:33:33.635002 74735616 task_status_update_manager.cpp:181] Pausing
sending task status updates
I0927 12:33:33.635011 76881920 slave.cpp:1254] New master detected at
master@10.0.49.4:65455
I0927 12:33:33.635061 76881920 slave.cpp:1319] Detecting new master
I0927 12:33:33.635187 75808768 master.cpp:9883] Adding framework
b351e786-2364-4c2e-bb10-1efc3c97e509-0000 (default) at
scheduler-b7d3e590-e445-4362-83b8-6ac0125c4e84@10.0.49.4:65455 with roles { }
suppressed
I0927 12:33:33.635412 74199040 sched.cpp:744] Framework registered with
b351e786-2364-4c2e-bb10-1efc3c97e509-0000
I0927 12:33:33.635471 76345344 hierarchical.cpp:306] Added framework
b351e786-2364-4c2e-bb10-1efc3c97e509-0000
I0927 12:33:33.635481 74199040 sched.cpp:758] Scheduler::registered took 38771ns
I0927 12:33:33.635582 76345344 hierarchical.cpp:1568] Performed allocation for
0 agents in 30988ns
I0927 12:33:33.639854 77418496 slave.cpp:1346] Authenticating with master
master@10.0.49.4:65455
I0927 12:33:33.639914 77418496 slave.cpp:1355] Using default CRAM-MD5
authenticatee
I0927 12:33:33.640022 74735616 authenticatee.cpp:121] Creating new client SASL
connection
I0927 12:33:33.640166 75272192 master.cpp:9653] Authenticating
slave(525)@10.0.49.4:65455
I0927 12:33:33.640249 75808768 authenticator.cpp:414] Starting authentication
session for crammd5-authenticatee(1065)@10.0.49.4:65455
I0927 12:33:33.640349 74199040 authenticator.cpp:98] Creating new server SASL
connection
I0927 12:33:33.640429 76345344 authenticatee.cpp:213] Received SASL
authentication mechanisms: CRAM-MD5
I0927 12:33:33.640447 76345344 authenticatee.cpp:239] Attempting to
authenticate with mechanism 'CRAM-MD5'
I0927 12:33:33.640494 77955072 authenticator.cpp:204] Received SASL
authentication start
I0927 12:33:33.640555 77955072 authenticator.cpp:326] Authentication requires
more steps
I0927 12:33:33.640640 76881920 authenticatee.cpp:259] Received SASL
authentication step
I0927 12:33:33.640692 77418496 authenticator.cpp:232] Received SASL
authentication step
I0927 12:33:33.640709 77418496 auxprop.cpp:109] Request to lookup properties
for user: 'test-principal' realm: 'Jenkinss-Mac-mini.local' server FQDN:
'Jenkinss-Mac-mini.local' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0927 12:33:33.640717 77418496 auxprop.cpp:181] Looking up auxiliary property
'*userPassword'
I0927 12:33:33.640730 77418496 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0927 12:33:33.640739 77418496 auxprop.cpp:109] Request to lookup properties
for user: 'test-principal' realm: 'Jenkinss-Mac-mini.local' server FQDN:
'Jenkinss-Mac-mini.local' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0927 12:33:33.640745 77418496 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0927 12:33:33.640751 77418496 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0927 12:33:33.640760 77418496 authenticator.cpp:318] Authentication success
I0927 12:33:33.640792 74735616 authenticatee.cpp:299] Authentication success
I0927 12:33:33.640821 75272192 master.cpp:9685] Successfully authenticated
principal 'test-principal' at slave(525)@10.0.49.4:65455
I0927 12:33:33.640841 75808768 authenticator.cpp:432] Authentication session
cleanup for crammd5-authenticatee(1065)@10.0.49.4:65455
I0927 12:33:33.640990 74199040 slave.cpp:1446] Successfully authenticated with
master master@10.0.49.4:65455
I0927 12:33:33.641175 74199040 slave.cpp:1877] Will retry registration in
14.237508ms if necessary
I0927 12:33:33.641237 75272192 master.cpp:6605] Received register agent message
from slave(525)@10.0.49.4:65455 (Jenkinss-Mac-mini.local)
I0927 12:33:33.641325 75272192 master.cpp:3964] Authorizing agent providing
resources 'cpus:2; mem:1024; disk:1024; ports:[31000-32000]' with principal
'test-principal'
I0927 12:33:33.641625 77418496 master.cpp:6672] Authorized registration of
agent at slave(525)@10.0.49.4:65455 (Jenkinss-Mac-mini.local)
I0927 12:33:33.641679 77418496 master.cpp:6787] Registering agent at
slave(525)@10.0.49.4:65455 (Jenkinss-Mac-mini.local) with id
b351e786-2364-4c2e-bb10-1efc3c97e509-S0
I0927 12:33:33.641891 76345344 registrar.cpp:487] Applied 1 operations in
90244ns; attempting to update the registry
I0927 12:33:33.642176 76881920 registrar.cpp:544] Successfully updated the
registry in 254976ns
I0927 12:33:33.642241 75808768 master.cpp:6835] Admitted agent
b351e786-2364-4c2e-bb10-1efc3c97e509-S0 at slave(525)@10.0.49.4:65455
(Jenkinss-Mac-mini.local)
I0927 12:33:33.642446 75808768 master.cpp:6880] Registered agent
b351e786-2364-4c2e-bb10-1efc3c97e509-S0 at slave(525)@10.0.49.4:65455
(Jenkinss-Mac-mini.local) with cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0927 12:33:33.642514 77955072 slave.cpp:1479] Registered with master
master@10.0.49.4:65455; given agent ID b351e786-2364-4c2e-bb10-1efc3c97e509-S0
I0927 12:33:33.642576 74735616 task_status_update_manager.cpp:188] Resuming
sending task status updates
I0927 12:33:33.642596 76345344 hierarchical.cpp:605] Added agent
b351e786-2364-4c2e-bb10-1efc3c97e509-S0 (Jenkinss-Mac-mini.local) with cpus:2;
mem:1024; disk:1024; ports:[31000-32000] (allocated: {})
I0927 12:33:33.642906 77955072 slave.cpp:1499] Checkpointing SlaveInfo to
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_Reboot_MfmJ3l/meta/slaves/b351e786-2364-4c2e-bb10-1efc3c97e509-S0/slave.info'
I0927 12:33:33.642946 76345344 hierarchical.cpp:1568] Performed allocation for
1 agents in 269854ns
I0927 12:33:33.643107 74199040 master.cpp:9468] Sending offers [
b351e786-2364-4c2e-bb10-1efc3c97e509-O0 ] to framework
b351e786-2364-4c2e-bb10-1efc3c97e509-0000 (default) at
scheduler-b7d3e590-e445-4362-83b8-6ac0125c4e84@10.0.49.4:65455
I0927 12:33:33.643388 76881920 sched.cpp:914] Scheduler::resourceOffers took
110616ns
I0927 12:33:33.643627 77955072 slave.cpp:1548] Forwarding agent update
{"operations":{},"resource_version_uuid":{"value":"ZjTWqkhCS1OSH+7JL8WTmQ=="},"slave_id":{"value":"b351e786-2364-4c2e-bb10-1efc3c97e509-S0"},"update_oversubscribed_resources":false}
I0927 12:33:33.644104 74735616 master.cpp:7939] Ignoring update on agent
b351e786-2364-4c2e-bb10-1efc3c97e509-S0 at slave(525)@10.0.49.4:65455
(Jenkinss-Mac-mini.local) as it reports no changes
I0927 12:33:33.644417 74735616 master.cpp:11462] Removing offer
b351e786-2364-4c2e-bb10-1efc3c97e509-O0
I0927 12:33:33.644670 74735616 master.cpp:4467] Processing ACCEPT call for
offers: [ b351e786-2364-4c2e-bb10-1efc3c97e509-O0 ] on agent
b351e786-2364-4c2e-bb10-1efc3c97e509-S0 at slave(525)@10.0.49.4:65455
(Jenkinss-Mac-mini.local) for framework
b351e786-2364-4c2e-bb10-1efc3c97e509-0000 (default) at
scheduler-b7d3e590-e445-4362-83b8-6ac0125c4e84@10.0.49.4:65455
I0927 12:33:33.644731 74735616 master.cpp:3541] Authorizing framework principal
'test-principal' to launch task 29779217-3d76-4b6a-9324-cd0fe3300b02
I0927 12:33:33.645570 75808768 master.cpp:12209] Adding task
29779217-3d76-4b6a-9324-cd0fe3300b02 with resources cpus(allocated: *):2;
mem(allocated: *):1024; disk(allocated: *):1024; ports(allocated:
*):[31000-32000] on agent b351e786-2364-4c2e-bb10-1efc3c97e509-S0 at
slave(525)@10.0.49.4:65455 (Jenkinss-Mac-mini.local)
I0927 12:33:33.645707 75808768 master.cpp:5439] Launching task
29779217-3d76-4b6a-9324-cd0fe3300b02 of framework
b351e786-2364-4c2e-bb10-1efc3c97e509-0000 (default) at
scheduler-b7d3e590-e445-4362-83b8-6ac0125c4e84@10.0.49.4:65455 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 b351e786-2364-4c2e-bb10-1efc3c97e509-S0 at slave(525)@10.0.49.4:65455
(Jenkinss-Mac-mini.local) on new executor
I0927 12:33:33.646374 74735616 slave.cpp:2014] Got assigned task
'29779217-3d76-4b6a-9324-cd0fe3300b02' for framework
b351e786-2364-4c2e-bb10-1efc3c97e509-0000
I0927 12:33:33.646473 74735616 slave.cpp:8908] Checkpointing FrameworkInfo to
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_Reboot_MfmJ3l/meta/slaves/b351e786-2364-4c2e-bb10-1efc3c97e509-S0/frameworks/b351e786-2364-4c2e-bb10-1efc3c97e509-0000/framework.info'
I0927 12:33:33.646921 74735616 slave.cpp:8919] Checkpointing framework pid
'scheduler-b7d3e590-e445-4362-83b8-6ac0125c4e84@10.0.49.4:65455' to
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_Reboot_MfmJ3l/meta/slaves/b351e786-2364-4c2e-bb10-1efc3c97e509-S0/frameworks/b351e786-2364-4c2e-bb10-1efc3c97e509-0000/framework.pid'
I0927 12:33:33.647595 74735616 slave.cpp:2388] Authorizing task
'29779217-3d76-4b6a-9324-cd0fe3300b02' for framework
b351e786-2364-4c2e-bb10-1efc3c97e509-0000
I0927 12:33:33.647636 74735616 slave.cpp:8466] Authorizing framework principal
'test-principal' to launch task 29779217-3d76-4b6a-9324-cd0fe3300b02
I0927 12:33:33.648391 74735616 slave.cpp:2831] Launching task
'29779217-3d76-4b6a-9324-cd0fe3300b02' for framework
b351e786-2364-4c2e-bb10-1efc3c97e509-0000
I0927 12:33:33.648459 74735616 paths.cpp:752] Creating sandbox
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_Reboot_MfmJ3l/slaves/b351e786-2364-4c2e-bb10-1efc3c97e509-S0/frameworks/b351e786-2364-4c2e-bb10-1efc3c97e509-0000/executors/29779217-3d76-4b6a-9324-cd0fe3300b02/runs/bd8fb76e-8a17-41d4-b6d4-1ac81a2d0632'
for user 'jenkins'
I0927 12:33:33.649603 74735616 slave.cpp:9694] Checkpointing ExecutorInfo to
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_Reboot_MfmJ3l/meta/slaves/b351e786-2364-4c2e-bb10-1efc3c97e509-S0/frameworks/b351e786-2364-4c2e-bb10-1efc3c97e509-0000/executors/29779217-3d76-4b6a-9324-cd0fe3300b02/executor.info'
I0927 12:33:33.650365 74735616 paths.cpp:755] Creating sandbox
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_Reboot_MfmJ3l/meta/slaves/b351e786-2364-4c2e-bb10-1efc3c97e509-S0/frameworks/b351e786-2364-4c2e-bb10-1efc3c97e509-0000/executors/29779217-3d76-4b6a-9324-cd0fe3300b02/runs/bd8fb76e-8a17-41d4-b6d4-1ac81a2d0632'
I0927 12:33:33.650733 74735616 slave.cpp:8994] Launching executor
'29779217-3d76-4b6a-9324-cd0fe3300b02' of framework
b351e786-2364-4c2e-bb10-1efc3c97e509-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
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_Reboot_MfmJ3l/slaves/b351e786-2364-4c2e-bb10-1efc3c97e509-S0/frameworks/b351e786-2364-4c2e-bb10-1efc3c97e509-0000/executors/29779217-3d76-4b6a-9324-cd0fe3300b02/runs/bd8fb76e-8a17-41d4-b6d4-1ac81a2d0632'
I0927 12:33:33.651190 74735616 slave.cpp:9725] Checkpointing TaskInfo to
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_Reboot_MfmJ3l/meta/slaves/b351e786-2364-4c2e-bb10-1efc3c97e509-S0/frameworks/b351e786-2364-4c2e-bb10-1efc3c97e509-0000/executors/29779217-3d76-4b6a-9324-cd0fe3300b02/runs/bd8fb76e-8a17-41d4-b6d4-1ac81a2d0632/tasks/29779217-3d76-4b6a-9324-cd0fe3300b02/task.info'
I0927 12:33:33.651871 74735616 slave.cpp:3028] Queued task
'29779217-3d76-4b6a-9324-cd0fe3300b02' for executor
'29779217-3d76-4b6a-9324-cd0fe3300b02' of framework
b351e786-2364-4c2e-bb10-1efc3c97e509-0000
I0927 12:33:33.651938 74735616 slave.cpp:988] Successfully attached
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_Reboot_MfmJ3l/slaves/b351e786-2364-4c2e-bb10-1efc3c97e509-S0/frameworks/b351e786-2364-4c2e-bb10-1efc3c97e509-0000/executors/29779217-3d76-4b6a-9324-cd0fe3300b02/runs/bd8fb76e-8a17-41d4-b6d4-1ac81a2d0632'
to virtual path
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_Reboot_MfmJ3l/slaves/b351e786-2364-4c2e-bb10-1efc3c97e509-S0/frameworks/b351e786-2364-4c2e-bb10-1efc3c97e509-0000/executors/29779217-3d76-4b6a-9324-cd0fe3300b02/runs/latest'
I0927 12:33:33.652115 74735616 slave.cpp:3509] Launching container
bd8fb76e-8a17-41d4-b6d4-1ac81a2d0632 for executor
'29779217-3d76-4b6a-9324-cd0fe3300b02' of framework
b351e786-2364-4c2e-bb10-1efc3c97e509-0000
I0927 12:33:33.652395 74735616 slave.cpp:988] Successfully attached
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_Reboot_MfmJ3l/slaves/b351e786-2364-4c2e-bb10-1efc3c97e509-S0/frameworks/b351e786-2364-4c2e-bb10-1efc3c97e509-0000/executors/29779217-3d76-4b6a-9324-cd0fe3300b02/runs/bd8fb76e-8a17-41d4-b6d4-1ac81a2d0632'
to virtual path
'/frameworks/b351e786-2364-4c2e-bb10-1efc3c97e509-0000/executors/29779217-3d76-4b6a-9324-cd0fe3300b02/runs/latest'
I0927 12:33:33.652424 74735616 slave.cpp:988] Successfully attached
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_Reboot_MfmJ3l/slaves/b351e786-2364-4c2e-bb10-1efc3c97e509-S0/frameworks/b351e786-2364-4c2e-bb10-1efc3c97e509-0000/executors/29779217-3d76-4b6a-9324-cd0fe3300b02/runs/bd8fb76e-8a17-41d4-b6d4-1ac81a2d0632'
to virtual path
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_Reboot_MfmJ3l/slaves/b351e786-2364-4c2e-bb10-1efc3c97e509-S0/frameworks/b351e786-2364-4c2e-bb10-1efc3c97e509-0000/executors/29779217-3d76-4b6a-9324-cd0fe3300b02/runs/bd8fb76e-8a17-41d4-b6d4-1ac81a2d0632'
I0927 12:33:33.652649 76881920 containerizer.cpp:1280] Starting container
bd8fb76e-8a17-41d4-b6d4-1ac81a2d0632
I0927 12:33:33.653412 76881920 containerizer.cpp:1446] Checkpointed
ContainerConfig at
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_Reboot_WZrsCD/containers/bd8fb76e-8a17-41d4-b6d4-1ac81a2d0632/config'
I0927 12:33:33.653439 76881920 containerizer.cpp:3118] Transitioning the state
of container bd8fb76e-8a17-41d4-b6d4-1ac81a2d0632 from PROVISIONING to PREPARING
I0927 12:33:33.655432 75272192 containerizer.cpp:1939] Launching
'mesos-containerizer' with flags '--help="false"
--launch_info="{"command":{"arguments":["mesos-executor","--launcher_dir=/Users/jenkins/workspace/workspace/mesos/Mesos_CI-build/FLAG/SSL/label/mac/mesos/build/src"],"shell":false,"value":"/Users/jenkins/workspace/workspace/mesos/Mesos_CI-build/FLAG/SSL/label/mac/mesos/build/src/mesos-executor"},"environment":{"variables":[{"name":"LIBPROCESS_PORT","type":"VALUE","value":"0"},{"name":"MESOS_AGENT_ENDPOINT","type":"VALUE","value":"10.0.49.4:65455"},{"name":"MESOS_CHECKPOINT","type":"VALUE","value":"1"},{"name":"MESOS_DIRECTORY","type":"VALUE","value":"/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_Reboot_MfmJ3l/slaves/b351e786-2364-4c2e-bb10-1efc3c97e509-S0/frameworks/b351e786-2364-4c2e-bb10-1efc3c97e509-0000/executors/29779217-3d76-4b6a-9324-cd0fe3300b02/runs/bd8fb76e-8a17-41d4-b6d4-1ac81a2d0632"},{"name":"MESOS_EXECUTOR_AUTHENTICATION_TOKEN","type":"VALUE","value":"eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJjaWQiOiJiZDhmYjc2ZS04YTE3LTQxZDQtYjZkNC0xYWM4MWEyZDA2MzIiLCJlaWQiOiIyOTc3OTIxNy0zZDc2LTRiNmEtOTMyNC1jZDBmZTMzMDBiMDIiLCJmaWQiOiJiMzUxZTc4Ni0yMzY0LTRjMmUtYmIxMC0xZWZjM2M5N2U1MDktMDAwMCJ9.I7wKRNdHADpS6OKxxrb15Ov7iIlmKhgniM0WE2UDB_I"},{"name":"MESOS_EXECUTOR_ID","type":"VALUE","value":"29779217-3d76-4b6a-9324-cd0fe3300b02"},{"name":"MESOS_EXECUTOR_SHUTDOWN_GRACE_PERIOD","type":"VALUE","value":"5secs"},{"name":"MESOS_FRAMEWORK_ID","type":"VALUE","value":"b351e786-2364-4c2e-bb10-1efc3c97e509-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":"b351e786-2364-4c2e-bb10-1efc3c97e509-S0"},{"name":"MESOS_SLAVE_PID","type":"VALUE","value":"slave(525)@10.0.49.4:65455"},{"name":"MESOS_SUBSCRIPTION_BACKOFF_MAX","type":"VALUE","value":"2secs"},{"name":"MESOS_SANDBOX","type":"VALUE","value":"/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_Reboot_MfmJ3l/slaves/b351e786-2364-4c2e-bb10-1efc3c97e509-S0/frameworks/b351e786-2364-4c2e-bb10-1efc3c97e509-0000/executors/29779217-3d76-4b6a-9324-cd0fe3300b02/runs/bd8fb76e-8a17-41d4-b6d4-1ac81a2d0632"}]},"task_environment":{},"user":"jenkins","working_directory":"/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_Reboot_MfmJ3l/slaves/b351e786-2364-4c2e-bb10-1efc3c97e509-S0/frameworks/b351e786-2364-4c2e-bb10-1efc3c97e509-0000/executors/29779217-3d76-4b6a-9324-cd0fe3300b02/runs/bd8fb76e-8a17-41d4-b6d4-1ac81a2d0632"}"
--pipe_read="20" --pipe_write="26"
--runtime_directory="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_Reboot_WZrsCD/containers/bd8fb76e-8a17-41d4-b6d4-1ac81a2d0632"'
I0927 12:33:33.657145 75272192 launcher.cpp:150] Forked child with pid '29340'
for container 'bd8fb76e-8a17-41d4-b6d4-1ac81a2d0632'
I0927 12:33:33.657331 75272192 containerizer.cpp:2044] Checkpointing
container's forked pid 29340 to
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_Reboot_MfmJ3l/meta/slaves/b351e786-2364-4c2e-bb10-1efc3c97e509-S0/frameworks/b351e786-2364-4c2e-bb10-1efc3c97e509-0000/executors/29779217-3d76-4b6a-9324-cd0fe3300b02/runs/bd8fb76e-8a17-41d4-b6d4-1ac81a2d0632/pids/forked.pid'
I0927 12:33:33.658349 75272192 containerizer.cpp:3118] Transitioning the state
of container bd8fb76e-8a17-41d4-b6d4-1ac81a2d0632 from PREPARING to ISOLATING
I0927 12:33:33.660046 75272192 containerizer.cpp:3118] Transitioning the state
of container bd8fb76e-8a17-41d4-b6d4-1ac81a2d0632 from ISOLATING to FETCHING
I0927 12:33:33.660158 76345344 fetcher.cpp:369] Starting to fetch URIs for
container: bd8fb76e-8a17-41d4-b6d4-1ac81a2d0632, directory:
/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_Reboot_MfmJ3l/slaves/b351e786-2364-4c2e-bb10-1efc3c97e509-S0/frameworks/b351e786-2364-4c2e-bb10-1efc3c97e509-0000/executors/29779217-3d76-4b6a-9324-cd0fe3300b02/runs/bd8fb76e-8a17-41d4-b6d4-1ac81a2d0632
I0927 12:33:33.660800 76881920 containerizer.cpp:3118] Transitioning the state
of container bd8fb76e-8a17-41d4-b6d4-1ac81a2d0632 from FETCHING to RUNNING
[warn] kq_init: detected broken kqueue; not using.: Undefined error: 0
I0927 12:33:33.822764 85651456 exec.cpp:162] Version: 1.8.0
I0927 12:33:33.826525 76345344 slave.cpp:4803] Got registration for executor
'29779217-3d76-4b6a-9324-cd0fe3300b02' of framework
b351e786-2364-4c2e-bb10-1efc3c97e509-0000 from executor(1)@10.0.49.4:50585
I0927 12:33:33.826947 76345344 slave.cpp:4889] Checkpointing executor pid
'executor(1)@10.0.49.4:50585' to
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_Reboot_MfmJ3l/meta/slaves/b351e786-2364-4c2e-bb10-1efc3c97e509-S0/frameworks/b351e786-2364-4c2e-bb10-1efc3c97e509-0000/executors/29779217-3d76-4b6a-9324-cd0fe3300b02/runs/bd8fb76e-8a17-41d4-b6d4-1ac81a2d0632/pids/libprocess.pid'
I0927 12:33:33.828539 74735616 slave.cpp:3241] Sending queued task
'29779217-3d76-4b6a-9324-cd0fe3300b02' to executor
'29779217-3d76-4b6a-9324-cd0fe3300b02' of framework
b351e786-2364-4c2e-bb10-1efc3c97e509-0000 at executor(1)@10.0.49.4:50585
I0927 12:33:33.828557 83505152 exec.cpp:236] Executor registered on agent
b351e786-2364-4c2e-bb10-1efc3c97e509-S0
I0927 12:33:33.835078 85651456 executor.cpp:182] Received SUBSCRIBED event
I0927 12:33:33.835548 85651456 executor.cpp:186] Subscribed executor on
Jenkinss-Mac-mini.local
I0927 12:33:33.835656 85651456 executor.cpp:182] Received LAUNCH event
I0927 12:33:33.841550 85651456 executor.cpp:679] Starting task
29779217-3d76-4b6a-9324-cd0fe3300b02
I0927 12:33:33.847766 75808768 slave.cpp:5269] Handling status update
TASK_STARTING (Status UUID: 473c3758-9a55-447a-9389-0f30b912e995) for task
29779217-3d76-4b6a-9324-cd0fe3300b02 of framework
b351e786-2364-4c2e-bb10-1efc3c97e509-0000 from executor(1)@10.0.49.4:50585
I0927 12:33:33.848549 85651456 executor.cpp:499] Running
'/Users/jenkins/workspace/workspace/mesos/Mesos_CI-build/FLAG/SSL/label/mac/mesos/build/src/mesos-containerizer
launch <POSSIBLY-SENSITIVE-DATA>'
I0927 12:33:33.848577 77418496 task_status_update_manager.cpp:328] Received
task status update TASK_STARTING (Status UUID:
473c3758-9a55-447a-9389-0f30b912e995) for task
29779217-3d76-4b6a-9324-cd0fe3300b02 of framework
b351e786-2364-4c2e-bb10-1efc3c97e509-0000
I0927 12:33:33.848615 77418496 task_status_update_manager.cpp:507] Creating
StatusUpdate stream for task 29779217-3d76-4b6a-9324-cd0fe3300b02 of framework
b351e786-2364-4c2e-bb10-1efc3c97e509-0000
I0927 12:33:33.849201 77418496 task_status_update_manager.cpp:842]
Checkpointing UPDATE for task status update TASK_STARTING (Status UUID:
473c3758-9a55-447a-9389-0f30b912e995) for task
29779217-3d76-4b6a-9324-cd0fe3300b02 of framework
b351e786-2364-4c2e-bb10-1efc3c97e509-0000
I0927 12:33:33.849369 77418496 task_status_update_manager.cpp:383] Forwarding
task status update TASK_STARTING (Status UUID:
473c3758-9a55-447a-9389-0f30b912e995) for task
29779217-3d76-4b6a-9324-cd0fe3300b02 of framework
b351e786-2364-4c2e-bb10-1efc3c97e509-0000 to the agent
I0927 12:33:33.849474 77955072 slave.cpp:5761] Forwarding the update
TASK_STARTING (Status UUID: 473c3758-9a55-447a-9389-0f30b912e995) for task
29779217-3d76-4b6a-9324-cd0fe3300b02 of framework
b351e786-2364-4c2e-bb10-1efc3c97e509-0000 to master@10.0.49.4:65455
I0927 12:33:33.849640 77955072 slave.cpp:5654] Task status update manager
successfully handled status update TASK_STARTING (Status UUID:
473c3758-9a55-447a-9389-0f30b912e995) for task
29779217-3d76-4b6a-9324-cd0fe3300b02 of framework
b351e786-2364-4c2e-bb10-1efc3c97e509-0000
I0927 12:33:33.849674 77955072 slave.cpp:5670] Sending acknowledgement for
status update TASK_STARTING (Status UUID: 473c3758-9a55-447a-9389-0f30b912e995)
for task 29779217-3d76-4b6a-9324-cd0fe3300b02 of framework
b351e786-2364-4c2e-bb10-1efc3c97e509-0000 to executor(1)@10.0.49.4:50585
I0927 12:33:33.849817 74735616 master.cpp:8375] Status update TASK_STARTING
(Status UUID: 473c3758-9a55-447a-9389-0f30b912e995) for task
29779217-3d76-4b6a-9324-cd0fe3300b02 of framework
b351e786-2364-4c2e-bb10-1efc3c97e509-0000 from agent
b351e786-2364-4c2e-bb10-1efc3c97e509-S0 at slave(525)@10.0.49.4:65455
(Jenkinss-Mac-mini.local)
I0927 12:33:33.849792 85651456 executor.cpp:693] Forked command at 29368
I0927 12:33:33.849851 74735616 master.cpp:8432] Forwarding status update
TASK_STARTING (Status UUID: 473c3758-9a55-447a-9389-0f30b912e995) for task
29779217-3d76-4b6a-9324-cd0fe3300b02 of framework
b351e786-2364-4c2e-bb10-1efc3c97e509-0000
I0927 12:33:33.849973 74735616 master.cpp:10932] Updating the state of task
29779217-3d76-4b6a-9324-cd0fe3300b02 of framework
b351e786-2364-4c2e-bb10-1efc3c97e509-0000 (latest state: TASK_STARTING, status
update state: TASK_STARTING)
I0927 12:33:33.850181 75808768 sched.cpp:1022] Scheduler::statusUpdate took
59451ns
I0927 12:33:33.850389 76345344 master.cpp:6241] Processing ACKNOWLEDGE call for
status 473c3758-9a55-447a-9389-0f30b912e995 for task
29779217-3d76-4b6a-9324-cd0fe3300b02 of framework
b351e786-2364-4c2e-bb10-1efc3c97e509-0000 (default) at
scheduler-b7d3e590-e445-4362-83b8-6ac0125c4e84@10.0.49.4:65455 on agent
b351e786-2364-4c2e-bb10-1efc3c97e509-S0
I0927 12:33:33.850618 75272192 task_status_update_manager.cpp:401] Received
task status update acknowledgement (UUID: 473c3758-9a55-447a-9389-0f30b912e995)
for task 29779217-3d76-4b6a-9324-cd0fe3300b02 of framework
b351e786-2364-4c2e-bb10-1efc3c97e509-0000
I0927 12:33:33.850680 75272192 task_status_update_manager.cpp:842]
Checkpointing ACK for task status update TASK_STARTING (Status UUID:
473c3758-9a55-447a-9389-0f30b912e995) for task
29779217-3d76-4b6a-9324-cd0fe3300b02 of framework
b351e786-2364-4c2e-bb10-1efc3c97e509-0000
I0927 12:33:33.850814 2560127808 slave.cpp:909] Agent terminating
I0927 12:33:33.851411 75272192 master.cpp:1251] Agent
b351e786-2364-4c2e-bb10-1efc3c97e509-S0 at slave(525)@10.0.49.4:65455
(Jenkinss-Mac-mini.local) disconnected
I0927 12:33:33.851459 75272192 master.cpp:3267] Disconnecting agent
b351e786-2364-4c2e-bb10-1efc3c97e509-S0 at slave(525)@10.0.49.4:65455
(Jenkinss-Mac-mini.local)
I0927 12:33:33.851498 75272192 master.cpp:3286] Deactivating agent
b351e786-2364-4c2e-bb10-1efc3c97e509-S0 at slave(525)@10.0.49.4:65455
(Jenkinss-Mac-mini.local)
I0927 12:33:33.851685 77418496 hierarchical.cpp:803] Agent
b351e786-2364-4c2e-bb10-1efc3c97e509-S0 deactivated
I0927 12:33:33.858314 81895424 exec.cpp:445] Executor asked to shutdown
I0927 12:33:33.858335 78491648 process.cpp:2632] Failed to deliver libprocess
message to /slave(525)/mesos.internal.StatusUpdateMessage
I0927 12:33:33.858819 84041728 executor.cpp:182] Received SHUTDOWN event
I0927 12:33:33.858850 84041728 executor.cpp:796] Shutting down
I0927 12:33:33.858909 84041728 executor.cpp:909] Sending SIGTERM to process
tree at pid 29368
I0927 12:33:33.890872 84041728 executor.cpp:922] Sent SIGTERM to the following
process trees:
[
--- 29368
/Users/jenkins/workspace/workspace/mesos/Mesos_CI-build/FLAG/SSL/label/mac/mesos/build/src/.libs/mesos-containerizer
launch --help=false --launch_info={"command":{"shell":true,"value":"sleep
1000"},"environment":{"variables":[{"name":"PATH","type":"VALUE","value":"/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin"},{"name":"PWD","type":"VALUE","value":"/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_Reboot_MfmJ3l/slaves/b351e786-2364-4c2e-bb10-1efc3c97e509-S0/frameworks/b351e786-2364-4c2e-bb10-1efc3c97e509-0000/executors/29779217-3d76-4b6a-9324-cd0fe3300b02/runs/bd8fb76e-8a17-41d4-b6d4-1ac81a2d0632"},{"name":"MESOS_SLAVE_PID","type":"VALUE","value":"slave(525)@10.0.49.4:65455"},{"name":"MESOS_SUBSCRIPTION_BACKOFF_MAX","type":"VALUE","value":"2secs"},{"name":"MESOS_RECOVERY_TIMEOUT","type":"VALUE","value":"15mins"},{"name":"MESOS_FRAMEWORK_ID","type":"VALUE","value":"b351e786-2364-4c2e-bb10-1efc3c97e509-0000"},{"name":"MESOS_EXECUTOR_ID","type":"VALUE","value":"29779217-3d76-4b6a-9324-cd0fe3300b02"},{"name":"MESOS_EXECUTOR_AUTHENTICATION_TOKEN","type":"VALUE","value":"eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJjaWQiOiJiZDhmYjc2ZS04YTE3LTQxZDQtYjZkNC0xYWM4MWEyZDA2MzIiLCJlaWQiOiIyOTc3OTIxNy0zZDc2LTRiNmEtOTMyNC1jZDBmZTMzMDBiMDIiLCJmaWQiOiJiMzUxZTc4Ni0yMzY0LTRjMmUtYmIxMC0xZWZjM2M5N2U1MDktMDAwMCJ9.I7wKRNdHADpS6OKxxrb15Ov7iIlmKhgniM0WE2UDB_I"},{"name":"MESOS_CHECKPOINT","type":"VALUE","value":"1"},{"name":"MESOS_SLAVE_ID","type":"VALUE","value":"b351e786-2364-4c2e-bb10-1efc3c97e509-S0"},{"name":"MESOS_SANDBOX","type":"VALUE","value":"/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_Reboot_MfmJ3l/slaves/b351e786-2364-4c2e-bb10-1efc3c97e509-S0/frameworks/b351e786-2364-4c2e-bb10-1efc3c97e509-0000/executors/29779217-3d76-4b6a-9324-cd0fe3300b02/runs/bd8fb76e-8a17-41d4-b6d4-1ac81a2d0632"},{"name":"MESOS_EXECUTOR_SHUTDOWN_GRACE_PERIOD","type":"VALUE","value":"5secs"},{"name":"SHLVL","type":"VALUE","value":"0"},{"name":"DUALCASE","type":"VALUE","value":"1"},{"name":"MESOS_AGENT_ENDPOINT","type":"VALUE","value":"10.0.49.4:65455"},{"name":"DYLD_LIBRARY_PATH","type":"VALUE","value":"/Users/jenkins/workspace/workspace/mesos/Mesos_CI-build/FLAG/SSL/label/mac/mesos/build/src/.libs"},{"name":"__CF_USER_TEXT_ENCODING","type":"VALUE","value":"0x1F5:0x0:0x0"},{"name":"MESOS_DIRECTORY","type":"VALUE","value":"/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_Reboot_MfmJ3l/slaves/b351e786-2364-4c2e-bb10-1efc3c97e509-S0/frameworks/b351e786-2364-4c2e-bb10-1efc3c97e509-0000/executors/29779217-3d76-4b6a-9324-cd0fe3300b02/runs/bd8fb76e-8a17-41d4-b6d4-1ac81a2d0632"},{"name":"LIBPROCESS_PORT","type":"VALUE","value":"0"},{"name":"MESOS_HTTP_COMMAND_EXECUTOR","type":"VALUE","value":"0"},{"name":"BIN_SH","type":"VALUE","value":"xpg4"}]}}
]
I0927 12:33:33.890951 84041728 executor.cpp:926] Scheduling escalation to
SIGKILL in 3secs from now
I0927 12:33:33.926167 85651456 executor.cpp:994] Command terminated with signal
Terminated: 15 (pid: 29368)
I0927 12:33:33.932322 78491648 process.cpp:2632] Failed to deliver libprocess
message to /slave(525)/mesos.internal.StatusUpdateMessage
I0927 12:34:09.694378 77955072 hierarchical.cpp:1568] Performed allocation for
1 agents in 308683ns
../../src/tests/slave_recovery_tests.cpp:2746: Failure
Failed to wait 15secs for executorStatus
I0927 12:34:09.700620 74199040 master.cpp:1366] Framework
b351e786-2364-4c2e-bb10-1efc3c97e509-0000 (default) at
scheduler-b7d3e590-e445-4362-83b8-6ac0125c4e84@10.0.49.4:65455 disconnected
I0927 12:34:09.700706 74199040 master.cpp:3230] Deactivating framework
b351e786-2364-4c2e-bb10-1efc3c97e509-0000 (default) at
scheduler-b7d3e590-e445-4362-83b8-6ac0125c4e84@10.0.49.4:65455
I0927 12:34:09.701102 74199040 master.cpp:3207] Disconnecting framework
b351e786-2364-4c2e-bb10-1efc3c97e509-0000 (default) at
scheduler-b7d3e590-e445-4362-83b8-6ac0125c4e84@10.0.49.4:65455
I0927 12:34:09.701148 74199040 master.cpp:1381] Giving framework
b351e786-2364-4c2e-bb10-1efc3c97e509-0000 (default) at
scheduler-b7d3e590-e445-4362-83b8-6ac0125c4e84@10.0.49.4:65455 0ns to failover
I0927 12:34:09.701460 74735616 hierarchical.cpp:420] Deactivated framework
b351e786-2364-4c2e-bb10-1efc3c97e509-0000
I0927 12:34:09.701930 74199040 master.cpp:9261] Framework failover timeout,
removing framework b351e786-2364-4c2e-bb10-1efc3c97e509-0000 (default) at
scheduler-b7d3e590-e445-4362-83b8-6ac0125c4e84@10.0.49.4:65455
I0927 12:34:09.701957 74199040 master.cpp:10197] Removing framework
b351e786-2364-4c2e-bb10-1efc3c97e509-0000 (default) at
scheduler-b7d3e590-e445-4362-83b8-6ac0125c4e84@10.0.49.4:65455
I0927 12:34:09.702101 74199040 master.cpp:10932] Updating the state of task
29779217-3d76-4b6a-9324-cd0fe3300b02 of framework
b351e786-2364-4c2e-bb10-1efc3c97e509-0000 (latest state: TASK_KILLED, status
update state: TASK_KILLED)
I0927 12:34:09.702507 74199040 master.cpp:11030] Removing task
29779217-3d76-4b6a-9324-cd0fe3300b02 with resources cpus(allocated: *):2;
mem(allocated: *):1024; disk(allocated: *):1024; ports(allocated:
*):[31000-32000] of framework b351e786-2364-4c2e-bb10-1efc3c97e509-0000 on
agent b351e786-2364-4c2e-bb10-1efc3c97e509-S0 at slave(525)@10.0.49.4:65455
(Jenkinss-Mac-mini.local)
I0927 12:34:09.702842 76881920 hierarchical.cpp:1240] Recovered cpus(allocated:
*):2; mem(allocated: *):1024; disk(allocated: *):1024; ports(allocated:
*):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000],
allocated: {}) on agent b351e786-2364-4c2e-bb10-1efc3c97e509-S0 from framework
b351e786-2364-4c2e-bb10-1efc3c97e509-0000
I0927 12:34:09.703212 76881920 hierarchical.cpp:359] Removed framework
b351e786-2364-4c2e-bb10-1efc3c97e509-0000
I0927 12:34:09.765949 2560127808 master.cpp:1093] Master terminating
I0927 12:34:09.766347 77955072 hierarchical.cpp:645] Removed agent
b351e786-2364-4c2e-bb10-1efc3c97e509-S0
[ FAILED ] SlaveRecoveryTest/0.Reboot, where TypeParam =
mesos::internal::slave::MesosContainerizer (36150 ms)
{noformat}
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
