Benno Evers created MESOS-9262:
----------------------------------
Summary:
ProvisionerDockerBackendTest.ROOT_INTERNET_CURL_DTYPE_Whiteout is flaky
Key: MESOS-9262
URL: https://issues.apache.org/jira/browse/MESOS-9262
Project: Mesos
Issue Type: Bug
Reporter: Benno Evers
Observed in an internal CI run (4489):
{noformat}
../../src/tests/containerizer/provisioner_docker_tests.cpp:915
Expected: TASK_STARTING
To be equal to: statusStarting->state()
Which is: TASK_FAILED
{noformat}
Full log:
{noformat}
[ RUN ]
BackendFlag/ProvisionerDockerBackendTest.ROOT_INTERNET_CURL_DTYPE_Whiteout/0
I0925 23:59:24.750632 21740 cluster.cpp:173] Creating default 'local' authorizer
I0925 23:59:24.752059 3540 master.cpp:413] Master
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1 (ip-172-16-10-34.ec2.internal) started on
172.16.10.34:41596
I0925 23:59:24.752087 3540 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="/tmp/f5XfyH/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="/tmp/f5XfyH/master" --zk_session_timeout="10secs"
I0925 23:59:24.752307 3540 master.cpp:465] Master only allowing authenticated
frameworks to register
I0925 23:59:24.752393 3540 master.cpp:471] Master only allowing authenticated
agents to register
I0925 23:59:24.752409 3540 master.cpp:477] Master only allowing authenticated
HTTP frameworks to register
I0925 23:59:24.752418 3540 credentials.hpp:37] Loading credentials for
authentication from '/tmp/f5XfyH/credentials'
I0925 23:59:24.752590 3540 master.cpp:521] Using default 'crammd5'
authenticator
I0925 23:59:24.752715 3540 http.cpp:1037] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-readonly'
I0925 23:59:24.752769 3540 http.cpp:1037] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-readwrite'
I0925 23:59:24.752804 3540 http.cpp:1037] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-scheduler'
I0925 23:59:24.752835 3540 master.cpp:602] Authorization enabled
I0925 23:59:24.753206 3539 whitelist_watcher.cpp:77] No whitelist given
I0925 23:59:24.753266 3544 hierarchical.cpp:182] Initialized hierarchical
allocator process
I0925 23:59:24.753803 3540 master.cpp:2083] Elected as the leading master!
I0925 23:59:24.753823 3540 master.cpp:1638] Recovering from registrar
I0925 23:59:24.753863 3540 registrar.cpp:339] Recovering registrar
I0925 23:59:24.754007 3540 registrar.cpp:383] Successfully fetched the
registry (0B) in 130048ns
I0925 23:59:24.754041 3540 registrar.cpp:487] Applied 1 operations in 8734ns;
attempting to update the registry
I0925 23:59:24.754166 3540 registrar.cpp:544] Successfully updated the
registry in 108032ns
I0925 23:59:24.754195 3540 registrar.cpp:416] Successfully recovered registrar
I0925 23:59:24.754266 3540 master.cpp:1752] Recovered 0 agents from the
registry (172B); allowing 10mins for agents to reregister
I0925 23:59:24.754314 3540 hierarchical.cpp:220] Skipping recovery of
hierarchical allocator: nothing to recover
W0925 23:59:24.756233 21740 process.cpp:2810] Attempted to spawn already
running process [email protected]:41596
I0925 23:59:24.756603 21740 containerizer.cpp:305] Using isolation {
environment_secret, volume/sandbox_path, volume/host_path, docker/runtime,
filesystem/linux, network/cni, volume/image }
I0925 23:59:24.758536 21740 linux_launcher.cpp:144] Using /cgroup/freezer as
the freezer hierarchy for the Linux launcher
sh: hadoop: command not found
I0925 23:59:24.815798 21740 fetcher.cpp:66] Skipping URI fetcher plugin
'hadoop' as it could not be created: Failed to create HDFS client: Hadoop
client is not available, exit status: 32512
I0925 23:59:24.815888 21740 registry_puller.cpp:128] Creating registry puller
with docker registry 'https://registry-1.docker.io'
I0925 23:59:24.816609 21740 provisioner.cpp:298] Using default backend 'copy'
I0925 23:59:24.817026 21740 linux.cpp:158] Bind mounting
'/tmp/BackendFlag_ProvisionerDockerBackendTest_ROOT_INTERNET_CURL_DTYPE_Whiteout_0_Z9m3Wr'
and making it a shared mount
I0925 23:59:24.826529 21740 cluster.cpp:485] Creating default 'local' authorizer
I0925 23:59:24.827316 3542 slave.cpp:267] Mesos agent started on
(1320)@172.16.10.34:41596
W0925 23:59:24.827353 21740 process.cpp:2810] Attempted to spawn already
running process [email protected]:41596
I0925 23:59:24.827337 3542 slave.cpp:268] Flags at startup: --acls=""
--appc_simple_discovery_uri_prefix="http://";
--appc_store_dir="/tmp/BackendFlag_ProvisionerDockerBackendTest_ROOT_INTERNET_CURL_DTYPE_Whiteout_0_bHmRlc/store/appc"
--authenticate_http_executors="true" --authenticate_http_readonly="true"
--authenticate_http_readwrite="true" --authenticatee="crammd5"
--authentication_backoff_factor="1secs" --authentication_timeout_max="1mins"
--authentication_timeout_min="5secs" --authorizer="local"
--cgroups_cpu_enable_pids_and_tids_count="false"
--cgroups_destroy_timeout="1mins" --cgroups_enable_cfs="false"
--cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false"
--cgroups_root="mesos" --container_disk_watch_interval="15secs"
--containerizers="mesos"
--credential="/tmp/BackendFlag_ProvisionerDockerBackendTest_ROOT_INTERNET_CURL_DTYPE_Whiteout_0_bHmRlc/credential"
--default_role="*" --disallow_sharing_agent_pid_namespace="false"
--disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true"
--docker_registry="https://registry-1.docker.io"; --docker_remove_delay="6hrs"
--docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns"
--docker_store_dir="/tmp/BackendFlag_ProvisionerDockerBackendTest_ROOT_INTERNET_CURL_DTYPE_Whiteout_0_bHmRlc/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="/tmp/BackendFlag_ProvisionerDockerBackendTest_ROOT_INTERNET_CURL_DTYPE_Whiteout_0_bHmRlc/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="/tmp/BackendFlag_ProvisionerDockerBackendTest_ROOT_INTERNET_CURL_DTYPE_Whiteout_0_bHmRlc/http_credentials"
--http_heartbeat_interval="30secs" --image_providers="docker"
--image_provisioner_backend="copy" --initialize_driver_logging="true"
--isolation="docker/runtime,filesystem/linux"
--jwt_secret_key="/tmp/BackendFlag_ProvisionerDockerBackendTest_ROOT_INTERNET_CURL_DTYPE_Whiteout_0_bHmRlc/jwt_secret_key"
--launcher="linux"
--launcher_dir="/home/centos/workspace/mesos/Mesos_CI-build/FLAG/SSL/label/mesos-ec2-centos-6/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"
--perf_duration="10secs" --perf_interval="1mins" --port="5051"
--qos_correction_interval_min="0ns" --quiet="false"
--reconfiguration_policy="equal" --recover="reconnect"
--recovery_timeout="15mins" --registration_backoff_factor="10ms"
--resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]"
--revocable_cpu_low_priority="true"
--runtime_dir="/tmp/BackendFlag_ProvisionerDockerBackendTest_ROOT_INTERNET_CURL_DTYPE_Whiteout_0_bHmRlc"
--sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true"
--systemd_enable_support="true"
--systemd_runtime_directory="/run/systemd/system" --version="false"
--work_dir="/tmp/BackendFlag_ProvisionerDockerBackendTest_ROOT_INTERNET_CURL_DTYPE_Whiteout_0_Z9m3Wr"
--zk_session_timeout="10secs"
I0925 23:59:24.827893 3542 credentials.hpp:86] Loading credential for
authentication from
'/tmp/BackendFlag_ProvisionerDockerBackendTest_ROOT_INTERNET_CURL_DTYPE_Whiteout_0_bHmRlc/credential'
I0925 23:59:24.827970 3542 slave.cpp:300] Agent using credential for:
test-principal
I0925 23:59:24.827981 3542 credentials.hpp:37] Loading credentials for
authentication from
'/tmp/BackendFlag_ProvisionerDockerBackendTest_ROOT_INTERNET_CURL_DTYPE_Whiteout_0_bHmRlc/http_credentials'
I0925 23:59:24.828085 3542 http.cpp:1037] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-executor'
I0925 23:59:24.828128 3542 http.cpp:1058] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-executor'
I0925 23:59:24.828174 3542 http.cpp:1037] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-readonly'
I0925 23:59:24.828197 3542 http.cpp:1058] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-readonly'
I0925 23:59:24.828228 3542 http.cpp:1037] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-readwrite'
I0925 23:59:24.828248 3542 http.cpp:1058] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-readwrite'
I0925 23:59:24.828307 3542 disk_profile_adaptor.cpp:80] Creating default disk
profile adaptor module
I0925 23:59:24.829134 3542 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"}]
I0925 23:59:24.829207 3542 slave.cpp:623] Agent attributes: [ ]
I0925 23:59:24.829216 3542 slave.cpp:632] Agent hostname:
ip-172-16-10-34.ec2.internal
I0925 23:59:24.829392 21740 sched.cpp:232] Version: 1.8.0
I0925 23:59:24.829735 3545 state.cpp:66] Recovering state from
'/tmp/BackendFlag_ProvisionerDockerBackendTest_ROOT_INTERNET_CURL_DTYPE_Whiteout_0_Z9m3Wr/meta'
I0925 23:59:24.829830 3545 slave.cpp:6909] Finished recovering checkpointed
state from
'/tmp/BackendFlag_ProvisionerDockerBackendTest_ROOT_INTERNET_CURL_DTYPE_Whiteout_0_Z9m3Wr/meta',
beginning agent recovery
I0925 23:59:24.829871 3545 sched.cpp:336] New master detected at
[email protected]:41596
I0925 23:59:24.829897 3545 sched.cpp:401] Authenticating with master
[email protected]:41596
I0925 23:59:24.829905 3545 sched.cpp:408] Using default CRAM-MD5 authenticatee
I0925 23:59:24.829993 3545 authenticatee.cpp:121] Creating new client SASL
connection
I0925 23:59:24.830085 3545 master.cpp:9653] Authenticating
[email protected]:41596
I0925 23:59:24.830135 3545 authenticator.cpp:414] Starting authentication
session for crammd5-authenticatee(2252)@172.16.10.34:41596
I0925 23:59:24.830193 3545 authenticator.cpp:98] Creating new server SASL
connection
I0925 23:59:24.830247 3545 authenticatee.cpp:213] Received SASL authentication
mechanisms: CRAM-MD5
I0925 23:59:24.830260 3545 authenticatee.cpp:239] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0925 23:59:24.830287 3545 authenticator.cpp:204] Received SASL authentication
start
I0925 23:59:24.830324 3545 authenticator.cpp:326] Authentication requires more
steps
I0925 23:59:24.830353 3545 authenticatee.cpp:259] Received SASL authentication
step
I0925 23:59:24.830390 3545 authenticator.cpp:232] Received SASL authentication
step
I0925 23:59:24.830405 3545 auxprop.cpp:109] Request to lookup properties for
user: 'test-principal' realm: 'ip-172-16-10-34' server FQDN: 'ip-172-16-10-34'
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0925 23:59:24.830413 3545 auxprop.cpp:181] Looking up auxiliary property
'*userPassword'
I0925 23:59:24.830430 3545 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0925 23:59:24.830440 3545 auxprop.cpp:109] Request to lookup properties for
user: 'test-principal' realm: 'ip-172-16-10-34' server FQDN: 'ip-172-16-10-34'
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0925 23:59:24.830447 3545 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0925 23:59:24.830452 3545 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0925 23:59:24.830466 3545 authenticator.cpp:318] Authentication success
I0925 23:59:24.830516 3545 authenticatee.cpp:299] Authentication success
I0925 23:59:24.830559 3545 master.cpp:9685] Successfully authenticated
principal 'test-principal' at
[email protected]:41596
I0925 23:59:24.830582 3545 authenticator.cpp:432] Authentication session
cleanup for crammd5-authenticatee(2252)@172.16.10.34:41596
I0925 23:59:24.830641 3545 sched.cpp:513] Successfully authenticated with
master [email protected]:41596
I0925 23:59:24.830651 3545 sched.cpp:817] Sending SUBSCRIBE call to
[email protected]:41596
I0925 23:59:24.830693 3545 sched.cpp:850] Will retry registration in
1.728532442secs if necessary
I0925 23:59:24.830785 3545 master.cpp:2854] Received SUBSCRIBE call for
framework 'default' at
[email protected]:41596
I0925 23:59:24.830809 3545 master.cpp:2155] Authorizing framework principal
'test-principal' to receive offers for roles '{ * }'
I0925 23:59:24.830898 3545 master.cpp:2935] Subscribing framework default with
checkpointing disabled and capabilities [ MULTI_ROLE, RESERVATION_REFINEMENT ]
I0925 23:59:24.831234 3545 master.cpp:9883] Adding framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000 (default) at
[email protected]:41596 with roles {
} suppressed
I0925 23:59:24.829519 3542 task_status_update_manager.cpp:181] Pausing sending
task status updates
I0925 23:59:24.831936 3540 hierarchical.cpp:306] Added framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000
I0925 23:59:24.831987 3540 hierarchical.cpp:1564] Performed allocation for 0
agents in 10207ns
I0925 23:59:24.832023 3546 sched.cpp:744] Framework registered with
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000
I0925 23:59:24.832048 3546 sched.cpp:758] Scheduler::registered took 9741ns
I0925 23:59:24.832111 3542 task_status_update_manager.cpp:207] Recovering task
status update manager
I0925 23:59:24.832325 3539 containerizer.cpp:727] Recovering Mesos containers
I0925 23:59:24.832402 3539 linux_launcher.cpp:286] Recovering Linux launcher
I0925 23:59:24.832723 3541 containerizer.cpp:1053] Recovering isolators
I0925 23:59:24.833292 3544 containerizer.cpp:1092] Recovering provisioner
I0925 23:59:24.833516 3545 metadata_manager.cpp:254] No images to load from
disk. Docker provisioner image storage path
'/tmp/BackendFlag_ProvisionerDockerBackendTest_ROOT_INTERNET_CURL_DTYPE_Whiteout_0_bHmRlc/store/docker/storedImages'
does not exist
I0925 23:59:24.833583 3539 provisioner.cpp:494] Provisioner recovery complete
I0925 23:59:24.833848 3545 composing.cpp:339] Finished recovering all
containerizers
I0925 23:59:24.833928 3545 slave.cpp:7138] Recovering executors
I0925 23:59:24.833951 3545 slave.cpp:7291] Finished recovery
I0925 23:59:24.834298 3545 task_status_update_manager.cpp:181] Pausing sending
task status updates
I0925 23:59:24.834306 3542 slave.cpp:1254] New master detected at
[email protected]:41596
I0925 23:59:24.834349 3542 slave.cpp:1319] Detecting new master
I0925 23:59:24.843549 3541 slave.cpp:1346] Authenticating with master
[email protected]:41596
I0925 23:59:24.843577 3541 slave.cpp:1355] Using default CRAM-MD5 authenticatee
I0925 23:59:24.843642 3541 authenticatee.cpp:121] Creating new client SASL
connection
I0925 23:59:24.843709 3541 master.cpp:9653] Authenticating
slave(1320)@172.16.10.34:41596
I0925 23:59:24.843750 3541 authenticator.cpp:414] Starting authentication
session for crammd5-authenticatee(2253)@172.16.10.34:41596
I0925 23:59:24.843801 3541 authenticator.cpp:98] Creating new server SASL
connection
I0925 23:59:24.843855 3541 authenticatee.cpp:213] Received SASL authentication
mechanisms: CRAM-MD5
I0925 23:59:24.843868 3541 authenticatee.cpp:239] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0925 23:59:24.843895 3541 authenticator.cpp:204] Received SASL authentication
start
I0925 23:59:24.843928 3541 authenticator.cpp:326] Authentication requires more
steps
I0925 23:59:24.843960 3541 authenticatee.cpp:259] Received SASL authentication
step
I0925 23:59:24.843996 3541 authenticator.cpp:232] Received SASL authentication
step
I0925 23:59:24.844010 3541 auxprop.cpp:109] Request to lookup properties for
user: 'test-principal' realm: 'ip-172-16-10-34' server FQDN: 'ip-172-16-10-34'
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0925 23:59:24.844018 3541 auxprop.cpp:181] Looking up auxiliary property
'*userPassword'
I0925 23:59:24.844027 3541 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0925 23:59:24.844036 3541 auxprop.cpp:109] Request to lookup properties for
user: 'test-principal' realm: 'ip-172-16-10-34' server FQDN: 'ip-172-16-10-34'
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0925 23:59:24.844043 3541 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0925 23:59:24.844049 3541 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0925 23:59:24.844061 3541 authenticator.cpp:318] Authentication success
I0925 23:59:24.844094 3541 authenticatee.cpp:299] Authentication success
I0925 23:59:24.844127 3541 authenticator.cpp:432] Authentication session
cleanup for crammd5-authenticatee(2253)@172.16.10.34:41596
I0925 23:59:24.844188 3541 slave.cpp:1446] Successfully authenticated with
master [email protected]:41596
I0925 23:59:24.844127 3539 master.cpp:9685] Successfully authenticated
principal 'test-principal' at slave(1320)@172.16.10.34:41596
I0925 23:59:24.844287 3541 slave.cpp:1877] Will retry registration in
9.704886ms if necessary
I0925 23:59:24.844362 3541 master.cpp:6605] Received register agent message
from slave(1320)@172.16.10.34:41596 (ip-172-16-10-34.ec2.internal)
I0925 23:59:24.844429 3541 master.cpp:3964] Authorizing agent providing
resources 'cpus:2; mem:1024; disk:1024; ports:[31000-32000]' with principal
'test-principal'
I0925 23:59:24.844772 3543 master.cpp:6672] Authorized registration of agent
at slave(1320)@172.16.10.34:41596 (ip-172-16-10-34.ec2.internal)
I0925 23:59:24.844822 3543 master.cpp:6787] Registering agent at
slave(1320)@172.16.10.34:41596 (ip-172-16-10-34.ec2.internal) with id
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-S0
I0925 23:59:24.844954 3543 registrar.cpp:487] Applied 1 operations in 38265ns;
attempting to update the registry
I0925 23:59:24.845108 3543 registrar.cpp:544] Successfully updated the
registry in 134144ns
I0925 23:59:24.845170 3543 master.cpp:6835] Admitted agent
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-S0 at slave(1320)@172.16.10.34:41596
(ip-172-16-10-34.ec2.internal)
I0925 23:59:24.845288 3543 master.cpp:6880] Registered agent
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-S0 at slave(1320)@172.16.10.34:41596
(ip-172-16-10-34.ec2.internal) with cpus:2; mem:1024; disk:1024;
ports:[31000-32000]
I0925 23:59:24.845357 3539 hierarchical.cpp:601] Added agent
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-S0 (ip-172-16-10-34.ec2.internal) with
cpus:2; mem:1024; disk:1024; ports:[31000-32000] (allocated: {})
I0925 23:59:24.845366 3543 slave.cpp:1479] Registered with master
[email protected]:41596; given agent ID
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-S0
I0925 23:59:24.845572 3539 hierarchical.cpp:1564] Performed allocation for 1
agents in 157648ns
I0925 23:59:24.845599 3539 task_status_update_manager.cpp:188] Resuming
sending task status updates
I0925 23:59:24.845604 3543 slave.cpp:1499] Checkpointing SlaveInfo to
'/tmp/BackendFlag_ProvisionerDockerBackendTest_ROOT_INTERNET_CURL_DTYPE_Whiteout_0_Z9m3Wr/meta/slaves/34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-S0/slave.info'
I0925 23:59:24.845702 3539 master.cpp:9468] Sending offers [
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-O0 ] to framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000 (default) at
[email protected]:41596
I0925 23:59:24.845860 3539 sched.cpp:914] Scheduler::resourceOffers took
30041ns
I0925 23:59:24.845896 3543 slave.cpp:1548] Forwarding agent update
{"operations":{},"resource_version_uuid":{"value":"sPyNvrF7RfKD3z2f+5ihmA=="},"slave_id":{"value":"34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-S0"},"update_oversubscribed_resources":false}
I0925 23:59:24.846091 3543 master.cpp:7939] Ignoring update on agent
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-S0 at slave(1320)@172.16.10.34:41596
(ip-172-16-10-34.ec2.internal) as it reports no changes
I0925 23:59:24.846624 3544 master.cpp:11462] Removing offer
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-O0
I0925 23:59:24.846743 3544 master.cpp:4467] Processing ACCEPT call for offers:
[ 34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-O0 ] on agent
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-S0 at slave(1320)@172.16.10.34:41596
(ip-172-16-10-34.ec2.internal) for framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000 (default) at
[email protected]:41596
I0925 23:59:24.846781 3544 master.cpp:3541] Authorizing framework principal
'test-principal' to launch task c32a603e-7202-4534-a218-3116d8d5bb34
I0925 23:59:24.847184 3544 master.cpp:12209] Adding task
c32a603e-7202-4534-a218-3116d8d5bb34 with resources cpus(allocated: *):1;
mem(allocated: *):128 on agent 34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-S0 at
slave(1320)@172.16.10.34:41596 (ip-172-16-10-34.ec2.internal)
I0925 23:59:24.847262 3544 master.cpp:5439] Launching task
c32a603e-7202-4534-a218-3116d8d5bb34 of framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000 (default) at
[email protected]:41596 with
resources
[{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":1.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":128.0},"type":"SCALAR"}]
on agent 34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-S0 at
slave(1320)@172.16.10.34:41596 (ip-172-16-10-34.ec2.internal) on new executor
I0925 23:59:24.847594 3544 slave.cpp:2014] Got assigned task
'c32a603e-7202-4534-a218-3116d8d5bb34' for framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000
I0925 23:59:24.847895 3544 slave.cpp:2388] Authorizing task
'c32a603e-7202-4534-a218-3116d8d5bb34' for framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000
I0925 23:59:24.847925 3544 slave.cpp:8466] Authorizing framework principal
'test-principal' to launch task c32a603e-7202-4534-a218-3116d8d5bb34
I0925 23:59:24.847950 3545 hierarchical.cpp:1236] Recovered cpus(allocated:
*):1; mem(allocated: *):896; disk(allocated: *):1024; ports(allocated:
*):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000],
allocated: cpus(allocated: *):1; mem(allocated: *):128) on agent
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-S0 from framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000
I0925 23:59:24.847985 3545 hierarchical.cpp:1282] Framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000 filtered agent
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-S0 for 5secs
I0925 23:59:24.848315 3544 slave.cpp:2831] Launching task
'c32a603e-7202-4534-a218-3116d8d5bb34' for framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000
I0925 23:59:24.848376 3544 paths.cpp:752] Creating sandbox
'/tmp/BackendFlag_ProvisionerDockerBackendTest_ROOT_INTERNET_CURL_DTYPE_Whiteout_0_Z9m3Wr/slaves/34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-S0/frameworks/34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000/executors/c32a603e-7202-4534-a218-3116d8d5bb34/runs/c09a3eb9-7d46-4ff0-8b70-ec87d7adf2e2'
for user 'root'
I0925 23:59:24.849427 3544 slave.cpp:8994] Launching executor
'c32a603e-7202-4534-a218-3116d8d5bb34' of framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000 with resources
[{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":32.0},"type":"SCALAR"}]
in work directory
'/tmp/BackendFlag_ProvisionerDockerBackendTest_ROOT_INTERNET_CURL_DTYPE_Whiteout_0_Z9m3Wr/slaves/34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-S0/frameworks/34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000/executors/c32a603e-7202-4534-a218-3116d8d5bb34/runs/c09a3eb9-7d46-4ff0-8b70-ec87d7adf2e2'
I0925 23:59:24.849750 3544 slave.cpp:3028] Queued task
'c32a603e-7202-4534-a218-3116d8d5bb34' for executor
'c32a603e-7202-4534-a218-3116d8d5bb34' of framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000
I0925 23:59:24.849884 3544 slave.cpp:3509] Launching container
c09a3eb9-7d46-4ff0-8b70-ec87d7adf2e2 for executor
'c32a603e-7202-4534-a218-3116d8d5bb34' of framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000
I0925 23:59:24.849990 3544 slave.cpp:988] Successfully attached
'/tmp/BackendFlag_ProvisionerDockerBackendTest_ROOT_INTERNET_CURL_DTYPE_Whiteout_0_Z9m3Wr/slaves/34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-S0/frameworks/34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000/executors/c32a603e-7202-4534-a218-3116d8d5bb34/runs/c09a3eb9-7d46-4ff0-8b70-ec87d7adf2e2'
to virtual path
'/tmp/BackendFlag_ProvisionerDockerBackendTest_ROOT_INTERNET_CURL_DTYPE_Whiteout_0_Z9m3Wr/slaves/34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-S0/frameworks/34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000/executors/c32a603e-7202-4534-a218-3116d8d5bb34/runs/latest'
I0925 23:59:24.850276 3540 slave.cpp:988] Successfully attached
'/tmp/BackendFlag_ProvisionerDockerBackendTest_ROOT_INTERNET_CURL_DTYPE_Whiteout_0_Z9m3Wr/slaves/34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-S0/frameworks/34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000/executors/c32a603e-7202-4534-a218-3116d8d5bb34/runs/c09a3eb9-7d46-4ff0-8b70-ec87d7adf2e2'
to virtual path
'/frameworks/34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000/executors/c32a603e-7202-4534-a218-3116d8d5bb34/runs/latest'
I0925 23:59:24.850299 3540 slave.cpp:988] Successfully attached
'/tmp/BackendFlag_ProvisionerDockerBackendTest_ROOT_INTERNET_CURL_DTYPE_Whiteout_0_Z9m3Wr/slaves/34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-S0/frameworks/34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000/executors/c32a603e-7202-4534-a218-3116d8d5bb34/runs/c09a3eb9-7d46-4ff0-8b70-ec87d7adf2e2'
to virtual path
'/tmp/BackendFlag_ProvisionerDockerBackendTest_ROOT_INTERNET_CURL_DTYPE_Whiteout_0_Z9m3Wr/slaves/34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-S0/frameworks/34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000/executors/c32a603e-7202-4534-a218-3116d8d5bb34/runs/c09a3eb9-7d46-4ff0-8b70-ec87d7adf2e2'
I0925 23:59:24.850303 3546 containerizer.cpp:1280] Starting container
c09a3eb9-7d46-4ff0-8b70-ec87d7adf2e2
I0925 23:59:24.851299 3543 metadata_manager.cpp:179] Looking for image
'zhq527725/whiteout'
I0925 23:59:24.851474 3544 registry_puller.cpp:286] Pulling image
'zhq527725/whiteout' from
'docker-manifest://registry-1.docker.io:443zhq527725/whiteout?latest#https' to
'/tmp/BackendFlag_ProvisionerDockerBackendTest_ROOT_INTERNET_CURL_DTYPE_Whiteout_0_bHmRlc/store/docker/staging/0IaCds'
I0925 23:59:25.219962 3546 registry_puller.cpp:314] The manifest for image
'zhq527725/whiteout' is '{
"schemaVersion": 1,
"name": "zhq527725/whiteout",
"tag": "latest",
"architecture": "amd64",
"fsLayers": [
{
"blobSum":
"sha256:0f8d75b536b30787770857e66db830c31aa28fa0eeca41140a4eadefe2961d61"
},
{
"blobSum":
"sha256:eb3473a516b96cd180c4b9be783e585ef60e977ea97cd7cc3eca4edce6282c3d"
},
{
"blobSum":
"sha256:c0cb142e43453ebb1f82b905aa472e6e66017efd43872135bc5372e4fac04031"
}
],
"history": [
{
"v1Compatibility":
"{\"architecture\":\"amd64\",\"config\":{\"Hostname\":\"09713501c176\",\"Domainname\":\"\",\"User\":\"\",\"AttachStdin\":false,\"AttachStdout\":false,\"AttachStderr\":false,\"Tty\":false,\"OpenStdin\":false,\"StdinOnce\":false,\"Env\":[\"PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin\"],\"Cmd\":null,\"ArgsEscaped\":true,\"Image\":\"sha256:f2a1adb3a6fc1186c7736a8158b87d0837d0ede164be1be21701a5bcf4204ffc\",\"Volumes\":null,\"WorkingDir\":\"\",\"Entrypoint\":null,\"OnBuild\":[],\"Labels\":{}},\"container\":\"584b213d8a54906c6009c7db86549c5bd67f2a4f2d525e779236b1a4966b1616\",\"container_config\":{\"Hostname\":\"09713501c176\",\"Domainname\":\"\",\"User\":\"\",\"AttachStdin\":false,\"AttachStdout\":false,\"AttachStderr\":false,\"Tty\":false,\"OpenStdin\":false,\"StdinOnce\":false,\"Env\":[\"PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin\"],\"Cmd\":[\"/bin/sh\",\"-c\",\"rm
-rf /dir1/file1 \\u0026\\u0026 rm -rf /dir1/dir2 \\u0026\\u0026 mkdir
/dir1/dir2 \\u0026\\u0026 touch
/dir1/dir2/file3\"],\"ArgsEscaped\":true,\"Image\":\"sha256:f2a1adb3a6fc1186c7736a8158b87d0837d0ede164be1be21701a5bcf4204ffc\",\"Volumes\":null,\"WorkingDir\":\"\",\"Entrypoint\":null,\"OnBuild\":[],\"Labels\":{}},\"created\":\"2016-11-01T05:17:38.750859292Z\",\"docker_version\":\"1.12.1\",\"id\":\"91b73244b546ccedbd9aac865689c7d97992ed6e39dc071e34a94626225fe0d5\",\"os\":\"linux\",\"parent\":\"249d9d7ac4cda9384bc13fc2d6f04c0080f56c857c3a5713a1b142f4523f8ab1\"}"
},
{
"v1Compatibility":
"{\"id\":\"249d9d7ac4cda9384bc13fc2d6f04c0080f56c857c3a5713a1b142f4523f8ab1\",\"parent\":\"2b25bf24b28139726f2f32099b8f317df063c2f248a6d6abc4b008c1ceacac17\",\"created\":\"2016-11-01T05:17:37.246870934Z\",\"container_config\":{\"Cmd\":[\"/bin/sh
-c mkdir -p /dir1/dir2 \\u0026\\u0026 touch /dir1/file1 \\u0026\\u0026 touch
/dir1/dir2/file2\"]}}"
},
{
"v1Compatibility":
"{\"id\":\"2b25bf24b28139726f2f32099b8f317df063c2f248a6d6abc4b008c1ceacac17\",\"created\":\"2016-09-23T16:29:57.276868291Z\",\"container_config\":{\"Cmd\":[\"/bin/sh
-c #(nop) ADD
file:d6ee3ba7a4d59b161917082cc7242c660c61bb3f3cc1549c7e2dfff2b0de7104 in /
\"]}}"
}
],
"signatures": [
{
"header": {
"jwk": {
"crv": "P-256",
"kid":
"RWL7:5LI3:DN3M:6MAU:TYS3:FDVQ:IAQ7:B4U5:EDR5:CWCJ:Z6QP:GS4J",
"kty": "EC",
"x": "YFNI2IDVayhTWkAUesuPj_5JvQr4RWnkokSNMtE5v40",
"y": "5oHQggdpLiw8UsxXVW7McssLG_3ze5j1fdxER7wdy84"
},
"alg": "ES256"
},
"signature":
"u77AB7re-0Bg9F_PDKYwiaKkQEYYN24jhqqowUrj5pTSNYxRPkF4EfIfvrJJj3vz_g6f4XHUFB9-AuHVEIOIsw",
"protected":
"eyJmb3JtYXRMZW5ndGgiOjI3MDksImZvcm1hdFRhaWwiOiJDbjAiLCJ0aW1lIjoiMjAxOC0wOS0yNVQyMzo1OToyNVoifQ"
}
]
}'
I0925 23:59:25.220041 3546 registry_puller.cpp:460] Fetching blob
'sha256:0f8d75b536b30787770857e66db830c31aa28fa0eeca41140a4eadefe2961d61' for
layer '91b73244b546ccedbd9aac865689c7d97992ed6e39dc071e34a94626225fe0d5' of
image 'zhq527725/whiteout'
I0925 23:59:25.220063 3546 registry_puller.cpp:460] Fetching blob
'sha256:eb3473a516b96cd180c4b9be783e585ef60e977ea97cd7cc3eca4edce6282c3d' for
layer '249d9d7ac4cda9384bc13fc2d6f04c0080f56c857c3a5713a1b142f4523f8ab1' of
image 'zhq527725/whiteout'
I0925 23:59:25.220223 3546 registry_puller.cpp:460] Fetching blob
'sha256:c0cb142e43453ebb1f82b905aa472e6e66017efd43872135bc5372e4fac04031' for
layer '2b25bf24b28139726f2f32099b8f317df063c2f248a6d6abc4b008c1ceacac17' of
image 'zhq527725/whiteout'
I0925 23:59:25.754042 3542 hierarchical.cpp:2386] Filtered offer with cpus:1;
mem:896; disk:1024; ports:[31000-32000] on agent
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-S0 for role * of framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000
I0925 23:59:25.754099 3542 hierarchical.cpp:1564] Performed allocation for 1
agents in 145743ns
I0925 23:59:26.755367 3542 hierarchical.cpp:2386] Filtered offer with cpus:1;
mem:896; disk:1024; ports:[31000-32000] on agent
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-S0 for role * of framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000
I0925 23:59:26.755429 3542 hierarchical.cpp:1564] Performed allocation for 1
agents in 143397ns
I0925 23:59:27.756673 3545 hierarchical.cpp:2386] Filtered offer with cpus:1;
mem:896; disk:1024; ports:[31000-32000] on agent
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-S0 for role * of framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000
I0925 23:59:27.756736 3545 hierarchical.cpp:1564] Performed allocation for 1
agents in 150210ns
I0925 23:59:28.757097 3542 hierarchical.cpp:2386] Filtered offer with cpus:1;
mem:896; disk:1024; ports:[31000-32000] on agent
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-S0 for role * of framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000
I0925 23:59:28.757158 3542 hierarchical.cpp:1564] Performed allocation for 1
agents in 136320ns
I0925 23:59:29.757962 3546 hierarchical.cpp:2386] Filtered offer with cpus:1;
mem:896; disk:1024; ports:[31000-32000] on agent
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-S0 for role * of framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000
I0925 23:59:29.758021 3546 hierarchical.cpp:1564] Performed allocation for 1
agents in 192281ns
I0925 23:59:30.758527 3539 hierarchical.cpp:1564] Performed allocation for 1
agents in 172911ns
I0925 23:59:30.758664 3540 master.cpp:9468] Sending offers [
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-O1 ] to framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000 (default) at
[email protected]:41596
I0925 23:59:30.758831 3540 sched.cpp:914] Scheduler::resourceOffers took
11616ns
I0925 23:59:31.759116 3546 hierarchical.cpp:1564] Performed allocation for 1
agents in 50969ns
I0925 23:59:32.759626 3545 hierarchical.cpp:1564] Performed allocation for 1
agents in 48423ns
I0925 23:59:33.760504 3542 hierarchical.cpp:1564] Performed allocation for 1
agents in 48001ns
I0925 23:59:34.761240 3539 hierarchical.cpp:1564] Performed allocation for 1
agents in 48277ns
I0925 23:59:35.762264 3540 hierarchical.cpp:1564] Performed allocation for 1
agents in 45247ns
I0925 23:59:36.762837 3541 hierarchical.cpp:1564] Performed allocation for 1
agents in 47251ns
I0925 23:59:37.763509 3540 hierarchical.cpp:1564] Performed allocation for 1
agents in 45296ns
I0925 23:59:38.763999 3545 hierarchical.cpp:1564] Performed allocation for 1
agents in 47030ns
I0925 23:59:39.764392 3546 hierarchical.cpp:1564] Performed allocation for 1
agents in 47839ns
E0925 23:59:40.077899 3539 slave.cpp:6162] Container
'c09a3eb9-7d46-4ff0-8b70-ec87d7adf2e2' for executor
'c32a603e-7202-4534-a218-3116d8d5bb34' of framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000 failed to start: Collect failed:
Failed to perform 'curl': curl: (52) Empty reply from server
I0925 23:59:40.078114 3541 containerizer.cpp:2455] Destroying container
c09a3eb9-7d46-4ff0-8b70-ec87d7adf2e2 in PROVISIONING state
I0925 23:59:40.078130 3541 containerizer.cpp:3118] Transitioning the state of
container c09a3eb9-7d46-4ff0-8b70-ec87d7adf2e2 from PROVISIONING to DESTROYING
I0925 23:59:40.078178 3541 containerizer.cpp:2517] Waiting for the provisioner
to complete provisioning before destroying container
c09a3eb9-7d46-4ff0-8b70-ec87d7adf2e2
I0925 23:59:40.078261 3541 provisioner.cpp:597] Ignoring destroy request for
unknown container c09a3eb9-7d46-4ff0-8b70-ec87d7adf2e2
I0925 23:59:40.078485 3541 slave.cpp:6282] Executor
'c32a603e-7202-4534-a218-3116d8d5bb34' of framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000 has terminated with unknown status
I0925 23:59:40.078692 3541 slave.cpp:5269] Handling status update TASK_FAILED
(Status UUID: 4018b162-d678-40c4-8701-72e9d2cc1862) for task
c32a603e-7202-4534-a218-3116d8d5bb34 of framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000 from @0.0.0.0:0
E0925 23:59:40.078896 3541 slave.cpp:5600] Failed to update resources for
container c09a3eb9-7d46-4ff0-8b70-ec87d7adf2e2 of executor
'c32a603e-7202-4534-a218-3116d8d5bb34' running task
c32a603e-7202-4534-a218-3116d8d5bb34 on status update for terminal task,
destroying container: Container not found
W0925 23:59:40.078968 3541 composing.cpp:609] Attempted to destroy unknown
container c09a3eb9-7d46-4ff0-8b70-ec87d7adf2e2
I0925 23:59:40.078997 3539 task_status_update_manager.cpp:328] Received task
status update TASK_FAILED (Status UUID: 4018b162-d678-40c4-8701-72e9d2cc1862)
for task c32a603e-7202-4534-a218-3116d8d5bb34 of framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000
I0925 23:59:40.079020 3539 task_status_update_manager.cpp:507] Creating
StatusUpdate stream for task c32a603e-7202-4534-a218-3116d8d5bb34 of framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000
I0925 23:59:40.079157 3539 task_status_update_manager.cpp:383] Forwarding task
status update TASK_FAILED (Status UUID: 4018b162-d678-40c4-8701-72e9d2cc1862)
for task c32a603e-7202-4534-a218-3116d8d5bb34 of framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000 to the agent
I0925 23:59:40.079221 3539 slave.cpp:5761] Forwarding the update TASK_FAILED
(Status UUID: 4018b162-d678-40c4-8701-72e9d2cc1862) for task
c32a603e-7202-4534-a218-3116d8d5bb34 of framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000 to [email protected]:41596
I0925 23:59:40.079296 3539 slave.cpp:5654] Task status update manager
successfully handled status update TASK_FAILED (Status UUID:
4018b162-d678-40c4-8701-72e9d2cc1862) for task
c32a603e-7202-4534-a218-3116d8d5bb34 of framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000
I0925 23:59:40.079375 3539 master.cpp:8375] Status update TASK_FAILED (Status
UUID: 4018b162-d678-40c4-8701-72e9d2cc1862) for task
c32a603e-7202-4534-a218-3116d8d5bb34 of framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000 from agent
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-S0 at slave(1320)@172.16.10.34:41596
(ip-172-16-10-34.ec2.internal)
I0925 23:59:40.079398 3539 master.cpp:8432] Forwarding status update
TASK_FAILED (Status UUID: 4018b162-d678-40c4-8701-72e9d2cc1862) for task
c32a603e-7202-4534-a218-3116d8d5bb34 of framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000
I0925 23:59:40.079457 3539 master.cpp:10932] Updating the state of task
c32a603e-7202-4534-a218-3116d8d5bb34 of framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000 (latest state: TASK_FAILED, status
update state: TASK_FAILED)
I0925 23:59:40.079643 3542 sched.cpp:1022] Scheduler::statusUpdate took 27246ns
I0925 23:59:40.079654 3539 hierarchical.cpp:1236] Recovered cpus(allocated:
*):1; mem(allocated: *):128 (total: cpus:2; mem:1024; disk:1024;
ports:[31000-32000], allocated: cpus(allocated: *):1; mem(allocated: *):896;
disk(allocated: *):1024; ports(allocated: *):[31000-32000]) on agent
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-S0 from framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000
I0925 23:59:40.079749 3540 master.cpp:6241] Processing ACKNOWLEDGE call for
status 4018b162-d678-40c4-8701-72e9d2cc1862 for task
c32a603e-7202-4534-a218-3116d8d5bb34 of framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000 (default) at
[email protected]:41596 on agent
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-S0
I0925 23:59:40.079773 3540 master.cpp:11030] Removing task
c32a603e-7202-4534-a218-3116d8d5bb34 with resources cpus(allocated: *):1;
mem(allocated: *):128 of framework 34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000 on
agent 34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-S0 at slave(1320)@172.16.10.34:41596
(ip-172-16-10-34.ec2.internal)
I0925 23:59:40.079895 3540 task_status_update_manager.cpp:401] Received task
status update acknowledgement (UUID: 4018b162-d678-40c4-8701-72e9d2cc1862) for
task c32a603e-7202-4534-a218-3116d8d5bb34 of framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000
I0925 23:59:40.079917 3540 task_status_update_manager.cpp:538] Cleaning up
status update stream for task c32a603e-7202-4534-a218-3116d8d5bb34 of framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000
I0925 23:59:40.079983 3540 slave.cpp:4505] Task status update manager
successfully handled status update acknowledgement (UUID:
4018b162-d678-40c4-8701-72e9d2cc1862) for task
c32a603e-7202-4534-a218-3116d8d5bb34 of framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000
I0925 23:59:40.079998 3540 slave.cpp:9651] Completing task
c32a603e-7202-4534-a218-3116d8d5bb34
I0925 23:59:40.080005 3540 slave.cpp:6387] Cleaning up executor
'c32a603e-7202-4534-a218-3116d8d5bb34' of framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000
I0925 23:59:40.080106 3541 gc.cpp:95] Scheduling
'/tmp/BackendFlag_ProvisionerDockerBackendTest_ROOT_INTERNET_CURL_DTYPE_Whiteout_0_Z9m3Wr/slaves/34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-S0/frameworks/34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000/executors/c32a603e-7202-4534-a218-3116d8d5bb34/runs/c09a3eb9-7d46-4ff0-8b70-ec87d7adf2e2'
for gc 6.99999907329778days in the future
I0925 23:59:40.080207 3544 gc.cpp:95] Scheduling
'/tmp/BackendFlag_ProvisionerDockerBackendTest_ROOT_INTERNET_CURL_DTYPE_Whiteout_0_Z9m3Wr/slaves/34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-S0/frameworks/34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000/executors/c32a603e-7202-4534-a218-3116d8d5bb34'
for gc 6.99999907226963days in the future
I0925 23:59:40.080296 3540 slave.cpp:6516] Cleaning up framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000
I0925 23:59:40.080351 3542 task_status_update_manager.cpp:289] Closing task
status update streams for framework 34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000
I0925 23:59:40.080377 3540 gc.cpp:95] Scheduling
'/tmp/BackendFlag_ProvisionerDockerBackendTest_ROOT_INTERNET_CURL_DTYPE_Whiteout_0_Z9m3Wr/slaves/34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-S0/frameworks/34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000'
for gc 6.99999906998815days in the future
../../src/tests/containerizer/provisioner_docker_tests.cpp:915: Failure
Expected: TASK_STARTING
To be equal to: statusStarting->state()
Which is: TASK_FAILED
I0925 23:59:40.764869 3542 hierarchical.cpp:1564] Performed allocation for 1
agents in 146265ns
I0925 23:59:40.765002 3539 master.cpp:9468] Sending offers [
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-O2 ] to framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000 (default) at
[email protected]:41596
I0925 23:59:40.765169 3539 sched.cpp:914] Scheduler::resourceOffers took
12261ns
I0925 23:59:41.765647 3541 hierarchical.cpp:1564] Performed allocation for 1
agents in 74914ns
I0925 23:59:42.766710 3542 hierarchical.cpp:1564] Performed allocation for 1
agents in 48384ns
I0925 23:59:43.767702 3546 hierarchical.cpp:1564] Performed allocation for 1
agents in 66501ns
I0925 23:59:44.768342 3540 hierarchical.cpp:1564] Performed allocation for 1
agents in 46549ns
I0925 23:59:45.769346 3543 hierarchical.cpp:1564] Performed allocation for 1
agents in 47761ns
I0925 23:59:46.770074 3544 hierarchical.cpp:1564] Performed allocation for 1
agents in 46849ns
I0925 23:59:47.770905 3545 hierarchical.cpp:1564] Performed allocation for 1
agents in 47100ns
I0925 23:59:48.771682 3539 hierarchical.cpp:1564] Performed allocation for 1
agents in 46827ns
I0925 23:59:49.772459 3541 hierarchical.cpp:1564] Performed allocation for 1
agents in 46281ns
I0925 23:59:50.773319 3543 hierarchical.cpp:1564] Performed allocation for 1
agents in 47818ns
I0925 23:59:51.774134 3544 hierarchical.cpp:1564] Performed allocation for 1
agents in 48894ns
I0925 23:59:52.774857 3545 hierarchical.cpp:1564] Performed allocation for 1
agents in 48782ns
I0925 23:59:53.775614 3539 hierarchical.cpp:1564] Performed allocation for 1
agents in 46377ns
I0925 23:59:54.776389 3541 hierarchical.cpp:1564] Performed allocation for 1
agents in 47268ns
../../src/tests/containerizer/provisioner_docker_tests.cpp:917: Failure
Failed to wait 15secs for statusRunning
../../src/tests/containerizer/provisioner_docker_tests.cpp:906: Failure
Actual function call count doesn't match EXPECT_CALL(sched,
statusUpdate(&driver, _))...
Expected: to be called 3 times
Actual: called once - unsatisfied and active
I0925 23:59:55.081843 21740 slave.cpp:909] Agent terminating
I0925 23:59:55.082181 3542 master.cpp:1366] Framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000 (default) at
[email protected]:41596 disconnected
I0925 23:59:55.082211 3542 master.cpp:3230] Deactivating framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000 (default) at
[email protected]:41596
I0925 23:59:55.082289 3542 master.cpp:11462] Removing offer
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-O2
I0925 23:59:55.082417 3542 master.cpp:11462] Removing offer
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-O1
I0925 23:59:55.082439 3542 master.cpp:3207] Disconnecting framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000 (default) at
[email protected]:41596
I0925 23:59:55.082476 3542 master.cpp:1381] Giving framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000 (default) at
[email protected]:41596 0ns to
failover
I0925 23:59:55.082617 3543 hierarchical.cpp:420] Deactivated framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000
I0925 23:59:55.082721 3543 hierarchical.cpp:1236] Recovered cpus(allocated:
*):1; mem(allocated: *):128 (total: cpus:2; mem:1024; disk:1024;
ports:[31000-32000], allocated: cpus(allocated: *):1; mem(allocated: *):896;
disk(allocated: *):1024; ports(allocated: *):[31000-32000]) on agent
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-S0 from framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000
I0925 23:59:55.082852 3543 hierarchical.cpp:1236] Recovered cpus(allocated:
*):1; mem(allocated: *):896; disk(allocated: *):1024; ports(allocated:
*):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000],
allocated: {}) on agent 34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-S0 from framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000
I0925 23:59:55.082957 3542 master.cpp:1251] Agent
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-S0 at slave(1320)@172.16.10.34:41596
(ip-172-16-10-34.ec2.internal) disconnected
I0925 23:59:55.082971 3542 master.cpp:3267] Disconnecting agent
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-S0 at slave(1320)@172.16.10.34:41596
(ip-172-16-10-34.ec2.internal)
I0925 23:59:55.082988 3542 master.cpp:3286] Deactivating agent
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-S0 at slave(1320)@172.16.10.34:41596
(ip-172-16-10-34.ec2.internal)
I0925 23:59:55.083029 3542 hierarchical.cpp:795] Agent
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-S0 deactivated
I0925 23:59:55.083098 3540 master.cpp:9261] Framework failover timeout,
removing framework 34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000 (default) at
[email protected]:41596
I0925 23:59:55.083112 3540 master.cpp:10197] Removing framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000 (default) at
[email protected]:41596
I0925 23:59:55.083237 3540 hierarchical.cpp:359] Removed framework
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000
I0925 23:59:55.085688 21740 master.cpp:1093] Master terminating
I0925 23:59:55.085791 3541 hierarchical.cpp:637] Removed agent
34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-S0
[ FAILED ]
BackendFlag/ProvisionerDockerBackendTest.ROOT_INTERNET_CURL_DTYPE_Whiteout/0,
where GetParam() = "copy" (30337 ms)
{noformat}
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
