Benno Evers created MESOS-9466:
----------------------------------
Summary: FetcherCacheTest.LocalCachedMissing is flaky
Key: MESOS-9466
URL: https://issues.apache.org/jira/browse/MESOS-9466
Project: Mesos
Issue Type: Bug
Environment: Mac OSX with ssl enabled
Reporter: Benno Evers
Observed the following failure in an internal CI run:
{noformat}
../../src/tests/fetcher_cache_tests.cpp:722: Failure
Failed to wait 15secs for awaitFinished(task.get())
{noformat}
Full log:
{noformat}
[ RUN ] FetcherCacheTest.LocalCachedMissing
I1210 16:16:09.364095 338650560 cluster.cpp:173] Creating default 'local'
authorizer
I1210 16:16:09.365344 237985792 master.cpp:414] Master
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca (Jenkinss-Mac-mini.local) started on
10.0.49.4:54069
I1210 16:16:09.365368 237985792 master.cpp:417] 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/OBl7Zi/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"
--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="/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/OBl7Zi/master"
--zk_session_timeout="10secs"
I1210 16:16:09.365530 237985792 master.cpp:466] Master only allowing
authenticated frameworks to register
I1210 16:16:09.365541 237985792 master.cpp:472] Master only allowing
authenticated agents to register
I1210 16:16:09.365550 237985792 master.cpp:478] Master only allowing
authenticated HTTP frameworks to register
I1210 16:16:09.365559 237985792 credentials.hpp:37] Loading credentials for
authentication from
'/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/OBl7Zi/credentials'
I1210 16:16:09.365763 237985792 master.cpp:522] Using default 'crammd5'
authenticator
I1210 16:16:09.365819 237985792 http.cpp:1017] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-readonly'
I1210 16:16:09.365888 237985792 http.cpp:1017] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-readwrite'
I1210 16:16:09.365967 237985792 http.cpp:1017] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-scheduler'
I1210 16:16:09.366027 237985792 master.cpp:603] Authorization enabled
I1210 16:16:09.366263 239058944 whitelist_watcher.cpp:77] No whitelist given
I1210 16:16:09.366286 237449216 hierarchical.cpp:175] Initialized hierarchical
allocator process
I1210 16:16:09.368378 237985792 master.cpp:2089] Elected as the leading master!
I1210 16:16:09.368408 237985792 master.cpp:1644] Recovering from registrar
I1210 16:16:09.368455 235839488 registrar.cpp:339] Recovering registrar
I1210 16:16:09.368711 235839488 registrar.cpp:383] Successfully fetched the
registry (0B) in 224us
I1210 16:16:09.368775 235839488 registrar.cpp:487] Applied 1 operations in
23922ns; attempting to update the registry
I1210 16:16:09.369017 235839488 registrar.cpp:544] Successfully updated the
registry in 218112ns
I1210 16:16:09.369065 235839488 registrar.cpp:416] Successfully recovered
registrar
I1210 16:16:09.369207 238522368 master.cpp:1758] Recovered 0 agents from the
registry (155B); allowing 10mins for agents to reregister
I1210 16:16:09.369225 236912640 hierarchical.cpp:215] Skipping recovery of
hierarchical allocator: nothing to recover
W1210 16:16:09.369658 338650560 process.cpp:2829] Attempted to spawn already
running process version@10.0.49.4:54069
I1210 16:16:09.370749 338650560 containerizer.cpp:305] Using isolation {
environment_secret, filesystem/posix, posix/mem, posix/cpu }
I1210 16:16:09.371047 338650560 provisioner.cpp:298] Using default backend
'copy'
W1210 16:16:09.372812 338650560 process.cpp:2829] Attempted to spawn already
running process files@10.0.49.4:54069
I1210 16:16:09.373267 338650560 cluster.cpp:485] Creating default 'local'
authorizer
I1210 16:16:09.374140 235302912 slave.cpp:268] Mesos agent started on
(72)@10.0.49.4:54069
I1210 16:16:09.374166 235302912 slave.cpp:269] Flags at startup: --acls=""
--appc_simple_discovery_uri_prefix="http://";
--appc_store_dir="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_lOXN2a/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/FetcherCacheTest_LocalCachedMissing_lOXN2a/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/FetcherCacheTest_LocalCachedMissing_lOXN2a/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/FetcherCacheTest_LocalCachedMissing_lOXN2a/fetch"
--fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins"
--frameworks_home="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_lOXN2a/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="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_lOXN2a/http_credentials"
--http_heartbeat_interval="30secs" --initialize_driver_logging="true"
--isolation="posix/cpu,posix/mem"
--jwt_secret_key="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_lOXN2a/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:1000;mem:1000"
--runtime_dir="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_lOXN2a"
--sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true"
--version="false"
--work_dir="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod"
--zk_session_timeout="10secs"
I1210 16:16:09.374377 235302912 credentials.hpp:86] Loading credential for
authentication from
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_lOXN2a/credential'
I1210 16:16:09.374498 235302912 slave.cpp:301] Agent using credential for:
test-principal
I1210 16:16:09.374528 235302912 credentials.hpp:37] Loading credentials for
authentication from
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_lOXN2a/http_credentials'
I1210 16:16:09.374711 235302912 http.cpp:1017] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-executor'
I1210 16:16:09.374785 235302912 http.cpp:1038] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-executor'
I1210 16:16:09.374910 235302912 http.cpp:1017] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-readonly'
I1210 16:16:09.374956 235302912 http.cpp:1038] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-readonly'
I1210 16:16:09.375041 235302912 http.cpp:1017] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-readwrite'
I1210 16:16:09.375116 235302912 http.cpp:1038] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-readwrite'
I1210 16:16:09.375293 235302912 disk_profile_adaptor.cpp:80] Creating default
disk profile adaptor module
I1210 16:16:09.375599 235302912 slave.cpp:616] Agent resources:
[{"name":"cpus","scalar":{"value":1000.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1000.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1064061.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
I1210 16:16:09.375717 235302912 slave.cpp:624] Agent attributes: [ ]
I1210 16:16:09.375730 235302912 slave.cpp:633] Agent hostname:
Jenkinss-Mac-mini.local
I1210 16:16:09.375802 239058944 task_status_update_manager.cpp:181] Pausing
sending task status updates
I1210 16:16:09.376260 237985792 state.cpp:66] Recovering state from
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/meta'
I1210 16:16:09.376351 236376064 slave.cpp:6935] Finished recovering
checkpointed state from
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/meta',
beginning agent recovery
I1210 16:16:09.376411 239058944 task_status_update_manager.cpp:207] Recovering
task status update manager
I1210 16:16:09.376525 235839488 containerizer.cpp:727] Recovering Mesos
containers
I1210 16:16:09.376662 235839488 containerizer.cpp:1053] Recovering isolators
I1210 16:16:09.376950 237449216 containerizer.cpp:1092] Recovering provisioner
I1210 16:16:09.377251 238522368 provisioner.cpp:494] Provisioner recovery
complete
I1210 16:16:09.377533 239058944 composing.cpp:339] Finished recovering all
containerizers
I1210 16:16:09.377598 238522368 slave.cpp:7164] Recovering executors
I1210 16:16:09.377668 238522368 slave.cpp:7317] Finished recovery
I1210 16:16:09.378412 237449216 task_status_update_manager.cpp:181] Pausing
sending task status updates
I1210 16:16:09.378417 238522368 slave.cpp:1259] New master detected at
master@10.0.49.4:54069
I1210 16:16:09.378460 238522368 slave.cpp:1324] Detecting new master
I1210 16:16:09.390152 239058944 slave.cpp:1351] Authenticating with master
master@10.0.49.4:54069
I1210 16:16:09.390199 239058944 slave.cpp:1360] Using default CRAM-MD5
authenticatee
I1210 16:16:09.390297 235839488 authenticatee.cpp:121] Creating new client SASL
connection
I1210 16:16:09.390475 237985792 master.cpp:9683] Authenticating
slave(72)@10.0.49.4:54069
I1210 16:16:09.390545 236912640 authenticator.cpp:414] Starting authentication
session for crammd5-authenticatee(167)@10.0.49.4:54069
I1210 16:16:09.390635 237449216 authenticator.cpp:98] Creating new server SASL
connection
I1210 16:16:09.390718 238522368 authenticatee.cpp:213] Received SASL
authentication mechanisms: CRAM-MD5
I1210 16:16:09.390789 238522368 authenticatee.cpp:239] Attempting to
authenticate with mechanism 'CRAM-MD5'
I1210 16:16:09.390838 235302912 authenticator.cpp:204] Received SASL
authentication start
I1210 16:16:09.390929 235302912 authenticator.cpp:326] Authentication requires
more steps
I1210 16:16:09.390996 236376064 authenticatee.cpp:259] Received SASL
authentication step
I1210 16:16:09.391064 239058944 authenticator.cpp:232] Received SASL
authentication step
I1210 16:16:09.391082 239058944 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
I1210 16:16:09.391094 239058944 auxprop.cpp:181] Looking up auxiliary property
'*userPassword'
I1210 16:16:09.391115 239058944 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I1210 16:16:09.391130 239058944 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
I1210 16:16:09.391142 239058944 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I1210 16:16:09.391151 239058944 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1210 16:16:09.391165 239058944 authenticator.cpp:318] Authentication success
I1210 16:16:09.391219 235839488 authenticatee.cpp:299] Authentication success
I1210 16:16:09.391225 237985792 master.cpp:9715] Successfully authenticated
principal 'test-principal' at slave(72)@10.0.49.4:54069
I1210 16:16:09.391260 236912640 authenticator.cpp:432] Authentication session
cleanup for crammd5-authenticatee(167)@10.0.49.4:54069
I1210 16:16:09.391443 237449216 slave.cpp:1451] Successfully authenticated with
master master@10.0.49.4:54069
I1210 16:16:09.391636 237449216 slave.cpp:1882] Will retry registration in
6.666879ms if necessary
I1210 16:16:09.391723 237985792 master.cpp:6605] Received register agent
message from slave(72)@10.0.49.4:54069 (Jenkinss-Mac-mini.local)
I1210 16:16:09.391819 237985792 master.cpp:3935] Authorizing agent providing
resources 'cpus:1000; mem:1000; disk:1064061; ports:[31000-32000]' with
principal 'test-principal'
I1210 16:16:09.392087 236912640 master.cpp:6672] Authorized registration of
agent at slave(72)@10.0.49.4:54069 (Jenkinss-Mac-mini.local)
I1210 16:16:09.392146 236912640 master.cpp:6787] Registering agent at
slave(72)@10.0.49.4:54069 (Jenkinss-Mac-mini.local) with id
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0
I1210 16:16:09.392383 239058944 registrar.cpp:487] Applied 1 operations in
111743ns; attempting to update the registry
I1210 16:16:09.392611 239058944 registrar.cpp:544] Successfully updated the
registry in 185856ns
I1210 16:16:09.392686 236376064 master.cpp:6835] Admitted agent
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0 at slave(72)@10.0.49.4:54069
(Jenkinss-Mac-mini.local)
I1210 16:16:09.392930 236376064 master.cpp:6880] Registered agent
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0 at slave(72)@10.0.49.4:54069
(Jenkinss-Mac-mini.local) with cpus:1000; mem:1000; disk:1064061;
ports:[31000-32000]
I1210 16:16:09.393071 236912640 slave.cpp:1484] Registered with master
master@10.0.49.4:54069; given agent ID 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0
I1210 16:16:09.393079 237449216 hierarchical.cpp:603] Added agent
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0 (Jenkinss-Mac-mini.local) with
cpus:1000; mem:1000; disk:1064061; ports:[31000-32000] (allocated: {})
I1210 16:16:09.393172 239058944 task_status_update_manager.cpp:188] Resuming
sending task status updates
I1210 16:16:09.393249 237449216 hierarchical.cpp:1566] Performed allocation for
1 agents in 52421ns
I1210 16:16:09.393488 236912640 slave.cpp:1504] Checkpointing SlaveInfo to
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/meta/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/slave.info'
I1210 16:16:09.393718 338650560 sched.cpp:232] Version: 1.8.0
I1210 16:16:09.393957 237449216 sched.cpp:336] New master detected at
master@10.0.49.4:54069
I1210 16:16:09.394006 237449216 sched.cpp:401] Authenticating with master
master@10.0.49.4:54069
I1210 16:16:09.394017 237449216 sched.cpp:408] Using default CRAM-MD5
authenticatee
I1210 16:16:09.394122 237985792 authenticatee.cpp:121] Creating new client SASL
connection
I1210 16:16:09.394381 236376064 master.cpp:9683] Authenticating
scheduler-b81d7c78-4560-4ead-8d61-f29263a54aa9@10.0.49.4:54069
I1210 16:16:09.394335 236912640 slave.cpp:1553] Forwarding agent update
{"operations":{},"resource_version_uuid":{"value":"lMz6MpzGQTCaPnpqiRjWhg=="},"slave_id":{"value":"57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0"},"update_oversubscribed_resources":false}
I1210 16:16:09.394500 239058944 authenticator.cpp:414] Starting authentication
session for crammd5-authenticatee(168)@10.0.49.4:54069
I1210 16:16:09.394601 236376064 authenticator.cpp:98] Creating new server SASL
connection
I1210 16:16:09.394701 237985792 authenticatee.cpp:213] Received SASL
authentication mechanisms: CRAM-MD5
I1210 16:16:09.394759 237985792 authenticatee.cpp:239] Attempting to
authenticate with mechanism 'CRAM-MD5'
I1210 16:16:09.394876 236912640 authenticator.cpp:204] Received SASL
authentication start
I1210 16:16:09.394873 235839488 master.cpp:7939] Ignoring update on agent
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0 at slave(72)@10.0.49.4:54069
(Jenkinss-Mac-mini.local) as it reports no changes
I1210 16:16:09.394955 236912640 authenticator.cpp:326] Authentication requires
more steps
I1210 16:16:09.395030 237449216 authenticatee.cpp:259] Received SASL
authentication step
I1210 16:16:09.395083 235302912 authenticator.cpp:232] Received SASL
authentication step
I1210 16:16:09.395105 235302912 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
I1210 16:16:09.395118 235302912 auxprop.cpp:181] Looking up auxiliary property
'*userPassword'
I1210 16:16:09.395141 235302912 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I1210 16:16:09.395156 235302912 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
I1210 16:16:09.395169 235302912 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I1210 16:16:09.395177 235302912 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1210 16:16:09.395210 235302912 authenticator.cpp:318] Authentication success
I1210 16:16:09.395296 239058944 authenticatee.cpp:299] Authentication success
I1210 16:16:09.395418 236376064 master.cpp:9715] Successfully authenticated
principal 'test-principal' at
scheduler-b81d7c78-4560-4ead-8d61-f29263a54aa9@10.0.49.4:54069
I1210 16:16:09.395560 237985792 authenticator.cpp:432] Authentication session
cleanup for crammd5-authenticatee(168)@10.0.49.4:54069
I1210 16:16:09.395798 235839488 sched.cpp:513] Successfully authenticated with
master master@10.0.49.4:54069
I1210 16:16:09.395817 235839488 sched.cpp:817] Sending SUBSCRIBE call to
master@10.0.49.4:54069
I1210 16:16:09.395967 235839488 sched.cpp:850] Will retry registration in
1.408513877secs if necessary
I1210 16:16:09.396147 236376064 master.cpp:2865] Received SUBSCRIBE call for
framework 'default' at
scheduler-b81d7c78-4560-4ead-8d61-f29263a54aa9@10.0.49.4:54069
W1210 16:16:09.396168 236376064 master.cpp:2873] Setting 'principal' in
FrameworkInfo to 'test-principal' because the framework authenticated with that
principal but did not set it in FrameworkInfo
I1210 16:16:09.396184 236376064 master.cpp:2161] Authorizing framework
principal 'test-principal' to receive offers for roles '{ * }'
I1210 16:16:09.396402 235302912 master.cpp:2946] Subscribing framework default
with checkpointing enabled and capabilities [ ]
I1210 16:16:09.397051 235302912 master.cpp:9913] Adding framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 (default) at
scheduler-b81d7c78-4560-4ead-8d61-f29263a54aa9@10.0.49.4:54069 with roles { }
suppressed
I1210 16:16:09.397307 237985792 sched.cpp:744] Framework registered with
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:09.397382 237985792 sched.cpp:758] Scheduler::registered took
54660ns
I1210 16:16:09.397450 237449216 hierarchical.cpp:304] Added framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:09.397909 237449216 hierarchical.cpp:1566] Performed allocation for
1 agents in 379109ns
I1210 16:16:09.398092 235839488 master.cpp:9498] Sending offers [
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-O0 ] to framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 (default) at
scheduler-b81d7c78-4560-4ead-8d61-f29263a54aa9@10.0.49.4:54069
I1210 16:16:09.398402 235302912 sched.cpp:914] Scheduler::resourceOffers took
108227ns
I1210 16:16:09.399013 238522368 master.cpp:11501] Removing offer
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-O0
I1210 16:16:09.399245 238522368 master.cpp:4456] Processing ACCEPT call for
offers: [ 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-O0 ] on agent
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0 at slave(72)@10.0.49.4:54069
(Jenkinss-Mac-mini.local) for framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 (default) at
scheduler-b81d7c78-4560-4ead-8d61-f29263a54aa9@10.0.49.4:54069
I1210 16:16:09.399317 238522368 master.cpp:3552] Authorizing framework
principal 'test-principal' to launch task 0
I1210 16:16:09.399968 239058944 master.cpp:4033] Adding task 0 with resources
cpus(allocated: *):1; mem(allocated: *):1 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 (default) at
scheduler-b81d7c78-4560-4ead-8d61-f29263a54aa9@10.0.49.4:54069 on agent
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0 at slave(72)@10.0.49.4:54069
(Jenkinss-Mac-mini.local)
I1210 16:16:09.400104 239058944 master.cpp:5428] Launching task 0 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 (default) at
scheduler-b81d7c78-4560-4ead-8d61-f29263a54aa9@10.0.49.4:54069 with resources
[{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":1.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":1.0},"type":"SCALAR"}]
on agent 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0 at slave(72)@10.0.49.4:54069
(Jenkinss-Mac-mini.local) on new executor
I1210 16:16:09.400518 236376064 hierarchical.cpp:1238] Recovered
cpus(allocated: *):999; mem(allocated: *):999; disk(allocated: *):1064061;
ports(allocated: *):[31000-32000] (total: cpus:1000; mem:1000; disk:1064061;
ports:[31000-32000], allocated: cpus(allocated: *):1; mem(allocated: *):1) on
agent 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0 from framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:09.400552 236376064 hierarchical.cpp:1284] Framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 filtered agent
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0 for 5secs
I1210 16:16:09.400775 236912640 slave.cpp:2019] Got assigned task '0' for
framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:09.400923 236912640 slave.cpp:8918] Checkpointing FrameworkInfo to
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/meta/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/framework.info'
I1210 16:16:09.401618 236912640 slave.cpp:8929] Checkpointing framework pid
'scheduler-b81d7c78-4560-4ead-8d61-f29263a54aa9@10.0.49.4:54069' to
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/meta/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/framework.pid'
I1210 16:16:09.402329 236912640 slave.cpp:2393] Authorizing task '0' for
framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:09.402366 236912640 slave.cpp:8494] Authorizing framework principal
'test-principal' to launch task 0
I1210 16:16:09.403012 236912640 slave.cpp:2836] Launching task '0' for
framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:09.403077 236912640 paths.cpp:752] Creating sandbox
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/0/runs/98607e71-d684-4edc-b473-53f66474b58f'
for user 'jenkins'
I1210 16:16:09.404078 236912640 slave.cpp:9704] Checkpointing ExecutorInfo to
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/meta/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/0/executor.info'
I1210 16:16:09.404745 236912640 paths.cpp:755] Creating sandbox
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/meta/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/0/runs/98607e71-d684-4edc-b473-53f66474b58f'
I1210 16:16:09.405272 236912640 slave.cpp:9004] Launching executor '0' of
framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-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/FetcherCacheTest_LocalCachedMissing_kN4Xod/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/0/runs/98607e71-d684-4edc-b473-53f66474b58f'
I1210 16:16:09.405728 236912640 slave.cpp:9735] Checkpointing TaskInfo to
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/meta/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/0/runs/98607e71-d684-4edc-b473-53f66474b58f/tasks/0/task.info'
I1210 16:16:09.406410 236912640 slave.cpp:3033] Queued task '0' for executor
'0' of framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:09.406471 236912640 slave.cpp:993] Successfully attached
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/0/runs/98607e71-d684-4edc-b473-53f66474b58f'
to virtual path
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/0/runs/latest'
I1210 16:16:09.406738 236912640 slave.cpp:3514] Launching container
98607e71-d684-4edc-b473-53f66474b58f for executor '0' of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:09.406939 236912640 slave.cpp:993] Successfully attached
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/0/runs/98607e71-d684-4edc-b473-53f66474b58f'
to virtual path
'/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/0/runs/latest'
I1210 16:16:09.406970 236912640 slave.cpp:993] Successfully attached
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/0/runs/98607e71-d684-4edc-b473-53f66474b58f'
to virtual path
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/0/runs/98607e71-d684-4edc-b473-53f66474b58f'
I1210 16:16:09.407258 237985792 containerizer.cpp:1288] Starting container
98607e71-d684-4edc-b473-53f66474b58f
I1210 16:16:09.408113 237985792 containerizer.cpp:1454] Checkpointed
ContainerConfig at
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_lOXN2a/containers/98607e71-d684-4edc-b473-53f66474b58f/config'
I1210 16:16:09.408131 237985792 containerizer.cpp:3130] Transitioning the state
of container 98607e71-d684-4edc-b473-53f66474b58f from PROVISIONING to PREPARING
I1210 16:16:09.409781 238522368 containerizer.cpp:1947] 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:54069"},{"name":"MESOS_CHECKPOINT","type":"VALUE","value":"1"},{"name":"MESOS_DIRECTORY","type":"VALUE","value":"/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/0/runs/98607e71-d684-4edc-b473-53f66474b58f"},{"name":"MESOS_EXECUTOR_AUTHENTICATION_TOKEN","type":"VALUE","value":"eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJjaWQiOiI5ODYwN2U3MS1kNjg0LTRlZGMtYjQ3My01M2Y2NjQ3NGI1OGYiLCJlaWQiOiIwIiwiZmlkIjoiNTdmMjgwMzUtZTVmYS00ZTJhLThiOGMtMWNhZjFmOWM4NWNhLTAwMDAifQ.2yLte9yqgGgaVK7E5iaHdNp62Gyu-OnBXuM92CzKfC8"},{"name":"MESOS_EXECUTOR_ID","type":"VALUE","value":"0"},{"name":"MESOS_EXECUTOR_SHUTDOWN_GRACE_PERIOD","type":"VALUE","value":"5secs"},{"name":"MESOS_FRAMEWORK_ID","type":"VALUE","value":"57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-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":"57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0"},{"name":"MESOS_SLAVE_PID","type":"VALUE","value":"slave(72)@10.0.49.4:54069"},{"name":"MESOS_SUBSCRIPTION_BACKOFF_MAX","type":"VALUE","value":"2secs"},{"name":"MESOS_SANDBOX","type":"VALUE","value":"/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/0/runs/98607e71-d684-4edc-b473-53f66474b58f"}]},"task_environment":{},"user":"jenkins","working_directory":"/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/0/runs/98607e71-d684-4edc-b473-53f66474b58f"}"
--pipe_read="12" --pipe_write="15"
--runtime_directory="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_lOXN2a/containers/98607e71-d684-4edc-b473-53f66474b58f"'
I1210 16:16:09.411166 238522368 launcher.cpp:145] Forked child with pid '32293'
for container '98607e71-d684-4edc-b473-53f66474b58f'
I1210 16:16:09.411396 238522368 containerizer.cpp:2052] Checkpointing
container's forked pid 32293 to
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/meta/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/0/runs/98607e71-d684-4edc-b473-53f66474b58f/pids/forked.pid'
I1210 16:16:09.412559 238522368 containerizer.cpp:3130] Transitioning the state
of container 98607e71-d684-4edc-b473-53f66474b58f from PREPARING to ISOLATING
I1210 16:16:09.413570 238522368 containerizer.cpp:3130] Transitioning the state
of container 98607e71-d684-4edc-b473-53f66474b58f from ISOLATING to FETCHING
I1210 16:16:09.413830 237985792 fetcher.cpp:369] Starting to fetch URIs for
container: 98607e71-d684-4edc-b473-53f66474b58f, directory:
/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/0/runs/98607e71-d684-4edc-b473-53f66474b58f
I1210 16:16:09.413925 237985792 fetcher.cpp:1015] Created cache entry
'jenkins@/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/mesos-fetcher-test-assets/mesos-fetcher-test-cmd'
with file: c1-mesos-fetc_r-test-cmd
I1210 16:16:09.414022 239058944 fetcher.cpp:312] Fetching size for URI:
/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/mesos-fetcher-test-assets/mesos-fetcher-test-cmd
I1210 16:16:09.414189 237985792 fetcher.cpp:731] Claiming fetcher cache space
for:
jenkins@/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/mesos-fetcher-test-assets/mesos-fetcher-test-cmd
I1210 16:16:09.414209 237985792 fetcher.cpp:1266] Claimed cache space: 30B, now
using: 30B
I1210 16:16:09.415144 236912640 fetcher.cpp:889] Fetching URIs using command
'/Users/jenkins/workspace/workspace/mesos/Mesos_CI-build/FLAG/SSL/label/mac/mesos/build/src/mesos-fetcher'
I1210 16:16:09.538447 236376064 fetcher.cpp:1278] Released cache space: 0B, now
using: 30B
I1210 16:16:09.538640 237985792 containerizer.cpp:3130] Transitioning the state
of container 98607e71-d684-4edc-b473-53f66474b58f from FETCHING to RUNNING
[warn] kq_init: detected broken kqueue; not using.: Undefined error: 0
I1210 16:16:09.611101 13078528 exec.cpp:162] Version: 1.8.0
I1210 16:16:09.614238 236912640 slave.cpp:4829] Got registration for executor
'0' of framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 from
executor(1)@10.0.49.4:54519
I1210 16:16:09.614504 236912640 slave.cpp:4915] Checkpointing executor pid
'executor(1)@10.0.49.4:54519' to
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/meta/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/0/runs/98607e71-d684-4edc-b473-53f66474b58f/pids/libprocess.pid'
I1210 16:16:09.616137 237985792 slave.cpp:3246] Sending queued task '0' to
executor '0' of framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 at
executor(1)@10.0.49.4:54519
I1210 16:16:09.616175 10932224 exec.cpp:236] Executor registered on agent
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0
I1210 16:16:09.619885 9322496 executor.cpp:184] Received SUBSCRIBED event
I1210 16:16:09.620349 9322496 executor.cpp:188] Subscribed executor on
Jenkinss-Mac-mini.local
I1210 16:16:09.620441 9322496 executor.cpp:184] Received LAUNCH event
I1210 16:16:09.623586 9322496 executor.cpp:687] Starting task 0
I1210 16:16:09.626994 237449216 slave.cpp:5295] Handling status update
TASK_STARTING (Status UUID: 90dab562-4fe9-4ac0-96ef-cd2a4c0299f3) for task 0 of
framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 from
executor(1)@10.0.49.4:54519
I1210 16:16:09.627763 239058944 task_status_update_manager.cpp:328] Received
task status update TASK_STARTING (Status UUID:
90dab562-4fe9-4ac0-96ef-cd2a4c0299f3) for task 0 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:09.627810 239058944 task_status_update_manager.cpp:507] Creating
StatusUpdate stream for task 0 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:09.628340 239058944 task_status_update_manager.cpp:842]
Checkpointing UPDATE for task status update TASK_STARTING (Status UUID:
90dab562-4fe9-4ac0-96ef-cd2a4c0299f3) for task 0 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:09.628520 239058944 task_status_update_manager.cpp:383] Forwarding
task status update TASK_STARTING (Status UUID:
90dab562-4fe9-4ac0-96ef-cd2a4c0299f3) for task 0 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 to the agent
I1210 16:16:09.628594 237985792 slave.cpp:5787] Forwarding the update
TASK_STARTING (Status UUID: 90dab562-4fe9-4ac0-96ef-cd2a4c0299f3) for task 0 of
framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 to master@10.0.49.4:54069
I1210 16:16:09.628742 237985792 slave.cpp:5680] Task status update manager
successfully handled status update TASK_STARTING (Status UUID:
90dab562-4fe9-4ac0-96ef-cd2a4c0299f3) for task 0 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:09.628780 237985792 slave.cpp:5696] Sending acknowledgement for
status update TASK_STARTING (Status UUID: 90dab562-4fe9-4ac0-96ef-cd2a4c0299f3)
for task 0 of framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 to
executor(1)@10.0.49.4:54519
I1210 16:16:09.628799 237449216 master.cpp:8375] Status update TASK_STARTING
(Status UUID: 90dab562-4fe9-4ac0-96ef-cd2a4c0299f3) for task 0 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 from agent
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0 at slave(72)@10.0.49.4:54069
(Jenkinss-Mac-mini.local)
I1210 16:16:09.628862 237449216 master.cpp:8432] Forwarding status update
TASK_STARTING (Status UUID: 90dab562-4fe9-4ac0-96ef-cd2a4c0299f3) for task 0 of
framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:09.629009 237449216 master.cpp:10962] Updating the state of task 0
of framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 (latest state:
TASK_STARTING, status update state: TASK_STARTING)
I1210 16:16:09.629267 236376064 sched.cpp:1022] Scheduler::statusUpdate took
124679ns
I1210 16:16:09.629458 236912640 master.cpp:6231] Processing ACKNOWLEDGE call
for status 90dab562-4fe9-4ac0-96ef-cd2a4c0299f3 for task 0 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 (default) at
scheduler-b81d7c78-4560-4ead-8d61-f29263a54aa9@10.0.49.4:54069 on agent
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0
I1210 16:16:09.629652 238522368 task_status_update_manager.cpp:401] Received
task status update acknowledgement (UUID: 90dab562-4fe9-4ac0-96ef-cd2a4c0299f3)
for task 0 of framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:09.629731 238522368 task_status_update_manager.cpp:842]
Checkpointing ACK for task status update TASK_STARTING (Status UUID:
90dab562-4fe9-4ac0-96ef-cd2a4c0299f3) for task 0 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:09.629899 235302912 slave.cpp:4531] Task status update manager
successfully handled status update acknowledgement (UUID:
90dab562-4fe9-4ac0-96ef-cd2a4c0299f3) for task 0 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:09.631857 9322496 executor.cpp:502] Running
'/Users/jenkins/workspace/workspace/mesos/Mesos_CI-build/FLAG/SSL/label/mac/mesos/build/src/mesos-containerizer
launch <POSSIBLY-SENSITIVE-DATA>'
I1210 16:16:09.632958 9322496 executor.cpp:702] Forked command at 32337
I1210 16:16:09.634002 239058944 slave.cpp:5295] Handling status update
TASK_RUNNING (Status UUID: de60ec3b-bcfe-4451-9a01-e3a090f6dc86) for task 0 of
framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 from
executor(1)@10.0.49.4:54519
I1210 16:16:09.634852 235839488 task_status_update_manager.cpp:328] Received
task status update TASK_RUNNING (Status UUID:
de60ec3b-bcfe-4451-9a01-e3a090f6dc86) for task 0 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:09.634909 235839488 task_status_update_manager.cpp:842]
Checkpointing UPDATE for task status update TASK_RUNNING (Status UUID:
de60ec3b-bcfe-4451-9a01-e3a090f6dc86) for task 0 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:09.635073 235839488 task_status_update_manager.cpp:383] Forwarding
task status update TASK_RUNNING (Status UUID:
de60ec3b-bcfe-4451-9a01-e3a090f6dc86) for task 0 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 to the agent
I1210 16:16:09.635138 236376064 slave.cpp:5787] Forwarding the update
TASK_RUNNING (Status UUID: de60ec3b-bcfe-4451-9a01-e3a090f6dc86) for task 0 of
framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 to master@10.0.49.4:54069
I1210 16:16:09.635252 236376064 slave.cpp:5680] Task status update manager
successfully handled status update TASK_RUNNING (Status UUID:
de60ec3b-bcfe-4451-9a01-e3a090f6dc86) for task 0 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:09.635288 236376064 slave.cpp:5696] Sending acknowledgement for
status update TASK_RUNNING (Status UUID: de60ec3b-bcfe-4451-9a01-e3a090f6dc86)
for task 0 of framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 to
executor(1)@10.0.49.4:54519
I1210 16:16:09.635329 235302912 master.cpp:8375] Status update TASK_RUNNING
(Status UUID: de60ec3b-bcfe-4451-9a01-e3a090f6dc86) for task 0 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 from agent
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0 at slave(72)@10.0.49.4:54069
(Jenkinss-Mac-mini.local)
I1210 16:16:09.635365 235302912 master.cpp:8432] Forwarding status update
TASK_RUNNING (Status UUID: de60ec3b-bcfe-4451-9a01-e3a090f6dc86) for task 0 of
framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:09.635504 235302912 master.cpp:10962] Updating the state of task 0
of framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 (latest state:
TASK_RUNNING, status update state: TASK_RUNNING)
I1210 16:16:09.635769 239058944 sched.cpp:1022] Scheduler::statusUpdate took
123976ns
I1210 16:16:09.635946 237985792 master.cpp:6231] Processing ACKNOWLEDGE call
for status de60ec3b-bcfe-4451-9a01-e3a090f6dc86 for task 0 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 (default) at
scheduler-b81d7c78-4560-4ead-8d61-f29263a54aa9@10.0.49.4:54069 on agent
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0
I1210 16:16:09.636263 238522368 task_status_update_manager.cpp:401] Received
task status update acknowledgement (UUID: de60ec3b-bcfe-4451-9a01-e3a090f6dc86)
for task 0 of framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:09.636348 238522368 task_status_update_manager.cpp:842]
Checkpointing ACK for task status update TASK_RUNNING (Status UUID:
de60ec3b-bcfe-4451-9a01-e3a090f6dc86) for task 0 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:09.636556 236912640 slave.cpp:4531] Task status update manager
successfully handled status update acknowledgement (UUID:
de60ec3b-bcfe-4451-9a01-e3a090f6dc86) for task 0 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:09.818617 12541952 executor.cpp:1003] Command exited with status 0
(pid: 32337)
I1210 16:16:09.824929 236376064 slave.cpp:5295] Handling status update
TASK_FINISHED (Status UUID: 23d1be88-f8dd-42be-a714-488e676d79bd) for task 0 of
framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 from
executor(1)@10.0.49.4:54519
I1210 16:16:09.826036 236376064 task_status_update_manager.cpp:328] Received
task status update TASK_FINISHED (Status UUID:
23d1be88-f8dd-42be-a714-488e676d79bd) for task 0 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:09.826090 236376064 task_status_update_manager.cpp:842]
Checkpointing UPDATE for task status update TASK_FINISHED (Status UUID:
23d1be88-f8dd-42be-a714-488e676d79bd) for task 0 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:09.826233 236376064 task_status_update_manager.cpp:383] Forwarding
task status update TASK_FINISHED (Status UUID:
23d1be88-f8dd-42be-a714-488e676d79bd) for task 0 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 to the agent
I1210 16:16:09.826321 237985792 slave.cpp:5787] Forwarding the update
TASK_FINISHED (Status UUID: 23d1be88-f8dd-42be-a714-488e676d79bd) for task 0 of
framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 to master@10.0.49.4:54069
I1210 16:16:09.826442 237985792 slave.cpp:5680] Task status update manager
successfully handled status update TASK_FINISHED (Status UUID:
23d1be88-f8dd-42be-a714-488e676d79bd) for task 0 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:09.826467 237985792 slave.cpp:5696] Sending acknowledgement for
status update TASK_FINISHED (Status UUID: 23d1be88-f8dd-42be-a714-488e676d79bd)
for task 0 of framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 to
executor(1)@10.0.49.4:54519
I1210 16:16:09.826479 239058944 master.cpp:8375] Status update TASK_FINISHED
(Status UUID: 23d1be88-f8dd-42be-a714-488e676d79bd) for task 0 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 from agent
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0 at slave(72)@10.0.49.4:54069
(Jenkinss-Mac-mini.local)
I1210 16:16:09.826530 239058944 master.cpp:8432] Forwarding status update
TASK_FINISHED (Status UUID: 23d1be88-f8dd-42be-a714-488e676d79bd) for task 0 of
framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:09.826664 239058944 master.cpp:10962] Updating the state of task 0
of framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 (latest state:
TASK_FINISHED, status update state: TASK_FINISHED)
I1210 16:16:09.826915 235302912 hierarchical.cpp:1238] Recovered
cpus(allocated: *):1; mem(allocated: *):1 (total: cpus:1000; mem:1000;
disk:1064061; ports:[31000-32000], allocated: {}) on agent
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0 from framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:09.826970 236912640 sched.cpp:1022] Scheduler::statusUpdate took
136503ns
I1210 16:16:09.827250 237985792 master.cpp:6231] Processing ACKNOWLEDGE call
for status 23d1be88-f8dd-42be-a714-488e676d79bd for task 0 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 (default) at
scheduler-b81d7c78-4560-4ead-8d61-f29263a54aa9@10.0.49.4:54069 on agent
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0
I1210 16:16:09.827327 237985792 master.cpp:11060] Removing task 0 with
resources cpus(allocated: *):1; mem(allocated: *):1 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 on agent
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0 at slave(72)@10.0.49.4:54069
(Jenkinss-Mac-mini.local)
I1210 16:16:09.827527 235302912 task_status_update_manager.cpp:401] Received
task status update acknowledgement (UUID: 23d1be88-f8dd-42be-a714-488e676d79bd)
for task 0 of framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:09.827582 235302912 task_status_update_manager.cpp:842]
Checkpointing ACK for task status update TASK_FINISHED (Status UUID:
23d1be88-f8dd-42be-a714-488e676d79bd) for task 0 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:09.827683 235302912 task_status_update_manager.cpp:538] Cleaning up
status update stream for task 0 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:09.828022 236376064 slave.cpp:4531] Task status update manager
successfully handled status update acknowledgement (UUID:
23d1be88-f8dd-42be-a714-488e676d79bd) for task 0 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:09.828052 236376064 slave.cpp:9661] Completing task 0
I1210 16:16:09.828192 236912640 gc.cpp:95] Scheduling
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/meta/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/0/runs/98607e71-d684-4edc-b473-53f66474b58f/tasks/0'
for gc 6.99999041519704days in the future
I1210 16:16:09.828567 239058944 process.cpp:3588] Handling HTTP event for
process 'metrics' with path: '/metrics/snapshot'
I1210 16:16:09.828972 235839488 http.cpp:910] Authorizing principal 'ANY' to
GET the endpoint '/metrics/snapshot'
I1210 16:16:10.369973 235302912 hierarchical.cpp:1566] Performed allocation for
1 agents in 291748ns
I1210 16:16:10.370169 239058944 master.cpp:9498] Sending offers [
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-O1 ] to framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 (default) at
scheduler-b81d7c78-4560-4ead-8d61-f29263a54aa9@10.0.49.4:54069
I1210 16:16:10.370458 237985792 sched.cpp:914] Scheduler::resourceOffers took
82688ns
I1210 16:16:10.371140 237985792 master.cpp:11501] Removing offer
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-O1
I1210 16:16:10.371336 237985792 master.cpp:4456] Processing ACCEPT call for
offers: [ 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-O1 ] on agent
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0 at slave(72)@10.0.49.4:54069
(Jenkinss-Mac-mini.local) for framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 (default) at
scheduler-b81d7c78-4560-4ead-8d61-f29263a54aa9@10.0.49.4:54069
I1210 16:16:10.371392 237985792 master.cpp:3552] Authorizing framework
principal 'test-principal' to launch task 1
I1210 16:16:10.371954 238522368 master.cpp:4033] Adding task 1 with resources
cpus(allocated: *):1; mem(allocated: *):1 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 (default) at
scheduler-b81d7c78-4560-4ead-8d61-f29263a54aa9@10.0.49.4:54069 on agent
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0 at slave(72)@10.0.49.4:54069
(Jenkinss-Mac-mini.local)
I1210 16:16:10.372066 238522368 master.cpp:5428] Launching task 1 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 (default) at
scheduler-b81d7c78-4560-4ead-8d61-f29263a54aa9@10.0.49.4:54069 with resources
[{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":1.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":1.0},"type":"SCALAR"}]
on agent 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0 at slave(72)@10.0.49.4:54069
(Jenkinss-Mac-mini.local) on new executor
I1210 16:16:10.372387 236912640 hierarchical.cpp:1238] Recovered
cpus(allocated: *):999; mem(allocated: *):999; disk(allocated: *):1064061;
ports(allocated: *):[31000-32000] (total: cpus:1000; mem:1000; disk:1064061;
ports:[31000-32000], allocated: cpus(allocated: *):1; mem(allocated: *):1) on
agent 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0 from framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:10.372447 236912640 hierarchical.cpp:1284] Framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 filtered agent
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0 for 5secs
I1210 16:16:10.372745 239058944 slave.cpp:2019] Got assigned task '1' for
framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:10.373194 239058944 slave.cpp:2393] Authorizing task '1' for
framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:10.373231 239058944 slave.cpp:8494] Authorizing framework principal
'test-principal' to launch task 1
I1210 16:16:10.373836 239058944 slave.cpp:2836] Launching task '1' for
framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:10.373891 239058944 paths.cpp:752] Creating sandbox
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/1/runs/0c4182d5-3fac-4804-8109-59ac953c657b'
for user 'jenkins'
I1210 16:16:10.397675 239058944 slave.cpp:9704] Checkpointing ExecutorInfo to
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/meta/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/1/executor.info'
I1210 16:16:10.398460 239058944 paths.cpp:755] Creating sandbox
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/meta/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/1/runs/0c4182d5-3fac-4804-8109-59ac953c657b'
I1210 16:16:10.398917 239058944 slave.cpp:9004] Launching executor '1' of
framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-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/FetcherCacheTest_LocalCachedMissing_kN4Xod/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/1/runs/0c4182d5-3fac-4804-8109-59ac953c657b'
I1210 16:16:10.399370 239058944 slave.cpp:9735] Checkpointing TaskInfo to
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/meta/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/1/runs/0c4182d5-3fac-4804-8109-59ac953c657b/tasks/1/task.info'
I1210 16:16:10.400189 239058944 slave.cpp:3033] Queued task '1' for executor
'1' of framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:10.400250 239058944 slave.cpp:993] Successfully attached
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/1/runs/0c4182d5-3fac-4804-8109-59ac953c657b'
to virtual path
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/1/runs/latest'
I1210 16:16:10.400415 239058944 slave.cpp:3514] Launching container
0c4182d5-3fac-4804-8109-59ac953c657b for executor '1' of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:10.400692 239058944 slave.cpp:993] Successfully attached
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/1/runs/0c4182d5-3fac-4804-8109-59ac953c657b'
to virtual path
'/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/1/runs/latest'
I1210 16:16:10.400722 239058944 slave.cpp:993] Successfully attached
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/1/runs/0c4182d5-3fac-4804-8109-59ac953c657b'
to virtual path
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/1/runs/0c4182d5-3fac-4804-8109-59ac953c657b'
I1210 16:16:10.400936 236376064 containerizer.cpp:1288] Starting container
0c4182d5-3fac-4804-8109-59ac953c657b
I1210 16:16:10.401732 236376064 containerizer.cpp:1454] Checkpointed
ContainerConfig at
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_lOXN2a/containers/0c4182d5-3fac-4804-8109-59ac953c657b/config'
I1210 16:16:10.401758 236376064 containerizer.cpp:3130] Transitioning the state
of container 0c4182d5-3fac-4804-8109-59ac953c657b from PROVISIONING to PREPARING
I1210 16:16:10.403399 237985792 containerizer.cpp:1947] 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:54069"},{"name":"MESOS_CHECKPOINT","type":"VALUE","value":"1"},{"name":"MESOS_DIRECTORY","type":"VALUE","value":"/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/1/runs/0c4182d5-3fac-4804-8109-59ac953c657b"},{"name":"MESOS_EXECUTOR_AUTHENTICATION_TOKEN","type":"VALUE","value":"eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJjaWQiOiIwYzQxODJkNS0zZmFjLTQ4MDQtODEwOS01OWFjOTUzYzY1N2IiLCJlaWQiOiIxIiwiZmlkIjoiNTdmMjgwMzUtZTVmYS00ZTJhLThiOGMtMWNhZjFmOWM4NWNhLTAwMDAifQ.cKJzt6wnlBlsUVk5SRnR5gsZ7qaQ6_lZjxdn76IsmMc"},{"name":"MESOS_EXECUTOR_ID","type":"VALUE","value":"1"},{"name":"MESOS_EXECUTOR_SHUTDOWN_GRACE_PERIOD","type":"VALUE","value":"5secs"},{"name":"MESOS_FRAMEWORK_ID","type":"VALUE","value":"57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-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":"57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0"},{"name":"MESOS_SLAVE_PID","type":"VALUE","value":"slave(72)@10.0.49.4:54069"},{"name":"MESOS_SUBSCRIPTION_BACKOFF_MAX","type":"VALUE","value":"2secs"},{"name":"MESOS_SANDBOX","type":"VALUE","value":"/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/1/runs/0c4182d5-3fac-4804-8109-59ac953c657b"}]},"task_environment":{},"user":"jenkins","working_directory":"/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/1/runs/0c4182d5-3fac-4804-8109-59ac953c657b"}"
--pipe_read="16" --pipe_write="17"
--runtime_directory="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_lOXN2a/containers/0c4182d5-3fac-4804-8109-59ac953c657b"'
I1210 16:16:10.404641 237985792 launcher.cpp:145] Forked child with pid '32352'
for container '0c4182d5-3fac-4804-8109-59ac953c657b'
I1210 16:16:10.404827 237985792 containerizer.cpp:2052] Checkpointing
container's forked pid 32352 to
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/meta/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/1/runs/0c4182d5-3fac-4804-8109-59ac953c657b/pids/forked.pid'
I1210 16:16:10.406164 237985792 containerizer.cpp:3130] Transitioning the state
of container 0c4182d5-3fac-4804-8109-59ac953c657b from PREPARING to ISOLATING
I1210 16:16:10.407160 237985792 containerizer.cpp:3130] Transitioning the state
of container 0c4182d5-3fac-4804-8109-59ac953c657b from ISOLATING to FETCHING
I1210 16:16:10.407255 235839488 fetcher.cpp:369] Starting to fetch URIs for
container: 0c4182d5-3fac-4804-8109-59ac953c657b, directory:
/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/1/runs/0c4182d5-3fac-4804-8109-59ac953c657b
I1210 16:16:10.407351 235839488 fetcher.cpp:1201] Validating cache entry
'jenkins@/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/mesos-fetcher-test-assets/mesos-fetcher-test-cmd'
with filename: c1-mesos-fetc_r-test-cmd
W1210 16:16:10.407407 235839488 fetcher.cpp:1038] Validation failed: 'Cache
file does not exist: c1-mesos-fetc_r-test-cmd'. Removing cache entry...
I1210 16:16:10.407444 235839488 fetcher.cpp:1113] Removing cache entry
'jenkins@/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/mesos-fetcher-test-assets/mesos-fetcher-test-cmd'
with filename: c1-mesos-fetc_r-test-cmd
I1210 16:16:10.407487 235839488 fetcher.cpp:1278] Released cache space: 30B,
now using: 0B
I1210 16:16:10.407538 235839488 fetcher.cpp:1015] Created cache entry
'jenkins@/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/mesos-fetcher-test-assets/mesos-fetcher-test-cmd'
with file: c2-mesos-fetc_r-test-cmd
I1210 16:16:10.407665 235302912 fetcher.cpp:312] Fetching size for URI:
/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/mesos-fetcher-test-assets/mesos-fetcher-test-cmd
I1210 16:16:10.407793 235839488 fetcher.cpp:731] Claiming fetcher cache space
for:
jenkins@/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/mesos-fetcher-test-assets/mesos-fetcher-test-cmd
I1210 16:16:10.407809 235839488 fetcher.cpp:1266] Claimed cache space: 30B, now
using: 30B
I1210 16:16:10.408769 239058944 fetcher.cpp:889] Fetching URIs using command
'/Users/jenkins/workspace/workspace/mesos/Mesos_CI-build/FLAG/SSL/label/mac/mesos/build/src/mesos-fetcher'
I1210 16:16:22.022130 13615104 process.cpp:927] Stopped the socket accept loop
I1210 16:16:22.023329 238522368 fetcher.cpp:1278] Released cache space: 0B, now
using: 30B
I1210 16:16:22.024173 237449216 hierarchical.cpp:2388] Filtered offer with
cpus:999; mem:999; disk:1064061; ports:[31000-32000] on agent
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0 for role * of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:22.024291 239058944 containerizer.cpp:3130] Transitioning the state
of container 0c4182d5-3fac-4804-8109-59ac953c657b from FETCHING to RUNNING
I1210 16:16:22.024305 237449216 hierarchical.cpp:1566] Performed allocation for
1 agents in 731655ns
I1210 16:16:22.029410 237449216 slave.cpp:5919] Got exited event for
executor(1)@10.0.49.4:54519
[warn] kq_init: detected broken kqueue; not using.: Undefined error: 0
I1210 16:16:22.111475 140914688 exec.cpp:162] Version: 1.8.0
I1210 16:16:22.114994 235302912 slave.cpp:4829] Got registration for executor
'1' of framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 from
executor(1)@10.0.49.4:54523
I1210 16:16:22.115306 235302912 slave.cpp:4915] Checkpointing executor pid
'executor(1)@10.0.49.4:54523' to
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/meta/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/1/runs/0c4182d5-3fac-4804-8109-59ac953c657b/pids/libprocess.pid'
I1210 16:16:23.025322 235839488 hierarchical.cpp:1566] Performed allocation for
1 agents in 306298ns
I1210 16:16:23.025530 238522368 master.cpp:9498] Sending offers [
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-O2 ] to framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 (default) at
scheduler-b81d7c78-4560-4ead-8d61-f29263a54aa9@10.0.49.4:54069
I1210 16:16:23.025810 236376064 sched.cpp:914] Scheduler::resourceOffers took
61329ns
I1210 16:16:23.026015 237985792 master.cpp:5839] Processing DECLINE call for
offers: [ 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-O2 ] for framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 (default) at
scheduler-b81d7c78-4560-4ead-8d61-f29263a54aa9@10.0.49.4:54069 with 5 seconds
filter
I1210 16:16:23.026165 237985792 master.cpp:11501] Removing offer
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-O2
I1210 16:16:23.026269 237449216 hierarchical.cpp:1238] Recovered
cpus(allocated: *):999; mem(allocated: *):999; disk(allocated: *):1064061;
ports(allocated: *):[31000-32000] (total: cpus:1000; mem:1000; disk:1064061;
ports:[31000-32000], allocated: cpus(allocated: *):1; mem(allocated: *):1) on
agent 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0 from framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:23.026309 237449216 hierarchical.cpp:1284] Framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 filtered agent
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0 for 5secs
I1210 16:16:24.026404 238522368 hierarchical.cpp:2388] Filtered offer with
cpus:999; mem:999; disk:1064061; ports:[31000-32000] on agent
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0 for role * of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:24.026460 238522368 hierarchical.cpp:1566] Performed allocation for
1 agents in 205078ns
I1210 16:16:25.036691 238522368 hierarchical.cpp:2388] Filtered offer with
cpus:999; mem:999; disk:1064061; ports:[31000-32000] on agent
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0 for role * of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:25.036784 238522368 hierarchical.cpp:1566] Performed allocation for
1 agents in 273723ns
I1210 16:16:25.265630 137695232 exec.cpp:236] Executor registered on agent
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0
I1210 16:16:25.265864 236912640 slave.cpp:3246] Sending queued task '1' to
executor '1' of framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 at
executor(1)@10.0.49.4:54523
I1210 16:16:25.269999 140378112 executor.cpp:184] Received SUBSCRIBED event
I1210 16:16:25.270548 140378112 executor.cpp:188] Subscribed executor on
Jenkinss-Mac-mini.local
I1210 16:16:25.270653 140378112 executor.cpp:184] Received LAUNCH event
I1210 16:16:25.273725 140378112 executor.cpp:687] Starting task 1
I1210 16:16:25.274462 238522368 slave.cpp:5295] Handling status update
TASK_STARTING (Status UUID: f3a1f9c5-8a48-4938-a9d7-c16565cdd539) for task 1 of
framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 from
executor(1)@10.0.49.4:54523
I1210 16:16:25.275591 235302912 task_status_update_manager.cpp:328] Received
task status update TASK_STARTING (Status UUID:
f3a1f9c5-8a48-4938-a9d7-c16565cdd539) for task 1 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:25.275626 235302912 task_status_update_manager.cpp:507] Creating
StatusUpdate stream for task 1 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:25.276105 235302912 task_status_update_manager.cpp:842]
Checkpointing UPDATE for task status update TASK_STARTING (Status UUID:
f3a1f9c5-8a48-4938-a9d7-c16565cdd539) for task 1 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:25.276309 235302912 task_status_update_manager.cpp:383] Forwarding
task status update TASK_STARTING (Status UUID:
f3a1f9c5-8a48-4938-a9d7-c16565cdd539) for task 1 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 to the agent
I1210 16:16:25.276410 238522368 slave.cpp:5787] Forwarding the update
TASK_STARTING (Status UUID: f3a1f9c5-8a48-4938-a9d7-c16565cdd539) for task 1 of
framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 to master@10.0.49.4:54069
I1210 16:16:25.276556 238522368 slave.cpp:5680] Task status update manager
successfully handled status update TASK_STARTING (Status UUID:
f3a1f9c5-8a48-4938-a9d7-c16565cdd539) for task 1 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:25.276597 238522368 slave.cpp:5696] Sending acknowledgement for
status update TASK_STARTING (Status UUID: f3a1f9c5-8a48-4938-a9d7-c16565cdd539)
for task 1 of framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 to
executor(1)@10.0.49.4:54523
I1210 16:16:25.276705 236912640 master.cpp:8375] Status update TASK_STARTING
(Status UUID: f3a1f9c5-8a48-4938-a9d7-c16565cdd539) for task 1 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 from agent
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0 at slave(72)@10.0.49.4:54069
(Jenkinss-Mac-mini.local)
I1210 16:16:25.276741 236912640 master.cpp:8432] Forwarding status update
TASK_STARTING (Status UUID: f3a1f9c5-8a48-4938-a9d7-c16565cdd539) for task 1 of
framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:25.276836 236912640 master.cpp:10962] Updating the state of task 1
of framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 (latest state:
TASK_STARTING, status update state: TASK_STARTING)
I1210 16:16:25.277143 235839488 sched.cpp:1022] Scheduler::statusUpdate took
126138ns
I1210 16:16:25.277431 236376064 master.cpp:6231] Processing ACKNOWLEDGE call
for status f3a1f9c5-8a48-4938-a9d7-c16565cdd539 for task 1 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 (default) at
scheduler-b81d7c78-4560-4ead-8d61-f29263a54aa9@10.0.49.4:54069 on agent
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0
I1210 16:16:25.277642 237985792 task_status_update_manager.cpp:401] Received
task status update acknowledgement (UUID: f3a1f9c5-8a48-4938-a9d7-c16565cdd539)
for task 1 of framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:25.277739 237985792 task_status_update_manager.cpp:842]
Checkpointing ACK for task status update TASK_STARTING (Status UUID:
f3a1f9c5-8a48-4938-a9d7-c16565cdd539) for task 1 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:25.277957 237449216 slave.cpp:4531] Task status update manager
successfully handled status update acknowledgement (UUID:
f3a1f9c5-8a48-4938-a9d7-c16565cdd539) for task 1 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:25.282706 140378112 executor.cpp:502] Running
'/Users/jenkins/workspace/workspace/mesos/Mesos_CI-build/FLAG/SSL/label/mac/mesos/build/src/mesos-containerizer
launch <POSSIBLY-SENSITIVE-DATA>'
I1210 16:16:25.283923 140378112 executor.cpp:702] Forked command at 32399
I1210 16:16:25.288559 235302912 slave.cpp:5295] Handling status update
TASK_RUNNING (Status UUID: 6f5eb4d9-8f88-4bfe-8a42-521aa4b76f8c) for task 1 of
framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 from
executor(1)@10.0.49.4:54523
I1210 16:16:25.289335 239058944 task_status_update_manager.cpp:328] Received
task status update TASK_RUNNING (Status UUID:
6f5eb4d9-8f88-4bfe-8a42-521aa4b76f8c) for task 1 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:25.289381 239058944 task_status_update_manager.cpp:842]
Checkpointing UPDATE for task status update TASK_RUNNING (Status UUID:
6f5eb4d9-8f88-4bfe-8a42-521aa4b76f8c) for task 1 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:25.289521 239058944 task_status_update_manager.cpp:383] Forwarding
task status update TASK_RUNNING (Status UUID:
6f5eb4d9-8f88-4bfe-8a42-521aa4b76f8c) for task 1 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 to the agent
I1210 16:16:25.289605 237985792 slave.cpp:5787] Forwarding the update
TASK_RUNNING (Status UUID: 6f5eb4d9-8f88-4bfe-8a42-521aa4b76f8c) for task 1 of
framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 to master@10.0.49.4:54069
I1210 16:16:25.289719 237985792 slave.cpp:5680] Task status update manager
successfully handled status update TASK_RUNNING (Status UUID:
6f5eb4d9-8f88-4bfe-8a42-521aa4b76f8c) for task 1 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:25.289750 237985792 slave.cpp:5696] Sending acknowledgement for
status update TASK_RUNNING (Status UUID: 6f5eb4d9-8f88-4bfe-8a42-521aa4b76f8c)
for task 1 of framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 to
executor(1)@10.0.49.4:54523
I1210 16:16:25.289819 237449216 master.cpp:8375] Status update TASK_RUNNING
(Status UUID: 6f5eb4d9-8f88-4bfe-8a42-521aa4b76f8c) for task 1 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 from agent
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0 at slave(72)@10.0.49.4:54069
(Jenkinss-Mac-mini.local)
I1210 16:16:25.289855 237449216 master.cpp:8432] Forwarding status update
TASK_RUNNING (Status UUID: 6f5eb4d9-8f88-4bfe-8a42-521aa4b76f8c) for task 1 of
framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:25.289954 237449216 master.cpp:10962] Updating the state of task 1
of framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 (latest state:
TASK_RUNNING, status update state: TASK_RUNNING)
I1210 16:16:25.290194 235302912 sched.cpp:1022] Scheduler::statusUpdate took
86953ns
I1210 16:16:25.290359 236912640 master.cpp:6231] Processing ACKNOWLEDGE call
for status 6f5eb4d9-8f88-4bfe-8a42-521aa4b76f8c for task 1 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 (default) at
scheduler-b81d7c78-4560-4ead-8d61-f29263a54aa9@10.0.49.4:54069 on agent
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0
I1210 16:16:25.290596 238522368 task_status_update_manager.cpp:401] Received
task status update acknowledgement (UUID: 6f5eb4d9-8f88-4bfe-8a42-521aa4b76f8c)
for task 1 of framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:25.290714 238522368 task_status_update_manager.cpp:842]
Checkpointing ACK for task status update TASK_RUNNING (Status UUID:
6f5eb4d9-8f88-4bfe-8a42-521aa4b76f8c) for task 1 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:25.290896 239058944 slave.cpp:4531] Task status update manager
successfully handled status update acknowledgement (UUID:
6f5eb4d9-8f88-4bfe-8a42-521aa4b76f8c) for task 1 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:25.291153 237449216 containerizer.cpp:2969] Container
98607e71-d684-4edc-b473-53f66474b58f has exited
I1210 16:16:25.291168 237449216 containerizer.cpp:2463] Destroying container
98607e71-d684-4edc-b473-53f66474b58f in RUNNING state
I1210 16:16:25.291177 237449216 containerizer.cpp:3130] Transitioning the state
of container 98607e71-d684-4edc-b473-53f66474b58f from RUNNING to DESTROYING
I1210 16:16:25.291282 237449216 launcher.cpp:161] Asked to destroy container
98607e71-d684-4edc-b473-53f66474b58f
I1210 16:16:25.306565 235839488 provisioner.cpp:597] Ignoring destroy request
for unknown container 98607e71-d684-4edc-b473-53f66474b58f
I1210 16:16:25.307340 237985792 slave.cpp:6315] Executor '0' of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 exited with status 0
I1210 16:16:25.307379 237985792 slave.cpp:6413] Cleaning up executor '0' of
framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 at
executor(1)@10.0.49.4:54519
I1210 16:16:25.307703 236912640 gc.cpp:95] Scheduling
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/0/runs/98607e71-d684-4edc-b473-53f66474b58f'
for gc 6.9999964390163days in the future
I1210 16:16:25.307894 238522368 gc.cpp:95] Scheduling
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/0'
for gc 6.99999643679407days in the future
I1210 16:16:25.308003 235839488 gc.cpp:95] Scheduling
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/meta/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/0/runs/98607e71-d684-4edc-b473-53f66474b58f'
for gc 6.9999964354963days in the future
I1210 16:16:25.308115 236376064 gc.cpp:95] Scheduling
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/meta/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/0'
for gc 6.99999643443259days in the future
../../src/tests/fetcher_cache_tests.cpp:722: Failure
Failed to wait 15secs for awaitFinished(task.get())
Begin listing sandboxes
Begin listing sandbox
`/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/0/runs/latest`:
Begin file contents of `stdout`:
End file
Begin file contents of `stderr`:
I1210 16:16:09.482434 212895168 logging.cpp:206] Logging to STDERR
I1210 16:16:09.483124 212895168 fetcher.cpp:562] Fetcher Info:
{"cache_directory":"/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_lOXN2a/fetch/jenkins","frameworks_home":"/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_lOXN2a/frameworks","items":[{"action":"DOWNLOAD_AND_CACHE","cache_filename":"c1-mesos-fetc_r-test-cmd","uri":{"cache":true,"executable":true,"extract":true,"value":"/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/mesos-fetcher-test-assets/mesos-fetcher-test-cmd"}}],"sandbox_directory":"/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/0/runs/98607e71-d684-4edc-b473-53f66474b58f","stall_timeout":{"nanoseconds":60000000000},"user":"jenkins"}
I1210 16:16:09.491118 212895168 fetcher.cpp:459] Fetching URI
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/mesos-fetcher-test-assets/mesos-fetcher-test-cmd'
I1210 16:16:09.494292 212895168 fetcher.cpp:349] Fetching URI
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/mesos-fetcher-test-assets/mesos-fetcher-test-cmd'
from cache
I1210 16:16:09.497059 212895168 fetcher.cpp:618] Fetched
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/mesos-fetcher-test-assets/mesos-fetcher-test-cmd'
to
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/0/runs/98607e71-d684-4edc-b473-53f66474b58f/mesos-fetcher-test-cmd'
I1210 16:16:09.497107 212895168 fetcher.cpp:623] Successfully fetched all URIs
into
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/0/runs/98607e71-d684-4edc-b473-53f66474b58f'
End file
Begin file contents of `mesos-fetcher-test-cmd`:
touch mesos-fetcher-test-cmd$1
End file
Begin file contents of `mesos-fetcher-test-cmd0`:
End file
End sandbox
Begin listing sandbox
`/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/1/runs/latest`:
Begin file contents of `stdout`:
End file
Begin file contents of `stderr`:
I1210 16:16:10.476529 241812928 logging.cpp:206] Logging to STDERR
I1210 16:16:10.477288 241812928 fetcher.cpp:562] Fetcher Info:
{"cache_directory":"/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_lOXN2a/fetch/jenkins","frameworks_home":"/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_lOXN2a/frameworks","items":[{"action":"DOWNLOAD_AND_CACHE","cache_filename":"c2-mesos-fetc_r-test-cmd","uri":{"cache":true,"executable":true,"extract":true,"value":"/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/mesos-fetcher-test-assets/mesos-fetcher-test-cmd"}}],"sandbox_directory":"/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/1/runs/0c4182d5-3fac-4804-8109-59ac953c657b","stall_timeout":{"nanoseconds":60000000000},"user":"jenkins"}
I1210 16:16:10.485134 241812928 fetcher.cpp:459] Fetching URI
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/mesos-fetcher-test-assets/mesos-fetcher-test-cmd'
I1210 16:16:10.488224 241812928 fetcher.cpp:349] Fetching URI
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/mesos-fetcher-test-assets/mesos-fetcher-test-cmd'
from cache
I1210 16:16:10.491027 241812928 fetcher.cpp:618] Fetched
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/mesos-fetcher-test-assets/mesos-fetcher-test-cmd'
to
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/1/runs/0c4182d5-3fac-4804-8109-59ac953c657b/mesos-fetcher-test-cmd'
I1210 16:16:10.491078 241812928 fetcher.cpp:623] Successfully fetched all URIs
into
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/FetcherCacheTest_LocalCachedMissing_kN4Xod/slaves/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0/frameworks/57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000/executors/1/runs/0c4182d5-3fac-4804-8109-59ac953c657b'
End file
Begin file contents of `mesos-fetcher-test-cmd`:
touch mesos-fetcher-test-cmd$1
End file
Begin file contents of `mesos-fetcher-test-cmd1`:
End file
End sandbox
End sandboxes
I1210 16:16:25.375491 338650560 sched.cpp:2008] Asked to stop the driver
I1210 16:16:25.375562 238522368 sched.cpp:1184] Stopping framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:25.375735 235839488 master.cpp:10215] Processing TEARDOWN call for
framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 (default) at
scheduler-b81d7c78-4560-4ead-8d61-f29263a54aa9@10.0.49.4:54069
I1210 16:16:25.375759 235839488 master.cpp:10227] Removing framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 (default) at
scheduler-b81d7c78-4560-4ead-8d61-f29263a54aa9@10.0.49.4:54069
I1210 16:16:25.375774 235839488 master.cpp:3241] Deactivating framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 (default) at
scheduler-b81d7c78-4560-4ead-8d61-f29263a54aa9@10.0.49.4:54069
I1210 16:16:25.375922 235839488 master.cpp:10962] Updating the state of task 1
of framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 (latest state:
TASK_KILLED, status update state: TASK_KILLED)
I1210 16:16:25.375936 239058944 hierarchical.cpp:418] Deactivated framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:25.376030 235302912 slave.cpp:3901] Asked to shut down framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 by master@10.0.49.4:54069
I1210 16:16:25.376071 235302912 slave.cpp:3926] Shutting down framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:25.376092 235302912 slave.cpp:6666] Shutting down executor '1' of
framework 57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 at
executor(1)@10.0.49.4:54523
I1210 16:16:25.376178 235839488 master.cpp:11060] Removing task 1 with
resources cpus(allocated: *):1; mem(allocated: *):1 of framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000 on agent
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0 at slave(72)@10.0.49.4:54069
(Jenkinss-Mac-mini.local)
I1210 16:16:25.376291 238522368 hierarchical.cpp:1238] Recovered
cpus(allocated: *):1; mem(allocated: *):1 (total: cpus:1000; mem:1000;
disk:1064061; ports:[31000-32000], allocated: {}) on agent
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0 from framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:25.376503 235839488 master.cpp:1117] Master terminating
I1210 16:16:25.376809 236912640 hierarchical.cpp:357] Removed framework
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-0000
I1210 16:16:25.376935 137158656 exec.cpp:445] Executor asked to shutdown
I1210 16:16:25.377189 235302912 slave.cpp:5919] Got exited event for
master@10.0.49.4:54069
W1210 16:16:25.377215 235302912 slave.cpp:5924] Master disconnected! Waiting
for a new master to be elected
I1210 16:16:25.377274 236912640 hierarchical.cpp:643] Removed agent
57f28035-e5fa-4e2a-8b8c-1caf1f9c85ca-S0
I1210 16:16:25.377341 138768384 executor.cpp:184] Received SHUTDOWN event
I1210 16:16:25.377408 138768384 executor.cpp:805] Shutting down
I1210 16:16:25.377449 138768384 executor.cpp:918] Sending SIGTERM to process
tree at pid 32399
I1210 16:16:25.379637 338650560 slave.cpp:914] Agent terminating
I1210 16:16:25.380705 235839488 containerizer.cpp:2463] Destroying container
0c4182d5-3fac-4804-8109-59ac953c657b in RUNNING state
I1210 16:16:25.380750 235839488 containerizer.cpp:3130] Transitioning the state
of container 0c4182d5-3fac-4804-8109-59ac953c657b from RUNNING to DESTROYING
I1210 16:16:25.380890 235839488 launcher.cpp:161] Asked to destroy container
0c4182d5-3fac-4804-8109-59ac953c657b
I1210 16:16:25.397290 138768384 executor.cpp:931] Sent SIGTERM to the following
process trees:
[
]
I1210 16:16:25.397343 138768384 executor.cpp:935] Scheduling escalation to
SIGKILL in 3secs from now
I1210 16:16:25.397447 138768384 executor.cpp:1003] Command exited with status 0
(pid: 32399)
I1210 16:16:25.405634 239595520 process.cpp:2651] Failed to deliver libprocess
message to /slave(72)/mesos.internal.StatusUpdateMessage
I1210 16:16:25.502879 239058944 containerizer.cpp:2969] Container
0c4182d5-3fac-4804-8109-59ac953c657b has exited
I1210 16:16:25.503803 236376064 provisioner.cpp:597] Ignoring destroy request
for unknown container 0c4182d5-3fac-4804-8109-59ac953c657b
[ FAILED ] FetcherCacheTest.LocalCachedMissing (16155 ms)
{noformat}
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
