Details
-
Bug
-
Status: Open
-
Major
-
Resolution: Unresolved
-
None
-
None
-
None
Description
Observed in an internal CI run (4489):
../../src/tests/containerizer/provisioner_docker_tests.cpp:915
Expected: TASK_STARTING
To be equal to: statusStarting->state()
Which is: TASK_FAILED
Full log:
[ 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 files@172.16.10.34: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 version@172.16.10.34: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 master@172.16.10.34:41596
I0925 23:59:24.829897 3545 sched.cpp:401] Authenticating with master master@172.16.10.34: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 scheduler-798c72e4-69a5-4b49-b012-a2487a866be1@172.16.10.34: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 scheduler-798c72e4-69a5-4b49-b012-a2487a866be1@172.16.10.34: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 master@172.16.10.34:41596
I0925 23:59:24.830651 3545 sched.cpp:817] Sending SUBSCRIBE call to master@172.16.10.34: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 scheduler-798c72e4-69a5-4b49-b012-a2487a866be1@172.16.10.34: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 scheduler-798c72e4-69a5-4b49-b012-a2487a866be1@172.16.10.34: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 master@172.16.10.34: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 master@172.16.10.34: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 master@172.16.10.34: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 master@172.16.10.34: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 scheduler-798c72e4-69a5-4b49-b012-a2487a866be1@172.16.10.34: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 scheduler-798c72e4-69a5-4b49-b012-a2487a866be1@172.16.10.34: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 scheduler-798c72e4-69a5-4b49-b012-a2487a866be1@172.16.10.34: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 scheduler-798c72e4-69a5-4b49-b012-a2487a866be1@172.16.10.34: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 master@172.16.10.34: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 scheduler-798c72e4-69a5-4b49-b012-a2487a866be1@172.16.10.34: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 scheduler-798c72e4-69a5-4b49-b012-a2487a866be1@172.16.10.34: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 scheduler-798c72e4-69a5-4b49-b012-a2487a866be1@172.16.10.34:41596 disconnected
I0925 23:59:55.082211 3542 master.cpp:3230] Deactivating framework 34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000 (default) at scheduler-798c72e4-69a5-4b49-b012-a2487a866be1@172.16.10.34: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 scheduler-798c72e4-69a5-4b49-b012-a2487a866be1@172.16.10.34:41596
I0925 23:59:55.082476 3542 master.cpp:1381] Giving framework 34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000 (default) at scheduler-798c72e4-69a5-4b49-b012-a2487a866be1@172.16.10.34: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 scheduler-798c72e4-69a5-4b49-b012-a2487a866be1@172.16.10.34:41596
I0925 23:59:55.083112 3540 master.cpp:10197] Removing framework 34b4dabd-2b7c-4ba6-bccf-4dfa968087a1-0000 (default) at scheduler-798c72e4-69a5-4b49-b012-a2487a866be1@172.16.10.34: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)
Attachments
Issue Links
- is related to
-
-
- Accepted
-