[
https://issues.apache.org/jira/browse/MESOS-9262?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16628547#comment-16628547
]
Alexander Rukletsov commented on MESOS-9262:
--------------------------------------------
{noformat}
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
{noformat}
I wonder whether this is related to the recent flavour of MESOS-7425 and why we
use weird images like {{zhq527725/whiteout}}?
> 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
> Priority: Major
> Labels: flaky-test
>
> 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)
