[
https://issues.apache.org/jira/browse/MESOS-8773?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16614810#comment-16614810
]
Tomasz Janiszewski commented on MESOS-8773:
-------------------------------------------
[~bmahler] Do you think it could be related to
https://github.com/apache/mesos/commit/aa8de47d4661996f252672d8dab4252a7d377645
> DiskQuotaTest.SlaveRecovery is FLAKY on ARM
> -------------------------------------------
>
> Key: MESOS-8773
> URL: https://issues.apache.org/jira/browse/MESOS-8773
> Project: Mesos
> Issue Type: Bug
> Affects Versions: 1.7.0
> Reporter: Tomasz Janiszewski
> Priority: Major
> Labels: Flaky, flaky-test
>
> ARM CI randomly fails due to {{DiskQuotaTest.SlaveRecovery}}
> {code:Bash:title=DiskQuotaTest.SlaveRecovery|borderStyle=solid}
> [ 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 [email protected]: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 [email protected]: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
> [email protected]:45557
> I0912 18:37:55.445902 38735 sched.cpp:401] Authenticating with master
> [email protected]: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
> [email protected]: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
> [email protected]: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 [email protected]:45557
> I0912 18:37:55.451364 38657 sched.cpp:817] Sending SUBSCRIBE call to
> [email protected]: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
> [email protected]: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
> [email protected]: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
> [email protected]: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
> [email protected]: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 [email protected]: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
> [email protected]: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
> [email protected]: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 [email protected]: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
> [email protected]: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
> '[email protected]: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 [email protected]: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
> [email protected]: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 [email protected]: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
> [email protected]: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 [email protected]: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
> [email protected]: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
> [email protected]:45557 disconnected
> I0912 18:37:56.493532 38715 master.cpp:3230] Deactivating framework
> c7797969-05a8-4105-a072-ffe5c94c28ab-0000 (default) at
> [email protected]:45557
> I0912 18:37:56.493799 38715 master.cpp:3207] Disconnecting framework
> c7797969-05a8-4105-a072-ffe5c94c28ab-0000 (default) at
> [email protected]:45557
> I0912 18:37:56.493975 38715 master.cpp:1381] Giving framework
> c7797969-05a8-4105-a072-ffe5c94c28ab-0000 (default) at
> [email protected]: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
> [email protected]:45557
> I0912 18:37:56.495220 38683 master.cpp:10197] Removing framework
> c7797969-05a8-4105-a072-ffe5c94c28ab-0000 (default) at
> [email protected]: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)
> {code}
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
