You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "Vinod Kone (JIRA)" <ji...@apache.org> on 2019/02/06 14:13:00 UTC
[jira] [Commented] (MESOS-3968) DiskQuotaTest.SlaveRecovery is
flaky
[ https://issues.apache.org/jira/browse/MESOS-3968?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16761767#comment-16761767 ]
Vinod Kone commented on MESOS-3968:
-----------------------------------
Observed this again in internal CI.
{code}
[ RUN ] DiskQuotaTest.SlaveRecovery
I0205 21:09:19.279057 296834496 cluster.cpp:174] Creating default 'local' authorizer
I0205 21:09:19.280333 54652928 master.cpp:414] Master 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6 (Jenkinss-Mac-mini.local) started on 10.0.49.4:65013
I0205 21:09:19.280360 54652928 master.cpp:417] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="1secs" --alloca
tor="hierarchical" --authenticate_agents="true" --authenticate_frameworks="true" --authenticate_http_frameworks="true" --authenticate_http_readonly="true" --authenticate_http_read
write="true" --authentication_v0_timeout="15secs" --authenticators="crammd5" --authorizers="local" --credentials="/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/tvVUip/c
redentials" --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_operator_event_stream_subscribers="1000" --max_unreachable_tasks_per_framework="1000" --memory_profiling="false" --min_allocatable_resources="cpu
s:0.01|mem:32" --port="5050" --publish_per_framework_metrics="true" --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_d
omain="false" --role_sorter="drf" --root_submissions="true" --version="false" --webui_dir="/usr/local/share/mesos/webui" --work_dir="/private/var/folders/6w/rw03zh013y38ys6cyn8qpp
f80000gn/T/tvVUip/master" --zk_session_timeout="10secs"
I0205 21:09:19.280541 54652928 master.cpp:466] Master only allowing authenticated frameworks to register
I0205 21:09:19.280555 54652928 master.cpp:472] Master only allowing authenticated agents to register
I0205 21:09:19.280565 54652928 master.cpp:478] Master only allowing authenticated HTTP frameworks to register
I0205 21:09:19.280573 54652928 credentials.hpp:37] Loading credentials for authentication from '/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/tvVUip/credentials'
I0205 21:09:19.280757 54652928 master.cpp:522] Using default 'crammd5' authenticator
I0205 21:09:19.280833 54652928 http.cpp:965] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
I0205 21:09:19.280908 54652928 http.cpp:965] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
I0205 21:09:19.281013 54652928 http.cpp:965] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
I0205 21:09:19.281059 54652928 master.cpp:603] Authorization enabled
I0205 21:09:19.281299 54116352 whitelist_watcher.cpp:77] No whitelist given
I0205 21:09:19.281442 53579776 hierarchical.cpp:176] Initialized hierarchical allocator process
I0205 21:09:19.282912 54116352 master.cpp:2103] Elected as the leading master!
I0205 21:09:19.282936 54116352 master.cpp:1638] Recovering from registrar
I0205 21:09:19.282989 57335808 registrar.cpp:339] Recovering registrar
I0205 21:09:19.283207 55189504 registrar.cpp:383] Successfully fetched the registry (0B) in 197120ns
I0205 21:09:19.283324 55189504 registrar.cpp:487] Applied 1 operations in 40938ns; attempting to update the registry
I0205 21:09:19.283577 53579776 registrar.cpp:544] Successfully updated the registry in 217856ns
I0205 21:09:19.283679 53579776 registrar.cpp:416] Successfully recovered registrar
I0205 21:09:19.283867 54652928 master.cpp:1752] Recovered 0 agents from the registry (155B); allowing 10mins for agents to reregister
I0205 21:09:19.283895 57335808 hierarchical.cpp:216] Skipping recovery of hierarchical allocator: nothing to recover
I0205 21:09:19.285928 296834496 containerizer.cpp:309] Using isolation { environment_secret, posix/cpu, filesystem/posix, posix/mem, disk/du }
I0205 21:09:19.286176 296834496 provisioner.cpp:298] Using default backend 'copy'
W0205 21:09:19.288060 296834496 process.cpp:2829] Attempted to spawn already running process files@10.0.49.4:65013
I0205 21:09:19.288446 296834496 cluster.cpp:486] Creating default 'local' authorizer
I0205 21:09:19.289405 55189504 slave.cpp:268] Mesos agent started on (42)@10.0.49.4:65013
I0205 21:09:19.289433 55189504 slave.cpp:269] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/private/var/folders/6w/rw03zh013y38ys6cyn
8qppf80000gn/T/tvVUip/7oYyzh/store/appc" --authenticate_http_executors="true" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authenticatee="crammd5" --
authentication_backoff_factor="1secs" --authentication_timeout_max="1mins" --authentication_timeout_min="5secs" --authorizer="local" --container_disk_watch_interval="1ms" --contai
nerizers="mesos" --credential="/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/tvVUip/7oYyzh/credential" --default_role="*" --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" --d
ocker_store_dir="/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/tvVUip/7oYyzh/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --enf
orce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_reregistration_timeout="2secs" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/
private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/tvVUip/7oYyzh/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/private/var/folders/6w/
rw03zh013y38ys6cyn8qppf80000gn/T/tvVUip/7oYyzh/frameworks" --gc_delay="1weeks" --gc_disk_headroom="0.1" --gc_non_executor_container_sandboxes="false" --help="false" --hostname_loo
kup="true" --http_command_executor="false" --http_credentials="/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/tvVUip/7oYyzh/http_credentials" --http_heartbeat_interval="
30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem,disk/du" --jwt_secret_key="/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/tvVUip/7oYyzh/jwt_s
ecret_key" --launcher="posix" --launcher_dir="/Users/jenkins/workspace/workspace/mesos/Mesos_CI-build/FLAG/SSL/label/mac/mesos/build/src" --logbufsecs="0" --logging_level="INFO" -
-max_completed_executors_per_framework="150" --memory_profiling="false" --network_cni_metrics="true" --network_cni_root_dir_persist="false" --oversubscribed_resources_interval="15
secs" --port="5051" --qos_correction_interval_min="0ns" --quiet="false" --reconfiguration_policy="equal" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_f
actor="10ms" --resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]" --runtime_dir="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/DiskQuotaTest_SlaveRecovery_8TOmLN"
--sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --version="false" --work_dir="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/DiskQuotaTest_SlaveRecovery_EmdfgZ" --zk_session_timeout="10secs"
I0205 21:09:19.289757 55189504 credentials.hpp:86] Loading credential for authentication from '/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/tvVUip/7oYyzh/credential'
W0205 21:09:19.289820 296834496 process.cpp:2829] Attempted to spawn already running process version@10.0.49.4:65013
I0205 21:09:19.289896 55189504 slave.cpp:301] Agent using credential for: test-principal
I0205 21:09:19.289911 55189504 credentials.hpp:37] Loading credentials for authentication from '/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/tvVUip/7oYyzh/http_credentials'
I0205 21:09:19.290133 55189504 http.cpp:965] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-executor'
I0205 21:09:19.290216 55189504 http.cpp:986] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-executor'
I0205 21:09:19.290305 55189504 http.cpp:965] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
I0205 21:09:19.290347 55189504 http.cpp:986] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-readonly'
I0205 21:09:19.290406 55189504 http.cpp:965] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite'
I0205 21:09:19.290555 55189504 http.cpp:986] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-readwrite'
I0205 21:09:19.290778 55189504 disk_profile_adaptor.cpp:80] Creating default disk profile adaptor module
I0205 21:09:19.291154 55189504 slave.cpp:616] 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"}]
I0205 21:09:19.291283 55189504 slave.cpp:624] Agent attributes: [ ]
I0205 21:09:19.291296 55189504 slave.cpp:633] Agent hostname: Jenkinss-Mac-mini.local
I0205 21:09:19.291399 54652928 task_status_update_manager.cpp:181] Pausing sending task status updates
I0205 21:09:19.291465 53579776 status_update_manager_process.hpp:379] Pausing operation status update manager
I0205 21:09:19.291540 296834496 sched.cpp:232] Version: 1.8.0
I0205 21:09:19.291914 53579776 sched.cpp:336] New master detected at master@10.0.49.4:65013
I0205 21:09:19.291970 53579776 sched.cpp:401] Authenticating with master master@10.0.49.4:65013
I0205 21:09:19.291986 53579776 sched.cpp:408] Using default CRAM-MD5 authenticatee
I0205 21:09:19.292255 54116352 state.cpp:66] Recovering state from '/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/DiskQuotaTest_SlaveRecovery_EmdfgZ/meta'
I0205 21:09:19.292291 56262656 authenticatee.cpp:121] Creating new client SASL connection
I0205 21:09:19.292451 53579776 slave.cpp:7004] Finished recovering checkpointed state from '/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/DiskQuotaTest_SlaveRecovery_EmdfgZ/meta', beginning agent recovery
I0205 21:09:19.292484 56799232 master.cpp:9902] Authenticating scheduler-611df321-e66d-4bb4-bbdd-7a82ec93238b@10.0.49.4:65013
I0205 21:09:19.292523 55726080 task_status_update_manager.cpp:207] Recovering task status update manager
I0205 21:09:19.292559 54652928 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(96)@10.0.49.4:65013
I0205 21:09:19.292775 56262656 authenticator.cpp:98] Creating new server SASL connection
I0205 21:09:19.292793 53579776 containerizer.cpp:735] Recovering Mesos containers
I0205 21:09:19.292971 53579776 containerizer.cpp:1061] Recovering isolators
I0205 21:09:19.292971 56799232 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0205 21:09:19.293017 56799232 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0205 21:09:19.293226 55189504 authenticator.cpp:204] Received SASL authentication start
I0205 21:09:19.293332 55189504 authenticator.cpp:326] Authentication requires more steps
I0205 21:09:19.293473 54116352 containerizer.cpp:1100] Recovering provisioner
I0205 21:09:19.293540 56799232 authenticatee.cpp:259] Received SASL authentication step
I0205 21:09:19.293648 55726080 authenticator.cpp:232] Received SASL authentication step
I0205 21:09:19.293679 55726080 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'Jenkinss-Mac-mini.local' server FQDN: 'Jenkinss-Mac-mini.local' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0205 21:09:19.293696 55726080 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0205 21:09:19.293718 55726080 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0205 21:09:19.293767 55726080 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'Jenkinss-Mac-mini.local' server FQDN: 'Jenkinss-Mac-mini.local' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0205 21:09:19.293782 55726080 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0205 21:09:19.293792 55726080 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0205 21:09:19.293802 55189504 provisioner.cpp:494] Provisioner recovery complete
I0205 21:09:19.293807 55726080 authenticator.cpp:318] Authentication success
I0205 21:09:19.293969 57335808 authenticatee.cpp:299] Authentication success
I0205 21:09:19.294083 56799232 master.cpp:9934] Successfully authenticated principal 'test-principal' at scheduler-611df321-e66d-4bb4-bbdd-7a82ec93238b@10.0.49.4:65013
I0205 21:09:19.294095 53579776 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(96)@10.0.49.4:65013
I0205 21:09:19.294229 55189504 sched.cpp:513] Successfully authenticated with master master@10.0.49.4:65013
I0205 21:09:19.294256 55189504 sched.cpp:817] Sending SUBSCRIBE call to master@10.0.49.4:65013
I0205 21:09:19.294368 55189504 sched.cpp:850] Will retry registration in 658.570288ms if necessary
I0205 21:09:19.294463 57335808 master.cpp:2879] Received SUBSCRIBE call for framework 'default' at scheduler-611df321-e66d-4bb4-bbdd-7a82ec93238b@10.0.49.4:65013
I0205 21:09:19.294481 57335808 master.cpp:2175] Authorizing framework principal 'test-principal' to receive offers for roles '{ * }'
I0205 21:09:19.294498 54116352 composing.cpp:339] Finished recovering all containerizers
I0205 21:09:19.294710 56262656 slave.cpp:7233] Recovering executors
I0205 21:09:19.294757 56799232 master.cpp:2960] Subscribing framework default with checkpointing enabled and capabilities [ MULTI_ROLE, RESERVATION_REFINEMENT ]
I0205 21:09:19.294764 56262656 slave.cpp:7386] Finished recovery
I0205 21:09:19.295415 56799232 master.cpp:10132] Adding framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000 (default) at scheduler-611df321-e66d-4bb4-bbdd-7a82ec93238b@10.0.49.4:65013 with roles { } suppressed
I0205 21:09:19.295711 55726080 sched.cpp:744] Framework registered with 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000
I0205 21:09:19.295739 56799232 task_status_update_manager.cpp:181] Pausing sending task status updates
I0205 21:09:19.295789 55189504 slave.cpp:1268] New master detected at master@10.0.49.4:65013
I0205 21:09:19.295823 57335808 hierarchical.cpp:305] Added framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000
I0205 21:09:19.295821 55189504 slave.cpp:1333] Detecting new master
I0205 21:09:19.295799 55726080 sched.cpp:758] Scheduler::registered took 102139ns
I0205 21:09:19.295928 56262656 status_update_manager_process.hpp:379] Pausing operation status update manager
I0205 21:09:19.296046 57335808 hierarchical.cpp:1558] Performed allocation for 0 agents in 171535ns
I0205 21:09:19.299664 55189504 slave.cpp:1360] Authenticating with master master@10.0.49.4:65013
I0205 21:09:19.299708 55189504 slave.cpp:1369] Using default CRAM-MD5 authenticatee
I0205 21:09:19.299819 56262656 authenticatee.cpp:121] Creating new client SASL connection
I0205 21:09:19.300019 57335808 master.cpp:9902] Authenticating slave(42)@10.0.49.4:65013
I0205 21:09:19.300083 53579776 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(97)@10.0.49.4:65013
I0205 21:09:19.300187 54652928 authenticator.cpp:98] Creating new server SASL connection
I0205 21:09:19.300303 56799232 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0205 21:09:19.300329 56799232 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0205 21:09:19.300379 55726080 authenticator.cpp:204] Received SASL authentication start
I0205 21:09:19.300498 55726080 authenticator.cpp:326] Authentication requires more steps
I0205 21:09:19.300541 55189504 authenticatee.cpp:259] Received SASL authentication step
I0205 21:09:19.300616 54116352 authenticator.cpp:232] Received SASL authentication step
I0205 21:09:19.300637 54116352 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'Jenkinss-Mac-mini.local' server FQDN: 'Jenkinss-Mac-mini.local' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0205 21:09:19.300648 54116352 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0205 21:09:19.300704 54116352 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0205 21:09:19.300748 54116352 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'Jenkinss-Mac-mini.local' server FQDN: 'Jenkinss-Mac-mini.local' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0205 21:09:19.300778 54116352 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0205 21:09:19.300791 54116352 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0205 21:09:19.300806 54116352 authenticator.cpp:318] Authentication success
I0205 21:09:19.300887 56262656 authenticatee.cpp:299] Authentication success
I0205 21:09:19.300992 54652928 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(97)@10.0.49.4:65013
I0205 21:09:19.301049 53579776 master.cpp:9934] Successfully authenticated principal 'test-principal' at slave(42)@10.0.49.4:65013
I0205 21:09:19.301196 56799232 slave.cpp:1460] Successfully authenticated with master master@10.0.49.4:65013
I0205 21:09:19.301432 56799232 slave.cpp:1893] Will retry registration in 18.073238ms if necessary
I0205 21:09:19.301512 57335808 master.cpp:6713] Received register agent message from slave(42)@10.0.49.4:65013 (Jenkinss-Mac-mini.local)
I0205 21:09:19.301622 57335808 master.cpp:3976] Authorizing agent providing resources 'cpus:2; mem:1024; disk:1024; ports:[31000-32000]' with principal 'test-principal'
I0205 21:09:19.301913 56262656 master.cpp:6780] Authorized registration of agent at slave(42)@10.0.49.4:65013 (Jenkinss-Mac-mini.local)
I0205 21:09:19.301965 56262656 master.cpp:6895] Registering agent at slave(42)@10.0.49.4:65013 (Jenkinss-Mac-mini.local) with id 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0
I0205 21:09:19.302306 54116352 registrar.cpp:487] Applied 1 operations in 133608ns; attempting to update the registry
I0205 21:09:19.302546 54652928 registrar.cpp:544] Successfully updated the registry in 201984ns
I0205 21:09:19.302636 56262656 master.cpp:6943] Admitted agent 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0 at slave(42)@10.0.49.4:65013 (Jenkinss-Mac-mini.local)
I0205 21:09:19.302924 56262656 master.cpp:6988] Registered agent 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0 at slave(42)@10.0.49.4:65013 (Jenkinss-Mac-mini.local) with cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0205 21:09:19.302996 57335808 slave.cpp:1493] Registered with master master@10.0.49.4:65013; given agent ID 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0
I0205 21:09:19.303069 54116352 hierarchical.cpp:604] Added agent 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0 (Jenkinss-Mac-mini.local) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (allocated: {})
I0205 21:09:19.303125 53579776 task_status_update_manager.cpp:188] Resuming sending task status updates
I0205 21:09:19.303171 55726080 status_update_manager_process.hpp:385] Resuming operation status update manager
I0205 21:09:19.303400 57335808 slave.cpp:1514] Checkpointing SlaveInfo to '/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/DiskQuotaTest_SlaveRecovery_EmdfgZ/meta/slaves/06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0/slave.info'
I0205 21:09:19.303496 54116352 hierarchical.cpp:1558] Performed allocation for 1 agents in 355215ns
I0205 21:09:19.303757 56799232 master.cpp:9717] Sending offers [ 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-O0 ] to framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000 (default) at scheduler-611df321-e66d-4bb4-bbdd-7a82ec93238b@10.0.49.4:65013
I0205 21:09:19.304136 56262656 sched.cpp:914] Scheduler::resourceOffers took 103128ns
I0205 21:09:19.304244 57335808 slave.cpp:1563] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"3vMxD5F8RXGK3S+S5QV0CA=="},"slave_id":{"value":"06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0"},"update_oversubscribed_resources":false}
I0205 21:09:19.304922 54116352 master.cpp:8047] Ignoring update on agent 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0 at slave(42)@10.0.49.4:65013 (Jenkinss-Mac-mini.local) as it reports no changes
I0205 21:09:19.305655 56262656 master.cpp:11749] Removing offer 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-O0
I0205 21:09:19.305902 56262656 master.cpp:4497] Processing ACCEPT call for offers: [ 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-O0 ] on agent 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0 at slave(42)@10.0.49.4:65013 (Jenkinss-Mac-mini.local) for framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000 (default) at scheduler-611df321-e66d-4bb4-bbdd-7a82ec93238b@10.0.49.4:65013
I0205 21:09:19.305966 56262656 master.cpp:3566] Authorizing framework principal 'test-principal' to launch task 74b96cfc-a233-4ddc-b114-4405e73ef8c3
I0205 21:09:19.306661 54652928 master.cpp:4074] Adding task 74b96cfc-a233-4ddc-b114-4405e73ef8c3 with resources cpus(allocated: *):1; mem(allocated: *):128; disk(allocated: *):3 of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000 (default) at scheduler-611df321-e66d-4bb4-bbdd-7a82ec93238b@10.0.49.4:65013 on agent 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0 at slave(42)@10.0.49.4:65013 (Jenkinss-Mac-mini.local)
I0205 21:09:19.306830 54652928 master.cpp:5476] Launching task 74b96cfc-a233-4ddc-b114-4405e73ef8c3 of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000 (default) at scheduler-611df321-e66d-4bb4-bbdd-7a82ec93238b@10.0.49.4:65013 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 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0 at slave(42)@10.0.49.4:65013 (Jenkinss-Mac-mini.local) on new executor
I0205 21:09:19.307287 56262656 hierarchical.cpp:1230] 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 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0 from framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000
I0205 21:09:19.307322 56262656 hierarchical.cpp:1276] Framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000 filtered agent 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0 for 5secs
I0205 21:09:19.307632 53579776 slave.cpp:2030] Got assigned task '74b96cfc-a233-4ddc-b114-4405e73ef8c3' for framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000
I0205 21:09:19.307742 53579776 slave.cpp:9097] Checkpointing FrameworkInfo to '/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/DiskQuotaTest_SlaveRecovery_EmdfgZ/meta/slaves/06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0/frameworks/06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000/framework.info'
I0205 21:09:19.308406 53579776 slave.cpp:9108] Checkpointing framework pid 'scheduler-611df321-e66d-4bb4-bbdd-7a82ec93238b@10.0.49.4:65013' to '/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/DiskQuotaTest_SlaveRecovery_EmdfgZ/meta/slaves/06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0/frameworks/06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000/framework.pid'
I0205 21:09:19.309358 53579776 slave.cpp:2404] Authorizing task '74b96cfc-a233-4ddc-b114-4405e73ef8c3' for framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000
I0205 21:09:19.309402 53579776 slave.cpp:8673] Authorizing framework principal 'test-principal' to launch task 74b96cfc-a233-4ddc-b114-4405e73ef8c3
I0205 21:09:19.310168 53579776 slave.cpp:2847] Launching task '74b96cfc-a233-4ddc-b114-4405e73ef8c3' for framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000
I0205 21:09:19.310231 53579776 paths.cpp:752] Creating sandbox '/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/DiskQuotaTest_SlaveRecovery_EmdfgZ/slaves/06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0/frameworks/06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000/executors/74b96cfc-a233-4ddc-b114-4405e73ef8c3/runs/37db7c9c-52e1-4683-9785-8e34bc1c610e' for user 'jenkins'
I0205 21:09:19.311069 53579776 slave.cpp:9883] Checkpointing ExecutorInfo to '/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/DiskQuotaTest_SlaveRecovery_EmdfgZ/meta/slaves/06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0/frameworks/06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000/executors/74b96cfc-a233-4ddc-b114-4405e73ef8c3/executor.info'
I0205 21:09:19.311977 53579776 paths.cpp:755] Creating sandbox '/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/DiskQuotaTest_SlaveRecovery_EmdfgZ/meta/slaves/06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0/frameworks/06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000/executors/74b96cfc-a233-4ddc-b114-4405e73ef8c3/runs/37db7c9c-52e1-4683-9785-8e34bc1c610e'
I0205 21:09:19.312338 53579776 slave.cpp:9183] Launching executor '74b96cfc-a233-4ddc-b114-4405e73ef8c3' of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-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 '/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/DiskQuotaTest_SlaveRecovery_EmdfgZ/slaves/06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0/frameworks/06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000/executors/74b96cfc-a233-4ddc-b114-4405e73ef8c3/runs/37db7c9c-52e1-4683-9785-8e34bc1c610e'
I0205 21:09:19.312806 53579776 slave.cpp:9914] Checkpointing TaskInfo to '/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/DiskQuotaTest_SlaveRecovery_EmdfgZ/meta/slaves/06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0/frameworks/06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000/executors/74b96cfc-a233-4ddc-b114-4405e73ef8c3/runs/37db7c9c-52e1-4683-9785-8e34bc1c610e/tasks/:
74b96cfc-a233-4ddc-b114-4405e73ef8c3/task.info'
I0205 21:09:19.313616 53579776 slave.cpp:3044] Queued task '74b96cfc-a233-4ddc-b114-4405e73ef8c3' for executor '74b96cfc-a233-4ddc-b114-4405e73ef8c3' of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000
I0205 21:09:19.313674 53579776 slave.cpp:1001] Successfully attached '/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/DiskQuotaTest_SlaveRecovery_EmdfgZ/slaves/06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0/frameworks/06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000/executors/74b96cfc-a233-4ddc-b114-4405e73ef8c3/runs/37db7c9c-52e1-4683-9785-8e34bc1c610e' to virtual path '/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/DiskQuotaTest_SlaveRecovery_EmdfgZ/slaves/06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0/frameworks/06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000/executors/74b96cfc-a233-4ddc-b114-4405e73ef8c3/runs/latest'
I0205 21:09:19.313874 53579776 slave.cpp:3525] Launching container 37db7c9c-52e1-4683-9785-8e34bc1c610e for executor '74b96cfc-a233-4ddc-b114-4405e73ef8c3' of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000
I0205 21:09:19.314136 53579776 slave.cpp:1001] Successfully attached '/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/DiskQuotaTest_SlaveRecovery_EmdfgZ/slaves/06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0/frameworks/06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000/executors/74b96cfc-a233-4ddc-b114-4405e73ef8c3/runs/37db7c9c-52e1-4683-9785-8e34bc1c610e' to virtual path '/frameworks/06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000/executors/74b96cfc-a233-4ddc-b114-4405e73ef8c3/runs/latest'
I0205 21:09:19.314189 53579776 slave.cpp:1001] Successfully attached '/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/DiskQuotaTest_SlaveRecovery_EmdfgZ/slaves/06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0/frameworks/06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000/executors/74b96cfc-a233-4ddc-b114-4405e73ef8c3/runs/37db7c9c-52e1-4683-9785-8e34bc1c610e' to virtual path '/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/DiskQuotaTest_SlaveRecovery_EmdfgZ/slaves/06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0/frameworks/06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000/executors/74b96cfc-a233-4ddc-b114-4405e73ef8c3/runs/37db7c9c-52e1-4683-9785-8e34bc1c610e'
I0205 21:09:19.314442 57335808 containerizer.cpp:1296] Starting container 37db7c9c-52e1-4683-9785-8e34bc1c610e
I0205 21:09:19.315446 57335808 containerizer.cpp:1468] Checkpointed ContainerConfig at '/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/DiskQuotaTest_SlaveRecovery_8TOmLN/containers/37db7c9c-52e1-4683-9785-8e34bc1c610e/config'
I0205 21:09:19.315496 57335808 containerizer.cpp:3144] Transitioning the state of container 37db7c9c-52e1-4683-9785-8e34bc1c610e from PROVISIONING to PREPARING
I0205 21:09:19.317613 56799232 containerizer.cpp:1961] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"arguments":["mesos-executor","--launcher_dir=/Users/jenkins/workspace/workspace/mesos/Mesos_CI-build/FLAG/SSL/label/mac/mesos/build/src"],"shell":false,"value":"/Users/jenkins/workspace/workspace/mesos/Mesos_CI-build/FLAG/SSL/label/mac/mesos/build/src/mesos-executor"},"environment":{"variables":[{"name":"LIBPROCESS_PORT","type":"VALUE","value":"0"},{"name":"MESOS_AGENT_ENDPOINT","type":"VALUE","value":"10.0.49.4:65013"},{"name":"MESOS_CHECKPOINT","type":"VALUE","value":"1"},{"name":"MESOS_DIRECTORY","type":"VALUE","value":"/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/DiskQuotaTest_SlaveRecovery_EmdfgZ/slaves/06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0/frameworks/06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000/executors/74b96cfc-a233-4ddc-b114-4405e73ef8c3/runs/37db7c9c-52e1-4683-9785-8e34bc1c610e"},{"name":"MESOS_EXECUTOR_AUTHENTICATION_TOKEN","type":"VALUE","value":"eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJjaWQiOiIzN2RiN2M5Yy01MmUxLTQ2ODMtOTc4NS04ZTM0YmMxYzYxMGUiLCJlaWQiOiI3NGI5NmNmYy1hMjMzLTRkZGMtYjExNC00NDA1ZTczZWY4YzMiLCJmaWQiOiIwNmZiNjhiNi1jNDc2LTQyMTgtOGNhZi0yZWI1ZWViM2QyZjYtMDAwMCJ9.zWeF1R_7xOP_FE292SOwzjKyHQAeqZQtNXjYY07PeCQ"},{"name":"MESOS_EXECUTOR_ID","type":"VALUE","value":"74b96cfc-a233-4ddc-b114-4405e73ef8c3"},{"name":"MESOS_EXECUTOR_SHUTDOWN_GRACE_PERIOD","type":"VALUE","value":"5secs"},{"name":"MESOS_FRAMEWORK_ID","type":"VALUE","value":"06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-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":"06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0"},{"name":"MESOS_SLAVE_PID","type":"VALUE","value":"slave(42)@10.0.49.4:65013"},{"name":"MESOS_SUBSCRIPTION_BACKOFF_MAX","type":"VALUE","value":"2secs"},{"name":"MESOS_SANDBOX","type":"VALUE","value":"/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/DiskQuotaTest_SlaveRecovery_EmdfgZ/slaves/06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0/frameworks/06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000/executors/74b96cfc-a233-4ddc-b114-4405e73ef8c3/runs/37db7c9c-52e1-4683-9785-8e34bc1c610e"}]},"task_environment":{},"user":"jenkins","working_directory":"/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/DiskQuotaTest_SlaveRecovery_EmdfgZ/slaves/06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0/frameworks/06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000/executors/74b96cfc-a233-4ddc-b114-4405e73ef8c3/runs/37db7c9c-52e1-4683-9785-8e34bc1c610e"}" --pipe_read="12" --pipe_write="15" --runtime_directory="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/DiskQuotaTest_SlaveRecovery_8TOmLN/containers/37db7c9c-52e1-4683-9785-8e34bc1c610e"'
I0205 21:09:19.318980 56799232 launcher.cpp:145] Forked child with pid '10156' for container '37db7c9c-52e1-4683-9785-8e34bc1c610e'
I0205 21:09:19.319182 56799232 containerizer.cpp:2066] Checkpointing container's forked pid 10156 to '/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/DiskQuotaTest_SlaveRecovery_EmdfgZ/meta/slaves/06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0/frameworks/06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000/executors/74b96cfc-a233-4ddc-b114-4405e73ef8c3/runs/37db7c9c-52e1-4683-9785-8e34bc1c610e/pids/forked.pid'
I0205 21:09:19.320978 56799232 containerizer.cpp:3144] Transitioning the state of container 37db7c9c-52e1-4683-9785-8e34bc1c610e from PREPARING to ISOLATING
I0205 21:09:19.322140 56799232 containerizer.cpp:3144] Transitioning the state of container 37db7c9c-52e1-4683-9785-8e34bc1c610e from ISOLATING to FETCHING
I0205 21:09:19.322289 54116352 fetcher.cpp:369] Starting to fetch URIs for container: 37db7c9c-52e1-4683-9785-8e34bc1c610e, directory: /var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/DiskQuotaTest_SlaveRecovery_EmdfgZ/slaves/06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0/frameworks/06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000/executors/74b96cfc-a233-4ddc-b114-4405e73ef8c3/runs/37db7c9c-52e1-4683-9785-8e34bc1c610e
I0205 21:09:19.323313 55189504 containerizer.cpp:3144] Transitioning the state of container 37db7c9c-52e1-4683-9785-8e34bc1c610e from FETCHING to RUNNING
[warn] kq_init: detected broken kqueue; not using.: Undefined error: 0
I0205 21:09:19.459352 186830848 exec.cpp:162] Version: 1.8.0
I0205 21:09:19.462440 57335808 slave.cpp:4850] Got registration for executor '74b96cfc-a233-4ddc-b114-4405e73ef8c3' of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000 from executor(1)@10.0.49.4:65248
I0205 21:09:19.462801 57335808 slave.cpp:4936] Checkpointing executor pid 'executor(1)@10.0.49.4:65248' to '/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/DiskQuotaTest_SlaveRecovery_EmdfgZ/meta/slaves/06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0/frameworks/06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000/executors/74b96cfc-a233-4ddc-b114-4405e73ef8c3/runs/37db7c9c-52e1-4683-9785-8e34bc1c610e/pids/libprocess.pid'
I0205 21:09:19.464210 56799232 disk.cpp:213] Updating the disk resources for container 37db7c9c-52e1-4683-9785-8e34bc1c610e to cpus(allocated: *):1.1; mem(allocated: *):160; disk(allocated: *):3
I0205 21:09:19.464588 184684544 exec.cpp:236] Executor registered on agent 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0
I0205 21:09:19.464735 57335808 slave.cpp:3257] Sending queued task '74b96cfc-a233-4ddc-b114-4405e73ef8c3' to executor '74b96cfc-a233-4ddc-b114-4405e73ef8c3' of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000 at executor(1)@10.0.49.4:65248
I0205 21:09:19.468976 186830848 executor.cpp:184] Received SUBSCRIBED event
I0205 21:09:19.469424 186830848 executor.cpp:188] Subscribed executor on Jenkinss-Mac-mini.local
I0205 21:09:19.469527 186830848 executor.cpp:184] Received LAUNCH event
I0205 21:09:19.472615 186830848 executor.cpp:691] Starting task 74b96cfc-a233-4ddc-b114-4405e73ef8c3
I0205 21:09:19.476161 55726080 slave.cpp:5316] Handling status update TASK_STARTING (Status UUID: 10c02846-0d46-4554-ab64-7dac01db4749) for task 74b96cfc-a233-4ddc-b114-4405e73ef8c3 of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000 from executor(1)@10.0.49.4:65248
I0205 21:09:19.477424 55189504 task_status_update_manager.cpp:328] Received task status update TASK_STARTING (Status UUID: 10c02846-0d46-4554-ab64-7dac01db4749) for task 74b96cfc-a233-4ddc-b114-4405e73ef8c3 of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000
I0205 21:09:19.477466 55189504 task_status_update_manager.cpp:507] Creating StatusUpdate stream for task 74b96cfc-a233-4ddc-b114-4405e73ef8c3 of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000
I0205 21:09:19.478104 55189504 task_status_update_manager.cpp:842] Checkpointing UPDATE for task status update TASK_STARTING (Status UUID: 10c02846-0d46-4554-ab64-7dac01db4749) for task 74b96cfc-a233-4ddc-b114-4405e73ef8c3 of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000
I0205 21:09:19.478338 55189504 task_status_update_manager.cpp:383] Forwarding task status update TASK_STARTING (Status UUID: 10c02846-0d46-4554-ab64-7dac01db4749) for task 74b96cfc-a233-4ddc-b114-4405e73ef8c3 of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000 to the agent
I0205 21:09:19.478416 53579776 slave.cpp:5808] Forwarding the update TASK_STARTING (Status UUID: 10c02846-0d46-4554-ab64-7dac01db4749) for task 74b96cfc-a233-4ddc-b114-4405e73ef8c3 of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000 to master@10.0.49.4:65013
I0205 21:09:19.478585 53579776 slave.cpp:5701] Task status update manager successfully handled status update TASK_STARTING (Status UUID: 10c02846-0d46-4554-ab64-7dac01db4749) for task 74b96cfc-a233-4ddc-b114-4405e73ef8c3 of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000
I0205 21:09:19.478618 53579776 slave.cpp:5717] Sending acknowledgement for status update TASK_STARTING (Status UUID: 10c02846-0d46-4554-ab64-7dac01db4749) for task 74b96cfc-a233-4ddc-b114-4405e73ef8c3 of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000 to executor(1)@10.0.49.4:65248
I0205 21:09:19.478705 56262656 master.cpp:8516] Status update TASK_STARTING (Status UUID: 10c02846-0d46-4554-ab64-7dac01db4749) for task 74b96cfc-a233-4ddc-b114-4405e73ef8c3 of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000 from agent 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0 at slave(42)@10.0.49.4:65013 (Jenkinss-Mac-mini.local)
I0205 21:09:19.478780 56262656 master.cpp:8573] Forwarding status update TASK_STARTING (Status UUID: 10c02846-0d46-4554-ab64-7dac01db4749) for task 74b96cfc-a233-4ddc-b114-4405e73ef8c3 of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000
I0205 21:09:19.478955 56262656 master.cpp:11210] Updating the state of task 74b96cfc-a233-4ddc-b114-4405e73ef8c3 of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000 (latest state: TASK_STARTING, status update state: TASK_STARTING)
I0205 21:09:19.479411 55726080 sched.cpp:1022] Scheduler::statusUpdate took 143246ns
I0205 21:09:19.479840 55189504 master.cpp:6339] Processing ACKNOWLEDGE call for status 10c02846-0d46-4554-ab64-7dac01db4749 for task 74b96cfc-a233-4ddc-b114-4405e73ef8c3 of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000 (default) at scheduler-611df321-e66d-4bb4-bbdd-7a82ec93238b@10.0.49.4:65013 on agent 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0
I0205 21:09:19.480038 54116352 task_status_update_manager.cpp:401] Received task status update acknowledgement (UUID: 10c02846-0d46-4554-ab64-7dac01db4749) for task 74b96cfc-a233-4ddc-b114-4405e73ef8c3 of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000
I0205 21:09:19.480103 54116352 task_status_update_manager.cpp:842] Checkpointing ACK for task status update TASK_STARTING (Status UUID: 10c02846-0d46-4554-ab64-7dac01db4749) for task 74b96cfc-a233-4ddc-b114-4405e73ef8c3 of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000
I0205 21:09:19.480311 54652928 slave.cpp:4540] Task status update manager successfully handled status update acknowledgement (UUID: 10c02846-0d46-4554-ab64-7dac01db4749) for task 74b96cfc-a233-4ddc-b114-4405e73ef8c3 of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000
I0205 21:09:19.481475 186830848 executor.cpp:506] Running '/Users/jenkins/workspace/workspace/mesos/Mesos_CI-build/FLAG/SSL/label/mac/mesos/build/src/mesos-containerizer launch <POSSIBLY-SENSITIVE-DATA>'
I0205 21:09:19.482641 186830848 executor.cpp:706] Forked command at 10185
I0205 21:09:19.487126 56799232 slave.cpp:5316] Handling status update TASK_RUNNING (Status UUID: 370f2ffd-1db2-4c09-9135-7daecbda8977) for task 74b96cfc-a233-4ddc-b114-4405e73ef8c3 of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000 from executor(1)@10.0.49.4:65248
I0205 21:09:19.488173 56799232 task_status_update_manager.cpp:328] Received task status update TASK_RUNNING (Status UUID: 370f2ffd-1db2-4c09-9135-7daecbda8977) for task 74b96cfc-a233-4ddc-b114-4405e73ef8c3 of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000
I0205 21:09:19.488225 56799232 task_status_update_manager.cpp:842] Checkpointing UPDATE for task status update TASK_RUNNING (Status UUID: 370f2ffd-1db2-4c09-9135-7daecbda8977) for task 74b96cfc-a233-4ddc-b114-4405e73ef8c3 of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000
I0205 21:09:19.488445 56799232 task_status_update_manager.cpp:383] Forwarding task status update TASK_RUNNING (Status UUID: 370f2ffd-1db2-4c09-9135-7daecbda8977) for task 74b96cfc-a233-4ddc-b114-4405e73ef8c3 of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000 to the agent
I0205 21:09:19.488570 57335808 slave.cpp:5808] Forwarding the update TASK_RUNNING (Status UUID: 370f2ffd-1db2-4c09-9135-7daecbda8977) for task 74b96cfc-a233-4ddc-b114-4405e73ef8c3 of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000 to master@10.0.49.4:65013
I0205 21:09:19.488703 57335808 slave.cpp:5701] Task status update manager successfully handled status update TASK_RUNNING (Status UUID: 370f2ffd-1db2-4c09-9135-7daecbda8977) for task 74b96cfc-a233-4ddc-b114-4405e73ef8c3 of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000
I0205 21:09:19.488737 57335808 slave.cpp:5717] Sending acknowledgement for status update TASK_RUNNING (Status UUID: 370f2ffd-1db2-4c09-9135-7daecbda8977) for task 74b96cfc-a233-4ddc-b114-4405e73ef8c3 of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000 to executor(1)@10.0.49.4:65248
I0205 21:09:19.488873 54652928 master.cpp:8516] Status update TASK_RUNNING (Status UUID: 370f2ffd-1db2-4c09-9135-7daecbda8977) for task 74b96cfc-a233-4ddc-b114-4405e73ef8c3 of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000 from agent 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0 at slave(42)@10.0.49.4:65013 (Jenkinss-Mac-mini.local)
I0205 21:09:19.488916 54652928 master.cpp:8573] Forwarding status update TASK_RUNNING (Status UUID: 370f2ffd-1db2-4c09-9135-7daecbda8977) for task 74b96cfc-a233-4ddc-b114-4405e73ef8c3 of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000
I0205 21:09:19.489107 54652928 master.cpp:11210] Updating the state of task 74b96cfc-a233-4ddc-b114-4405e73ef8c3 of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
I0205 21:09:19.489356 55726080 sched.cpp:1022] Scheduler::statusUpdate took 87826ns
I0205 21:09:19.489681 55189504 master.cpp:6339] Processing ACKNOWLEDGE call for status 370f2ffd-1db2-4c09-9135-7daecbda8977 for task 74b96cfc-a233-4ddc-b114-4405e73ef8c3 of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000 (default) at scheduler-611df321-e66d-4bb4-bbdd-7a82ec93238b@10.0.49.4:65013 on agent 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0
I0205 21:09:19.490129 55726080 task_status_update_manager.cpp:401] Received task status update acknowledgement (UUID: 370f2ffd-1db2-4c09-9135-7daecbda8977) for task 74b96cfc-a233-4ddc-b114-4405e73ef8c3 of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000
I0205 21:09:19.490226 55726080 task_status_update_manager.cpp:842] Checkpointing ACK for task status update TASK_RUNNING (Status UUID: 370f2ffd-1db2-4c09-9135-7daecbda8977) for task 74b96cfc-a233-4ddc-b114-4405e73ef8c3 of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000
I0205 21:09:19.490432 53579776 slave.cpp:4540] Task status update manager successfully handled status update acknowledgement (UUID: 370f2ffd-1db2-4c09-9135-7daecbda8977) for task 74b96cfc-a233-4ddc-b114-4405e73ef8c3 of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000
I0205 21:09:19.490491 53579776 slave.cpp:922] Agent terminating
I0205 21:09:19.490916 54116352 master.cpp:1269] Agent 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0 at slave(42)@10.0.49.4:65013 (Jenkinss-Mac-mini.local) disconnected
I0205 21:09:19.490938 54116352 master.cpp:3292] Disconnecting agent 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0 at slave(42)@10.0.49.4:65013 (Jenkinss-Mac-mini.local)
I0205 21:09:19.490969 54116352 master.cpp:3311] Deactivating agent 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0 at slave(42)@10.0.49.4:65013 (Jenkinss-Mac-mini.local)
I0205 21:09:19.491143 54652928 hierarchical.cpp:793] Agent 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0 deactivated
I0205 21:09:19.491130 296834496 containerizer.cpp:309] Using isolation { environment_secret, posix/cpu, filesystem/posix, posix/mem, disk/du }
I0205 21:09:19.491418 296834496 provisioner.cpp:298] Using default backend 'copy'
W0205 21:09:19.524559 296834496 process.cpp:2829] Attempted to spawn already running process files@10.0.49.4:65013
I0205 21:09:19.525013 296834496 cluster.cpp:486] Creating default 'local' authorizer
I0205 21:09:19.525866 55189504 slave.cpp:268] Mesos agent started on (43)@10.0.49.4:65013
I0205 21:09:19.525892 55189504 slave.cpp:269] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/tvVUip/7oYyzh/store/appc" --authenticate_http_executors="true" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authenticatee="crammd5" --authentication_backoff_factor="1secs" --authentication_timeout_max="1mins" --authentication_timeout_min="5secs" --authorizer="local" --container_disk_watch_interval="1ms" --containerizers="mesos" --credential="/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/tvVUip/7oYyzh/credential" --default_role="*" --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="/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/tvVUip/7oYyzh/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="/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/tvVUip/7oYyzh/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/tvVUip/7oYyzh/frameworks" --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="/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/tvVUip/7oYyzh/http_credentials" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem,disk/du" --jwt_secret_key="/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/tvVUip/7oYyzh/jwt_secret_key" --launcher="posix" --launcher_dir="/Users/jenkins/workspace/workspace/mesos/Mesos_CI-build/FLAG/SSL/label/mac/mesos/build/src" --logbufsecs="0" --logging_level="INFO" --max_completed_executors_per_framework="150" --memory_profiling="false" --network_cni_metrics="true" --network_cni_root_dir_persist="false" --oversubscribed_resources_interval="15secs" --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]" --runtime_dir="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/DiskQuotaTest_SlaveRecovery_8TOmLN" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --version="false" --work_dir="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/DiskQuotaTest_SlaveRecovery_EmdfgZ" --zk_session_timeout="10secs"
I0205 21:09:19.526211 55189504 credentials.hpp:86] Loading credential for authentication from '/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/tvVUip/7oYyzh/credential'
I0205 21:09:19.526366 55189504 slave.cpp:301] Agent using credential for: test-principal
I0205 21:09:19.526382 55189504 credentials.hpp:37] Loading credentials for authentication from '/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/tvVUip/7oYyzh/http_credentials'
I0205 21:09:19.526598 55189504 http.cpp:965] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-executor'
I0205 21:09:19.526670 55189504 http.cpp:986] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-executor'
I0205 21:09:19.526834 55189504 http.cpp:965] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
19.526880 55189504 http.cpp:986] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-readonly'
I0205 21:09:19.526939 55189504 http.cpp:965] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite'
I0205 21:09:19.526973 55189504 http.cpp:986] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-readwrite'
I0205 21:09:19.527333 55189504 disk_profile_adaptor.cpp:80] Creating default disk profile adaptor module
I0205 21:09:19.527798 55189504 slave.cpp:616] 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"}]
I0205 21:09:19.527997 55189504 slave.cpp:624] Agent attributes: [ ]
I0205 21:09:19.528012 55189504 slave.cpp:633] Agent hostname: Jenkinss-Mac-mini.local
I0205 21:09:19.528113 56799232 task_status_update_manager.cpp:181] Pausing sending task status updates
I0205 21:09:19.528170 55726080 status_update_manager_process.hpp:379] Pausing operation status update manager
I0205 21:09:19.528964 55726080 state.cpp:66] Recovering state from '/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/DiskQuotaTest_SlaveRecovery_EmdfgZ/meta'
I0205 21:09:19.529044 55726080 state.cpp:742] No committed checkpointed resources found at '/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/DiskQuotaTest_SlaveRecovery_EmdfgZ/meta/resources/resources.info'
I0205 21:09:19.532306 54652928 slave.cpp:7004] Finished recovering checkpointed state from '/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/DiskQuotaTest_SlaveRecovery_EmdfgZ/meta', beginning agent recovery
I0205 21:09:19.532567 54652928 slave.cpp:7483] Recovering framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000
I0205 21:09:19.532618 54652928 slave.cpp:9301] Recovering executor '74b96cfc-a233-4ddc-b114-4405e73ef8c3' of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000
I0205 21:09:19.533145 55189504 task_status_update_manager.cpp:207] Recovering task status update manager
I0205 21:09:19.533162 55189504 task_status_update_manager.cpp:215] Recovering executor '74b96cfc-a233-4ddc-b114-4405e73ef8c3' of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000
I0205 21:09:19.533208 55189504 task_status_update_manager.cpp:507] Creating StatusUpdate stream for task 74b96cfc-a233-4ddc-b114-4405e73ef8c3 of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000
I0205 21:09:19.533835 55189504 task_status_update_manager.cpp:818] Replaying task status update stream for task 74b96cfc-a233-4ddc-b114-4405e73ef8c3
I0205 21:09:19.534394 57335808 containerizer.cpp:735] Recovering Mesos containers
I0205 21:09:19.534451 57335808 containerizer.cpp:792] Recovering container 37db7c9c-52e1-4683-9785-8e34bc1c610e for executor '74b96cfc-a233-4ddc-b114-4405e73ef8c3' of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000
I0205 21:09:19.535430 57335808 containerizer.cpp:1061] Recovering isolators
I0205 21:09:19.536082 54652928 containerizer.cpp:1100] Recovering provisioner
I0205 21:09:19.536412 56799232 provisioner.cpp:494] Provisioner recovery complete
I0205 21:09:19.537351 56799232 composing.cpp:339] Finished recovering all containerizers
I0205 21:09:19.537561 55726080 slave.cpp:7233] Recovering executors
I0205 21:09:19.537621 55726080 slave.cpp:7257] Sending reconnect request to executor '74b96cfc-a233-4ddc-b114-4405e73ef8c3' of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000 at executor(1)@10.0.49.4:65248
I0205 21:09:19.538303 187367424 exec.cpp:282] Received reconnect request from agent 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0
I0205 21:09:19.549865 54652928 hierarchical.cpp:1558] Performed allocation for 1 agents in 107415ns
I0205 21:09:19.552104 53579776 slave.cpp:5013] Received re-registration message from executor '74b96cfc-a233-4ddc-b114-4405e73ef8c3' of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000
I0205 21:09:19.552646 53579776 slave.cpp:5244] Cleaning up un-reregistered executors
I0205 21:09:19.552702 53579776 slave.cpp:7386] Finished recovery
I0205 21:09:19.556924 56262656 slave.cpp:1268] New master detected at master@10.0.49.4:65013
I0205 21:09:19.557090 56262656 slave.cpp:1333] Detecting new master
I0205 21:09:19.557168 56262656 task_status_update_manager.cpp:181] Pausing sending task status updates
I0205 21:09:19.557199 56262656 status_update_manager_process.hpp:379] Pausing operation status update manager
I0205 21:09:19.557219 54652928 disk.cpp:213] Updating the disk resources for container 37db7c9c-52e1-4683-9785-8e34bc1c610e to cpus(allocated: *):1.1; mem(allocated: *):160; disk(allocated: *):3
I0205 21:09:19.557453 184684544 exec.cpp:259] Executor reregistered on agent 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0
I0205 21:09:19.560257 55726080 slave.cpp:1360] Authenticating with master master@10.0.49.4:65013
I0205 21:09:19.560324 55726080 slave.cpp:1369] Using default CRAM-MD5 authenticatee
I0205 21:09:19.560858 187904000 executor.cpp:184] Received SUBSCRIBED event
I0205 21:09:19.560885 187904000 executor.cpp:188] Subscribed executor on Jenkinss-Mac-mini.local
I0205 21:09:19.562775 54116352 authenticatee.cpp:121] Creating new client SASL connection
I0205 21:09:19.563474 53579776 master.cpp:9902] Authenticating slave(43)@10.0.49.4:65013
I0205 21:09:19.564205 56262656 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(98)@10.0.49.4:65013
I0205 21:09:19.564751 55726080 authenticator.cpp:98] Creating new server SASL connection
I0205 21:09:19.565106 54652928 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0205 21:09:19.565161 54652928 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0205 21:09:19.565459 57335808 authenticator.cpp:204] Received SASL authentication start
I0205 21:09:19.565558 57335808 authenticator.cpp:326] Authentication requires more steps
I0205 21:09:19.565673 53579776 authenticatee.cpp:259] Received SASL authentication step
I0205 21:09:19.565903 54116352 authenticator.cpp:232] Received SASL authentication step
I0205 21:09:19.565927 54116352 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'Jenkinss-Mac-mini.local' server FQDN: 'Jenkinss-Mac-mini.local' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0205 21:09:19.565940 54116352 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0205 21:09:19.565971 54116352 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0205 21:09:19.565989 54116352 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'Jenkinss-Mac-mini.local' server FQDN: 'Jenkinss-Mac-mini.local' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0205 21:09:19.566001 54116352 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0205 21:09:19.566010 54116352 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0205 21:09:19.566025 54116352 authenticator.cpp:318] Authentication success
I0205 21:09:19.566279 56262656 authenticatee.cpp:299] Authentication success
I0205 21:09:19.566370 55726080 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(98)@10.0.49.4:65013
I0205 21:09:19.566597 54652928 master.cpp:9934] Successfully authenticated principal 'test-principal' at slave(43)@10.0.49.4:65013
I0205 21:09:19.567034 55726080 slave.cpp:1460] Successfully authenticated with master master@10.0.49.4:65013
../../src/tests/disk_quota_tests.cpp:746: Failure
Value of: usage->has_disk_limit_bytes()
Actual: false
Expected: true
I0205 21:09:19.575804 57335808 master.cpp:1384] Framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000 (default) at scheduler-611df321-e66d-4bb4-bbdd-7a82ec93238b@10.0.49.4:65013 disconnected
I0205 21:09:19.575875 57335808 master.cpp:3255] Deactivating framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000 (default) at scheduler-611df321-e66d-4bb4-bbdd-7a82ec93238b@10.0.49.4:65013
I0205 21:09:19.575995 57335808 master.cpp:3232] Disconnecting framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000 (default) at scheduler-611df321-e66d-4bb4-bbdd-7a82ec93238b@10.0.49.4:65013
I0205 21:09:19.576041 57335808 master.cpp:1399] Giving framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000 (default) at scheduler-611df321-e66d-4bb4-bbdd-7a82ec93238b@10.0.49.4:65013 0ns to failover
I0205 21:09:19.576092 54116352 hierarchical.cpp:419] Deactivated framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000
I0205 21:09:19.576457 56262656 master.cpp:9509] Framework failover timeout, removing framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000 (default) at scheduler-611df321-e66d-4bb4-bbdd-7a82ec93238b@10.0.49.4:65013
I0205 21:09:19.576503 56262656 master.cpp:10449] Removing framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000 (default) at scheduler-611df321-e66d-4bb4-bbdd-7a82ec93238b@10.0.49.4:65013
I0205 21:09:19.576598 56262656 master.cpp:11210] Updating the state of task 74b96cfc-a233-4ddc-b114-4405e73ef8c3 of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000 (latest state: TASK_KILLED, status update state: TASK_KILLED)
I0205 21:09:19.577090 54652928 hierarchical.cpp:1230] Recovered cpus(allocated: *):1; mem(allocated: *):128; disk(allocated: *):3 (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000], allocated: {}) on agent 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0 from framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000
I0205 21:09:19.577272 56262656 master.cpp:11308] Removing task 74b96cfc-a233-4ddc-b114-4405e73ef8c3 with resources cpus(allocated: *):1; mem(allocated: *):128; disk(allocated: *):3 of framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000 on agent 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0 at slave(42)@10.0.49.4:65013 (Jenkinss-Mac-mini.local)
I0205 21:09:19.577656 55189504 hierarchical.cpp:358] Removed framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000
2+0 records in
2+0 records out
2097152 bytes transferred in 0.000938 secs (2235915867 bytes/sec)
I0205 21:09:19.589627 55726080 slave.cpp:1893] Will retry registration in 3.287238ms if necessary
I0205 21:09:19.589730 55726080 slave.cpp:922] Agent terminating
I0205 21:09:19.589836 56799232 master.cpp:7067] Received reregister agent message from agent 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0 at slave(43)@10.0.49.4:65013 (Jenkinss-Mac-mini.local)
I0205 21:09:19.590135 56799232 master.cpp:3976] Authorizing agent providing resources 'cpus:2; mem:1024; disk:1024; ports:[31000-32000]' with principal 'test-principal'
I0205 21:09:19.590515 54116352 containerizer.cpp:2477] Destroying container 37db7c9c-52e1-4683-9785-8e34bc1c610e in RUNNING state
I0205 21:09:19.590539 54116352 containerizer.cpp:3144] Transitioning the state of container 37db7c9c-52e1-4683-9785-8e34bc1c610e from RUNNING to DESTROYING
I0205 21:09:19.590592 53579776 master.cpp:7159] Authorized re-registration of agent 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0 at slave(43)@10.0.49.4:65013 (Jenkinss-Mac-mini.local)
I0205 21:09:19.590656 53579776 master.cpp:7243] Agent is already marked as registered: 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0 at slave(43)@10.0.49.4:65013 (Jenkinss-Mac-mini.local)
I0205 21:09:19.590663 54116352 launcher.cpp:161] Asked to destroy container 37db7c9c-52e1-4683-9785-8e34bc1c610e
I0205 21:09:19.590767 53579776 master.cpp:7611] Registry updated for slave 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0 at slave(43)@10.0.49.4:65013(Jenkinss-Mac-mini.local)
I0205 21:09:19.591043 56799232 hierarchical.cpp:704] Agent 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0 (Jenkinss-Mac-mini.local) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
W0205 21:09:19.591095 53579776 master.cpp:10111] Agent 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0 at slave(43)@10.0.49.4:65013 (Jenkinss-Mac-mini.local) reregistered with completed framework 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000 (default) at scheduler-611df321-e66d-4bb4-bbdd-7a82ec93238b@10.0.49.4:65013. Shutting down the framework on the agent
I0205 21:09:19.591272 56262656 hierarchical.cpp:781] Agent 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0 reactivated
I0205 21:09:19.754649 54116352 containerizer.cpp:2983] Container 37db7c9c-52e1-4683-9785-8e34bc1c610e has exited
I0205 21:09:19.755429 56799232 disk.cpp:325] Checking disk usage at '/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/DiskQuotaTest_SlaveRecovery_EmdfgZ/slaves/06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0/frameworks/06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-0000/executors/74b96cfc-a233-4ddc-b114-4405e73ef8c3/runs/37db7c9c-52e1-4683-9785-8e34bc1c610e' for container 37db7c9c-52e1-4683-9785-8e34bc1c610e has been cancelled
I0205 21:09:19.756091 54652928 provisioner.cpp:597] Ignoring destroy request for unknown container 37db7c9c-52e1-4683-9785-8e34bc1c610e
I0205 21:09:19.760756 296834496 master.cpp:1109] Master terminating
I0205 21:09:19.761062 53579776 hierarchical.cpp:644] Removed agent 06fb68b6-c476-4218-8caf-2eb5eeb3d2f6-S0
[ FAILED ]
{code}
> DiskQuotaTest.SlaveRecovery is flaky
> ------------------------------------
>
> Key: MESOS-3968
> URL: https://issues.apache.org/jira/browse/MESOS-3968
> Project: Mesos
> Issue Type: Bug
> Components: test
> Reporter: Benjamin Mahler
> Priority: Major
> Labels: flaky-test, mesosphere, mesosphere-oncall, storage
>
> {noformat: title=Failed Run}
> [ RUN ] DiskQuotaTest.SlaveRecovery
> I1120 12:02:54.015383 29806 leveldb.cpp:176] Opened db in 2.965411ms
> I1120 12:02:54.018033 29806 leveldb.cpp:183] Compacted db in 2.585354ms
> I1120 12:02:54.018175 29806 leveldb.cpp:198] Created db iterator in 27134ns
> I1120 12:02:54.018275 29806 leveldb.cpp:204] Seeked to beginning of db in 3025ns
> I1120 12:02:54.018375 29806 leveldb.cpp:273] Iterated through 0 keys in the db in 679ns
> I1120 12:02:54.018491 29806 replica.cpp:780] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> I1120 12:02:54.021386 29838 recover.cpp:449] Starting replica recovery
> I1120 12:02:54.021692 29838 recover.cpp:475] Replica is in EMPTY status
> I1120 12:02:54.022189 29827 master.cpp:367] Master 9a3c45ec-28b3-49e6-a83f-1f2035cc1105 (a51e6bb03b55) started on 172.17.5.188:41228
> I1120 12:02:54.022212 29827 master.cpp:369] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="true" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/DsMniF/credentials" --framework_sorter="drf" --help="false" --hostname_lookup="true" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_slave_ping_timeouts="5" --quiet="false" --recovery_slave_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_store_timeout="25secs" --registry_strict="true" --root_submissions="true" --slave_ping_timeout="15secs" --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false" --webui_dir="/mesos/mesos-0.26.0/_inst/share/mesos/webui" --work_dir="/tmp/DsMniF/master" --zk_session_timeout="10secs"
> I1120 12:02:54.022557 29827 master.cpp:414] Master only allowing authenticated frameworks to register
> I1120 12:02:54.022569 29827 master.cpp:419] Master only allowing authenticated slaves to register
> I1120 12:02:54.022578 29827 credentials.hpp:37] Loading credentials for authentication from '/tmp/DsMniF/credentials'
> I1120 12:02:54.022896 29827 master.cpp:458] Using default 'crammd5' authenticator
> I1120 12:02:54.023217 29827 master.cpp:495] Authorization enabled
> I1120 12:02:54.023512 29831 whitelist_watcher.cpp:79] No whitelist given
> I1120 12:02:54.023814 29833 replica.cpp:676] Replica in EMPTY status received a broadcasted recover request from (562)@172.17.5.188:41228
> I1120 12:02:54.023519 29832 hierarchical.cpp:153] Initialized hierarchical allocator process
> I1120 12:02:54.025997 29831 recover.cpp:195] Received a recover response from a replica in EMPTY status
> I1120 12:02:54.027042 29832 recover.cpp:566] Updating replica status to STARTING
> I1120 12:02:54.027354 29830 master.cpp:1612] The newly elected leader is master@172.17.5.188:41228 with id 9a3c45ec-28b3-49e6-a83f-1f2035cc1105
> I1120 12:02:54.027385 29830 master.cpp:1625] Elected as the leading master!
> I1120 12:02:54.027403 29830 master.cpp:1385] Recovering from registrar
> I1120 12:02:54.027679 29830 registrar.cpp:309] Recovering registrar
> I1120 12:02:54.028439 29840 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 1.195171ms
> I1120 12:02:54.028539 29840 replica.cpp:323] Persisted replica status to STARTING
> I1120 12:02:54.028944 29840 recover.cpp:475] Replica is in STARTING status
> I1120 12:02:54.030910 29840 replica.cpp:676] Replica in STARTING status received a broadcasted recover request from (563)@172.17.5.188:41228
> I1120 12:02:54.031429 29840 recover.cpp:195] Received a recover response from a replica in STARTING status
> I1120 12:02:54.032032 29840 recover.cpp:566] Updating replica status to VOTING
> I1120 12:02:54.032816 29840 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 496492ns
> I1120 12:02:54.032982 29840 replica.cpp:323] Persisted replica status to VOTING
> I1120 12:02:54.033254 29840 recover.cpp:580] Successfully joined the Paxos group
> I1120 12:02:54.033562 29840 recover.cpp:464] Recover process terminated
> I1120 12:02:54.034631 29839 log.cpp:661] Attempting to start the writer
> I1120 12:02:54.036386 29834 replica.cpp:496] Replica received implicit promise request from (564)@172.17.5.188:41228 with proposal 1
> I1120 12:02:54.037082 29834 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 642707ns
> I1120 12:02:54.037116 29834 replica.cpp:345] Persisted promised to 1
> I1120 12:02:54.038153 29834 coordinator.cpp:240] Coordinator attempting to fill missing positions
> I1120 12:02:54.039929 29828 replica.cpp:391] Replica received explicit promise request from (565)@172.17.5.188:41228 for position 0 with proposal 2
> I1120 12:02:54.040452 29828 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 459163ns
> I1120 12:02:54.040480 29828 replica.cpp:715] Persisted action at 0
> I1120 12:02:54.041595 29828 replica.cpp:540] Replica received write request for position 0 from (566)@172.17.5.188:41228
> I1120 12:02:54.041657 29828 leveldb.cpp:438] Reading position from leveldb took 31405ns
> I1120 12:02:54.041990 29828 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 285183ns
> I1120 12:02:54.042017 29828 replica.cpp:715] Persisted action at 0
> I1120 12:02:54.042682 29828 replica.cpp:694] Replica received learned notice for position 0 from @0.0.0.0:0
> I1120 12:02:54.043001 29828 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 289557ns
> I1120 12:02:54.043027 29828 replica.cpp:715] Persisted action at 0
> I1120 12:02:54.043047 29828 replica.cpp:700] Replica learned NOP action at position 0
> I1120 12:02:54.044025 29828 log.cpp:677] Writer started with ending position 0
> I1120 12:02:54.045470 29832 leveldb.cpp:438] Reading position from leveldb took 64416ns
> I1120 12:02:54.046702 29835 registrar.cpp:342] Successfully fetched the registry (0B) in 18.969088ms
> I1120 12:02:54.046843 29835 registrar.cpp:441] Applied 1 operations in 33491ns; attempting to update the 'registry'
> I1120 12:02:54.047698 29835 log.cpp:685] Attempting to append 176 bytes to the log
> I1120 12:02:54.047878 29830 coordinator.cpp:350] Coordinator attempting to write APPEND action at position 1
> I1120 12:02:54.048619 29830 replica.cpp:540] Replica received write request for position 1 from (567)@172.17.5.188:41228
> I1120 12:02:54.049104 29830 leveldb.cpp:343] Persisting action (195 bytes) to leveldb took 447606ns
> I1120 12:02:54.049131 29830 replica.cpp:715] Persisted action at 1
> I1120 12:02:54.049968 29830 replica.cpp:694] Replica received learned notice for position 1 from @0.0.0.0:0
> I1120 12:02:54.050310 29830 leveldb.cpp:343] Persisting action (197 bytes) to leveldb took 312460ns
> I1120 12:02:54.050335 29830 replica.cpp:715] Persisted action at 1
> I1120 12:02:54.050354 29830 replica.cpp:700] Replica learned APPEND action at position 1
> I1120 12:02:54.051472 29837 registrar.cpp:486] Successfully updated the 'registry' in 4.566016ms
> I1120 12:02:54.051630 29837 registrar.cpp:372] Successfully recovered registrar
> I1120 12:02:54.051705 29830 log.cpp:704] Attempting to truncate the log to 1
> I1120 12:02:54.051820 29825 coordinator.cpp:350] Coordinator attempting to write TRUNCATE action at position 2
> I1120 12:02:54.052055 29835 master.cpp:1422] Recovered 0 slaves from the Registry (137B) ; allowing 10mins for slaves to re-register
> I1120 12:02:54.052665 29839 replica.cpp:540] Replica received write request for position 2 from (568)@172.17.5.188:41228
> I1120 12:02:54.052981 29839 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 279767ns
> I1120 12:02:54.053007 29839 replica.cpp:715] Persisted action at 2
> I1120 12:02:54.053591 29826 replica.cpp:694] Replica received learned notice for position 2 from @0.0.0.0:0
> I1120 12:02:54.054116 29826 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 455681ns
> I1120 12:02:54.054214 29826 leveldb.cpp:401] Deleting ~1 keys from leveldb took 36349ns
> I1120 12:02:54.054291 29826 replica.cpp:715] Persisted action at 2
> I1120 12:02:54.054363 29826 replica.cpp:700] Replica learned TRUNCATE action at position 2
> I1120 12:02:54.064028 29806 containerizer.cpp:143] Using isolation: posix/cpu,posix/mem,posix/disk,filesystem/posix
> W1120 12:02:54.064376 29806 backend.cpp:50] Failed to create 'bind' backend: BindBackend requires root privileges
> I1120 12:02:54.068229 29838 slave.cpp:191] Slave started on 15)@172.17.5.188:41228
> I1120 12:02:54.068256 29838 slave.cpp:192] Flags at startup: --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" --cgroups_cpu_enable_pids_and_tids_count="false" --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_jdV8yV/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_auth_server="auth.docker.io" --docker_auth_server_port="443" --docker_kill_orphans="true" --docker_local_archives_dir="/tmp/mesos/images/docker" --docker_puller="local" --docker_puller_timeout="60" --docker_registry="registry-1.docker.io" --docker_registry_port="443" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/DiskQuotaTest_SlaveRecovery_jdV8yV/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem,posix/disk" --launcher_dir="/mesos/mesos-0.26.0/_build/src" --logbufsecs="0" --logging_level="INFO" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:2;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/DiskQuotaTest_SlaveRecovery_jdV8yV"
> I1120 12:02:54.068590 29838 credentials.hpp:85] Loading credential for authentication from '/tmp/DiskQuotaTest_SlaveRecovery_jdV8yV/credential'
> I1120 12:02:54.068781 29838 slave.cpp:322] Slave using credential for: test-principal
> I1120 12:02:54.069118 29838 resources.cpp:474] Parsing resources as JSON failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000]
> Trying semicolon-delimited string format instead
> I1120 12:02:54.069506 29838 slave.cpp:392] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I1120 12:02:54.069566 29838 slave.cpp:400] Slave attributes: [ ]
> I1120 12:02:54.069576 29838 slave.cpp:405] Slave hostname: a51e6bb03b55
> I1120 12:02:54.069582 29838 slave.cpp:410] Slave checkpoint: true
> I1120 12:02:54.070355 29806 sched.cpp:166] Version: 0.26.0
> I1120 12:02:54.070415 29840 state.cpp:54] Recovering state from '/tmp/DiskQuotaTest_SlaveRecovery_jdV8yV/meta'
> I1120 12:02:54.070790 29826 status_update_manager.cpp:202] Recovering status update manager
> I1120 12:02:54.070873 29832 sched.cpp:264] New master detected at master@172.17.5.188:41228
> I1120 12:02:54.070976 29832 sched.cpp:320] Authenticating with master master@172.17.5.188:41228
> I1120 12:02:54.070996 29832 sched.cpp:327] Using default CRAM-MD5 authenticatee
> I1120 12:02:54.071059 29830 containerizer.cpp:385] Recovering containerizer
> I1120 12:02:54.071216 29837 authenticatee.cpp:123] Creating new client SASL connection
> I1120 12:02:54.071487 29828 master.cpp:5156] Authenticating scheduler-a51a061b-8755-4242-9a63-69e987a1c91d@172.17.5.188:41228
> I1120 12:02:54.071609 29826 authenticator.cpp:415] Starting authentication session for crammd5_authenticatee(57)@172.17.5.188:41228
> I1120 12:02:54.071931 29839 authenticator.cpp:100] Creating new server SASL connection
> I1120 12:02:54.072005 29831 slave.cpp:4230] Finished recovery
> I1120 12:02:54.072157 29827 authenticatee.cpp:214] Received SASL authentication mechanisms: CRAM-MD5
> I1120 12:02:54.072187 29827 authenticatee.cpp:240] Attempting to authenticate with mechanism 'CRAM-MD5'
> I1120 12:02:54.072280 29835 authenticator.cpp:205] Received SASL authentication start
> I1120 12:02:54.072341 29835 authenticator.cpp:327] Authentication requires more steps
> I1120 12:02:54.072439 29838 authenticatee.cpp:260] Received SASL authentication step
> I1120 12:02:54.072506 29831 slave.cpp:4387] Querying resource estimator for oversubscribable resources
> I1120 12:02:54.072712 29839 authenticator.cpp:233] Received SASL authentication step
> I1120 12:02:54.072726 29831 slave.cpp:729] New master detected at master@172.17.5.188:41228
> I1120 12:02:54.072747 29839 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'a51e6bb03b55' server FQDN: 'a51e6bb03b55' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I1120 12:02:54.072753 29828 status_update_manager.cpp:176] Pausing sending status updates
> I1120 12:02:54.072772 29839 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
> I1120 12:02:54.072790 29831 slave.cpp:792] Authenticating with master master@172.17.5.188:41228
> I1120 12:02:54.072811 29831 slave.cpp:797] Using default CRAM-MD5 authenticatee
> I1120 12:02:54.072821 29839 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I1120 12:02:54.072849 29839 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'a51e6bb03b55' server FQDN: 'a51e6bb03b55' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I1120 12:02:54.072861 29839 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I1120 12:02:54.072870 29839 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I1120 12:02:54.072887 29839 authenticator.cpp:319] Authentication success
> I1120 12:02:54.072921 29831 slave.cpp:765] Detecting new master
> I1120 12:02:54.072978 29825 authenticatee.cpp:123] Creating new client SASL connection
> I1120 12:02:54.073007 29832 authenticatee.cpp:300] Authentication success
> I1120 12:02:54.073041 29836 master.cpp:5186] Successfully authenticated principal 'test-principal' at scheduler-a51a061b-8755-4242-9a63-69e987a1c91d@172.17.5.188:41228
> I1120 12:02:54.073103 29834 authenticator.cpp:433] Authentication session cleanup for crammd5_authenticatee(57)@172.17.5.188:41228
> I1120 12:02:54.073169 29831 slave.cpp:4401] Received oversubscribable resources from the resource estimator
> I1120 12:02:54.073313 29839 sched.cpp:409] Successfully authenticated with master master@172.17.5.188:41228
> I1120 12:02:54.073338 29839 sched.cpp:716] Sending SUBSCRIBE call to master@172.17.5.188:41228
> I1120 12:02:54.073359 29836 master.cpp:5156] Authenticating slave(15)@172.17.5.188:41228
> I1120 12:02:54.073415 29839 sched.cpp:749] Will retry registration in 689.900282ms if necessary
> I1120 12:02:54.073447 29837 authenticator.cpp:415] Starting authentication session for crammd5_authenticatee(58)@172.17.5.188:41228
> I1120 12:02:54.073626 29840 authenticator.cpp:100] Creating new server SASL connection
> I1120 12:02:54.073645 29836 master.cpp:2182] Received SUBSCRIBE call for framework 'default' at scheduler-a51a061b-8755-4242-9a63-69e987a1c91d@172.17.5.188:41228
> I1120 12:02:54.073698 29836 master.cpp:1651] Authorizing framework principal 'test-principal' to receive offers for role '*'
> I1120 12:02:54.073815 29827 authenticatee.cpp:214] Received SASL authentication mechanisms: CRAM-MD5
> I1120 12:02:54.073845 29827 authenticatee.cpp:240] Attempting to authenticate with mechanism 'CRAM-MD5'
> I1120 12:02:54.073977 29840 authenticator.cpp:205] Received SASL authentication start
> I1120 12:02:54.074062 29840 authenticator.cpp:327] Authentication requires more steps
> I1120 12:02:54.074100 29830 master.cpp:2253] Subscribing framework default with checkpointing enabled and capabilities [ ]
> I1120 12:02:54.074146 29840 authenticatee.cpp:260] Received SASL authentication step
> I1120 12:02:54.074242 29837 authenticator.cpp:233] Received SASL authentication step
> I1120 12:02:54.074272 29837 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'a51e6bb03b55' server FQDN: 'a51e6bb03b55' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I1120 12:02:54.074285 29837 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
> I1120 12:02:54.074309 29837 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I1120 12:02:54.074326 29837 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'a51e6bb03b55' server FQDN: 'a51e6bb03b55' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I1120 12:02:54.074334 29837 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I1120 12:02:54.074343 29837 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I1120 12:02:54.074362 29837 authenticator.cpp:319] Authentication success
> I1120 12:02:54.074432 29840 authenticatee.cpp:300] Authentication success
> I1120 12:02:54.074466 29834 hierarchical.cpp:197] Added framework 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000
> I1120 12:02:54.074501 29831 authenticator.cpp:433] Authentication session cleanup for crammd5_authenticatee(58)@172.17.5.188:41228
> I1120 12:02:54.074522 29834 hierarchical.cpp:979] No resources available to allocate!
> I1120 12:02:54.074558 29834 hierarchical.cpp:1072] No inverse offers to send out!
> I1120 12:02:54.074553 29830 master.cpp:5186] Successfully authenticated principal 'test-principal' at slave(15)@172.17.5.188:41228
> I1120 12:02:54.074589 29834 hierarchical.cpp:878] Performed allocation for 0 slaves in 102842ns
> I1120 12:02:54.074692 29837 slave.cpp:860] Successfully authenticated with master master@172.17.5.188:41228
> I1120 12:02:54.074815 29837 slave.cpp:1254] Will retry registration in 79918ns if necessary
> I1120 12:02:54.074836 29840 sched.cpp:643] Framework registered with 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000
> I1120 12:02:54.074882 29840 sched.cpp:657] Scheduler::registered took 22019ns
> I1120 12:02:54.075027 29835 master.cpp:3865] Registering slave at slave(15)@172.17.5.188:41228 (a51e6bb03b55) with id 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0
> I1120 12:02:54.075202 29838 slave.cpp:1254] Will retry registration in 21.508543ms if necessary
> I1120 12:02:54.075392 29835 master.cpp:3853] Ignoring register slave message from slave(15)@172.17.5.188:41228 (a51e6bb03b55) as admission is already in progress
> I1120 12:02:54.075512 29839 registrar.cpp:441] Applied 1 operations in 69618ns; attempting to update the 'registry'
> I1120 12:02:54.076251 29836 log.cpp:685] Attempting to append 345 bytes to the log
> I1120 12:02:54.076375 29825 coordinator.cpp:350] Coordinator attempting to write APPEND action at position 3
> I1120 12:02:54.077157 29835 replica.cpp:540] Replica received write request for position 3 from (582)@172.17.5.188:41228
> I1120 12:02:54.077776 29835 leveldb.cpp:343] Persisting action (364 bytes) to leveldb took 574611ns
> I1120 12:02:54.077800 29835 replica.cpp:715] Persisted action at 3
> I1120 12:02:54.078423 29836 replica.cpp:694] Replica received learned notice for position 3 from @0.0.0.0:0
> I1120 12:02:54.078816 29836 leveldb.cpp:343] Persisting action (366 bytes) to leveldb took 364281ns
> I1120 12:02:54.078838 29836 replica.cpp:715] Persisted action at 3
> I1120 12:02:54.078855 29836 replica.cpp:700] Replica learned APPEND action at position 3
> I1120 12:02:54.080191 29828 registrar.cpp:486] Successfully updated the 'registry' in 4.57088ms
> I1120 12:02:54.080413 29839 log.cpp:704] Attempting to truncate the log to 3
> I1120 12:02:54.080533 29838 coordinator.cpp:350] Coordinator attempting to write TRUNCATE action at position 4
> I1120 12:02:54.081109 29833 slave.cpp:3169] Received ping from slave-observer(14)@172.17.5.188:41228
> I1120 12:02:54.081207 29829 master.cpp:3933] Registered slave 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0 at slave(15)@172.17.5.188:41228 (a51e6bb03b55) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I1120 12:02:54.081274 29835 replica.cpp:540] Replica received write request for position 4 from (583)@172.17.5.188:41228
> I1120 12:02:54.081352 29833 slave.cpp:904] Registered with master master@172.17.5.188:41228; given slave ID 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0
> I1120 12:02:54.081351 29831 hierarchical.cpp:346] Added slave 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0 (a51e6bb03b55) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
> I1120 12:02:54.081375 29833 fetcher.cpp:79] Clearing fetcher cache
> I1120 12:02:54.081533 29840 status_update_manager.cpp:183] Resuming sending status updates
> I1120 12:02:54.081712 29835 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 395576ns
> I1120 12:02:54.081740 29835 replica.cpp:715] Persisted action at 4
> I1120 12:02:54.081778 29833 slave.cpp:927] Checkpointing SlaveInfo to '/tmp/DiskQuotaTest_SlaveRecovery_jdV8yV/meta/slaves/9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0/slave.info'
> I1120 12:02:54.082193 29833 slave.cpp:963] Forwarding total oversubscribed resources
> I1120 12:02:54.082223 29831 hierarchical.cpp:1072] No inverse offers to send out!
> I1120 12:02:54.082295 29831 hierarchical.cpp:894] Performed allocation for slave 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0 in 899836ns
> I1120 12:02:54.082224 29838 replica.cpp:694] Replica received learned notice for position 4 from @0.0.0.0:0
> I1120 12:02:54.082574 29827 master.cpp:4985] Sending 1 offers to framework 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 (default) at scheduler-a51a061b-8755-4242-9a63-69e987a1c91d@172.17.5.188:41228
> I1120 12:02:54.082801 29827 master.cpp:4275] Received update of slave 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0 at slave(15)@172.17.5.188:41228 (a51e6bb03b55) with total oversubscribed resources
> I1120 12:02:54.082866 29838 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 437289ns
> I1120 12:02:54.083017 29838 leveldb.cpp:401] Deleting ~2 keys from leveldb took 46020ns
> I1120 12:02:54.083115 29838 replica.cpp:715] Persisted action at 4
> I1120 12:02:54.083103 29837 hierarchical.cpp:402] Slave 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0 (a51e6bb03b55) updated with oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000])
> I1120 12:02:54.083201 29834 sched.cpp:813] Scheduler::resourceOffers took 183293ns
> I1120 12:02:54.083201 29838 replica.cpp:700] Replica learned TRUNCATE action at position 4
> I1120 12:02:54.083613 29806 resources.cpp:474] Parsing resources as JSON failed: cpus:1;mem:128;disk:3
> Trying semicolon-delimited string format instead
> I1120 12:02:54.083685 29837 hierarchical.cpp:979] No resources available to allocate!
> I1120 12:02:54.083792 29837 hierarchical.cpp:1072] No inverse offers to send out!
> I1120 12:02:54.083818 29837 hierarchical.cpp:894] Performed allocation for slave 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0 in 553630ns
> I1120 12:02:54.084825 29832 master.cpp:2921] Processing ACCEPT call for offers: [ 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-O0 ] on slave 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0 at slave(15)@172.17.5.188:41228 (a51e6bb03b55) for framework 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 (default) at scheduler-a51a061b-8755-4242-9a63-69e987a1c91d@172.17.5.188:41228
> I1120 12:02:54.084867 29832 master.cpp:2717] Authorizing framework principal 'test-principal' to launch task a40b962c-6507-488b-812f-af506f2c1206 as user 'mesos'
> I1120 12:02:54.086195 29836 master.hpp:178] Adding task a40b962c-6507-488b-812f-af506f2c1206 with resources cpus(*):1; mem(*):128; disk(*):3 on slave 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0 (a51e6bb03b55)
> I1120 12:02:54.086338 29836 master.cpp:3251] Launching task a40b962c-6507-488b-812f-af506f2c1206 of framework 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 (default) at scheduler-a51a061b-8755-4242-9a63-69e987a1c91d@172.17.5.188:41228 with resources cpus(*):1; mem(*):128; disk(*):3 on slave 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0 at slave(15)@172.17.5.188:41228 (a51e6bb03b55)
> I1120 12:02:54.086685 29840 slave.cpp:1294] Got assigned task a40b962c-6507-488b-812f-af506f2c1206 for framework 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000
> I1120 12:02:54.086848 29840 slave.cpp:4920] Checkpointing FrameworkInfo to '/tmp/DiskQuotaTest_SlaveRecovery_jdV8yV/meta/slaves/9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0/frameworks/9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000/framework.info'
> I1120 12:02:54.086874 29833 hierarchical.cpp:746] Recovered cpus(*):1; mem(*):896; disk(*):1021; ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):1; mem(*):128; disk(*):3) on slave 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0 from framework 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000
> I1120 12:02:54.086925 29833 hierarchical.cpp:783] Framework 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 filtered slave 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0 for 5secs
> I1120 12:02:54.087383 29840 slave.cpp:4931] Checkpointing framework pid 'scheduler-a51a061b-8755-4242-9a63-69e987a1c91d@172.17.5.188:41228' to '/tmp/DiskQuotaTest_SlaveRecovery_jdV8yV/meta/slaves/9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0/frameworks/9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000/framework.pid'
> I1120 12:02:54.087718 29840 resources.cpp:474] Parsing resources as JSON failed: cpus:0.1;mem:32
> Trying semicolon-delimited string format instead
> I1120 12:02:54.088153 29840 slave.cpp:1410] Launching task a40b962c-6507-488b-812f-af506f2c1206 for framework 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000
> I1120 12:02:54.088251 29840 resources.cpp:474] Parsing resources as JSON failed: cpus:0.1;mem:32
> Trying semicolon-delimited string format instead
> I1120 12:02:54.088942 29840 paths.cpp:436] Trying to chown '/tmp/DiskQuotaTest_SlaveRecovery_jdV8yV/slaves/9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0/frameworks/9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000/executors/a40b962c-6507-488b-812f-af506f2c1206/runs/d73a9e9b-b646-4f63-85b9-d632ceb1f075' to user 'mesos'
> I1120 12:02:54.092754 29840 slave.cpp:5360] Checkpointing ExecutorInfo to '/tmp/DiskQuotaTest_SlaveRecovery_jdV8yV/meta/slaves/9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0/frameworks/9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000/executors/a40b962c-6507-488b-812f-af506f2c1206/executor.info'
> I1120 12:02:54.093534 29840 slave.cpp:4999] Launching executor a40b962c-6507-488b-812f-af506f2c1206 of framework 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/DiskQuotaTest_SlaveRecovery_jdV8yV/slaves/9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0/frameworks/9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000/executors/a40b962c-6507-488b-812f-af506f2c1206/runs/d73a9e9b-b646-4f63-85b9-d632ceb1f075'
> I1120 12:02:54.094018 29838 containerizer.cpp:619] Starting container 'd73a9e9b-b646-4f63-85b9-d632ceb1f075' for executor 'a40b962c-6507-488b-812f-af506f2c1206' of framework '9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000'
> I1120 12:02:54.094111 29840 slave.cpp:5383] Checkpointing TaskInfo to '/tmp/DiskQuotaTest_SlaveRecovery_jdV8yV/meta/slaves/9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0/frameworks/9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000/executors/a40b962c-6507-488b-812f-af506f2c1206/runs/d73a9e9b-b646-4f63-85b9-d632ceb1f075/tasks/a40b962c-6507-488b-812f-af506f2c1206/task.info'
> I1120 12:02:54.094547 29840 slave.cpp:1628] Queuing task 'a40b962c-6507-488b-812f-af506f2c1206' for executor 'a40b962c-6507-488b-812f-af506f2c1206' of framework 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000
> I1120 12:02:54.094662 29840 slave.cpp:682] Successfully attached file '/tmp/DiskQuotaTest_SlaveRecovery_jdV8yV/slaves/9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0/frameworks/9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000/executors/a40b962c-6507-488b-812f-af506f2c1206/runs/d73a9e9b-b646-4f63-85b9-d632ceb1f075'
> I1120 12:02:54.097172 29825 launcher.cpp:134] Forked child with pid '30021' for container 'd73a9e9b-b646-4f63-85b9-d632ceb1f075'
> I1120 12:02:54.097375 29825 containerizer.cpp:852] Checkpointing executor's forked pid 30021 to '/tmp/DiskQuotaTest_SlaveRecovery_jdV8yV/meta/slaves/9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0/frameworks/9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000/executors/a40b962c-6507-488b-812f-af506f2c1206/runs/d73a9e9b-b646-4f63-85b9-d632ceb1f075/pids/forked.pid'
> WARNING: Logging before InitGoogleLogging() is written to STDERR
> I1120 12:02:54.254101 30035 process.cpp:961] libprocess is initialized on 172.17.5.188:52276 for 16 cpus
> I1120 12:02:54.255296 30035 logging.cpp:177] Logging to STDERR
> I1120 12:02:54.258533 30035 exec.cpp:136] Version: 0.26.0
> I1120 12:02:54.269281 30058 exec.cpp:186] Executor started at: executor(1)@172.17.5.188:52276 with pid 30035
> I1120 12:02:54.272449 29837 slave.cpp:2405] Got registration for executor 'a40b962c-6507-488b-812f-af506f2c1206' of framework 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 from executor(1)@172.17.5.188:52276
> I1120 12:02:54.272603 29837 slave.cpp:2490] Checkpointing executor pid 'executor(1)@172.17.5.188:52276' to '/tmp/DiskQuotaTest_SlaveRecovery_jdV8yV/meta/slaves/9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0/frameworks/9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000/executors/a40b962c-6507-488b-812f-af506f2c1206/runs/d73a9e9b-b646-4f63-85b9-d632ceb1f075/pids/libprocess.pid'
> I1120 12:02:54.274507 29830 disk.cpp:154] Updating the disk resources for container d73a9e9b-b646-4f63-85b9-d632ceb1f075 to cpus(*):1.1; mem(*):160; disk(*):3
> I1120 12:02:54.275303 29839 slave.cpp:1793] Sending queued task 'a40b962c-6507-488b-812f-af506f2c1206' to executor 'a40b962c-6507-488b-812f-af506f2c1206' of framework 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 at executor(1)@172.17.5.188:52276
> I1120 12:02:54.275486 30058 exec.cpp:210] Executor registered on slave 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0
> I1120 12:02:54.277315 30058 exec.cpp:222] Executor::registered took 318201ns
> Registered executor on a51e6bb03b55
> I1120 12:02:54.278136 30051 exec.cpp:297] Executor asked to run task 'a40b962c-6507-488b-812f-af506f2c1206'
> Starting task a40b962c-6507-488b-812f-af506f2c1206
> I1120 12:02:54.278244 30051 exec.cpp:306] Executor::launchTask took 76292ns
> sh -c 'dd if=/dev/zero of=file bs=1048576 count=2 && sleep 1000'
> Forked command at 30067
> I1120 12:02:54.281972 30057 exec.cpp:519] Executor sending status update TASK_RUNNING (UUID: ed7ce1df-70bd-42e9-a09d-e16b79d78f4c) for task a40b962c-6507-488b-812f-af506f2c1206 of framework 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000
> 2+0 records in
> 2+0 records out
> 2097152 bytes (2.1 MB) copied, 0.00335268 s, 626 MB/s
> I1120 12:02:55.025218 29827 hierarchical.cpp:1164] Filtered offer with cpus(*):1; mem(*):896; disk(*):1021; ports(*):[31000-32000] on slave 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0 for framework 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000
> I1120 12:02:55.025296 29827 hierarchical.cpp:979] No resources available to allocate!
> I1120 12:02:55.025339 29827 hierarchical.cpp:1072] No inverse offers to send out!
> I1120 12:02:55.025367 29827 hierarchical.cpp:878] Performed allocation for 1 slaves in 821045ns
> I1120 12:02:56.027402 29838 hierarchical.cpp:1164] Filtered offer with cpus(*):1; mem(*):896; disk(*):1021; ports(*):[31000-32000] on slave 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0 for framework 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000
> I1120 12:02:56.027516 29838 hierarchical.cpp:979] No resources available to allocate!
> I1120 12:02:56.027566 29838 hierarchical.cpp:1072] No inverse offers to send out!
> I1120 12:02:56.027598 29838 hierarchical.cpp:878] Performed allocation for 1 slaves in 1.05848ms
> I1120 12:02:57.028882 29840 hierarchical.cpp:1164] Filtered offer with cpus(*):1; mem(*):896; disk(*):1021; ports(*):[31000-32000] on slave 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0 for framework 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000
> I1120 12:02:57.028995 29840 hierarchical.cpp:979] No resources available to allocate!
> I1120 12:02:57.029047 29840 hierarchical.cpp:1072] No inverse offers to send out!
> I1120 12:02:57.029079 29840 hierarchical.cpp:878] Performed allocation for 1 slaves in 991084ns
> I1120 12:02:58.030680 29828 hierarchical.cpp:1164] Filtered offer with cpus(*):1; mem(*):896; disk(*):1021; ports(*):[31000-32000] on slave 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0 for framework 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000
> I1120 12:02:58.030779 29828 hierarchical.cpp:979] No resources available to allocate!
> I1120 12:02:58.030824 29828 hierarchical.cpp:1072] No inverse offers to send out!
> I1120 12:02:58.030853 29828 hierarchical.cpp:878] Performed allocation for 1 slaves in 869985ns
> I1120 12:02:59.032424 29837 hierarchical.cpp:1164] Filtered offer with cpus(*):1; mem(*):896; disk(*):1021; ports(*):[31000-32000] on slave 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0 for framework 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000
> I1120 12:02:59.032526 29837 hierarchical.cpp:979] No resources available to allocate!
> I1120 12:02:59.032574 29837 hierarchical.cpp:1072] No inverse offers to send out!
> I1120 12:02:59.032604 29837 hierarchical.cpp:878] Performed allocation for 1 slaves in 930207ns
> I1120 12:03:00.034873 29839 hierarchical.cpp:1072] No inverse offers to send out!
> I1120 12:03:00.034943 29839 hierarchical.cpp:878] Performed allocation for 1 slaves in 851471ns
> I1120 12:03:00.035372 29839 master.cpp:4985] Sending 1 offers to framework 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 (default) at scheduler-a51a061b-8755-4242-9a63-69e987a1c91d@172.17.5.188:41228
> I1120 12:03:00.035830 29828 sched.cpp:813] Scheduler::resourceOffers took 27519ns
> I1120 12:03:01.036597 29838 hierarchical.cpp:979] No resources available to allocate!
> I1120 12:03:01.036702 29838 hierarchical.cpp:1072] No inverse offers to send out!
> I1120 12:03:01.036738 29838 hierarchical.cpp:878] Performed allocation for 1 slaves in 786983ns
> I1120 12:03:02.038766 29828 hierarchical.cpp:979] No resources available to allocate!
> I1120 12:03:02.038861 29828 hierarchical.cpp:1072] No inverse offers to send out!
> I1120 12:03:02.038895 29828 hierarchical.cpp:878] Performed allocation for 1 slaves in 737171ns
> I1120 12:03:03.040204 29836 hierarchical.cpp:979] No resources available to allocate!
> I1120 12:03:03.040279 29836 hierarchical.cpp:1072] No inverse offers to send out!
> I1120 12:03:03.040397 29836 hierarchical.cpp:878] Performed allocation for 1 slaves in 677058ns
> I1120 12:03:04.042060 29831 hierarchical.cpp:979] No resources available to allocate!
> I1120 12:03:04.042136 29831 hierarchical.cpp:1072] No inverse offers to send out!
> I1120 12:03:04.042163 29831 hierarchical.cpp:878] Performed allocation for 1 slaves in 568286ns
> I1120 12:03:05.043707 29838 hierarchical.cpp:979] No resources available to allocate!
> I1120 12:03:05.043797 29838 hierarchical.cpp:1072] No inverse offers to send out!
> I1120 12:03:05.043826 29838 hierarchical.cpp:878] Performed allocation for 1 slaves in 701131ns
> I1120 12:03:06.045091 29836 hierarchical.cpp:979] No resources available to allocate!
> I1120 12:03:06.045178 29836 hierarchical.cpp:1072] No inverse offers to send out!
> I1120 12:03:06.045208 29836 hierarchical.cpp:878] Performed allocation for 1 slaves in 683215ns
> I1120 12:03:07.046598 29835 hierarchical.cpp:979] No resources available to allocate!
> I1120 12:03:07.046681 29835 hierarchical.cpp:1072] No inverse offers to send out!
> I1120 12:03:07.046711 29835 hierarchical.cpp:878] Performed allocation for 1 slaves in 645715ns
> I1120 12:03:08.048492 29827 hierarchical.cpp:979] No resources available to allocate!
> I1120 12:03:08.048583 29827 hierarchical.cpp:1072] No inverse offers to send out!
> I1120 12:03:08.048614 29827 hierarchical.cpp:878] Performed allocation for 1 slaves in 673997ns
> I1120 12:03:09.050271 29832 hierarchical.cpp:979] No resources available to allocate!
> I1120 12:03:09.050374 29832 hierarchical.cpp:1072] No inverse offers to send out!
> I1120 12:03:09.050417 29832 hierarchical.cpp:878] Performed allocation for 1 slaves in 894773ns
> I1120 12:03:09.074158 29834 slave.cpp:4387] Querying resource estimator for oversubscribable resources
> I1120 12:03:09.074461 29834 slave.cpp:4401] Received oversubscribable resources from the resource estimator
> I1120 12:03:09.081683 29840 slave.cpp:3169] Received ping from slave-observer(14)@172.17.5.188:41228
> ../../src/tests/disk_quota_tests.cpp:465: Failure
> Failed to wait 15secs for status
> I1120 12:03:09.089833 29825 master.cpp:1128] Framework 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 (default) at scheduler-a51a061b-8755-4242-9a63-69e987a1c91d@172.17.5.188:41228 disconnected
> I1120 12:03:09.090107 29825 master.cpp:2478] Disconnecting framework 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 (default) at scheduler-a51a061b-8755-4242-9a63-69e987a1c91d@172.17.5.188:41228
> I1120 12:03:09.090232 29825 master.cpp:2502] Deactivating framework 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 (default) at scheduler-a51a061b-8755-4242-9a63-69e987a1c91d@172.17.5.188:41228
> ../../src/tests/disk_quota_tests.cpp:459: Failure
> Actual function call count doesn't match EXPECT_CALL(sched, statusUpdate(&driver, _))...
> Expected: to be called at least once
> Actual: never called - unsatisfied and active
> W1120 12:03:09.090963 29825 master.hpp:1623] Master attempted to send message to disconnected framework 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 (default) at scheduler-a51a061b-8755-4242-9a63-69e987a1c91d@172.17.5.188:41228
> I1120 12:03:09.091192 29825 master.cpp:1152] Giving framework 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 (default) at scheduler-a51a061b-8755-4242-9a63-69e987a1c91d@172.17.5.188:41228 0ns to failover
> I1120 12:03:09.091501 29825 master.cpp:928] Master terminating
> I1120 12:03:09.091677 29839 hierarchical.cpp:275] Deactivated framework 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000
> W1120 12:03:09.091797 29825 master.cpp:6124] Removing task a40b962c-6507-488b-812f-af506f2c1206 with resources cpus(*):1; mem(*):128; disk(*):3 of framework 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 on slave 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0 at slave(15)@172.17.5.188:41228 (a51e6bb03b55) in non-terminal state TASK_STAGING
> I1120 12:03:09.092192 29839 hierarchical.cpp:746] Recovered cpus(*):1; mem(*):896; disk(*):1021; ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):1; mem(*):128; disk(*):3) on slave 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0 from framework 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000
> I1120 12:03:09.092428 29839 hierarchical.cpp:375] Removed slave 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0
> I1120 12:03:09.092726 29839 hierarchical.cpp:232] Removed framework 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000
> I1120 12:03:09.093112 29836 slave.cpp:3215] master@172.17.5.188:41228 exited
> W1120 12:03:09.093142 29836 slave.cpp:3218] Master disconnected! Waiting for a new master to be elected
> I1120 12:03:09.099444 29836 containerizer.cpp:1075] Destroying container 'd73a9e9b-b646-4f63-85b9-d632ceb1f075'
> I1120 12:03:09.127142 29834 containerizer.cpp:1258] Executor for container 'd73a9e9b-b646-4f63-85b9-d632ceb1f075' has exited
> I1120 12:03:09.130437 29831 slave.cpp:3553] Executor 'a40b962c-6507-488b-812f-af506f2c1206' of framework 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 terminated with signal Killed
> I1120 12:03:09.130599 29831 slave.cpp:2762] Handling status update TASK_FAILED (UUID: f13c71f7-c85b-4b9f-a36d-42a95cce4ebc) for task a40b962c-6507-488b-812f-af506f2c1206 of framework 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 from @0.0.0.0:0
> I1120 12:03:09.130785 29831 slave.cpp:5298] Terminating task a40b962c-6507-488b-812f-af506f2c1206
> W1120 12:03:09.131325 29831 containerizer.cpp:967] Ignoring update for unknown container: d73a9e9b-b646-4f63-85b9-d632ceb1f075
> I1120 12:03:09.132174 29830 status_update_manager.cpp:322] Received status update TASK_FAILED (UUID: f13c71f7-c85b-4b9f-a36d-42a95cce4ebc) for task a40b962c-6507-488b-812f-af506f2c1206 of framework 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000
> I1120 12:03:09.132282 29830 status_update_manager.cpp:499] Creating StatusUpdate stream for task a40b962c-6507-488b-812f-af506f2c1206 of framework 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000
> I1120 12:03:09.133081 29830 status_update_manager.cpp:826] Checkpointing UPDATE for status update TASK_FAILED (UUID: f13c71f7-c85b-4b9f-a36d-42a95cce4ebc) for task a40b962c-6507-488b-812f-af506f2c1206 of framework 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000
> I1120 12:03:09.133985 29832 slave.cpp:601] Slave terminating
> I1120 12:03:09.136636 29830 status_update_manager.cpp:376] Forwarding update TASK_FAILED (UUID: f13c71f7-c85b-4b9f-a36d-42a95cce4ebc) for task a40b962c-6507-488b-812f-af506f2c1206 of framework 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 to the slave
> [ FAILED ] DiskQuotaTest.SlaveRecovery (15127 ms)
> {noformat}
> {noformat: title=Good Run}
> [ RUN ] DiskQuotaTest.SlaveRecovery
> I1120 14:23:00.508623 29809 leveldb.cpp:176] Opened db in 2.857109ms
> I1120 14:23:00.509371 29809 leveldb.cpp:183] Compacted db in 691823ns
> I1120 14:23:00.509424 29809 leveldb.cpp:198] Created db iterator in 25782ns
> I1120 14:23:00.509436 29809 leveldb.cpp:204] Seeked to beginning of db in 2026ns
> I1120 14:23:00.509443 29809 leveldb.cpp:273] Iterated through 0 keys in the db in 262ns
> I1120 14:23:00.509493 29809 replica.cpp:780] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> I1120 14:23:00.510426 29829 recover.cpp:449] Starting replica recovery
> I1120 14:23:00.510720 29829 recover.cpp:475] Replica is in EMPTY status
> I1120 14:23:00.512007 29835 replica.cpp:676] Replica in EMPTY status received a broadcasted recover request from (554)@172.17.10.237:40088
> I1120 14:23:00.512296 29838 master.cpp:367] Master 1c180fae-4467-4812-9068-e694cb1c9940 (8b126df598c7) started on 172.17.10.237:40088
> I1120 14:23:00.512548 29843 recover.cpp:195] Received a recover response from a replica in EMPTY status
> I1120 14:23:00.512320 29838 master.cpp:369] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="true" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/EXdfqq/credentials" --framework_sorter="drf" --help="false" --hostname_lookup="true" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_slave_ping_timeouts="5" --quiet="false" --recovery_slave_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_store_timeout="25secs" --registry_strict="true" --root_submissions="true" --slave_ping_timeout="15secs" --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false" --webui_dir="/mesos/mesos-0.26.0/_inst/share/mesos/webui" --work_dir="/tmp/EXdfqq/master" --zk_session_timeout="10secs"
> I1120 14:23:00.512601 29838 master.cpp:414] Master only allowing authenticated frameworks to register
> I1120 14:23:00.512614 29838 master.cpp:419] Master only allowing authenticated slaves to register
> I1120 14:23:00.512622 29838 credentials.hpp:37] Loading credentials for authentication from '/tmp/EXdfqq/credentials'
> I1120 14:23:00.512943 29838 master.cpp:458] Using default 'crammd5' authenticator
> I1120 14:23:00.512966 29835 recover.cpp:566] Updating replica status to STARTING
> I1120 14:23:00.513171 29838 master.cpp:495] Authorization enabled
> I1120 14:23:00.513761 29832 hierarchical.cpp:153] Initialized hierarchical allocator process
> I1120 14:23:00.513826 29832 whitelist_watcher.cpp:79] No whitelist given
> I1120 14:23:00.513903 29829 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 496302ns
> I1120 14:23:00.513922 29829 replica.cpp:323] Persisted replica status to STARTING
> I1120 14:23:00.514123 29832 recover.cpp:475] Replica is in STARTING status
> I1120 14:23:00.515575 29830 replica.cpp:676] Replica in STARTING status received a broadcasted recover request from (555)@172.17.10.237:40088
> I1120 14:23:00.515874 29828 recover.cpp:195] Received a recover response from a replica in STARTING status
> I1120 14:23:00.516531 29839 recover.cpp:566] Updating replica status to VOTING
> I1120 14:23:00.517139 29828 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 492016ns
> I1120 14:23:00.517177 29828 replica.cpp:323] Persisted replica status to VOTING
> I1120 14:23:00.517336 29828 recover.cpp:580] Successfully joined the Paxos group
> I1120 14:23:00.517505 29842 master.cpp:1612] The newly elected leader is master@172.17.10.237:40088 with id 1c180fae-4467-4812-9068-e694cb1c9940
> I1120 14:23:00.517542 29842 master.cpp:1625] Elected as the leading master!
> I1120 14:23:00.517562 29842 master.cpp:1385] Recovering from registrar
> I1120 14:23:00.517652 29828 recover.cpp:464] Recover process terminated
> I1120 14:23:00.517840 29839 registrar.cpp:309] Recovering registrar
> I1120 14:23:00.519129 29840 log.cpp:661] Attempting to start the writer
> I1120 14:23:00.520586 29832 replica.cpp:496] Replica received implicit promise request from (556)@172.17.10.237:40088 with proposal 1
> I1120 14:23:00.521001 29832 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 376158ns
> I1120 14:23:00.521056 29832 replica.cpp:345] Persisted promised to 1
> I1120 14:23:00.521869 29830 coordinator.cpp:240] Coordinator attempting to fill missing positions
> I1120 14:23:00.523301 29835 replica.cpp:391] Replica received explicit promise request from (557)@172.17.10.237:40088 for position 0 with proposal 2
> I1120 14:23:00.523751 29835 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 397806ns
> I1120 14:23:00.523780 29835 replica.cpp:715] Persisted action at 0
> I1120 14:23:00.524871 29837 replica.cpp:540] Replica received write request for position 0 from (558)@172.17.10.237:40088
> I1120 14:23:00.525171 29837 leveldb.cpp:438] Reading position from leveldb took 200426ns
> I1120 14:23:00.525580 29837 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 328218ns
> I1120 14:23:00.525609 29837 replica.cpp:715] Persisted action at 0
> I1120 14:23:00.526381 29843 replica.cpp:694] Replica received learned notice for position 0 from @0.0.0.0:0
> I1120 14:23:00.526823 29843 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 311618ns
> I1120 14:23:00.526923 29843 replica.cpp:715] Persisted action at 0
> I1120 14:23:00.527019 29843 replica.cpp:700] Replica learned NOP action at position 0
> I1120 14:23:00.527701 29835 log.cpp:677] Writer started with ending position 0
> I1120 14:23:00.529162 29839 leveldb.cpp:438] Reading position from leveldb took 49313ns
> I1120 14:23:00.530751 29828 registrar.cpp:342] Successfully fetched the registry (0B) in 12.859136ms
> I1120 14:23:00.530978 29828 registrar.cpp:441] Applied 1 operations in 45309ns; attempting to update the 'registry'
> I1120 14:23:00.531807 29830 log.cpp:685] Attempting to append 178 bytes to the log
> I1120 14:23:00.531935 29839 coordinator.cpp:350] Coordinator attempting to write APPEND action at position 1
> I1120 14:23:00.532902 29842 replica.cpp:540] Replica received write request for position 1 from (559)@172.17.10.237:40088
> I1120 14:23:00.533485 29842 leveldb.cpp:343] Persisting action (197 bytes) to leveldb took 536837ns
> I1120 14:23:00.533514 29842 replica.cpp:715] Persisted action at 1
> I1120 14:23:00.534164 29833 replica.cpp:694] Replica received learned notice for position 1 from @0.0.0.0:0
> I1120 14:23:00.534489 29833 leveldb.cpp:343] Persisting action (199 bytes) to leveldb took 291755ns
> I1120 14:23:00.534524 29833 replica.cpp:715] Persisted action at 1
> I1120 14:23:00.534555 29833 replica.cpp:700] Replica learned APPEND action at position 1
> I1120 14:23:00.535744 29837 registrar.cpp:486] Successfully updated the 'registry' in 4.637184ms
> I1120 14:23:00.535953 29837 registrar.cpp:372] Successfully recovered registrar
> I1120 14:23:00.536512 29837 master.cpp:1422] Recovered 0 slaves from the Registry (139B) ; allowing 10mins for slaves to re-register
> I1120 14:23:00.536036 29839 log.cpp:704] Attempting to truncate the log to 1
> I1120 14:23:00.537062 29835 coordinator.cpp:350] Coordinator attempting to write TRUNCATE action at position 2
> I1120 14:23:00.538105 29836 replica.cpp:540] Replica received write request for position 2 from (560)@172.17.10.237:40088
> I1120 14:23:00.538614 29836 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 447383ns
> I1120 14:23:00.538640 29836 replica.cpp:715] Persisted action at 2
> I1120 14:23:00.539374 29836 replica.cpp:694] Replica received learned notice for position 2 from @0.0.0.0:0
> I1120 14:23:00.539808 29836 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 375315ns
> I1120 14:23:00.539885 29836 leveldb.cpp:401] Deleting ~1 keys from leveldb took 49469ns
> I1120 14:23:00.539938 29836 replica.cpp:715] Persisted action at 2
> I1120 14:23:00.539984 29836 replica.cpp:700] Replica learned TRUNCATE action at position 2
> I1120 14:23:00.549140 29809 containerizer.cpp:143] Using isolation: posix/cpu,posix/mem,posix/disk,filesystem/posix
> W1120 14:23:00.549513 29809 backend.cpp:50] Failed to create 'bind' backend: BindBackend requires root privileges
> I1120 14:23:00.553772 29837 slave.cpp:191] Slave started on 15)@172.17.10.237:40088
> I1120 14:23:00.553809 29837 slave.cpp:192] Flags at startup: --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" --cgroups_cpu_enable_pids_and_tids_count="false" --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_7QsJEm/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_auth_server="auth.docker.io" --docker_auth_server_port="443" --docker_kill_orphans="true" --docker_local_archives_dir="/tmp/mesos/images/docker" --docker_puller="local" --docker_puller_timeout="60" --docker_registry="registry-1.docker.io" --docker_registry_port="443" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem,posix/disk" --launcher_dir="/mesos/mesos-0.26.0/_build/src" --logbufsecs="0" --logging_level="INFO" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:2;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm"
> I1120 14:23:00.554425 29837 credentials.hpp:85] Loading credential for authentication from '/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm/credential'
> I1120 14:23:00.554700 29837 slave.cpp:322] Slave using credential for: test-principal
> I1120 14:23:00.554927 29837 resources.cpp:474] Parsing resources as JSON failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000]
> Trying semicolon-delimited string format instead
> I1120 14:23:00.555559 29837 slave.cpp:392] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I1120 14:23:00.555634 29837 slave.cpp:400] Slave attributes: [ ]
> I1120 14:23:00.555649 29837 slave.cpp:405] Slave hostname: 8b126df598c7
> I1120 14:23:00.555660 29837 slave.cpp:410] Slave checkpoint: true
> I1120 14:23:00.556748 29840 state.cpp:54] Recovering state from '/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm/meta'
> I1120 14:23:00.556985 29835 status_update_manager.cpp:202] Recovering status update manager
> I1120 14:23:00.557191 29809 sched.cpp:166] Version: 0.26.0
> I1120 14:23:00.557224 29834 containerizer.cpp:385] Recovering containerizer
> I1120 14:23:00.557792 29830 sched.cpp:264] New master detected at master@172.17.10.237:40088
> I1120 14:23:00.557881 29830 sched.cpp:320] Authenticating with master master@172.17.10.237:40088
> I1120 14:23:00.557900 29830 sched.cpp:327] Using default CRAM-MD5 authenticatee
> I1120 14:23:00.558094 29833 slave.cpp:4230] Finished recovery
> I1120 14:23:00.558136 29835 authenticatee.cpp:123] Creating new client SASL connection
> I1120 14:23:00.558425 29831 master.cpp:5156] Authenticating scheduler-6d6242c6-d043-47f4-b677-a3ca7dd7beb2@172.17.10.237:40088
> I1120 14:23:00.558540 29833 slave.cpp:4387] Querying resource estimator for oversubscribable resources
> I1120 14:23:00.558542 29828 authenticator.cpp:415] Starting authentication session for crammd5_authenticatee(57)@172.17.10.237:40088
> I1120 14:23:00.558759 29833 authenticator.cpp:100] Creating new server SASL connection
> I1120 14:23:00.558790 29830 status_update_manager.cpp:176] Pausing sending status updates
> I1120 14:23:00.558800 29834 slave.cpp:729] New master detected at master@172.17.10.237:40088
> I1120 14:23:00.558868 29834 slave.cpp:792] Authenticating with master master@172.17.10.237:40088
> I1120 14:23:00.558890 29834 slave.cpp:797] Using default CRAM-MD5 authenticatee
> I1120 14:23:00.558967 29842 authenticatee.cpp:214] Received SASL authentication mechanisms: CRAM-MD5
> I1120 14:23:00.559002 29842 authenticatee.cpp:240] Attempting to authenticate with mechanism 'CRAM-MD5'
> I1120 14:23:00.559113 29842 authenticator.cpp:205] Received SASL authentication start
> I1120 14:23:00.559131 29836 authenticatee.cpp:123] Creating new client SASL connection
> I1120 14:23:00.559203 29842 authenticator.cpp:327] Authentication requires more steps
> I1120 14:23:00.559296 29842 authenticatee.cpp:260] Received SASL authentication step
> I1120 14:23:00.559363 29834 slave.cpp:765] Detecting new master
> I1120 14:23:00.559437 29839 authenticator.cpp:233] Received SASL authentication step
> I1120 14:23:00.559448 29833 master.cpp:5156] Authenticating slave(15)@172.17.10.237:40088
> I1120 14:23:00.559478 29839 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '8b126df598c7' server FQDN: '8b126df598c7' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I1120 14:23:00.559483 29834 slave.cpp:4401] Received oversubscribable resources from the resource estimator
> I1120 14:23:00.559497 29839 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
> I1120 14:23:00.559553 29839 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I1120 14:23:00.559593 29839 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '8b126df598c7' server FQDN: '8b126df598c7' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I1120 14:23:00.559612 29839 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I1120 14:23:00.559623 29839 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I1120 14:23:00.559631 29833 authenticator.cpp:415] Starting authentication session for crammd5_authenticatee(58)@172.17.10.237:40088
> I1120 14:23:00.559645 29839 authenticator.cpp:319] Authentication success
> I1120 14:23:00.559837 29842 master.cpp:5186] Successfully authenticated principal 'test-principal' at scheduler-6d6242c6-d043-47f4-b677-a3ca7dd7beb2@172.17.10.237:40088
> I1120 14:23:00.559869 29833 authenticator.cpp:433] Authentication session cleanup for crammd5_authenticatee(57)@172.17.10.237:40088
> I1120 14:23:00.559895 29835 authenticator.cpp:100] Creating new server SASL connection
> I1120 14:23:00.559948 29837 authenticatee.cpp:300] Authentication success
> I1120 14:23:00.560255 29833 authenticatee.cpp:214] Received SASL authentication mechanisms: CRAM-MD5
> I1120 14:23:00.560281 29833 authenticatee.cpp:240] Attempting to authenticate with mechanism 'CRAM-MD5'
> I1120 14:23:00.560405 29834 authenticator.cpp:205] Received SASL authentication start
> I1120 14:23:00.560443 29831 sched.cpp:409] Successfully authenticated with master master@172.17.10.237:40088
> I1120 14:23:00.560461 29831 sched.cpp:716] Sending SUBSCRIBE call to master@172.17.10.237:40088
> I1120 14:23:00.560479 29834 authenticator.cpp:327] Authentication requires more steps
> I1120 14:23:00.560540 29831 sched.cpp:749] Will retry registration in 689.900282ms if necessary
> I1120 14:23:00.560587 29834 authenticatee.cpp:260] Received SASL authentication step
> I1120 14:23:00.560686 29831 authenticator.cpp:233] Received SASL authentication step
> I1120 14:23:00.560703 29829 master.cpp:2182] Received SUBSCRIBE call for framework 'default' at scheduler-6d6242c6-d043-47f4-b677-a3ca7dd7beb2@172.17.10.237:40088
> I1120 14:23:00.560793 29831 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '8b126df598c7' server FQDN: '8b126df598c7' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I1120 14:23:00.560808 29831 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
> I1120 14:23:00.560832 29829 master.cpp:1651] Authorizing framework principal 'test-principal' to receive offers for role '*'
> I1120 14:23:00.560839 29831 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I1120 14:23:00.560865 29831 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '8b126df598c7' server FQDN: '8b126df598c7' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I1120 14:23:00.560878 29831 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I1120 14:23:00.560888 29831 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I1120 14:23:00.560905 29831 authenticator.cpp:319] Authentication success
> I1120 14:23:00.560997 29828 authenticatee.cpp:300] Authentication success
> I1120 14:23:00.561012 29829 master.cpp:5186] Successfully authenticated principal 'test-principal' at slave(15)@172.17.10.237:40088
> I1120 14:23:00.561079 29831 authenticator.cpp:433] Authentication session cleanup for crammd5_authenticatee(58)@172.17.10.237:40088
> I1120 14:23:00.561125 29829 master.cpp:2253] Subscribing framework default with checkpointing enabled and capabilities [ ]
> I1120 14:23:00.561327 29828 slave.cpp:860] Successfully authenticated with master master@172.17.10.237:40088
> I1120 14:23:00.561463 29828 slave.cpp:1254] Will retry registration in 79918ns if necessary
> I1120 14:23:00.561574 29839 hierarchical.cpp:197] Added framework 1c180fae-4467-4812-9068-e694cb1c9940-0000
> I1120 14:23:00.561635 29839 hierarchical.cpp:979] No resources available to allocate!
> I1120 14:23:00.561674 29839 hierarchical.cpp:1072] No inverse offers to send out!
> I1120 14:23:00.561691 29833 sched.cpp:643] Framework registered with 1c180fae-4467-4812-9068-e694cb1c9940-0000
> I1120 14:23:00.561700 29839 hierarchical.cpp:878] Performed allocation for 0 slaves in 102623ns
> I1120 14:23:00.561728 29833 sched.cpp:657] Scheduler::registered took 17015ns
> I1120 14:23:00.561784 29829 master.cpp:3865] Registering slave at slave(15)@172.17.10.237:40088 (8b126df598c7) with id 1c180fae-4467-4812-9068-e694cb1c9940-S0
> I1120 14:23:00.562244 29843 registrar.cpp:441] Applied 1 operations in 58872ns; attempting to update the 'registry'
> I1120 14:23:00.562871 29830 slave.cpp:1254] Will retry registration in 21.508543ms if necessary
> I1120 14:23:00.562975 29840 log.cpp:685] Attempting to append 347 bytes to the log
> I1120 14:23:00.562986 29836 master.cpp:3853] Ignoring register slave message from slave(15)@172.17.10.237:40088 (8b126df598c7) as admission is already in progress
> I1120 14:23:00.563155 29833 coordinator.cpp:350] Coordinator attempting to write APPEND action at position 3
> I1120 14:23:00.563832 29833 replica.cpp:540] Replica received write request for position 3 from (574)@172.17.10.237:40088
> I1120 14:23:00.564071 29833 leveldb.cpp:343] Persisting action (366 bytes) to leveldb took 200681ns
> I1120 14:23:00.564095 29833 replica.cpp:715] Persisted action at 3
> I1120 14:23:00.564698 29843 replica.cpp:694] Replica received learned notice for position 3 from @0.0.0.0:0
> I1120 14:23:00.565131 29843 leveldb.cpp:343] Persisting action (368 bytes) to leveldb took 403511ns
> I1120 14:23:00.565153 29843 replica.cpp:715] Persisted action at 3
> I1120 14:23:00.565171 29843 replica.cpp:700] Replica learned APPEND action at position 3
> I1120 14:23:00.566464 29843 registrar.cpp:486] Successfully updated the 'registry' in 4.146944ms
> I1120 14:23:00.566681 29842 log.cpp:704] Attempting to truncate the log to 3
> I1120 14:23:00.566803 29839 coordinator.cpp:350] Coordinator attempting to write TRUNCATE action at position 4
> I1120 14:23:00.567150 29838 slave.cpp:3169] Received ping from slave-observer(14)@172.17.10.237:40088
> I1120 14:23:00.567309 29830 master.cpp:3933] Registered slave 1c180fae-4467-4812-9068-e694cb1c9940-S0 at slave(15)@172.17.10.237:40088 (8b126df598c7) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I1120 14:23:00.567924 29838 slave.cpp:904] Registered with master master@172.17.10.237:40088; given slave ID 1c180fae-4467-4812-9068-e694cb1c9940-S0
> I1120 14:23:00.567966 29838 fetcher.cpp:79] Clearing fetcher cache
> I1120 14:23:00.568330 29843 hierarchical.cpp:346] Added slave 1c180fae-4467-4812-9068-e694cb1c9940-S0 (8b126df598c7) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
> I1120 14:23:00.569124 29828 status_update_manager.cpp:183] Resuming sending status updates
> I1120 14:23:00.569195 29828 replica.cpp:540] Replica received write request for position 4 from (575)@172.17.10.237:40088
> I1120 14:23:00.569314 29843 hierarchical.cpp:1072] No inverse offers to send out!
> I1120 14:23:00.569357 29843 hierarchical.cpp:894] Performed allocation for slave 1c180fae-4467-4812-9068-e694cb1c9940-S0 in 977691ns
> I1120 14:23:00.569555 29838 slave.cpp:927] Checkpointing SlaveInfo to '/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm/meta/slaves/1c180fae-4467-4812-9068-e694cb1c9940-S0/slave.info'
> I1120 14:23:00.570016 29843 master.cpp:4985] Sending 1 offers to framework 1c180fae-4467-4812-9068-e694cb1c9940-0000 (default) at scheduler-6d6242c6-d043-47f4-b677-a3ca7dd7beb2@172.17.10.237:40088
> I1120 14:23:00.570436 29828 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 1.204214ms
> I1120 14:23:00.570466 29828 replica.cpp:715] Persisted action at 4
> I1120 14:23:00.570574 29843 sched.cpp:813] Scheduler::resourceOffers took 149218ns
> I1120 14:23:00.570871 29838 slave.cpp:963] Forwarding total oversubscribed resources
> I1120 14:23:00.571166 29838 master.cpp:4275] Received update of slave 1c180fae-4467-4812-9068-e694cb1c9940-S0 at slave(15)@172.17.10.237:40088 (8b126df598c7) with total oversubscribed resources
> I1120 14:23:00.571437 29838 hierarchical.cpp:402] Slave 1c180fae-4467-4812-9068-e694cb1c9940-S0 (8b126df598c7) updated with oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000])
> I1120 14:23:00.571689 29828 replica.cpp:694] Replica received learned notice for position 4 from @0.0.0.0:0
> I1120 14:23:00.571741 29838 hierarchical.cpp:979] No resources available to allocate!
> I1120 14:23:00.571775 29838 hierarchical.cpp:1072] No inverse offers to send out!
> I1120 14:23:00.571789 29838 hierarchical.cpp:894] Performed allocation for slave 1c180fae-4467-4812-9068-e694cb1c9940-S0 in 319667ns
> I1120 14:23:00.572039 29809 resources.cpp:474] Parsing resources as JSON failed: cpus:1;mem:128;disk:3
> Trying semicolon-delimited string format instead
> I1120 14:23:00.572206 29828 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 478524ns
> I1120 14:23:00.572283 29828 leveldb.cpp:401] Deleting ~2 keys from leveldb took 48209ns
> I1120 14:23:00.572304 29828 replica.cpp:715] Persisted action at 4
> I1120 14:23:00.572325 29828 replica.cpp:700] Replica learned TRUNCATE action at position 4
> I1120 14:23:00.573488 29840 master.cpp:2921] Processing ACCEPT call for offers: [ 1c180fae-4467-4812-9068-e694cb1c9940-O0 ] on slave 1c180fae-4467-4812-9068-e694cb1c9940-S0 at slave(15)@172.17.10.237:40088 (8b126df598c7) for framework 1c180fae-4467-4812-9068-e694cb1c9940-0000 (default) at scheduler-6d6242c6-d043-47f4-b677-a3ca7dd7beb2@172.17.10.237:40088
> I1120 14:23:00.573539 29840 master.cpp:2717] Authorizing framework principal 'test-principal' to launch task 47beaafe-f181-4d15-ab26-b35ba8296144 as user 'mesos'
> I1120 14:23:00.575311 29834 master.hpp:178] Adding task 47beaafe-f181-4d15-ab26-b35ba8296144 with resources cpus(*):1; mem(*):128; disk(*):3 on slave 1c180fae-4467-4812-9068-e694cb1c9940-S0 (8b126df598c7)
> I1120 14:23:00.575539 29834 master.cpp:3251] Launching task 47beaafe-f181-4d15-ab26-b35ba8296144 of framework 1c180fae-4467-4812-9068-e694cb1c9940-0000 (default) at scheduler-6d6242c6-d043-47f4-b677-a3ca7dd7beb2@172.17.10.237:40088 with resources cpus(*):1; mem(*):128; disk(*):3 on slave 1c180fae-4467-4812-9068-e694cb1c9940-S0 at slave(15)@172.17.10.237:40088 (8b126df598c7)
> I1120 14:23:00.575935 29832 slave.cpp:1294] Got assigned task 47beaafe-f181-4d15-ab26-b35ba8296144 for framework 1c180fae-4467-4812-9068-e694cb1c9940-0000
> I1120 14:23:00.576198 29832 slave.cpp:4920] Checkpointing FrameworkInfo to '/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm/meta/slaves/1c180fae-4467-4812-9068-e694cb1c9940-S0/frameworks/1c180fae-4467-4812-9068-e694cb1c9940-0000/framework.info'
> I1120 14:23:00.576717 29832 slave.cpp:4931] Checkpointing framework pid 'scheduler-6d6242c6-d043-47f4-b677-a3ca7dd7beb2@172.17.10.237:40088' to '/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm/meta/slaves/1c180fae-4467-4812-9068-e694cb1c9940-S0/frameworks/1c180fae-4467-4812-9068-e694cb1c9940-0000/framework.pid'
> I1120 14:23:00.577040 29834 hierarchical.cpp:746] Recovered cpus(*):1; mem(*):896; disk(*):1021; ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):1; mem(*):128; disk(*):3) on slave 1c180fae-4467-4812-9068-e694cb1c9940-S0 from framework 1c180fae-4467-4812-9068-e694cb1c9940-0000
> I1120 14:23:00.577139 29834 hierarchical.cpp:783] Framework 1c180fae-4467-4812-9068-e694cb1c9940-0000 filtered slave 1c180fae-4467-4812-9068-e694cb1c9940-S0 for 5secs
> I1120 14:23:00.577150 29832 resources.cpp:474] Parsing resources as JSON failed: cpus:0.1;mem:32
> Trying semicolon-delimited string format instead
> I1120 14:23:00.577736 29832 slave.cpp:1410] Launching task 47beaafe-f181-4d15-ab26-b35ba8296144 for framework 1c180fae-4467-4812-9068-e694cb1c9940-0000
> I1120 14:23:00.577821 29832 resources.cpp:474] Parsing resources as JSON failed: cpus:0.1;mem:32
> Trying semicolon-delimited string format instead
> I1120 14:23:00.578716 29832 paths.cpp:436] Trying to chown '/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm/slaves/1c180fae-4467-4812-9068-e694cb1c9940-S0/frameworks/1c180fae-4467-4812-9068-e694cb1c9940-0000/executors/47beaafe-f181-4d15-ab26-b35ba8296144/runs/a1cdc1eb-668a-4671-bfee-c78a4b026026' to user 'mesos'
> I1120 14:23:00.583127 29832 slave.cpp:5360] Checkpointing ExecutorInfo to '/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm/meta/slaves/1c180fae-4467-4812-9068-e694cb1c9940-S0/frameworks/1c180fae-4467-4812-9068-e694cb1c9940-0000/executors/47beaafe-f181-4d15-ab26-b35ba8296144/executor.info'
> I1120 14:23:00.583926 29832 slave.cpp:4999] Launching executor 47beaafe-f181-4d15-ab26-b35ba8296144 of framework 1c180fae-4467-4812-9068-e694cb1c9940-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm/slaves/1c180fae-4467-4812-9068-e694cb1c9940-S0/frameworks/1c180fae-4467-4812-9068-e694cb1c9940-0000/executors/47beaafe-f181-4d15-ab26-b35ba8296144/runs/a1cdc1eb-668a-4671-bfee-c78a4b026026'
> I1120 14:23:00.584372 29841 containerizer.cpp:619] Starting container 'a1cdc1eb-668a-4671-bfee-c78a4b026026' for executor '47beaafe-f181-4d15-ab26-b35ba8296144' of framework '1c180fae-4467-4812-9068-e694cb1c9940-0000'
> I1120 14:23:00.584478 29832 slave.cpp:5383] Checkpointing TaskInfo to '/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm/meta/slaves/1c180fae-4467-4812-9068-e694cb1c9940-S0/frameworks/1c180fae-4467-4812-9068-e694cb1c9940-0000/executors/47beaafe-f181-4d15-ab26-b35ba8296144/runs/a1cdc1eb-668a-4671-bfee-c78a4b026026/tasks/47beaafe-f181-4d15-ab26-b35ba8296144/task.info'
> I1120 14:23:00.585016 29832 slave.cpp:1628] Queuing task '47beaafe-f181-4d15-ab26-b35ba8296144' for executor '47beaafe-f181-4d15-ab26-b35ba8296144' of framework 1c180fae-4467-4812-9068-e694cb1c9940-0000
> I1120 14:23:00.585150 29832 slave.cpp:682] Successfully attached file '/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm/slaves/1c180fae-4467-4812-9068-e694cb1c9940-S0/frameworks/1c180fae-4467-4812-9068-e694cb1c9940-0000/executors/47beaafe-f181-4d15-ab26-b35ba8296144/runs/a1cdc1eb-668a-4671-bfee-c78a4b026026'
> I1120 14:23:00.589161 29839 launcher.cpp:134] Forked child with pid '30023' for container 'a1cdc1eb-668a-4671-bfee-c78a4b026026'
> I1120 14:23:00.589488 29839 containerizer.cpp:852] Checkpointing executor's forked pid 30023 to '/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm/meta/slaves/1c180fae-4467-4812-9068-e694cb1c9940-S0/frameworks/1c180fae-4467-4812-9068-e694cb1c9940-0000/executors/47beaafe-f181-4d15-ab26-b35ba8296144/runs/a1cdc1eb-668a-4671-bfee-c78a4b026026/pids/forked.pid'
> WARNING: Logging before InitGoogleLogging() is written to STDERR
> I1120 14:23:00.738919 30037 process.cpp:961] libprocess is initialized on 172.17.10.237:34984 for 16 cpus
> I1120 14:23:00.739723 30037 logging.cpp:177] Logging to STDERR
> I1120 14:23:00.741880 30037 exec.cpp:136] Version: 0.26.0
> I1120 14:23:00.748992 30051 exec.cpp:186] Executor started at: executor(1)@172.17.10.237:34984 with pid 30037
> I1120 14:23:00.751570 29839 slave.cpp:2405] Got registration for executor '47beaafe-f181-4d15-ab26-b35ba8296144' of framework 1c180fae-4467-4812-9068-e694cb1c9940-0000 from executor(1)@172.17.10.237:34984
> I1120 14:23:00.751797 29839 slave.cpp:2490] Checkpointing executor pid 'executor(1)@172.17.10.237:34984' to '/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm/meta/slaves/1c180fae-4467-4812-9068-e694cb1c9940-S0/frameworks/1c180fae-4467-4812-9068-e694cb1c9940-0000/executors/47beaafe-f181-4d15-ab26-b35ba8296144/runs/a1cdc1eb-668a-4671-bfee-c78a4b026026/pids/libprocess.pid'
> I1120 14:23:00.753489 29836 disk.cpp:154] Updating the disk resources for container a1cdc1eb-668a-4671-bfee-c78a4b026026 to cpus(*):1.1; mem(*):160; disk(*):3
> I1120 14:23:00.754307 30058 exec.cpp:210] Executor registered on slave 1c180fae-4467-4812-9068-e694cb1c9940-S0
> I1120 14:23:00.754490 29835 slave.cpp:1793] Sending queued task '47beaafe-f181-4d15-ab26-b35ba8296144' to executor '47beaafe-f181-4d15-ab26-b35ba8296144' of framework 1c180fae-4467-4812-9068-e694cb1c9940-0000 at executor(1)@172.17.10.237:34984
> I1120 14:23:00.756805 30058 exec.cpp:222] Executor::registered took 303359ns
> Registered executor on 8b126df598c7
> I1120 14:23:00.758246 30062 exec.cpp:297] Executor asked to run task '47beaafe-f181-4d15-ab26-b35ba8296144'
> I1120 14:23:00.758358 30062 exec.cpp:306] Executor::launchTask took 80134ns
> Starting task 47beaafe-f181-4d15-ab26-b35ba8296144
> Forked command at 30069
> sh -c 'dd if=/dev/zero of=file bs=1048576 count=2 && sleep 1000'
> I1120 14:23:00.762169 30063 exec.cpp:519] Executor sending status update TASK_RUNNING (UUID: 5c27277f-1e83-4459-aa6b-e5d5ed413346) for task 47beaafe-f181-4d15-ab26-b35ba8296144 of framework 1c180fae-4467-4812-9068-e694cb1c9940-0000
> I1120 14:23:00.763514 29833 slave.cpp:2762] Handling status update TASK_RUNNING (UUID: 5c27277f-1e83-4459-aa6b-e5d5ed413346) for task 47beaafe-f181-4d15-ab26-b35ba8296144 of framework 1c180fae-4467-4812-9068-e694cb1c9940-0000 from executor(1)@172.17.10.237:34984
> 2+0 records in
> 2+0 records out
> 2097152 bytes (2.1 MB) copied, 0.00252731 s, 830 MB/s
> I1120 14:23:00.764075 29843 status_update_manager.cpp:322] Received status update TASK_RUNNING (UUID: 5c27277f-1e83-4459-aa6b-e5d5ed413346) for task 47beaafe-f181-4d15-ab26-b35ba8296144 of framework 1c180fae-4467-4812-9068-e694cb1c9940-0000
> I1120 14:23:00.764118 29843 status_update_manager.cpp:499] Creating StatusUpdate stream for task 47beaafe-f181-4d15-ab26-b35ba8296144 of framework 1c180fae-4467-4812-9068-e694cb1c9940-0000
> I1120 14:23:00.764850 29843 status_update_manager.cpp:826] Checkpointing UPDATE for status update TASK_RUNNING (UUID: 5c27277f-1e83-4459-aa6b-e5d5ed413346) for task 47beaafe-f181-4d15-ab26-b35ba8296144 of framework 1c180fae-4467-4812-9068-e694cb1c9940-0000
> I1120 14:23:00.766163 29843 status_update_manager.cpp:376] Forwarding update TASK_RUNNING (UUID: 5c27277f-1e83-4459-aa6b-e5d5ed413346) for task 47beaafe-f181-4d15-ab26-b35ba8296144 of framework 1c180fae-4467-4812-9068-e694cb1c9940-0000 to the slave
> I1120 14:23:00.766497 29842 slave.cpp:3087] Forwarding the update TASK_RUNNING (UUID: 5c27277f-1e83-4459-aa6b-e5d5ed413346) for task 47beaafe-f181-4d15-ab26-b35ba8296144 of framework 1c180fae-4467-4812-9068-e694cb1c9940-0000 to master@172.17.10.237:40088
> I1120 14:23:00.766685 29842 slave.cpp:3005] Status update manager successfully handled status update TASK_RUNNING (UUID: 5c27277f-1e83-4459-aa6b-e5d5ed413346) for task 47beaafe-f181-4d15-ab26-b35ba8296144 of framework 1c180fae-4467-4812-9068-e694cb1c9940-0000
> I1120 14:23:00.766789 29842 slave.cpp:3011] Sending acknowledgement for status update TASK_RUNNING (UUID: 5c27277f-1e83-4459-aa6b-e5d5ed413346) for task 47beaafe-f181-4d15-ab26-b35ba8296144 of framework 1c180fae-4467-4812-9068-e694cb1c9940-0000 to executor(1)@172.17.10.237:34984
> I1120 14:23:00.766885 29836 master.cpp:4420] Status update TASK_RUNNING (UUID: 5c27277f-1e83-4459-aa6b-e5d5ed413346) for task 47beaafe-f181-4d15-ab26-b35ba8296144 of framework 1c180fae-4467-4812-9068-e694cb1c9940-0000 from slave 1c180fae-4467-4812-9068-e694cb1c9940-S0 at slave(15)@172.17.10.237:40088 (8b126df598c7)
> I1120 14:23:00.766930 29836 master.cpp:4468] Forwarding status update TASK_RUNNING (UUID: 5c27277f-1e83-4459-aa6b-e5d5ed413346) for task 47beaafe-f181-4d15-ab26-b35ba8296144 of framework 1c180fae-4467-4812-9068-e694cb1c9940-0000
> I1120 14:23:00.767144 29836 master.cpp:6072] Updating the state of task 47beaafe-f181-4d15-ab26-b35ba8296144 of framework 1c180fae-4467-4812-9068-e694cb1c9940-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
> I1120 14:23:00.767479 29834 sched.cpp:921] Scheduler::statusUpdate took 186955ns
> I1120 14:23:00.767841 29841 master.cpp:3577] Processing ACKNOWLEDGE call 5c27277f-1e83-4459-aa6b-e5d5ed413346 for task 47beaafe-f181-4d15-ab26-b35ba8296144 of framework 1c180fae-4467-4812-9068-e694cb1c9940-0000 (default) at scheduler-6d6242c6-d043-47f4-b677-a3ca7dd7beb2@172.17.10.237:40088 on slave 1c180fae-4467-4812-9068-e694cb1c9940-S0
> I1120 14:23:00.768232 29828 status_update_manager.cpp:394] Received status update acknowledgement (UUID: 5c27277f-1e83-4459-aa6b-e5d5ed413346) for task 47beaafe-f181-4d15-ab26-b35ba8296144 of framework 1c180fae-4467-4812-9068-e694cb1c9940-0000
> I1120 14:23:00.768232 30064 exec.cpp:343] Executor received status update acknowledgement 5c27277f-1e83-4459-aa6b-e5d5ed413346 for task 47beaafe-f181-4d15-ab26-b35ba8296144 of framework 1c180fae-4467-4812-9068-e694cb1c9940-0000
> I1120 14:23:00.768399 29828 status_update_manager.cpp:826] Checkpointing ACK for status update TASK_RUNNING (UUID: 5c27277f-1e83-4459-aa6b-e5d5ed413346) for task 47beaafe-f181-4d15-ab26-b35ba8296144 of framework 1c180fae-4467-4812-9068-e694cb1c9940-0000
> I1120 14:23:00.768795 29836 slave.cpp:601] Slave terminating
> I1120 14:23:00.769071 29834 master.cpp:1089] Slave 1c180fae-4467-4812-9068-e694cb1c9940-S0 at slave(15)@172.17.10.237:40088 (8b126df598c7) disconnected
> I1120 14:23:00.769114 29834 master.cpp:2537] Disconnecting slave 1c180fae-4467-4812-9068-e694cb1c9940-S0 at slave(15)@172.17.10.237:40088 (8b126df598c7)
> I1120 14:23:00.769186 29834 master.cpp:2556] Deactivating slave 1c180fae-4467-4812-9068-e694cb1c9940-S0 at slave(15)@172.17.10.237:40088 (8b126df598c7)
> I1120 14:23:00.769331 29839 hierarchical.cpp:431] Slave 1c180fae-4467-4812-9068-e694cb1c9940-S0 deactivated
> I1120 14:23:00.776927 29809 containerizer.cpp:143] Using isolation: posix/cpu,posix/mem,posix/disk,filesystem/posix
> W1120 14:23:00.777317 29809 backend.cpp:50] Failed to create 'bind' backend: BindBackend requires root privileges
> I1120 14:23:00.781699 29835 slave.cpp:191] Slave started on 16)@172.17.10.237:40088
> I1120 14:23:00.781730 29835 slave.cpp:192] Flags at startup: --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" --cgroups_cpu_enable_pids_and_tids_count="false" --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_7QsJEm/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_auth_server="auth.docker.io" --docker_auth_server_port="443" --docker_kill_orphans="true" --docker_local_archives_dir="/tmp/mesos/images/docker" --docker_puller="local" --docker_puller_timeout="60" --docker_registry="registry-1.docker.io" --docker_registry_port="443" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem,posix/disk" --launcher_dir="/mesos/mesos-0.26.0/_build/src" --logbufsecs="0" --logging_level="INFO" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:2;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm"
> I1120 14:23:00.782304 29835 credentials.hpp:85] Loading credential for authentication from '/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm/credential'
> I1120 14:23:00.782572 29835 slave.cpp:322] Slave using credential for: test-principal
> I1120 14:23:00.782752 29835 resources.cpp:474] Parsing resources as JSON failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000]
> Trying semicolon-delimited string format instead
> I1120 14:23:00.783296 29835 slave.cpp:392] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I1120 14:23:00.783377 29835 slave.cpp:400] Slave attributes: [ ]
> I1120 14:23:00.783392 29835 slave.cpp:405] Slave hostname: 8b126df598c7
> I1120 14:23:00.783403 29835 slave.cpp:410] Slave checkpoint: true
> I1120 14:23:00.784399 29831 state.cpp:54] Recovering state from '/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm/meta'
> I1120 14:23:00.784526 29831 state.cpp:681] No checkpointed resources found at '/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm/meta/resources/resources.info'
> I1120 14:23:00.789577 29842 fetcher.cpp:79] Clearing fetcher cache
> I1120 14:23:00.789696 29842 slave.cpp:4318] Recovering framework 1c180fae-4467-4812-9068-e694cb1c9940-0000
> I1120 14:23:00.789835 29842 slave.cpp:5108] Recovering executor '47beaafe-f181-4d15-ab26-b35ba8296144' of framework 1c180fae-4467-4812-9068-e694cb1c9940-0000
> I1120 14:23:00.791198 29831 status_update_manager.cpp:202] Recovering status update manager
> I1120 14:23:00.791378 29831 status_update_manager.cpp:210] Recovering executor '47beaafe-f181-4d15-ab26-b35ba8296144' of framework 1c180fae-4467-4812-9068-e694cb1c9940-0000
> I1120 14:23:00.791455 29831 status_update_manager.cpp:499] Creating StatusUpdate stream for task 47beaafe-f181-4d15-ab26-b35ba8296144 of framework 1c180fae-4467-4812-9068-e694cb1c9940-0000
> I1120 14:23:00.791661 29842 slave.cpp:682] Successfully attached file '/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm/slaves/1c180fae-4467-4812-9068-e694cb1c9940-S0/frameworks/1c180fae-4467-4812-9068-e694cb1c9940-0000/executors/47beaafe-f181-4d15-ab26-b35ba8296144/runs/a1cdc1eb-668a-4671-bfee-c78a4b026026'
> I1120 14:23:00.791911 29831 status_update_manager.cpp:802] Replaying status update stream for task 47beaafe-f181-4d15-ab26-b35ba8296144
> I1120 14:23:00.792646 29838 containerizer.cpp:385] Recovering containerizer
> I1120 14:23:00.792763 29838 containerizer.cpp:440] Recovering container 'a1cdc1eb-668a-4671-bfee-c78a4b026026' for executor '47beaafe-f181-4d15-ab26-b35ba8296144' of framework 1c180fae-4467-4812-9068-e694cb1c9940-0000
> I1120 14:23:00.794885 29843 slave.cpp:4170] Sending reconnect request to executor '47beaafe-f181-4d15-ab26-b35ba8296144' of framework 1c180fae-4467-4812-9068-e694cb1c9940-0000 at executor(1)@172.17.10.237:34984
> I1120 14:23:00.796262 30063 exec.cpp:256] Received reconnect request from slave 1c180fae-4467-4812-9068-e694cb1c9940-S0
> I1120 14:23:00.797771 29830 slave.cpp:2553] Re-registering executor '47beaafe-f181-4d15-ab26-b35ba8296144' of framework 1c180fae-4467-4812-9068-e694cb1c9940-0000
> I1120 14:23:00.798692 29839 disk.cpp:154] Updating the disk resources for container a1cdc1eb-668a-4671-bfee-c78a4b026026 to cpus(*):1.1; mem(*):160; disk(*):3
> I1120 14:23:00.798894 30056 exec.cpp:233] Executor re-registered on slave 1c180fae-4467-4812-9068-e694cb1c9940-S0
> I1120 14:23:00.800634 30056 exec.cpp:245] Executor::reregistered took 93607ns
> Re-registered executor on 8b126df598c7
> I1120 14:23:00.819314 29837 hierarchical.cpp:979] No resources available to allocate!
> I1120 14:23:00.819424 29837 hierarchical.cpp:1072] No inverse offers to send out!
> I1120 14:23:00.819461 29837 hierarchical.cpp:878] Performed allocation for 1 slaves in 288853ns
> I1120 14:23:00.819629 29842 slave.cpp:2702] Cleaning up un-reregistered executors
> I1120 14:23:00.819764 29842 slave.cpp:4230] Finished recovery
> I1120 14:23:00.820565 29842 slave.cpp:4387] Querying resource estimator for oversubscribable resources
> I1120 14:23:00.821192 29839 slave.cpp:729] New master detected at master@172.17.10.237:40088
> I1120 14:23:00.821283 29839 slave.cpp:792] Authenticating with master master@172.17.10.237:40088
> I1120 14:23:00.821306 29839 slave.cpp:797] Using default CRAM-MD5 authenticatee
> I1120 14:23:00.821481 29839 slave.cpp:765] Detecting new master
> I1120 14:23:00.821513 29838 status_update_manager.cpp:176] Pausing sending status updates
> I1120 14:23:00.821611 29839 slave.cpp:4401] Received oversubscribable resources from the resource estimator
> I1120 14:23:00.821673 29838 authenticatee.cpp:123] Creating new client SASL connection
> I1120 14:23:00.822047 29835 master.cpp:5156] Authenticating slave(16)@172.17.10.237:40088
> I1120 14:23:00.822258 29838 authenticator.cpp:415] Starting authentication session for crammd5_authenticatee(59)@172.17.10.237:40088
> I1120 14:23:00.822670 29838 authenticator.cpp:100] Creating new server SASL connection
> I1120 14:23:00.823243 29838 authenticatee.cpp:214] Received SASL authentication mechanisms: CRAM-MD5
> I1120 14:23:00.823315 29838 authenticatee.cpp:240] Attempting to authenticate with mechanism 'CRAM-MD5'
> I1120 14:23:00.823498 29838 authenticator.cpp:205] Received SASL authentication start
> I1120 14:23:00.823575 29838 authenticator.cpp:327] Authentication requires more steps
> I1120 14:23:00.823665 29838 authenticatee.cpp:260] Received SASL authentication step
> I1120 14:23:00.823760 29838 authenticator.cpp:233] Received SASL authentication step
> I1120 14:23:00.823802 29838 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '8b126df598c7' server FQDN: '8b126df598c7' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I1120 14:23:00.823817 29838 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
> I1120 14:23:00.823868 29838 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I1120 14:23:00.823894 29838 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '8b126df598c7' server FQDN: '8b126df598c7' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I1120 14:23:00.823904 29838 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I1120 14:23:00.823923 29838 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I1120 14:23:00.823951 29838 authenticator.cpp:319] Authentication success
> I1120 14:23:00.824367 29838 authenticatee.cpp:300] Authentication success
> I1120 14:23:00.824472 29838 authenticator.cpp:433] Authentication session cleanup for crammd5_authenticatee(59)@172.17.10.237:40088
> I1120 14:23:00.824760 29837 slave.cpp:860] Successfully authenticated with master master@172.17.10.237:40088
> I1120 14:23:00.825790 29837 slave.cpp:1254] Will retry registration in 15.206262ms if necessary
> I1120 14:23:00.826516 29835 master.cpp:3951] Queuing up re-registration request from slave(16)@172.17.10.237:40088 because authentication is still in progress
> I1120 14:23:00.827886 29835 master.cpp:5186] Successfully authenticated principal 'test-principal' at slave(16)@172.17.10.237:40088
> I1120 14:23:00.828341 29835 master.cpp:4025] Re-registering slave 1c180fae-4467-4812-9068-e694cb1c9940-S0 at slave(15)@172.17.10.237:40088 (8b126df598c7)
> I1120 14:23:00.828994 29835 master.cpp:4213] Sending updated checkpointed resources to slave 1c180fae-4467-4812-9068-e694cb1c9940-S0 at slave(16)@172.17.10.237:40088 (8b126df598c7)
> I1120 14:23:00.829118 29829 hierarchical.cpp:419] Slave 1c180fae-4467-4812-9068-e694cb1c9940-S0 reactivated
> I1120 14:23:00.829162 29834 slave.cpp:1004] Re-registered with master master@172.17.10.237:40088
> I1120 14:23:00.829407 29834 slave.cpp:1040] Forwarding total oversubscribed resources
> I1120 14:23:00.829641 29834 slave.cpp:2178] Updating framework 1c180fae-4467-4812-9068-e694cb1c9940-0000 pid to scheduler-6d6242c6-d043-47f4-b677-a3ca7dd7beb2@172.17.10.237:40088
> I1120 14:23:00.829697 29834 slave.cpp:2194] Checkpointing framework pid 'scheduler-6d6242c6-d043-47f4-b677-a3ca7dd7beb2@172.17.10.237:40088' to '/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm/meta/slaves/1c180fae-4467-4812-9068-e694cb1c9940-S0/frameworks/1c180fae-4467-4812-9068-e694cb1c9940-0000/framework.pid'
> I1120 14:23:00.830552 29834 slave.cpp:2274] Updated checkpointed resources from to
> I1120 14:23:00.830605 29834 status_update_manager.cpp:183] Resuming sending status updates
> I1120 14:23:00.830662 29834 status_update_manager.cpp:183] Resuming sending status updates
> I1120 14:23:00.831312 29838 master.cpp:4275] Received update of slave 1c180fae-4467-4812-9068-e694cb1c9940-S0 at slave(16)@172.17.10.237:40088 (8b126df598c7) with total oversubscribed resources
> I1120 14:23:00.832479 29839 hierarchical.cpp:402] Slave 1c180fae-4467-4812-9068-e694cb1c9940-S0 (8b126df598c7) updated with oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):1; mem(*):128; disk(*):3)
> I1120 14:23:00.833010 29839 hierarchical.cpp:1164] Filtered offer with cpus(*):1; mem(*):896; disk(*):1021; ports(*):[31000-32000] on slave 1c180fae-4467-4812-9068-e694cb1c9940-S0 for framework 1c180fae-4467-4812-9068-e694cb1c9940-0000
> I1120 14:23:00.833075 29839 hierarchical.cpp:979] No resources available to allocate!
> I1120 14:23:00.833114 29839 hierarchical.cpp:1072] No inverse offers to send out!
> I1120 14:23:00.833137 29839 hierarchical.cpp:894] Performed allocation for slave 1c180fae-4467-4812-9068-e694cb1c9940-S0 in 600049ns
> I1120 14:23:00.936514 29809 sched.cpp:1805] Asked to stop the driver
> I1120 14:23:00.936625 29833 sched.cpp:1043] Stopping framework '1c180fae-4467-4812-9068-e694cb1c9940-0000'
> I1120 14:23:00.936650 29842 master.cpp:928] Master terminating
> W1120 14:23:00.937158 29842 master.cpp:6124] Removing task 47beaafe-f181-4d15-ab26-b35ba8296144 with resources cpus(*):1; mem(*):128; disk(*):3 of framework 1c180fae-4467-4812-9068-e694cb1c9940-0000 on slave 1c180fae-4467-4812-9068-e694cb1c9940-S0 at slave(16)@172.17.10.237:40088 (8b126df598c7) in non-terminal state TASK_RUNNING
> I1120 14:23:00.937296 29835 hierarchical.cpp:375] Removed slave 1c180fae-4467-4812-9068-e694cb1c9940-S0
> I1120 14:23:00.937968 29828 hierarchical.cpp:232] Removed framework 1c180fae-4467-4812-9068-e694cb1c9940-0000
> I1120 14:23:00.938364 29834 slave.cpp:3215] master@172.17.10.237:40088 exited
> W1120 14:23:00.938438 29834 slave.cpp:3218] Master disconnected! Waiting for a new master to be elected
> I1120 14:23:00.942594 29833 containerizer.cpp:1075] Destroying container 'a1cdc1eb-668a-4671-bfee-c78a4b026026'
> I1120 14:23:01.027127 29838 containerizer.cpp:1258] Executor for container 'a1cdc1eb-668a-4671-bfee-c78a4b026026' has exited
> I1120 14:23:01.029253 29833 slave.cpp:3553] Executor '47beaafe-f181-4d15-ab26-b35ba8296144' of framework 1c180fae-4467-4812-9068-e694cb1c9940-0000 terminated with signal Killed
> I1120 14:23:01.029403 29833 slave.cpp:2762] Handling status update TASK_FAILED (UUID: d3f52651-280c-458f-844d-0901dcedc796) for task 47beaafe-f181-4d15-ab26-b35ba8296144 of framework 1c180fae-4467-4812-9068-e694cb1c9940-0000 from @0.0.0.0:0
> I1120 14:23:01.029593 29833 slave.cpp:5298] Terminating task 47beaafe-f181-4d15-ab26-b35ba8296144
> W1120 14:23:01.029963 29831 containerizer.cpp:967] Ignoring update for unknown container: a1cdc1eb-668a-4671-bfee-c78a4b026026
> I1120 14:23:01.030381 29834 status_update_manager.cpp:322] Received status update TASK_FAILED (UUID: d3f52651-280c-458f-844d-0901dcedc796) for task 47beaafe-f181-4d15-ab26-b35ba8296144 of framework 1c180fae-4467-4812-9068-e694cb1c9940-0000
> I1120 14:23:01.030426 29833 slave.cpp:601] Slave terminating
> I1120 14:23:01.030446 29834 status_update_manager.cpp:826] Checkpointing UPDATE for status update TASK_FAILED (UUID: d3f52651-280c-458f-844d-0901dcedc796) for task 47beaafe-f181-4d15-ab26-b35ba8296144 of framework 1c180fae-4467-4812-9068-e694cb1c9940-0000
> I1120 14:23:01.031471 29834 status_update_manager.cpp:376] Forwarding update TASK_FAILED (UUID: d3f52651-280c-458f-844d-0901dcedc796) for task 47beaafe-f181-4d15-ab26-b35ba8296144 of framework 1c180fae-4467-4812-9068-e694cb1c9940-0000 to the slave
> [ OK ] DiskQuotaTest.SlaveRecovery (530 ms)
> {noformat}
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)