Details
-
Bug
-
Status: Open
-
Major
-
Resolution: Unresolved
-
1.7.0
-
None
-
None
Description
ARM CI randomly fails due to DiskQuotaTest.SlaveRecovery
[ RUN ] DiskQuotaTest.SlaveRecovery I0912 18:37:55.395987 38652 cluster.cpp:173] Creating default 'local' authorizer I0912 18:37:55.401186 38719 master.cpp:413] Master c7797969-05a8-4105-a072-ffe5c94c28ab (0de113ebdc41) started on 172.17.0.4:45557 I0912 18:37:55.401280 38719 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/1R8Uhh/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="/tmp/SRC/build/mesos-1.8.0/_inst/share/mesos/webui" --work_dir="/tmp/1R8Uhh/master" --zk_session_timeout="10secs" I0912 18:37:55.401906 38719 master.cpp:465] Master only allowing authenticated frameworks to register I0912 18:37:55.401962 38719 master.cpp:471] Master only allowing authenticated agents to register I0912 18:37:55.402009 38719 master.cpp:477] Master only allowing authenticated HTTP frameworks to register I0912 18:37:55.402052 38719 credentials.hpp:37] Loading credentials for authentication from '/tmp/1R8Uhh/credentials' I0912 18:37:55.402516 38719 master.cpp:521] Using default 'crammd5' authenticator I0912 18:37:55.402922 38719 http.cpp:1037] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly' I0912 18:37:55.403275 38719 http.cpp:1037] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite' I0912 18:37:55.403566 38719 http.cpp:1037] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler' I0912 18:37:55.403851 38719 master.cpp:602] Authorization enabled I0912 18:37:55.404628 38739 hierarchical.cpp:182] Initialized hierarchical allocator process I0912 18:37:55.404647 38725 whitelist_watcher.cpp:77] No whitelist given I0912 18:37:55.410480 38732 master.cpp:2083] Elected as the leading master! I0912 18:37:55.410547 38732 master.cpp:1638] Recovering from registrar I0912 18:37:55.410846 38748 registrar.cpp:339] Recovering registrar I0912 18:37:55.411978 38748 registrar.cpp:383] Successfully fetched the registry (0B) in 1.053952ms I0912 18:37:55.412230 38748 registrar.cpp:487] Applied 1 operations in 100832ns; attempting to update the registry I0912 18:37:55.418246 38748 registrar.cpp:544] Successfully updated the registry in 5.888768ms I0912 18:37:55.418493 38748 registrar.cpp:416] Successfully recovered registrar I0912 18:37:55.419291 38746 master.cpp:1752] Recovered 0 agents from the registry (135B); allowing 10mins for agents to reregister I0912 18:37:55.419399 38712 hierarchical.cpp:220] Skipping recovery of hierarchical allocator: nothing to recover I0912 18:37:55.425879 38652 containerizer.cpp:305] Using isolation { environment_secret, filesystem/posix, network/cni, posix/mem, disk/du, posix/cpu } W0912 18:37:55.427079 38652 backend.cpp:76] Failed to create 'overlay' backend: OverlayBackend requires root privileges W0912 18:37:55.427168 38652 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges I0912 18:37:55.427255 38652 provisioner.cpp:298] Using default backend 'copy' W0912 18:37:55.436985 38652 process.cpp:2810] Attempted to spawn already running process files@172.17.0.4:45557 I0912 18:37:55.438319 38652 cluster.cpp:485] Creating default 'local' authorizer I0912 18:37:55.441820 38661 slave.cpp:267] Mesos agent started on (40)@172.17.0.4:45557 I0912 18:37:55.441913 38661 slave.cpp:268] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/DiskQuotaTest_SlaveRecovery_PWToQc/store/appc" --authenticate_http_readonly="true" --authenticate_http_readwrite="false" --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="1ms" --containerizers="mesos" --credential="/tmp/DiskQuotaTest_SlaveRecovery_PWToQc/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/DiskQuotaTest_SlaveRecovery_PWToQc/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/DiskQuotaTest_SlaveRecovery_PWToQc/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/DiskQuotaTest_SlaveRecovery_PWToQc/http_credentials" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem,disk/du" --launcher="posix" --launcher_dir="/tmp/SRC/build/mesos-1.8.0/_build/sub/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/DiskQuotaTest_SlaveRecovery_PWToQc" --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/DiskQuotaTest_SlaveRecovery_2QLn4J" --zk_session_timeout="10secs" I0912 18:37:55.442787 38661 credentials.hpp:86] Loading credential for authentication from '/tmp/DiskQuotaTest_SlaveRecovery_PWToQc/credential' W0912 18:37:55.442934 38652 process.cpp:2810] Attempted to spawn already running process version@172.17.0.4:45557 I0912 18:37:55.443086 38661 slave.cpp:300] Agent using credential for: test-principal I0912 18:37:55.443151 38661 credentials.hpp:37] Loading credentials for authentication from '/tmp/DiskQuotaTest_SlaveRecovery_PWToQc/http_credentials' I0912 18:37:55.443516 38661 http.cpp:1037] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly' I0912 18:37:55.444134 38661 disk_profile_adaptor.cpp:80] Creating default disk profile adaptor module I0912 18:37:55.444725 38652 sched.cpp:232] Version: 1.8.0 I0912 18:37:55.445701 38735 sched.cpp:336] New master detected at master@172.17.0.4:45557 I0912 18:37:55.445902 38735 sched.cpp:401] Authenticating with master master@172.17.0.4:45557 I0912 18:37:55.445964 38735 sched.cpp:408] Using default CRAM-MD5 authenticatee I0912 18:37:55.446480 38720 authenticatee.cpp:121] Creating new client SASL connection I0912 18:37:55.446610 38661 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"}] I0912 18:37:55.447016 38661 slave.cpp:623] Agent attributes: [ ] I0912 18:37:55.447077 38661 slave.cpp:632] Agent hostname: 0de113ebdc41 I0912 18:37:55.447237 38743 master.cpp:9653] Authenticating scheduler-39610234-c5eb-4cbd-b4e2-88f330d9ce64@172.17.0.4:45557 I0912 18:37:55.447505 38727 task_status_update_manager.cpp:181] Pausing sending task status updates I0912 18:37:55.447608 38709 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(87)@172.17.0.4:45557 I0912 18:37:55.448102 38679 authenticator.cpp:98] Creating new server SASL connection I0912 18:37:55.448593 38675 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 I0912 18:37:55.448683 38675 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' I0912 18:37:55.449071 38736 authenticator.cpp:204] Received SASL authentication start I0912 18:37:55.449211 38736 authenticator.cpp:326] Authentication requires more steps I0912 18:37:55.449460 38738 authenticatee.cpp:259] Received SASL authentication step I0912 18:37:55.449728 38721 authenticator.cpp:232] Received SASL authentication step I0912 18:37:55.449808 38721 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '0de113ebdc41' server FQDN: '0de113ebdc41' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0912 18:37:55.449879 38721 auxprop.cpp:181] Looking up auxiliary property '*userPassword' I0912 18:37:55.449992 38721 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0912 18:37:55.450085 38721 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '0de113ebdc41' server FQDN: '0de113ebdc41' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0912 18:37:55.450150 38721 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0912 18:37:55.450211 38721 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0912 18:37:55.450212 38710 state.cpp:66] Recovering state from '/tmp/DiskQuotaTest_SlaveRecovery_2QLn4J/meta' I0912 18:37:55.450325 38721 authenticator.cpp:318] Authentication success I0912 18:37:55.450532 38662 authenticatee.cpp:299] Authentication success I0912 18:37:55.450637 38653 slave.cpp:6909] Finished recovering checkpointed state from '/tmp/DiskQuotaTest_SlaveRecovery_2QLn4J/meta', beginning agent recovery I0912 18:37:55.450762 38708 master.cpp:9685] Successfully authenticated principal 'test-principal' at scheduler-39610234-c5eb-4cbd-b4e2-88f330d9ce64@172.17.0.4:45557 I0912 18:37:55.451002 38725 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(87)@172.17.0.4:45557 I0912 18:37:55.451086 38695 task_status_update_manager.cpp:207] Recovering task status update manager I0912 18:37:55.451297 38657 sched.cpp:513] Successfully authenticated with master master@172.17.0.4:45557 I0912 18:37:55.451364 38657 sched.cpp:817] Sending SUBSCRIBE call to master@172.17.0.4:45557 I0912 18:37:55.451638 38657 sched.cpp:850] Will retry registration in 1.854616116secs if necessary I0912 18:37:55.451776 38665 containerizer.cpp:727] Recovering Mesos containers I0912 18:37:55.451997 38726 master.cpp:2854] Received SUBSCRIBE call for framework 'default' at scheduler-39610234-c5eb-4cbd-b4e2-88f330d9ce64@172.17.0.4:45557 I0912 18:37:55.452065 38726 master.cpp:2155] Authorizing framework principal 'test-principal' to receive offers for roles '{ * }' I0912 18:37:55.452353 38665 containerizer.cpp:1053] Recovering isolators I0912 18:37:55.453115 38693 master.cpp:2935] Subscribing framework default with checkpointing enabled and capabilities [ MULTI_ROLE, RESERVATION_REFINEMENT ] I0912 18:37:55.453861 38706 containerizer.cpp:1092] Recovering provisioner I0912 18:37:55.455648 38737 provisioner.cpp:494] Provisioner recovery complete I0912 18:37:55.457115 38718 composing.cpp:339] Finished recovering all containerizers I0912 18:37:55.457453 38666 slave.cpp:7138] Recovering executors I0912 18:37:55.457711 38666 slave.cpp:7291] Finished recovery I0912 18:37:55.458673 38693 master.cpp:9883] Adding framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 (default) at scheduler-39610234-c5eb-4cbd-b4e2-88f330d9ce64@172.17.0.4:45557 with roles { } suppressed I0912 18:37:55.459583 38693 sched.cpp:744] Framework registered with c7797969-05a8-4105-a072-ffe5c94c28ab-0000 I0912 18:37:55.459661 38713 slave.cpp:1254] New master detected at master@172.17.0.4:45557 I0912 18:37:55.459715 38693 sched.cpp:758] Scheduler::registered took 91053ns I0912 18:37:55.459810 38713 slave.cpp:1319] Detecting new master I0912 18:37:55.459693 38687 task_status_update_manager.cpp:181] Pausing sending task status updates I0912 18:37:55.460155 38666 hierarchical.cpp:306] Added framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 I0912 18:37:55.460559 38666 hierarchical.cpp:1564] Performed allocation for 0 agents in 166674ns I0912 18:37:55.470784 38705 slave.cpp:1346] Authenticating with master master@172.17.0.4:45557 I0912 18:37:55.470932 38705 slave.cpp:1355] Using default CRAM-MD5 authenticatee I0912 18:37:55.471294 38715 authenticatee.cpp:121] Creating new client SASL connection I0912 18:37:55.471736 38699 master.cpp:9653] Authenticating slave(40)@172.17.0.4:45557 I0912 18:37:55.471947 38683 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(88)@172.17.0.4:45557 I0912 18:37:55.472369 38690 authenticator.cpp:98] Creating new server SASL connection I0912 18:37:55.472697 38656 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 I0912 18:37:55.472769 38656 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' I0912 18:37:55.472985 38707 authenticator.cpp:204] Received SASL authentication start I0912 18:37:55.473100 38707 authenticator.cpp:326] Authentication requires more steps I0912 18:37:55.473322 38663 authenticatee.cpp:259] Received SASL authentication step I0912 18:37:55.473561 38694 authenticator.cpp:232] Received SASL authentication step I0912 18:37:55.473637 38694 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '0de113ebdc41' server FQDN: '0de113ebdc41' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0912 18:37:55.473700 38694 auxprop.cpp:181] Looking up auxiliary property '*userPassword' I0912 18:37:55.473793 38694 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0912 18:37:55.473881 38694 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '0de113ebdc41' server FQDN: '0de113ebdc41' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0912 18:37:55.473943 38694 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0912 18:37:55.474002 38694 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0912 18:37:55.474071 38694 authenticator.cpp:318] Authentication success I0912 18:37:55.474264 38702 authenticatee.cpp:299] Authentication success I0912 18:37:55.474350 38735 master.cpp:9685] Successfully authenticated principal 'test-principal' at slave(40)@172.17.0.4:45557 I0912 18:37:55.474423 38688 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(88)@172.17.0.4:45557 I0912 18:37:55.474987 38694 slave.cpp:1446] Successfully authenticated with master master@172.17.0.4:45557 I0912 18:37:55.475708 38694 slave.cpp:1877] Will retry registration in 6.330244ms if necessary I0912 18:37:55.475947 38743 master.cpp:6605] Received register agent message from slave(40)@172.17.0.4:45557 (0de113ebdc41) I0912 18:37:55.476363 38743 master.cpp:3964] Authorizing agent providing resources 'cpus:2; mem:1024; disk:1024; ports:[31000-32000]' with principal 'test-principal' I0912 18:37:55.477432 38675 master.cpp:6672] Authorized registration of agent at slave(40)@172.17.0.4:45557 (0de113ebdc41) I0912 18:37:55.477605 38675 master.cpp:6787] Registering agent at slave(40)@172.17.0.4:45557 (0de113ebdc41) with id c7797969-05a8-4105-a072-ffe5c94c28ab-S0 I0912 18:37:55.478703 38747 registrar.cpp:487] Applied 1 operations in 493103ns; attempting to update the registry I0912 18:37:55.479769 38747 registrar.cpp:544] Successfully updated the registry in 953856ns I0912 18:37:55.480046 38739 master.cpp:6835] Admitted agent c7797969-05a8-4105-a072-ffe5c94c28ab-S0 at slave(40)@172.17.0.4:45557 (0de113ebdc41) I0912 18:37:55.481137 38739 master.cpp:6880] Registered agent c7797969-05a8-4105-a072-ffe5c94c28ab-S0 at slave(40)@172.17.0.4:45557 (0de113ebdc41) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] I0912 18:37:55.481360 38708 slave.cpp:1479] Registered with master master@172.17.0.4:45557; given agent ID c7797969-05a8-4105-a072-ffe5c94c28ab-S0 I0912 18:37:55.481564 38662 task_status_update_manager.cpp:188] Resuming sending task status updates I0912 18:37:55.482012 38708 slave.cpp:1499] Checkpointing SlaveInfo to '/tmp/DiskQuotaTest_SlaveRecovery_2QLn4J/meta/slaves/c7797969-05a8-4105-a072-ffe5c94c28ab-S0/slave.info' I0912 18:37:55.481994 38717 hierarchical.cpp:601] Added agent c7797969-05a8-4105-a072-ffe5c94c28ab-S0 (0de113ebdc41) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (allocated: {}) I0912 18:37:55.483934 38708 slave.cpp:1548] Forwarding agent update {"operations":{},"resource_version_uuid":{"value":"9uii54sGR2ytS8rBMMGvow=="},"slave_id":{"value":"c7797969-05a8-4105-a072-ffe5c94c28ab-S0"},"update_oversubscribed_resources":false} I0912 18:37:55.485009 38717 hierarchical.cpp:1564] Performed allocation for 1 agents in 2.722231ms I0912 18:37:55.485376 38708 master.cpp:7939] Ignoring update on agent c7797969-05a8-4105-a072-ffe5c94c28ab-S0 at slave(40)@172.17.0.4:45557 (0de113ebdc41) as it reports no changes I0912 18:37:55.486342 38708 master.cpp:9468] Sending offers [ c7797969-05a8-4105-a072-ffe5c94c28ab-O0 ] to framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 (default) at scheduler-39610234-c5eb-4cbd-b4e2-88f330d9ce64@172.17.0.4:45557 I0912 18:37:55.487388 38714 sched.cpp:914] Scheduler::resourceOffers took 275677ns I0912 18:37:55.490996 38664 master.cpp:11462] Removing offer c7797969-05a8-4105-a072-ffe5c94c28ab-O0 I0912 18:37:55.492046 38664 master.cpp:4467] Processing ACCEPT call for offers: [ c7797969-05a8-4105-a072-ffe5c94c28ab-O0 ] on agent c7797969-05a8-4105-a072-ffe5c94c28ab-S0 at slave(40)@172.17.0.4:45557 (0de113ebdc41) for framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 (default) at scheduler-39610234-c5eb-4cbd-b4e2-88f330d9ce64@172.17.0.4:45557 I0912 18:37:55.492270 38664 master.cpp:3541] Authorizing framework principal 'test-principal' to launch task 06719087-e7d8-4ee3-8ae5-236e323a2c0a I0912 18:37:55.496507 38659 master.cpp:12209] Adding task 06719087-e7d8-4ee3-8ae5-236e323a2c0a with resources cpus(allocated: *):1; mem(allocated: *):128; disk(allocated: *):3 on agent c7797969-05a8-4105-a072-ffe5c94c28ab-S0 at slave(40)@172.17.0.4:45557 (0de113ebdc41) I0912 18:37:55.497212 38659 master.cpp:5439] Launching task 06719087-e7d8-4ee3-8ae5-236e323a2c0a of framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 (default) at scheduler-39610234-c5eb-4cbd-b4e2-88f330d9ce64@172.17.0.4:45557 with resources [{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":1.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":128.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"disk","scalar":{"value":3.0},"type":"SCALAR"}] on agent c7797969-05a8-4105-a072-ffe5c94c28ab-S0 at slave(40)@172.17.0.4:45557 (0de113ebdc41) on new executor I0912 18:37:55.499549 38728 hierarchical.cpp:1236] Recovered cpus(allocated: *):1; mem(allocated: *):896; disk(allocated: *):1021; ports(allocated: *):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000], allocated: cpus(allocated: *):1; mem(allocated: *):128; disk(allocated: *):3) on agent c7797969-05a8-4105-a072-ffe5c94c28ab-S0 from framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 I0912 18:37:55.499620 38718 slave.cpp:2014] Got assigned task '06719087-e7d8-4ee3-8ae5-236e323a2c0a' for framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 I0912 18:37:55.499698 38728 hierarchical.cpp:1282] Framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 filtered agent c7797969-05a8-4105-a072-ffe5c94c28ab-S0 for 5secs I0912 18:37:55.500021 38718 slave.cpp:8908] Checkpointing FrameworkInfo to '/tmp/DiskQuotaTest_SlaveRecovery_2QLn4J/meta/slaves/c7797969-05a8-4105-a072-ffe5c94c28ab-S0/frameworks/c7797969-05a8-4105-a072-ffe5c94c28ab-0000/framework.info' I0912 18:37:55.501052 38718 slave.cpp:8919] Checkpointing framework pid 'scheduler-39610234-c5eb-4cbd-b4e2-88f330d9ce64@172.17.0.4:45557' to '/tmp/DiskQuotaTest_SlaveRecovery_2QLn4J/meta/slaves/c7797969-05a8-4105-a072-ffe5c94c28ab-S0/frameworks/c7797969-05a8-4105-a072-ffe5c94c28ab-0000/framework.pid' I0912 18:37:55.503863 38718 slave.cpp:2388] Authorizing task '06719087-e7d8-4ee3-8ae5-236e323a2c0a' for framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 I0912 18:37:55.504014 38718 slave.cpp:8466] Authorizing framework principal 'test-principal' to launch task 06719087-e7d8-4ee3-8ae5-236e323a2c0a I0912 18:37:55.507529 38718 slave.cpp:2831] Launching task '06719087-e7d8-4ee3-8ae5-236e323a2c0a' for framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 I0912 18:37:55.507725 38718 paths.cpp:752] Creating sandbox '/tmp/DiskQuotaTest_SlaveRecovery_2QLn4J/slaves/c7797969-05a8-4105-a072-ffe5c94c28ab-S0/frameworks/c7797969-05a8-4105-a072-ffe5c94c28ab-0000/executors/06719087-e7d8-4ee3-8ae5-236e323a2c0a/runs/c1ec0308-3a43-49f8-885f-3895295cc18f' for user 'mesos' I0912 18:37:55.509419 38718 slave.cpp:9694] Checkpointing ExecutorInfo to '/tmp/DiskQuotaTest_SlaveRecovery_2QLn4J/meta/slaves/c7797969-05a8-4105-a072-ffe5c94c28ab-S0/frameworks/c7797969-05a8-4105-a072-ffe5c94c28ab-0000/executors/06719087-e7d8-4ee3-8ae5-236e323a2c0a/executor.info' I0912 18:37:55.510865 38718 paths.cpp:755] Creating sandbox '/tmp/DiskQuotaTest_SlaveRecovery_2QLn4J/meta/slaves/c7797969-05a8-4105-a072-ffe5c94c28ab-S0/frameworks/c7797969-05a8-4105-a072-ffe5c94c28ab-0000/executors/06719087-e7d8-4ee3-8ae5-236e323a2c0a/runs/c1ec0308-3a43-49f8-885f-3895295cc18f' I0912 18:37:55.511574 38718 slave.cpp:8994] Launching executor '06719087-e7d8-4ee3-8ae5-236e323a2c0a' of framework c7797969-05a8-4105-a072-ffe5c94c28ab-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/DiskQuotaTest_SlaveRecovery_2QLn4J/slaves/c7797969-05a8-4105-a072-ffe5c94c28ab-S0/frameworks/c7797969-05a8-4105-a072-ffe5c94c28ab-0000/executors/06719087-e7d8-4ee3-8ae5-236e323a2c0a/runs/c1ec0308-3a43-49f8-885f-3895295cc18f' I0912 18:37:55.513037 38718 slave.cpp:3509] Launching container c1ec0308-3a43-49f8-885f-3895295cc18f for executor '06719087-e7d8-4ee3-8ae5-236e323a2c0a' of framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 I0912 18:37:55.514143 38718 slave.cpp:9725] Checkpointing TaskInfo to '/tmp/DiskQuotaTest_SlaveRecovery_2QLn4J/meta/slaves/c7797969-05a8-4105-a072-ffe5c94c28ab-S0/frameworks/c7797969-05a8-4105-a072-ffe5c94c28ab-0000/executors/06719087-e7d8-4ee3-8ae5-236e323a2c0a/runs/c1ec0308-3a43-49f8-885f-3895295cc18f/tasks/06719087-e7d8-4ee3-8ae5-236e323a2c0a/task.info' I0912 18:37:55.515821 38718 slave.cpp:3028] Queued task '06719087-e7d8-4ee3-8ae5-236e323a2c0a' for executor '06719087-e7d8-4ee3-8ae5-236e323a2c0a' of framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 I0912 18:37:55.516027 38718 slave.cpp:988] Successfully attached '/tmp/DiskQuotaTest_SlaveRecovery_2QLn4J/slaves/c7797969-05a8-4105-a072-ffe5c94c28ab-S0/frameworks/c7797969-05a8-4105-a072-ffe5c94c28ab-0000/executors/06719087-e7d8-4ee3-8ae5-236e323a2c0a/runs/c1ec0308-3a43-49f8-885f-3895295cc18f' to virtual path '/tmp/DiskQuotaTest_SlaveRecovery_2QLn4J/slaves/c7797969-05a8-4105-a072-ffe5c94c28ab-S0/frameworks/c7797969-05a8-4105-a072-ffe5c94c28ab-0000/executors/06719087-e7d8-4ee3-8ae5-236e323a2c0a/runs/latest' I0912 18:37:55.516151 38718 slave.cpp:988] Successfully attached '/tmp/DiskQuotaTest_SlaveRecovery_2QLn4J/slaves/c7797969-05a8-4105-a072-ffe5c94c28ab-S0/frameworks/c7797969-05a8-4105-a072-ffe5c94c28ab-0000/executors/06719087-e7d8-4ee3-8ae5-236e323a2c0a/runs/c1ec0308-3a43-49f8-885f-3895295cc18f' to virtual path '/frameworks/c7797969-05a8-4105-a072-ffe5c94c28ab-0000/executors/06719087-e7d8-4ee3-8ae5-236e323a2c0a/runs/latest' I0912 18:37:55.516278 38718 slave.cpp:988] Successfully attached '/tmp/DiskQuotaTest_SlaveRecovery_2QLn4J/slaves/c7797969-05a8-4105-a072-ffe5c94c28ab-S0/frameworks/c7797969-05a8-4105-a072-ffe5c94c28ab-0000/executors/06719087-e7d8-4ee3-8ae5-236e323a2c0a/runs/c1ec0308-3a43-49f8-885f-3895295cc18f' to virtual path '/tmp/DiskQuotaTest_SlaveRecovery_2QLn4J/slaves/c7797969-05a8-4105-a072-ffe5c94c28ab-S0/frameworks/c7797969-05a8-4105-a072-ffe5c94c28ab-0000/executors/06719087-e7d8-4ee3-8ae5-236e323a2c0a/runs/c1ec0308-3a43-49f8-885f-3895295cc18f' I0912 18:37:55.517109 38683 containerizer.cpp:1280] Starting container c1ec0308-3a43-49f8-885f-3895295cc18f I0912 18:37:55.519395 38683 containerizer.cpp:1446] Checkpointed ContainerConfig at '/tmp/DiskQuotaTest_SlaveRecovery_PWToQc/containers/c1ec0308-3a43-49f8-885f-3895295cc18f/config' I0912 18:37:55.519482 38683 containerizer.cpp:3118] Transitioning the state of container c1ec0308-3a43-49f8-885f-3895295cc18f from PROVISIONING to PREPARING I0912 18:37:55.527345 38694 containerizer.cpp:1939] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"arguments":["mesos-executor","--launcher_dir=/tmp/SRC/build/mesos-1.8.0/_build/sub/src"],"shell":false,"value":"/tmp/SRC/build/mesos-1.8.0/_build/sub/src/mesos-executor"},"environment":{"variables":[{"name":"LIBPROCESS_PORT","type":"VALUE","value":"0"},{"name":"MESOS_AGENT_ENDPOINT","type":"VALUE","value":"172.17.0.4:45557"},{"name":"MESOS_CHECKPOINT","type":"VALUE","value":"1"},{"name":"MESOS_DIRECTORY","type":"VALUE","value":"/tmp/DiskQuotaTest_SlaveRecovery_2QLn4J/slaves/c7797969-05a8-4105-a072-ffe5c94c28ab-S0/frameworks/c7797969-05a8-4105-a072-ffe5c94c28ab-0000/executors/06719087-e7d8-4ee3-8ae5-236e323a2c0a/runs/c1ec0308-3a43-49f8-885f-3895295cc18f"},{"name":"MESOS_EXECUTOR_ID","type":"VALUE","value":"06719087-e7d8-4ee3-8ae5-236e323a2c0a"},{"name":"MESOS_EXECUTOR_SHUTDOWN_GRACE_PERIOD","type":"VALUE","value":"5secs"},{"name":"MESOS_FRAMEWORK_ID","type":"VALUE","value":"c7797969-05a8-4105-a072-ffe5c94c28ab-0000"},{"name":"MESOS_HTTP_COMMAND_EXECUTOR","type":"VALUE","value":"0"},{"name":"MESOS_RECOVERY_TIMEOUT","type":"VALUE","value":"15mins"},{"name":"MESOS_SLAVE_ID","type":"VALUE","value":"c7797969-05a8-4105-a072-ffe5c94c28ab-S0"},{"name":"MESOS_SLAVE_PID","type":"VALUE","value":"slave(40)@172.17.0.4:45557"},{"name":"MESOS_SUBSCRIPTION_BACKOFF_MAX","type":"VALUE","value":"2secs"},{"name":"MESOS_SANDBOX","type":"VALUE","value":"/tmp/DiskQuotaTest_SlaveRecovery_2QLn4J/slaves/c7797969-05a8-4105-a072-ffe5c94c28ab-S0/frameworks/c7797969-05a8-4105-a072-ffe5c94c28ab-0000/executors/06719087-e7d8-4ee3-8ae5-236e323a2c0a/runs/c1ec0308-3a43-49f8-885f-3895295cc18f"}]},"task_environment":{},"user":"mesos","working_directory":"/tmp/DiskQuotaTest_SlaveRecovery_2QLn4J/slaves/c7797969-05a8-4105-a072-ffe5c94c28ab-S0/frameworks/c7797969-05a8-4105-a072-ffe5c94c28ab-0000/executors/06719087-e7d8-4ee3-8ae5-236e323a2c0a/runs/c1ec0308-3a43-49f8-885f-3895295cc18f"}" --pipe_read="9" --pipe_write="12" --runtime_directory="/tmp/DiskQuotaTest_SlaveRecovery_PWToQc/containers/c1ec0308-3a43-49f8-885f-3895295cc18f" --unshare_namespace_mnt="false"' I0912 18:37:55.536696 38694 launcher.cpp:150] Forked child with pid '41933' for container 'c1ec0308-3a43-49f8-885f-3895295cc18f' I0912 18:37:55.537061 38694 containerizer.cpp:2044] Checkpointing container's forked pid 41933 to '/tmp/DiskQuotaTest_SlaveRecovery_2QLn4J/meta/slaves/c7797969-05a8-4105-a072-ffe5c94c28ab-S0/frameworks/c7797969-05a8-4105-a072-ffe5c94c28ab-0000/executors/06719087-e7d8-4ee3-8ae5-236e323a2c0a/runs/c1ec0308-3a43-49f8-885f-3895295cc18f/pids/forked.pid' I0912 18:37:55.539252 38694 containerizer.cpp:3118] Transitioning the state of container c1ec0308-3a43-49f8-885f-3895295cc18f from PREPARING to ISOLATING I0912 18:37:55.543573 38704 containerizer.cpp:3118] Transitioning the state of container c1ec0308-3a43-49f8-885f-3895295cc18f from ISOLATING to FETCHING I0912 18:37:55.543953 38674 fetcher.cpp:369] Starting to fetch URIs for container: c1ec0308-3a43-49f8-885f-3895295cc18f, directory: /tmp/DiskQuotaTest_SlaveRecovery_2QLn4J/slaves/c7797969-05a8-4105-a072-ffe5c94c28ab-S0/frameworks/c7797969-05a8-4105-a072-ffe5c94c28ab-0000/executors/06719087-e7d8-4ee3-8ae5-236e323a2c0a/runs/c1ec0308-3a43-49f8-885f-3895295cc18f I0912 18:37:55.545998 38658 containerizer.cpp:3118] Transitioning the state of container c1ec0308-3a43-49f8-885f-3895295cc18f from FETCHING to RUNNING I0912 18:37:56.198743 41940 exec.cpp:162] Version: 1.8.0 I0912 18:37:56.225723 38748 slave.cpp:4803] Got registration for executor '06719087-e7d8-4ee3-8ae5-236e323a2c0a' of framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 from executor(1)@172.17.0.4:42049 I0912 18:37:56.226621 38748 slave.cpp:4889] Checkpointing executor pid 'executor(1)@172.17.0.4:42049' to '/tmp/DiskQuotaTest_SlaveRecovery_2QLn4J/meta/slaves/c7797969-05a8-4105-a072-ffe5c94c28ab-S0/frameworks/c7797969-05a8-4105-a072-ffe5c94c28ab-0000/executors/06719087-e7d8-4ee3-8ae5-236e323a2c0a/runs/c1ec0308-3a43-49f8-885f-3895295cc18f/pids/libprocess.pid' I0912 18:37:56.231092 38680 disk.cpp:213] Updating the disk resources for container c1ec0308-3a43-49f8-885f-3895295cc18f to cpus(allocated: *):1.1; mem(allocated: *):160; disk(allocated: *):3 I0912 18:37:56.236663 41952 exec.cpp:236] Executor registered on agent c7797969-05a8-4105-a072-ffe5c94c28ab-S0 I0912 18:37:56.239409 38682 slave.cpp:3241] Sending queued task '06719087-e7d8-4ee3-8ae5-236e323a2c0a' to executor '06719087-e7d8-4ee3-8ae5-236e323a2c0a' of framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 at executor(1)@172.17.0.4:42049 I0912 18:37:56.247769 41959 executor.cpp:182] Received SUBSCRIBED event I0912 18:37:56.253047 41959 executor.cpp:186] Subscribed executor on 0de113ebdc41 I0912 18:37:56.253502 41959 executor.cpp:182] Received LAUNCH event I0912 18:37:56.260115 41959 executor.cpp:679] Starting task 06719087-e7d8-4ee3-8ae5-236e323a2c0a I0912 18:37:56.267983 38692 slave.cpp:5269] Handling status update TASK_STARTING (Status UUID: a43fc102-df2b-4fff-b2fa-620d81b08517) for task 06719087-e7d8-4ee3-8ae5-236e323a2c0a of framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 from executor(1)@172.17.0.4:42049 I0912 18:37:56.272810 38685 task_status_update_manager.cpp:328] Received task status update TASK_STARTING (Status UUID: a43fc102-df2b-4fff-b2fa-620d81b08517) for task 06719087-e7d8-4ee3-8ae5-236e323a2c0a of framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 I0912 18:37:56.272925 38685 task_status_update_manager.cpp:507] Creating StatusUpdate stream for task 06719087-e7d8-4ee3-8ae5-236e323a2c0a of framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 I0912 18:37:56.274581 38685 task_status_update_manager.cpp:842] Checkpointing UPDATE for task status update TASK_STARTING (Status UUID: a43fc102-df2b-4fff-b2fa-620d81b08517) for task 06719087-e7d8-4ee3-8ae5-236e323a2c0a of framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 I0912 18:37:56.275315 38685 task_status_update_manager.cpp:383] Forwarding task status update TASK_STARTING (Status UUID: a43fc102-df2b-4fff-b2fa-620d81b08517) for task 06719087-e7d8-4ee3-8ae5-236e323a2c0a of framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 to the agent I0912 18:37:56.275712 38705 slave.cpp:5761] Forwarding the update TASK_STARTING (Status UUID: a43fc102-df2b-4fff-b2fa-620d81b08517) for task 06719087-e7d8-4ee3-8ae5-236e323a2c0a of framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 to master@172.17.0.4:45557 I0912 18:37:56.276219 38705 slave.cpp:5654] Task status update manager successfully handled status update TASK_STARTING (Status UUID: a43fc102-df2b-4fff-b2fa-620d81b08517) for task 06719087-e7d8-4ee3-8ae5-236e323a2c0a of framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 I0912 18:37:56.276363 38705 slave.cpp:5670] Sending acknowledgement for status update TASK_STARTING (Status UUID: a43fc102-df2b-4fff-b2fa-620d81b08517) for task 06719087-e7d8-4ee3-8ae5-236e323a2c0a of framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 to executor(1)@172.17.0.4:42049 I0912 18:37:56.276513 38715 master.cpp:8375] Status update TASK_STARTING (Status UUID: a43fc102-df2b-4fff-b2fa-620d81b08517) for task 06719087-e7d8-4ee3-8ae5-236e323a2c0a of framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 from agent c7797969-05a8-4105-a072-ffe5c94c28ab-S0 at slave(40)@172.17.0.4:45557 (0de113ebdc41) I0912 18:37:56.276652 38715 master.cpp:8432] Forwarding status update TASK_STARTING (Status UUID: a43fc102-df2b-4fff-b2fa-620d81b08517) for task 06719087-e7d8-4ee3-8ae5-236e323a2c0a of framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 I0912 18:37:56.277201 38715 master.cpp:10932] Updating the state of task 06719087-e7d8-4ee3-8ae5-236e323a2c0a of framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 (latest state: TASK_STARTING, status update state: TASK_STARTING) I0912 18:37:56.277707 38718 sched.cpp:1022] Scheduler::statusUpdate took 274047ns I0912 18:37:56.278570 38690 master.cpp:6241] Processing ACKNOWLEDGE call for status a43fc102-df2b-4fff-b2fa-620d81b08517 for task 06719087-e7d8-4ee3-8ae5-236e323a2c0a of framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 (default) at scheduler-39610234-c5eb-4cbd-b4e2-88f330d9ce64@172.17.0.4:45557 on agent c7797969-05a8-4105-a072-ffe5c94c28ab-S0 I0912 18:37:56.279355 38701 task_status_update_manager.cpp:401] Received task status update acknowledgement (UUID: a43fc102-df2b-4fff-b2fa-620d81b08517) for task 06719087-e7d8-4ee3-8ae5-236e323a2c0a of framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 I0912 18:37:56.279573 38701 task_status_update_manager.cpp:842] Checkpointing ACK for task status update TASK_STARTING (Status UUID: a43fc102-df2b-4fff-b2fa-620d81b08517) for task 06719087-e7d8-4ee3-8ae5-236e323a2c0a of framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 I0912 18:37:56.280108 38683 slave.cpp:4505] Task status update manager successfully handled status update acknowledgement (UUID: a43fc102-df2b-4fff-b2fa-620d81b08517) for task 06719087-e7d8-4ee3-8ae5-236e323a2c0a of framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 I0912 18:37:56.315037 41959 executor.cpp:499] Running '/tmp/SRC/build/mesos-1.8.0/_build/sub/src/mesos-containerizer launch <POSSIBLY-SENSITIVE-DATA>' I0912 18:37:56.325644 41959 executor.cpp:693] Forked command at 42034 I0912 18:37:56.336020 38735 slave.cpp:5269] Handling status update TASK_RUNNING (Status UUID: 2e4d8529-02a4-4b13-a0cb-83252880f9fc) for task 06719087-e7d8-4ee3-8ae5-236e323a2c0a of framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 from executor(1)@172.17.0.4:42049 I0912 18:37:56.340095 38745 task_status_update_manager.cpp:328] Received task status update TASK_RUNNING (Status UUID: 2e4d8529-02a4-4b13-a0cb-83252880f9fc) for task 06719087-e7d8-4ee3-8ae5-236e323a2c0a of framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 I0912 18:37:56.340250 38745 task_status_update_manager.cpp:842] Checkpointing UPDATE for task status update TASK_RUNNING (Status UUID: 2e4d8529-02a4-4b13-a0cb-83252880f9fc) for task 06719087-e7d8-4ee3-8ae5-236e323a2c0a of framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 I0912 18:37:56.340787 38745 task_status_update_manager.cpp:383] Forwarding task status update TASK_RUNNING (Status UUID: 2e4d8529-02a4-4b13-a0cb-83252880f9fc) for task 06719087-e7d8-4ee3-8ae5-236e323a2c0a of framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 to the agent I0912 18:37:56.341208 38689 slave.cpp:5761] Forwarding the update TASK_RUNNING (Status UUID: 2e4d8529-02a4-4b13-a0cb-83252880f9fc) for task 06719087-e7d8-4ee3-8ae5-236e323a2c0a of framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 to master@172.17.0.4:45557 I0912 18:37:56.341701 38689 slave.cpp:5654] Task status update manager successfully handled status update TASK_RUNNING (Status UUID: 2e4d8529-02a4-4b13-a0cb-83252880f9fc) for task 06719087-e7d8-4ee3-8ae5-236e323a2c0a of framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 I0912 18:37:56.341832 38689 slave.cpp:5670] Sending acknowledgement for status update TASK_RUNNING (Status UUID: 2e4d8529-02a4-4b13-a0cb-83252880f9fc) for task 06719087-e7d8-4ee3-8ae5-236e323a2c0a of framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 to executor(1)@172.17.0.4:42049 I0912 18:37:56.341933 38740 master.cpp:8375] Status update TASK_RUNNING (Status UUID: 2e4d8529-02a4-4b13-a0cb-83252880f9fc) for task 06719087-e7d8-4ee3-8ae5-236e323a2c0a of framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 from agent c7797969-05a8-4105-a072-ffe5c94c28ab-S0 at slave(40)@172.17.0.4:45557 (0de113ebdc41) I0912 18:37:56.342066 38740 master.cpp:8432] Forwarding status update TASK_RUNNING (Status UUID: 2e4d8529-02a4-4b13-a0cb-83252880f9fc) for task 06719087-e7d8-4ee3-8ae5-236e323a2c0a of framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 I0912 18:37:56.342591 38740 master.cpp:10932] Updating the state of task 06719087-e7d8-4ee3-8ae5-236e323a2c0a of framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING) I0912 18:37:56.343075 38653 sched.cpp:1022] Scheduler::statusUpdate took 234877ns I0912 18:37:56.343899 38721 master.cpp:6241] Processing ACKNOWLEDGE call for status 2e4d8529-02a4-4b13-a0cb-83252880f9fc for task 06719087-e7d8-4ee3-8ae5-236e323a2c0a of framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 (default) at scheduler-39610234-c5eb-4cbd-b4e2-88f330d9ce64@172.17.0.4:45557 on agent c7797969-05a8-4105-a072-ffe5c94c28ab-S0 I0912 18:37:56.344735 38694 slave.cpp:909] Agent terminating I0912 18:37:56.344775 38704 task_status_update_manager.cpp:401] Received task status update acknowledgement (UUID: 2e4d8529-02a4-4b13-a0cb-83252880f9fc) for task 06719087-e7d8-4ee3-8ae5-236e323a2c0a of framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 I0912 18:37:56.345064 38704 task_status_update_manager.cpp:842] Checkpointing ACK for task status update TASK_RUNNING (Status UUID: 2e4d8529-02a4-4b13-a0cb-83252880f9fc) for task 06719087-e7d8-4ee3-8ae5-236e323a2c0a of framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 I0912 18:37:56.346503 38712 master.cpp:1251] Agent c7797969-05a8-4105-a072-ffe5c94c28ab-S0 at slave(40)@172.17.0.4:45557 (0de113ebdc41) disconnected I0912 18:37:56.346592 38712 master.cpp:3267] Disconnecting agent c7797969-05a8-4105-a072-ffe5c94c28ab-S0 at slave(40)@172.17.0.4:45557 (0de113ebdc41) I0912 18:37:56.346803 38712 master.cpp:3286] Deactivating agent c7797969-05a8-4105-a072-ffe5c94c28ab-S0 at slave(40)@172.17.0.4:45557 (0de113ebdc41) I0912 18:37:56.347152 38742 hierarchical.cpp:795] Agent c7797969-05a8-4105-a072-ffe5c94c28ab-S0 deactivated I0912 18:37:56.347219 38652 containerizer.cpp:305] Using isolation { environment_secret, filesystem/posix, network/cni, posix/mem, disk/du, posix/cpu } W0912 18:37:56.348449 38652 backend.cpp:76] Failed to create 'overlay' backend: OverlayBackend requires root privileges W0912 18:37:56.348538 38652 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges I0912 18:37:56.348645 38652 provisioner.cpp:298] Using default backend 'copy' I0912 18:37:56.407004 38684 hierarchical.cpp:1564] Performed allocation for 1 agents in 520654ns W0912 18:37:56.408903 38652 process.cpp:2810] Attempted to spawn already running process files@172.17.0.4:45557 I0912 18:37:56.410372 38652 cluster.cpp:485] Creating default 'local' authorizer I0912 18:37:56.414408 38672 slave.cpp:267] Mesos agent started on (41)@172.17.0.4:45557 I0912 18:37:56.414500 38672 slave.cpp:268] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/DiskQuotaTest_SlaveRecovery_PWToQc/store/appc" --authenticate_http_readonly="true" --authenticate_http_readwrite="false" --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="1ms" --containerizers="mesos" --credential="/tmp/DiskQuotaTest_SlaveRecovery_PWToQc/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/DiskQuotaTest_SlaveRecovery_PWToQc/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/DiskQuotaTest_SlaveRecovery_PWToQc/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/DiskQuotaTest_SlaveRecovery_PWToQc/http_credentials" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem,disk/du" --launcher="posix" --launcher_dir="/tmp/SRC/build/mesos-1.8.0/_build/sub/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/DiskQuotaTest_SlaveRecovery_PWToQc" --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/DiskQuotaTest_SlaveRecovery_2QLn4J" --zk_session_timeout="10secs" I0912 18:37:56.415846 38672 credentials.hpp:86] Loading credential for authentication from '/tmp/DiskQuotaTest_SlaveRecovery_PWToQc/credential' I0912 18:37:56.416215 38672 slave.cpp:300] Agent using credential for: test-principal I0912 18:37:56.416281 38672 credentials.hpp:37] Loading credentials for authentication from '/tmp/DiskQuotaTest_SlaveRecovery_PWToQc/http_credentials' I0912 18:37:56.416832 38672 http.cpp:1037] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly' I0912 18:37:56.417636 38672 disk_profile_adaptor.cpp:80] Creating default disk profile adaptor module I0912 18:37:56.421188 38672 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"}] I0912 18:37:56.421751 38672 slave.cpp:623] Agent attributes: [ ] I0912 18:37:56.421811 38672 slave.cpp:632] Agent hostname: 0de113ebdc41 I0912 18:37:56.422233 38744 task_status_update_manager.cpp:181] Pausing sending task status updates I0912 18:37:56.425968 38705 state.cpp:66] Recovering state from '/tmp/DiskQuotaTest_SlaveRecovery_2QLn4J/meta' I0912 18:37:56.426173 38705 state.cpp:711] No committed checkpointed resources found at '/tmp/DiskQuotaTest_SlaveRecovery_2QLn4J/meta/resources/resources.info' I0912 18:37:56.439404 38699 slave.cpp:6909] Finished recovering checkpointed state from '/tmp/DiskQuotaTest_SlaveRecovery_2QLn4J/meta', beginning agent recovery I0912 18:37:56.440963 38699 slave.cpp:7388] Recovering framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 I0912 18:37:56.441329 38699 slave.cpp:9112] Recovering executor '06719087-e7d8-4ee3-8ae5-236e323a2c0a' of framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 I0912 18:37:56.443415 38718 task_status_update_manager.cpp:207] Recovering task status update manager I0912 18:37:56.443552 38718 task_status_update_manager.cpp:215] Recovering executor '06719087-e7d8-4ee3-8ae5-236e323a2c0a' of framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 I0912 18:37:56.443763 38718 task_status_update_manager.cpp:507] Creating StatusUpdate stream for task 06719087-e7d8-4ee3-8ae5-236e323a2c0a of framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 I0912 18:37:56.444875 38718 task_status_update_manager.cpp:818] Replaying task status update stream for task 06719087-e7d8-4ee3-8ae5-236e323a2c0a I0912 18:37:56.446396 38690 containerizer.cpp:727] Recovering Mesos containers I0912 18:37:56.446627 38690 containerizer.cpp:784] Recovering container c1ec0308-3a43-49f8-885f-3895295cc18f for executor '06719087-e7d8-4ee3-8ae5-236e323a2c0a' of framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 I0912 18:37:56.450445 38690 containerizer.cpp:1053] Recovering isolators I0912 18:37:56.453826 38743 containerizer.cpp:1092] Recovering provisioner I0912 18:37:56.455097 38736 provisioner.cpp:494] Provisioner recovery complete I0912 18:37:56.458902 38662 composing.cpp:339] Finished recovering all containerizers I0912 18:37:56.459422 38704 slave.cpp:7138] Recovering executors I0912 18:37:56.459722 38704 slave.cpp:7162] Sending reconnect request to executor '06719087-e7d8-4ee3-8ae5-236e323a2c0a' of framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 at executor(1)@172.17.0.4:42049 I0912 18:37:56.463893 41971 exec.cpp:282] Received reconnect request from agent c7797969-05a8-4105-a072-ffe5c94c28ab-S0 I0912 18:37:56.470129 38746 slave.cpp:4966] Received re-registration message from executor '06719087-e7d8-4ee3-8ae5-236e323a2c0a' of framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 I0912 18:37:56.474167 41973 exec.cpp:259] Executor reregistered on agent c7797969-05a8-4105-a072-ffe5c94c28ab-S0 I0912 18:37:56.474432 38673 disk.cpp:213] Updating the disk resources for container c1ec0308-3a43-49f8-885f-3895295cc18f to cpus(allocated: *):1.1; mem(allocated: *):160; disk(allocated: *):3 I0912 18:37:56.481462 41977 executor.cpp:182] Received SUBSCRIBED event I0912 18:37:56.481546 41977 executor.cpp:186] Subscribed executor on 0de113ebdc41 I0912 18:37:56.486336 38696 slave.cpp:5197] Cleaning up un-reregistered executors I0912 18:37:56.486351 38706 hierarchical.cpp:1564] Performed allocation for 1 agents in 707649ns I0912 18:37:56.486817 38696 slave.cpp:7291] Finished recovery I0912 18:37:56.490710 38696 slave.cpp:1254] New master detected at master@172.17.0.4:45557 I0912 18:37:56.490926 38678 task_status_update_manager.cpp:181] Pausing sending task status updates I0912 18:37:56.491142 38696 slave.cpp:1319] Detecting new master ../../../src/tests/disk_quota_tests.cpp:746: Failure Value of: usage->has_disk_limit_bytes() Actual: false Expected: true I0912 18:37:56.493422 38715 master.cpp:1366] Framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 (default) at scheduler-39610234-c5eb-4cbd-b4e2-88f330d9ce64@172.17.0.4:45557 disconnected I0912 18:37:56.493532 38715 master.cpp:3230] Deactivating framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 (default) at scheduler-39610234-c5eb-4cbd-b4e2-88f330d9ce64@172.17.0.4:45557 I0912 18:37:56.493799 38715 master.cpp:3207] Disconnecting framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 (default) at scheduler-39610234-c5eb-4cbd-b4e2-88f330d9ce64@172.17.0.4:45557 I0912 18:37:56.493975 38715 master.cpp:1381] Giving framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 (default) at scheduler-39610234-c5eb-4cbd-b4e2-88f330d9ce64@172.17.0.4:45557 0ns to failover I0912 18:37:56.494099 38718 hierarchical.cpp:420] Deactivated framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 I0912 18:37:56.494824 38691 slave.cpp:909] Agent terminating I0912 18:37:56.495129 38683 master.cpp:9261] Framework failover timeout, removing framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 (default) at scheduler-39610234-c5eb-4cbd-b4e2-88f330d9ce64@172.17.0.4:45557 I0912 18:37:56.495220 38683 master.cpp:10197] Removing framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 (default) at scheduler-39610234-c5eb-4cbd-b4e2-88f330d9ce64@172.17.0.4:45557 I0912 18:37:56.495818 38683 master.cpp:10932] Updating the state of task 06719087-e7d8-4ee3-8ae5-236e323a2c0a of framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 (latest state: TASK_KILLED, status update state: TASK_KILLED) I0912 18:37:56.497730 38683 master.cpp:11030] Removing task 06719087-e7d8-4ee3-8ae5-236e323a2c0a with resources cpus(allocated: *):1; mem(allocated: *):128; disk(allocated: *):3 of framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 on agent c7797969-05a8-4105-a072-ffe5c94c28ab-S0 at slave(40)@172.17.0.4:45557 (0de113ebdc41) I0912 18:37:56.499536 38709 hierarchical.cpp:1236] Recovered cpus(allocated: *):1; mem(allocated: *):128; disk(allocated: *):3 (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000], allocated: {}) on agent c7797969-05a8-4105-a072-ffe5c94c28ab-S0 from framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 I0912 18:37:56.500663 38709 hierarchical.cpp:359] Removed framework c7797969-05a8-4105-a072-ffe5c94c28ab-0000 I0912 18:37:56.507202 38653 containerizer.cpp:2455] Destroying container c1ec0308-3a43-49f8-885f-3895295cc18f in RUNNING state I0912 18:37:56.507292 38653 containerizer.cpp:3118] Transitioning the state of container c1ec0308-3a43-49f8-885f-3895295cc18f from RUNNING to DESTROYING I0912 18:37:56.507948 38653 launcher.cpp:166] Asked to destroy container c1ec0308-3a43-49f8-885f-3895295cc18f I0912 18:37:56.586401 38657 containerizer.cpp:2957] Container c1ec0308-3a43-49f8-885f-3895295cc18f has exited I0912 18:37:56.605669 38706 provisioner.cpp:597] Ignoring destroy request for unknown container c1ec0308-3a43-49f8-885f-3895295cc18f I0912 18:37:56.640585 38652 master.cpp:1093] Master terminating I0912 18:37:56.642267 38680 hierarchical.cpp:637] Removed agent c7797969-05a8-4105-a072-ffe5c94c28ab-S0 [ FAILED ] DiskQuotaTest.SlaveRecovery (1259 ms)
Attachments
Issue Links
- relates to
-
-
- Accepted
-