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 2017/09/12 18:53:00 UTC
[jira] [Created] (MESOS-7972) SlaveTest.HTTPSchedulerSlaveRestart
test if flaky
Vinod Kone created MESOS-7972:
---------------------------------
Summary: SlaveTest.HTTPSchedulerSlaveRestart test if flaky
Key: MESOS-7972
URL: https://issues.apache.org/jira/browse/MESOS-7972
Project: Mesos
Issue Type: Bug
Components: test
Affects Versions: 1.4.0
Reporter: Vinod Kone
Saw this on ASF CI when testing 1.4.0-rc5
{code}
[ RUN ] SlaveTest.HTTPSchedulerSlaveRestart
I0912 05:40:15.280185 32547 cluster.cpp:162] Creating default 'local' authorizer
I0912 05:40:15.282783 32554 master.cpp:442] Master c23ff8cf-cb2f-40d0-8f18-871a41f128cf (b909d5e22907) started on 172.17.0.2:58922
I0912 05:40:15.282804 32554 master.cpp:444] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate_agents="true" --authenticate_frameworks="true" --authenticate_http_frameworks="true" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/he1E9j/credentials" --filter_gpu_resources="true" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_framework_authenticators="basic" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_agent_ping_timeouts="5" --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --max_unreachable_tasks_per_framework="1000" --port="5050" --quiet="false" --recovery_agent_removal_limit="100%" --registry="in_memory" --registry_fetch_timeout="1mins" --registry_gc_interval="15mins" --registry_max_agent_age="2weeks" --registry_max_agent_count="102400" --registry_store_timeout="100secs" --registry_strict="false" --root_submissions="true" --user_sorter="drf" --version="false" --webui_dir="/usr/local/share/mesos/webui" --work_dir="/tmp/he1E9j/master" --zk_session_timeout="10secs"
I0912 05:40:15.283092 32554 master.cpp:494] Master only allowing authenticated frameworks to register
I0912 05:40:15.283110 32554 master.cpp:508] Master only allowing authenticated agents to register
I0912 05:40:15.283118 32554 master.cpp:521] Master only allowing authenticated HTTP frameworks to register
I0912 05:40:15.283123 32554 credentials.hpp:37] Loading credentials for authentication from '/tmp/he1E9j/credentials'
I0912 05:40:15.283394 32554 master.cpp:566] Using default 'crammd5' authenticator
I0912 05:40:15.283543 32554 http.cpp:1026] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
I0912 05:40:15.283731 32554 http.cpp:1026] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
I0912 05:40:15.283887 32554 http.cpp:1026] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
I0912 05:40:15.284021 32554 master.cpp:646] Authorization enabled
I0912 05:40:15.284293 32552 whitelist_watcher.cpp:77] No whitelist given
I0912 05:40:15.284335 32550 hierarchical.cpp:171] Initialized hierarchical allocator process
I0912 05:40:15.287078 32561 master.cpp:2163] Elected as the leading master!
I0912 05:40:15.287103 32561 master.cpp:1702] Recovering from registrar
I0912 05:40:15.287214 32557 registrar.cpp:347] Recovering registrar
I0912 05:40:15.287703 32557 registrar.cpp:391] Successfully fetched the registry (0B) in 455936ns
I0912 05:40:15.287791 32557 registrar.cpp:495] Applied 1 operations in 24179ns; attempting to update the registry
I0912 05:40:15.288317 32557 registrar.cpp:552] Successfully updated the registry in 473088ns
I0912 05:40:15.288435 32557 registrar.cpp:424] Successfully recovered registrar
I0912 05:40:15.288789 32548 master.cpp:1801] Recovered 0 agents from the registry (129B); allowing 10mins for agents to re-register
I0912 05:40:15.288822 32559 hierarchical.cpp:209] Skipping recovery of hierarchical allocator: nothing to recover
I0912 05:40:15.292457 32547 containerizer.cpp:246] Using isolation: posix/cpu,posix/mem,filesystem/posix,network/cni,environment_secret
W0912 05:40:15.293053 32547 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges
W0912 05:40:15.293184 32547 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
I0912 05:40:15.293220 32547 provisioner.cpp:255] Using default backend 'copy'
W0912 05:40:15.297993 32547 process.cpp:3196] Attempted to spawn already running process files@172.17.0.2:58922
I0912 05:40:15.298338 32547 cluster.cpp:448] Creating default 'local' authorizer
I0912 05:40:15.300554 32551 slave.cpp:250] Mesos agent started on (198)@172.17.0.2:58922
I0912 05:40:15.300576 32551 slave.cpp:251] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/SlaveTest_HTTPSchedulerSlaveRestart_n3xE7x/store/appc" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authenticatee="crammd5" --authentication_backoff_factor="1secs" --authorizer="local" --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="15secs" --containerizers="mesos" --credential="/tmp/SlaveTest_HTTPSchedulerSlaveRestart_n3xE7x/credential" --default_role="*" --disallow_sharing_agent_pid_namespace="false" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/SlaveTest_HTTPSchedulerSlaveRestart_n3xE7x/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_reregistration_timeout="2:
secs" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/SlaveTest_HTTPSchedulerSlaveRestart_n3xE7x/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --http_command_executor="false" --http_credentials="/tmp/SlaveTest_HTTPSchedulerSlaveRestart_n3xE7x/http_credentials" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/mesos/build/src" --logbufsecs="0" --logging_level="INFO" --max_completed_executors_per_framework="150" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --port="5051" --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/SlaveTest_HTTPSchedulerSlaveRestart_n3xE7x" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_enable_support="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/SlaveTest_HTTPSchedulerSlaveRestart_68fE8V"
I0912 05:40:15.301059 32551 credentials.hpp:86] Loading credential for authentication from '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_n3xE7x/credential'
W0912 05:40:15.301174 32547 process.cpp:3196] Attempted to spawn already running process version@172.17.0.2:58922
I0912 05:40:15.301239 32551 slave.cpp:283] Agent using credential for: test-principal
I0912 05:40:15.301256 32551 credentials.hpp:37] Loading credentials for authentication from '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_n3xE7x/http_credentials'
I0912 05:40:15.301512 32551 http.cpp:1026] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
I0912 05:40:15.301681 32551 http.cpp:1026] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite'
I0912 05:40:15.301935 32547 sched.cpp:232] Version: 1.4.0
I0912 05:40:15.302479 32557 sched.cpp:336] New master detected at master@172.17.0.2:58922
I0912 05:40:15.302592 32557 sched.cpp:407] Authenticating with master master@172.17.0.2:58922
I0912 05:40:15.302614 32557 sched.cpp:414] Using default CRAM-MD5 authenticatee
I0912 05:40:15.302922 32553 authenticatee.cpp:121] Creating new client SASL connection
I0912 05:40:15.303220 32562 master.cpp:7832] Authenticating scheduler-228abf3d-36ea-4900-94a1-8b18d253716c@172.17.0.2:58922
I0912 05:40:15.303400 32556 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(406)@172.17.0.2:58922
I0912 05:40:15.303673 32554 authenticator.cpp:98] Creating new server SASL connection
I0912 05:40:15.303473 32551 slave.cpp:565] Agent resources: [{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
I0912 05:40:15.303707 32551 slave.cpp:573] Agent attributes: [ ]
I0912 05:40:15.303717 32551 slave.cpp:582] Agent hostname: b909d5e22907
I0912 05:40:15.303900 32559 status_update_manager.cpp:177] Pausing sending status updates
I0912 05:40:15.304033 32548 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0912 05:40:15.304070 32548 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0912 05:40:15.304189 32548 authenticator.cpp:204] Received SASL authentication start
I0912 05:40:15.304265 32548 authenticator.cpp:326] Authentication requires more steps
I0912 05:40:15.304404 32561 authenticatee.cpp:259] Received SASL authentication step
I0912 05:40:15.304566 32549 authenticator.cpp:232] Received SASL authentication step
I0912 05:40:15.304603 32549 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'b909d5e22907' server FQDN: 'b909d5e22907' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0912 05:40:15.304615 32549 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0912 05:40:15.304647 32549 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0912 05:40:15.304671 32549 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'b909d5e22907' server FQDN: 'b909d5e22907' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0912 05:40:15.304682 32549 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0912 05:40:15.304697 32549 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0912 05:40:15.304715 32549 authenticator.cpp:318] Authentication success
I0912 05:40:15.304852 32563 authenticatee.cpp:299] Authentication success
I0912 05:40:15.304916 32552 master.cpp:7862] Successfully authenticated principal 'test-principal' at scheduler-228abf3d-36ea-4900-94a1-8b18d253716c@172.17.0.2:58922
I0912 05:40:15.305004 32557 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(406)@172.17.0.2:58922
I0912 05:40:15.305253 32549 sched.cpp:513] Successfully authenticated with master master@172.17.0.2:58922
I0912 05:40:15.305269 32549 sched.cpp:836] Sending SUBSCRIBE call to master@172.17.0.2:58922
I0912 05:40:15.305433 32549 sched.cpp:869] Will retry registration in 237.896638ms if necessary
I0912 05:40:15.305629 32555 state.cpp:64] Recovering state from '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_68fE8V/meta'
I0912 05:40:15.305652 32559 master.cpp:2894] Received SUBSCRIBE call for framework 'default' at scheduler-228abf3d-36ea-4900-94a1-8b18d253716c@172.17.0.2:58922
I0912 05:40:15.305742 32559 master.cpp:2228] Authorizing framework principal 'test-principal' to receive offers for roles '{ * }'
I0912 05:40:15.305963 32560 status_update_manager.cpp:203] Recovering status update manager
I0912 05:40:15.306152 32550 containerizer.cpp:609] Recovering containerizer
I0912 05:40:15.306252 32553 master.cpp:2974] Subscribing framework default with checkpointing enabled and capabilities [ RESERVATION_REFINEMENT ]
I0912 05:40:15.306928 32559 sched.cpp:759] Framework registered with c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:15.307013 32559 sched.cpp:773] Scheduler::registered took 58136ns
I0912 05:40:15.307162 32552 hierarchical.cpp:303] Added framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:15.307384 32552 hierarchical.cpp:1925] No allocations performed
I0912 05:40:15.307423 32552 hierarchical.cpp:2015] No inverse offers to send out!
I0912 05:40:15.307464 32552 hierarchical.cpp:1468] Performed allocation for 0 agents in 124365ns
I0912 05:40:15.308010 32557 provisioner.cpp:416] Provisioner recovery complete
I0912 05:40:15.308349 32556 slave.cpp:6295] Finished recovery
I0912 05:40:15.308863 32556 slave.cpp:6477] Querying resource estimator for oversubscribable resources
I0912 05:40:15.309139 32562 slave.cpp:6491] Received oversubscribable resources {} from the resource estimator
I0912 05:40:15.309347 32562 slave.cpp:971] New master detected at master@172.17.0.2:58922
I0912 05:40:15.309409 32550 status_update_manager.cpp:177] Pausing sending status updates
I0912 05:40:15.309500 32562 slave.cpp:1006] Detecting new master
I0912 05:40:15.311897 32559 slave.cpp:1033] Authenticating with master master@172.17.0.2:58922
I0912 05:40:15.311975 32559 slave.cpp:1044] Using default CRAM-MD5 authenticatee
I0912 05:40:15.312253 32560 authenticatee.cpp:121] Creating new client SASL connection
I0912 05:40:15.312513 32560 master.cpp:7832] Authenticating slave(198)@172.17.0.2:58922
I0912 05:40:15.312654 32548 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(407)@172.17.0.2:58922
I0912 05:40:15.312940 32558 authenticator.cpp:98] Creating new server SASL connection
I0912 05:40:15.313187 32552 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0912 05:40:15.313213 32552 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0912 05:40:15.313313 32552 authenticator.cpp:204] Received SASL authentication start
I0912 05:40:15.313364 32552 authenticator.cpp:326] Authentication requires more steps
I0912 05:40:15.313478 32551 authenticatee.cpp:259] Received SASL authentication step
I0912 05:40:15.313613 32553 authenticator.cpp:232] Received SASL authentication step
I0912 05:40:15.313649 32553 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'b909d5e22907' server FQDN: 'b909d5e22907' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0912 05:40:15.313673 32553 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0912 05:40:15.313743 32553 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0912 05:40:15.313788 32553 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'b909d5e22907' server FQDN: 'b909d5e22907' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0912 05:40:15.313808 32553 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0912 05:40:15.313817 32553 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0912 05:40:15.313833 32553 authenticator.cpp:318] Authentication success
I0912 05:40:15.313931 32557 authenticatee.cpp:299] Authentication success
I0912 05:40:15.314019 32554 master.cpp:7862] Successfully authenticated principal 'test-principal' at slave(198)@172.17.0.2:58922
I0912 05:40:15.314079 32553 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(407)@172.17.0.2:58922
I0912 05:40:15.314239 32555 slave.cpp:1128] Successfully authenticated with master master@172.17.0.2:58922
I0912 05:40:15.314457 32555 slave.cpp:1607] Will retry registration in 9.221574ms if necessary
I0912 05:40:15.314672 32561 master.cpp:5714] Received register agent message from slave(198)@172.17.0.2:58922 (b909d5e22907)
I0912 05:40:15.314810 32561 master.cpp:3803] Authorizing agent with principal 'test-principal'
I0912 05:40:15.315261 32548 master.cpp:5774] Authorized registration of agent at slave(198)@172.17.0.2:58922 (b909d5e22907)
I0912 05:40:15.315383 32548 master.cpp:5867] Registering agent at slave(198)@172.17.0.2:58922 (b909d5e22907) with id c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0
I0912 05:40:15.315827 32558 registrar.cpp:495] Applied 1 operations in 55999ns; attempting to update the registry
I0912 05:40:15.316412 32558 registrar.cpp:552] Successfully updated the registry in 528896ns
I0912 05:40:15.316654 32557 master.cpp:5914] Admitted agent c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0 at slave(198)@172.17.0.2:58922 (b909d5e22907)
I0912 05:40:15.317286 32554 slave.cpp:4970] Received ping from slave-observer(191)@172.17.0.2:58922
I0912 05:40:15.317461 32554 slave.cpp:1174] Registered with master master@172.17.0.2:58922; given agent ID c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0
I0912 05:40:15.317587 32553 status_update_manager.cpp:184] Resuming sending status updates
I0912 05:40:15.317279 32557 master.cpp:5945] Registered agent c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0 at slave(198)@172.17.0.2:58922 (b909d5e22907) with [{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
I0912 05:40:15.317819 32562 hierarchical.cpp:593] Added agent c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0 (b909d5e22907) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (allocated: {})
I0912 05:40:15.317857 32554 slave.cpp:1194] Checkpointing SlaveInfo to '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_68fE8V/meta/slaves/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0/slave.info'
I0912 05:40:15.318280 32554 slave.cpp:1243] Forwarding total oversubscribed resources {}
I0912 05:40:15.318450 32554 master.cpp:6683] Received update of agent c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0 at slave(198)@172.17.0.2:58922 (b909d5e22907) with total oversubscribed resources {}
I0912 05:40:15.319030 32562 hierarchical.cpp:2015] No inverse offers to send out!
I0912 05:40:15.319090 32562 hierarchical.cpp:1468] Performed allocation for 1 agents in 1.101144ms
I0912 05:40:15.319267 32562 hierarchical.cpp:660] Agent c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0 (b909d5e22907) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0912 05:40:15.319643 32555 master.cpp:7662] Sending 1 offers to framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 (default) at scheduler-228abf3d-36ea-4900-94a1-8b18d253716c@172.17.0.2:58922
I0912 05:40:15.320127 32561 sched.cpp:933] Scheduler::resourceOffers took 109341ns
I0912 05:40:15.322115 32550 master.cpp:9159] Removing offer c23ff8cf-cb2f-40d0-8f18-871a41f128cf-O0
I0912 05:40:15.322265 32550 master.cpp:4153] Processing ACCEPT call for offers: [ c23ff8cf-cb2f-40d0-8f18-871a41f128cf-O0 ] on agent c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0 at slave(198)@172.17.0.2:58922 (b909d5e22907) for framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 (default) at scheduler-228abf3d-36ea-4900-94a1-8b18d253716c@172.17.0.2:58922
I0912 05:40:15.322368 32550 master.cpp:3530] Authorizing framework principal 'test-principal' to launch task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec
I0912 05:40:15.324560 32550 master.cpp:9719] Adding task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec with resources [{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}] on agent c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0 at slave(198)@172.17.0.2:58922 (b909d5e22907)
I0912 05:40:15.325297 32550 master.cpp:4816] Launching task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 (default) at scheduler-228abf3d-36ea-4900-94a1-8b18d253716c@172.17.0.2:58922 with resources [{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}] on agent c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0 at slave(198)@172.17.0.2:58922 (b909d5e22907)
I0912 05:40:15.327203 32560 slave.cpp:1736] Got assigned task '8fc99bc8-a2b6-498b-8bb2-af5d92e78cec' for framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:15.327380 32560 slave.cpp:7175] Checkpointing FrameworkInfo to '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_68fE8V/meta/slaves/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0/frameworks/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000/framework.info'
I0912 05:40:15.327888 32560 slave.cpp:7186] Checkpointing framework pid '@0.0.0.0:0' to '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_68fE8V/meta/slaves/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0/frameworks/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000/framework.pid'
I0912 05:40:15.327944 32550 hierarchical.cpp:887] Updated allocation of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 on agent c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0 from cpus(allocated: *):2; mem(allocated: *):1024; disk(allocated: *):1024; ports(allocated: *):[31000-32000] to cpus(allocated: *):2; mem(allocated: *):1024; disk(allocated: *):1024; ports(allocated: *):[31000-32000]
I0912 05:40:15.328968 32560 slave.cpp:2003] Authorizing task '8fc99bc8-a2b6-498b-8bb2-af5d92e78cec' for framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:15.329071 32560 slave.cpp:6794] Authorizing framework principal 'test-principal' to launch task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec
I0912 05:40:15.330121 32553 slave.cpp:2171] Launching task '8fc99bc8-a2b6-498b-8bb2-af5d92e78cec' for framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:15.330823 32553 paths.cpp:578] Trying to chown '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_68fE8V/slaves/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0/frameworks/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000/executors/8fc99bc8-a2b6-498b-8bb2-af5d92e78cec/runs/69e9c3b3-65c9-4c04-b38d-ef2266c2cdf5' to user 'mesos'
I0912 05:40:15.331084 32553 slave.cpp:7757] Checkpointing ExecutorInfo to '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_68fE8V/meta/slaves/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0/frameworks/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000/executors/8fc99bc8-a2b6-498b-8bb2-af5d92e78cec/executor.info'
I0912 05:40:15.331904 32553 slave.cpp:7256] Launching executor '8fc99bc8-a2b6-498b-8bb2-af5d92e78cec' of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 with resources [{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":32.0},"type":"SCALAR"}] in work directory '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_68fE8V/slaves/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0/frameworks/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000/executors/8fc99bc8-a2b6-498b-8bb2-af5d92e78cec/runs/69e9c3b3-65c9-4c04-b38d-ef2266c2cdf5'
I0912 05:40:15.332718 32553 slave.cpp:2858] Launching container 69e9c3b3-65c9-4c04-b38d-ef2266c2cdf5 for executor '8fc99bc8-a2b6-498b-8bb2-af5d92e78cec' of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:15.333190 32554 containerizer.cpp:1083] Starting container 69e9c3b3-65c9-4c04-b38d-ef2266c2cdf5
I0912 05:40:15.333230 32553 slave.cpp:7800] Checkpointing TaskInfo to '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_68fE8V/meta/slaves/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0/frameworks/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000/executors/8fc99bc8-a2b6-498b-8bb2-af5d92e78cec/runs/69e9c3b3-65c9-4c04-b38d-ef2266c2cdf5/tasks/8fc99bc8-a2b6-498b-8bb2-af5d92e78cec/task.info'
I0912 05:40:15.333696 32554 containerizer.cpp:2712] Transitioning the state of container 69e9c3b3-65c9-4c04-b38d-ef2266c2cdf5 from PROVISIONING to PREPARING
I0912 05:40:15.333937 32553 slave.cpp:2400] Queued task '8fc99bc8-a2b6-498b-8bb2-af5d92e78cec' for executor '8fc99bc8-a2b6-498b-8bb2-af5d92e78cec' of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:15.334064 32553 slave.cpp:924] Successfully attached file '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_68fE8V/slaves/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0/frameworks/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000/executors/8fc99bc8-a2b6-498b-8bb2-af5d92e78cec/runs/69e9c3b3-65c9-4c04-b38d-ef2266c2cdf5'
I0912 05:40:15.334168 32553 slave.cpp:924] Successfully attached file '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_68fE8V/slaves/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0/frameworks/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000/executors/8fc99bc8-a2b6-498b-8bb2-af5d92e78cec/runs/69e9c3b3-65c9-4c04-b38d-ef2266c2cdf5'
I0912 05:40:15.338408 32556 containerizer.cpp:1681] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"arguments":["mesos-executor","--launcher_dir=\/mesos\/build\/src"],"shell":false,"value":"\/mesos\/build\/src\/mesos-executor"},"environment":{"variables":[{"name":"LIBPROCESS_PORT","type":"VALUE","value":"0"},{"name":"MESOS_AGENT_ENDPOINT","type":"VALUE","value":"172.17.0.2:58922"},{"name":"MESOS_CHECKPOINT","type":"VALUE","value":"1"},{"name":"MESOS_DIRECTORY","type":"VALUE","value":"\/tmp\/SlaveTest_HTTPSchedulerSlaveRestart_68fE8V\/slaves\/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0\/frameworks\/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000\/executors\/8fc99bc8-a2b6-498b-8bb2-af5d92e78cec\/runs\/69e9c3b3-65c9-4c04-b38d-ef2266c2cdf5"},{"name":"MESOS_EXECUTOR_ID","type":"VALUE","value":"8fc99bc8-a2b6-498b-8bb2-af5d92e78cec"},{"name":"MESOS_EXECUTOR_SHUTDOWN_GRACE_PERIOD","type":"VALUE","value":"5secs"},{"name":"MESOS_FRAMEWORK_ID","type":"VALUE","value":"c23ff8cf-cb2f-40d0-8f18-871a41f128cf-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":"c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0"},{"name":"MESOS_SLAVE_PID","type":"VALUE","value":"slave(198)@172.17.0.2:58922"},{"name":"MESOS_SUBSCRIPTION_BACKOFF_MAX","type":"VALUE","value":"2secs"},{"name":"MESOS_SANDBOX","type":"VALUE","value":"\/tmp\/SlaveTest_HTTPSchedulerSlaveRestart_68fE8V\/slaves\/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0\/frameworks\/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000\/executors\/8fc99bc8-a2b6-498b-8bb2-af5d92e78cec\/runs\/69e9c3b3-65c9-4c04-b38d-ef2266c2cdf5"}]},"task_environment":{},"user":"mesos","working_directory":"\/tmp\/SlaveTest_HTTPSchedulerSlaveRestart_68fE8V\/slaves\/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0\/frameworks\/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000\/executors\/8fc99bc8-a2b6-498b-8bb2-af5d92e78cec\/runs\/69e9c3b3-65c9-4c04-b38d-ef2266c2cdf5"}" --pipe_read="6" --pipe_write="7" --runtime_directory="/tmp/SlaveTest_HTTPSchedulerSlaveRestart_n3xE7x/containers/69e9c3b3-65c9-4c04-b38d-ef2266c2cdf5" --unshare_namespace_mnt="false"'
I0912 05:40:15.340767 32556 launcher.cpp:140] Forked child with pid '1772' for container '69e9c3b3-65c9-4c04-b38d-ef2266c2cdf5'
I0912 05:40:15.340893 32556 containerizer.cpp:1773] Checkpointing container's forked pid 1772 to '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_68fE8V/meta/slaves/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0/frameworks/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000/executors/8fc99bc8-a2b6-498b-8bb2-af5d92e78cec/runs/69e9c3b3-65c9-4c04-b38d-ef2266c2cdf5/pids/forked.pid'
I0912 05:40:15.341821 32556 containerizer.cpp:2712] Transitioning the state of container 69e9c3b3-65c9-4c04-b38d-ef2266c2cdf5 from PREPARING to ISOLATING
I0912 05:40:15.343189 32558 containerizer.cpp:2712] Transitioning the state of container 69e9c3b3-65c9-4c04-b38d-ef2266c2cdf5 from ISOLATING to FETCHING
I0912 05:40:15.343369 32560 fetcher.cpp:377] Starting to fetch URIs for container: 69e9c3b3-65c9-4c04-b38d-ef2266c2cdf5, directory: /tmp/SlaveTest_HTTPSchedulerSlaveRestart_68fE8V/slaves/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0/frameworks/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000/executors/8fc99bc8-a2b6-498b-8bb2-af5d92e78cec/runs/69e9c3b3-65c9-4c04-b38d-ef2266c2cdf5
I0912 05:40:15.344462 32549 containerizer.cpp:2712] Transitioning the state of container 69e9c3b3-65c9-4c04-b38d-ef2266c2cdf5 from FETCHING to RUNNING
I0912 05:40:15.504098 1787 exec.cpp:162] Version: 1.4.0
I0912 05:40:15.510535 32550 slave.cpp:3935] Got registration for executor '8fc99bc8-a2b6-498b-8bb2-af5d92e78cec' of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 from executor(1)@172.17.0.2:33722
I0912 05:40:15.511157 32550 slave.cpp:4021] Checkpointing executor pid 'executor(1)@172.17.0.2:33722' to '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_68fE8V/meta/slaves/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0/frameworks/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000/executors/8fc99bc8-a2b6-498b-8bb2-af5d92e78cec/runs/69e9c3b3-65c9-4c04-b38d-ef2266c2cdf5/pids/libprocess.pid'
I0912 05:40:15.513628 32552 slave.cpp:2605] Sending queued task '8fc99bc8-a2b6-498b-8bb2-af5d92e78cec' to executor '8fc99bc8-a2b6-498b-8bb2-af5d92e78cec' of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 at executor(1)@172.17.0.2:33722
I0912 05:40:15.517511 1780 exec.cpp:237] Executor registered on agent c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0
I0912 05:40:15.521653 1774 executor.cpp:171] Received SUBSCRIBED event
I0912 05:40:15.522095 1774 executor.cpp:175] Subscribed executor on b909d5e22907
I0912 05:40:15.522334 1774 executor.cpp:171] Received LAUNCH event
I0912 05:40:15.522544 1774 executor.cpp:633] Starting task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec
I0912 05:40:15.528475 1774 executor.cpp:477] Running '/mesos/build/src/mesos-containerizer launch <POSSIBLY-SENSITIVE-DATA>'
I0912 05:40:15.531814 1774 executor.cpp:646] Forked command at 1791
I0912 05:40:15.538535 32556 slave.cpp:4399] Handling status update TASK_RUNNING (UUID: b4d60b7e-a8d0-448e-aaf6-4f83dbcb642e) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 from executor(1)@172.17.0.2:33722
I0912 05:40:15.540377 32548 status_update_manager.cpp:323] Received status update TASK_RUNNING (UUID: b4d60b7e-a8d0-448e-aaf6-4f83dbcb642e) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:15.540426 32548 status_update_manager.cpp:500] Creating StatusUpdate stream for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:15.541287 32548 status_update_manager.cpp:834] Checkpointing UPDATE for status update TASK_RUNNING (UUID: b4d60b7e-a8d0-448e-aaf6-4f83dbcb642e) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:15.541561 32548 status_update_manager.cpp:377] Forwarding update TASK_RUNNING (UUID: b4d60b7e-a8d0-448e-aaf6-4f83dbcb642e) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 to the agent
I0912 05:40:15.541859 32559 slave.cpp:4880] Forwarding the update TASK_RUNNING (UUID: b4d60b7e-a8d0-448e-aaf6-4f83dbcb642e) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 to master@172.17.0.2:58922
I0912 05:40:15.542114 32559 slave.cpp:4774] Status update manager successfully handled status update TASK_RUNNING (UUID: b4d60b7e-a8d0-448e-aaf6-4f83dbcb642e) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:15.542174 32559 slave.cpp:4790] Sending acknowledgement for status update TASK_RUNNING (UUID: b4d60b7e-a8d0-448e-aaf6-4f83dbcb642e) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 to executor(1)@172.17.0.2:33722
I0912 05:40:15.542295 32552 master.cpp:6841] Status update TASK_RUNNING (UUID: b4d60b7e-a8d0-448e-aaf6-4f83dbcb642e) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 from agent c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0 at slave(198)@172.17.0.2:58922 (b909d5e22907)
I0912 05:40:15.542371 32552 master.cpp:6903] Forwarding status update TASK_RUNNING (UUID: b4d60b7e-a8d0-448e-aaf6-4f83dbcb642e) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:15.542628 32552 master.cpp:8928] Updating the state of task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 (latest st:
ate: TASK_RUNNING, status update state: TASK_RUNNING)
I0912 05:40:15.542891 32563 sched.cpp:1041] Scheduler::statusUpdate took 114540ns
I0912 05:40:15.543287 32550 master.cpp:5479] Processing ACKNOWLEDGE call b4d60b7e-a8d0-448e-aaf6-4f83dbcb642e for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 (default) at scheduler-228abf3d-36ea-4900-94a1-8b18d253716c@172.17.0.2:58922 on agent c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0
I0912 05:40:15.543305 32547 slave.cpp:843] Agent terminating
I0912 05:40:15.543632 32550 master.cpp:1318] Agent c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0 at slave(198)@172.17.0.2:58922 (b909d5e22907) disconnected
I0912 05:40:15.543651 32550 master.cpp:3301] Disconnecting agent c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0 at slave(198)@172.17.0.2:58922 (b909d5e22907)
I0912 05:40:15.543767 32547 containerizer.cpp:246] Using isolation: posix/cpu,posix/mem,filesystem/posix,network/cni,environment_secret
I0912 05:40:15.543817 32550 master.cpp:3320] Deactivating agent c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0 at slave(198)@172.17.0.2:58922 (b909d5e22907)
I0912 05:40:15.543967 32560 hierarchical.cpp:690] Agent c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0 deactivated
W0912 05:40:15.544199 32547 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges
W0912 05:40:15.544307 32547 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
I0912 05:40:15.544339 32547 provisioner.cpp:255] Using default backend 'copy'
W0912 05:40:15.551013 32547 process.cpp:3196] Attempted to spawn already running process files@172.17.0.2:58922
I0912 05:40:15.551386 32547 cluster.cpp:448] Creating default 'local' authorizer
I0912 05:40:15.554386 32555 slave.cpp:250] Mesos agent started on (199)@172.17.0.2:58922
I0912 05:40:15.554404 32555 slave.cpp:251] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/SlaveTest_HTTPSchedulerSlaveRestart_n3xE7x/store/appc" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authenticatee="crammd5" --authentication_backoff_factor="1secs" --authorizer="local" --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="15secs" --containerizers="mesos" --credential="/tmp/SlaveTest_HTTPSchedulerSlaveRestart_n3xE7x/credential" --default_role="*" --disallow_sharing_agent_pid_namespace="false" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/SlaveTest_HTTPSchedulerSlaveRestart_n3xE7x/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_reregistration_timeout="2secs" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/SlaveTest_HTTPSchedulerSlaveRestart_n3xE7x/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --http_command_executor="false" --http_credentials="/tmp/SlaveTest_HTTPSchedulerSlaveRestart_n3xE7x/http_credentials" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/mesos/build/src" --logbufsecs="0" --logging_level="INFO" --max_completed_executors_per_framework="150" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --port="5051" --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/SlaveTest_HTTPSchedulerSlaveRestart_n3xE7x" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_enable_support="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/SlaveTest_HTTPSchedulerSlaveRestart_68fE8V"
I0912 05:40:15.554872 32555 credentials.hpp:86] Loading credential for authentication from '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_n3xE7x/credential'
I0912 05:40:15.555035 32555 slave.cpp:283] Agent using credential for: test-principal
I0912 05:40:15.555052 32555 credentials.hpp:37] Loading credentials for authentication from '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_n3xE7x/http_credentials'
I0912 05:40:15.555235 32555 http.cpp:1026] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
I0912 05:40:15.555388 32555 http.cpp:1026] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite'
I0912 05:40:15.556735 32555 slave.cpp:565] Agent resources: [{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
I0912 05:40:15.556988 32555 slave.cpp:573] Agent attributes: [ ]
I0912 05:40:15.557003 32555 slave.cpp:582] Agent hostname: b909d5e22907
I0912 05:40:15.557221 32560 status_update_manager.cpp:177] Pausing sending status updates
I0912 05:40:15.558465 32558 state.cpp:64] Recovering state from '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_68fE8V/meta'
I0912 05:40:15.558528 32558 state.cpp:722] No committed checkpointed resources found at '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_68fE8V/meta/resources/resources.info'
I0912 05:40:15.561717 32551 slave.cpp:6386] Recovering framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:15.561810 32551 slave.cpp:7335] Recovering executor '8fc99bc8-a2b6-498b-8bb2-af5d92e78cec' of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:15.562430 32552 status_update_manager.cpp:203] Recovering status update manager
I0912 05:40:15.562449 32552 status_update_manager.cpp:211] Recovering executor '8fc99bc8-a2b6-498b-8bb2-af5d92e78cec' of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:15.562503 32552 status_update_manager.cpp:500] Creating StatusUpdate stream for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:15.562918 32552 status_update_manager.cpp:810] Replaying status update stream for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec
I0912 05:40:15.563284 32556 containerizer.cpp:609] Recovering containerizer
I0912 05:40:15.563344 32556 containerizer.cpp:665] Recovering container 69e9c3b3-65c9-4c04-b38d-ef2266c2cdf5 for executor '8fc99bc8-a2b6-498b-8bb2-af5d92e78cec' of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:15.565598 32551 provisioner.cpp:416] Provisioner recovery complete
I0912 05:40:15.566550 32553 slave.cpp:6179] Sending reconnect request to executor '8fc99bc8-a2b6-498b-8bb2-af5d92e78cec' of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 at executor(1)@172.17.0.2:33722
I0912 05:40:15.567891 1775 exec.cpp:283] Received reconnect request from agent c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0
I0912 05:40:15.568752 32558 slave.cpp:4327] Cleaning up un-reregistered executors
I0912 05:40:15.568778 32558 slave.cpp:4345] Killing un-reregistered executor '8fc99bc8-a2b6-498b-8bb2-af5d92e78cec' of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 at executor(1)@172.17.0.2:33722
I0912 05:40:15.568904 32551 containerizer.cpp:2166] Destroying container 69e9c3b3-65c9-4c04-b38d-ef2266c2cdf5 in RUNNING state
I0912 05:40:15.568922 32559 hierarchical.cpp:1925] No allocations performed
I0912 05:40:15.569078 32559 hierarchical.cpp:2015] No inverse offers to send out!
I0912 05:40:15.568987 32551 containerizer.cpp:2712] Transitioning the state of container 69e9c3b3-65c9-4c04-b38d-ef2266c2cdf5 from RUNNING to DESTROYING
I0912 05:40:15.569145 32559 hierarchical.cpp:1468] Performed allocation for 1 agents in 332649ns
I0912 05:40:15.569416 32551 launcher.cpp:156] Asked to destroy container 69e9c3b3-65c9-4c04-b38d-ef2266c2cdf5
I0912 05:40:15.568934 32558 slave.cpp:6295] Finished recovery
I0912 05:40:15.572386 32558 slave.cpp:6477] Querying resource estimator for oversubscribable resources
I0912 05:40:15.572738 32558 slave.cpp:4109] Received re-registration message from executor '8fc99bc8-a2b6-498b-8bb2-af5d92e78cec' of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
W0912 05:40:15.572798 32558 slave.cpp:4161] Shutting down executor '8fc99bc8-a2b6-498b-8bb2-af5d92e78cec' of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 at executor(1)@172.17.0.2:33722 because it is in unexpected state TERMINATING
I0912 05:40:15.573163 32558 slave.cpp:971] New master detected at master@172.17.0.2:58922
I0912 05:40:15.573194 32562 status_update_manager.cpp:177] Pausing sending status updates
I0912 05:40:15.573314 32558 slave.cpp:1006] Detecting new master
I0912 05:40:15.573434 32558 slave.cpp:6491] Received oversubscribable resources {} from the resource estimator
I0912 05:40:15.573761 1789 exec.cpp:435] Executor asked to shutdown
I0912 05:40:15.574031 1782 executor.cpp:171] Received SHUTDOWN event
I0912 05:40:15.574048 1782 executor.cpp:743] Shutting down
I0912 05:40:15.574089 1782 executor.cpp:850] Sending SIGTERM to process tree at pid 1791
I0912 05:40:15.580627 32553 slave.cpp:1033] Authenticating with master master@172.17.0.2:58922
I0912 05:40:15.580713 32553 slave.cpp:1044] Using default CRAM-MD5 authenticatee
I0912 05:40:15.581008 32556 authenticatee.cpp:121] Creating new client SASL connection
I0912 05:40:15.581377 32555 master.cpp:7832] Authenticating slave(199)@172.17.0.2:58922
I0912 05:40:15.581524 32561 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(408)@172.17.0.2:58922
I0912 05:40:15.581822 32563 authenticator.cpp:98] Creating new server SASL connection
I0912 05:40:15.582089 32554 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0912 05:40:15.582123 32554 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0912 05:40:15.582270 32549 authenticator.cpp:204] Received SASL authentication start
I0912 05:40:15.582330 32549 authenticator.cpp:326] Authentication requires more steps
I0912 05:40:15.582463 32549 authenticatee.cpp:259] Received SASL authentication step
I0912 05:40:15.582597 32560 authenticator.cpp:232] Received SASL authentication step
I0912 05:40:15.582625 32560 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'b909d5e22907' server FQDN: 'b909d5e22907' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0912 05:40:15.582641 32560 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0912 05:40:15.582676 32560 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0912 05:40:15.582695 32560 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'b909d5e22907' server FQDN: 'b909d5e22907' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0912 05:40:15.582702 32560 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0912 05:40:15.582707 32560 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0912 05:40:15.582720 32560 authenticator.cpp:318] Authentication success
I0912 05:40:15.582815 32562 authenticatee.cpp:299] Authentication success
I0912 05:40:15.582855 32552 master.cpp:7862] Successfully authenticated principal 'test-principal' at slave(199)@172.17.0.2:58922
I0912 05:40:15.582882 32558 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(408)@172.17.0.2:58922
I0912 05:40:15.583106 32562 slave.cpp:1128] Successfully authenticated with master master@172.17.0.2:58922
I0912 05:40:15.583451 32562 slave.cpp:1607] Will retry registration in 949976ns if necessary
I0912 05:40:15.583799 32561 master.cpp:6014] Received re-register agent message from agent c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0 at slave(199)@172.17.0.2:58922 (b909d5e22907)
I0912 05:40:15.584031 32561 master.cpp:3803] Authorizing agent with principal 'test-principal'
I0912 05:40:15.584475 32554 master.cpp:6083] Authorized re-registration of agent c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0 at slave(199)@172.17.0.2:58922 (b909d5e22907)
I0912 05:40:15.584573 32554 master.cpp:6148] Re-registering agent c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0 at slave(198)@172.17.0.2:58922 (b909d5e22907)
I0912 05:40:15.584985 32557 hierarchical.cpp:678] Agent c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0 reactivated
I0912 05:40:15.584985 32554 master.cpp:6581] Sending updated checkpointed resources {} to agent c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0 at slave(199)@172.17.0.2:58922 (b909d5e22907)
I0912 05:40:15.585088 32559 slave.cpp:1607] Will retry registration in 30.237322ms if necessary
I0912 05:40:15.585434 32559 slave.cpp:1286] Re-registered with master master@172.17.0.2:58922
I0912 05:40:15.585535 32559 slave.cpp:1323] Forwarding total oversubscribed resources {}
I0912 05:40:15.585543 32556 status_update_manager.cpp:184] Resuming sending status updates
I0912 05:40:15.585543 32554 master.cpp:6014] Received re-register agent message from agent c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0 at slave(199)@172.17.0.2:58922 (b909d5e22907)
W0912 05:40:15.585662 32556 status_update_manager.cpp:191] Resending status update TASK_RUNNING (UUID: b4d60b7e-a8d0-448e-aaf6-4f83dbcb642e) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:15.585732 32556 status_update_manager.cpp:377] Forwarding update TASK_RUNNING (UUID: b4d60b7e-a8d0-448e-aaf6-4f83dbcb642e) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 to the agent
I0912 05:40:15.585903 32554 master.cpp:3803] Authorizing agent with principal 'test-principal'
I0912 05:40:15.585963 32559 slave.cpp:3430] Ignoring new checkpointed resources identical to the current version: {}
I0912 05:40:15.586246 32554 master.cpp:6683] Received update of agent c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0 at slave(199)@172.17.0.2:58922 (b909d5e22907) with total oversubscribed resources {}
I0912 05:40:15.586230 32559 slave.cpp:4880] Forwarding the update TASK_RUNNING (UUID: b4d60b7e-a8d0-448e-aaf6-4f83dbcb642e) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 to master@172.17.0.2:58922
I0912 05:40:15.586472 32554 master.cpp:6083] Authorized re-registration of agent c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0 at slave(199)@172.17.0.2:58922 (b909d5e22907)
I0912 05:40:15.586551 32556 hierarchical.cpp:660] Agent c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0 (b909d5e22907) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0912 05:40:15.586566 32554 master.cpp:6148] Re-registering agent c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0 at slave(199)@172.17.0.2:58922 (b909d5e22907)
I0912 05:40:15.586849 32554 master.cpp:6581] Sending updated checkpointed resources {} to agent c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0 at slave(199)@172.17.0.2:58922 (b909d5:
e22907)
W0912 05:40:15.586864 32563 slave.cpp:1304] Already re-registered with master master@172.17.0.2:58922
I0912 05:40:15.586884 32563 slave.cpp:1323] Forwarding total oversubscribed resources {}
I0912 05:40:15.587103 32563 slave.cpp:3366] Updating info for framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:15.587175 32563 slave.cpp:7175] Checkpointing FrameworkInfo to '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_68fE8V/meta/slaves/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0/frameworks/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000/framework.info'
I0912 05:40:15.587147 32554 master.cpp:6841] Status update TASK_RUNNING (UUID: b4d60b7e-a8d0-448e-aaf6-4f83dbcb642e) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 from agent c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0 at slave(199)@172.17.0.2:58922 (b909d5e22907)
I0912 05:40:15.587221 32554 master.cpp:6903] Forwarding status update TASK_RUNNING (UUID: b4d60b7e-a8d0-448e-aaf6-4f83dbcb642e) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:15.587436 32554 master.cpp:8928] Updating the state of task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
I0912 05:40:15.587570 32554 master.cpp:6683] Received update of agent c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0 at slave(199)@172.17.0.2:58922 (b909d5e22907) with total oversubscribed resources {}
I0912 05:40:15.587620 32557 sched.cpp:1041] Scheduler::statusUpdate took 30617ns
I0912 05:40:15.587770 32563 slave.cpp:7186] Checkpointing framework pid '@0.0.0.0:0' to '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_68fE8V/meta/slaves/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0/frameworks/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000/framework.pid'
I0912 05:40:15.587935 32554 master.cpp:5479] Processing ACKNOWLEDGE call b4d60b7e-a8d0-448e-aaf6-4f83dbcb642e for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 (default) at scheduler-228abf3d-36ea-4900-94a1-8b18d253716c@172.17.0.2:58922 on agent c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0
I0912 05:40:15.587941 32560 hierarchical.cpp:660] Agent c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0 (b909d5e22907) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0912 05:40:15.588253 32553 status_update_manager.cpp:184] Resuming sending status updates
W0912 05:40:15.588287 32553 status_update_manager.cpp:191] Resending status update TASK_RUNNING (UUID: b4d60b7e-a8d0-448e-aaf6-4f83dbcb642e) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:15.588327 32563 slave.cpp:3366] Updating info for framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 with pid updated to scheduler-228abf3d-36ea-4900-94a1-8b18d253716c@172.17.0.2:58922
I0912 05:40:15.588326 32553 status_update_manager.cpp:377] Forwarding update TASK_RUNNING (UUID: b4d60b7e-a8d0-448e-aaf6-4f83dbcb642e) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 to the agent
I0912 05:40:15.588404 32563 slave.cpp:7175] Checkpointing FrameworkInfo to '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_68fE8V/meta/slaves/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0/frameworks/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000/framework.info'
I0912 05:40:15.588801 32563 slave.cpp:7186] Checkpointing framework pid 'scheduler-228abf3d-36ea-4900-94a1-8b18d253716c@172.17.0.2:58922' to '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_68fE8V/meta/slaves/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0/frameworks/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000/framework.pid'
I0912 05:40:15.589190 32563 slave.cpp:3430] Ignoring new checkpointed resources identical to the current version: {}
I0912 05:40:15.589197 32552 status_update_manager.cpp:184] Resuming sending status updates
W0912 05:40:15.589220 32552 status_update_manager.cpp:191] Resending status update TASK_RUNNING (UUID: b4d60b7e-a8d0-448e-aaf6-4f83dbcb642e) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:15.589243 32552 status_update_manager.cpp:377] Forwarding update TASK_RUNNING (UUID: b4d60b7e-a8d0-448e-aaf6-4f83dbcb642e) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 to the agent
I0912 05:40:15.589283 32563 slave.cpp:4948] Sending message for framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 to scheduler-228abf3d-36ea-4900-94a1-8b18d253716c@172.17.0.2:58922
I0912 05:40:15.589493 32548 sched.cpp:1177] Scheduler::frameworkMessage took 29470ns
I0912 05:40:15.589572 32551 status_update_manager.cpp:395] Received status update acknowledgement (UUID: b4d60b7e-a8d0-448e-aaf6-4f83dbcb642e) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:15.589622 32563 slave.cpp:4880] Forwarding the update TASK_RUNNING (UUID: b4d60b7e-a8d0-448e-aaf6-4f83dbcb642e) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 to master@172.17.0.2:58922
I0912 05:40:15.589694 32551 status_update_manager.cpp:834] Checkpointing ACK for status update TASK_RUNNING (UUID: b4d60b7e-a8d0-448e-aaf6-4f83dbcb642e) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:15.589879 32563 slave.cpp:4880] Forwarding the update TASK_RUNNING (UUID: b4d60b7e-a8d0-448e-aaf6-4f83dbcb642e) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 to master@172.17.0.2:58922
I0912 05:40:15.589992 32555 master.cpp:6841] Status update TASK_RUNNING (UUID: b4d60b7e-a8d0-448e-aaf6-4f83dbcb642e) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 from agent c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0 at slave(199)@172.17.0.2:58922 (b909d5e22907)
I0912 05:40:15.590051 32563 slave.cpp:3663] Status update manager successfully handled status update acknowledgement (UUID: b4d60b7e-a8d0-448e-aaf6-4f83dbcb642e) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:15.590047 32555 master.cpp:6903] Forwarding status update TASK_RUNNING (UUID: b4d60b7e-a8d0-448e-aaf6-4f83dbcb642e) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:15.590234 32555 master.cpp:8928] Updating the state of task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
I0912 05:40:15.590378 32559 sched.cpp:1041] Scheduler::statusUpdate took 14489ns
I0912 05:40:15.590432 32555 master.cpp:6841] Status update TASK_RUNNING (UUID: b4d60b7e-a8d0-448e-aaf6-4f83dbcb642e) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 from agent c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0 at slave(199)@172.17.0.2:58922 (b909d5e22907)
I0912 05:40:15.590487 32555 master.cpp:6903] Forwarding status update TASK_RUNNING (UUID: b4d60b7e-a8d0-448e-aaf6-4f83dbcb642e) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:15.590644 32555 master.cpp:8928] Updating the state of task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
I0912 05:40:15.590761 32556 sched.cpp:1041] Scheduler::statusUpdate took 13603ns
I0912 05:40:15.590807 32555 master.cpp:5479] Processing ACKNOWLEDGE call b4d60b7e-a8d0-448e-aaf6-4f83dbcb642e for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 (default) at scheduler-228abf3d-36ea-4900-94a1-8b18d253716c@172.17.0.2:58922 on agent c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0
I0912 05:40:15.591056 32555 master.cpp:5479] Processing ACKNOWLEDGE call b4d60b7e-a8d0-448e-aaf6-4f83dbcb642e for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 (default) at scheduler-228abf3d-36ea-4900-94a1-8b18d253716c@172.17.0.2:58922 on agent c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0
I0912 05:40:15.591071 32562 status_update_manager.cpp:395] Received status update acknowledgement (UUID: b4d60b7e-a8d0-448e-aaf6-4f83dbcb642e) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:15.591341 32550 status_update_manager.cpp:395] Received status update acknowledgement (UUID: b4d60b7e-a8d0-448e-aaf6-4f83dbcb642e) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
E0912 05:40:15.591368 32561 slave.cpp:3656] Failed to handle status update acknowledgement (UUID: b4d60b7e-a8d0-448e-aaf6-4f83dbcb642e) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000: Unexpected status update acknowledgment (UUID: b4d60b7e-a8d0-448e-aaf6-4f83dbcb642e) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
E0912 05:40:15.591498 32549 slave.cpp:3656] Failed to handle status update acknowledgement (UUID: b4d60b7e-a8d0-448e-aaf6-4f83dbcb642e) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000: Unexpected status update acknowledgment (UUID: b4d60b7e-a8d0-448e-aaf6-4f83dbcb642e) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:15.669543 32554 containerizer.cpp:2612] Container 69e9c3b3-65c9-4c04-b38d-ef2266c2cdf5 has exited
I0912 05:40:15.671640 32560 provisioner.cpp:490] Ignoring destroy request for unknown container 69e9c3b3-65c9-4c04-b38d-ef2266c2cdf5
I0912 05:40:15.672369 32563 slave.cpp:5412] Executor '8fc99bc8-a2b6-498b-8bb2-af5d92e78cec' of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 terminated with signal Killed
I0912 05:40:15.672497 32563 slave.cpp:4399] Handling status update TASK_LOST (UUID: 1bc4622e-9dd3-49ef-9bfd-a875fb36bcd9) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 from @0.0.0.0:0
W0912 05:40:15.673275 32550 containerizer.cpp:1976] Ignoring update for unknown container 69e9c3b3-65c9-4c04-b38d-ef2266c2cdf5
I0912 05:40:15.673615 32557 status_update_manager.cpp:323] Received status update TASK_LOST (UUID: 1bc4622e-9dd3-49ef-9bfd-a875fb36bcd9) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:15.673672 32557 status_update_manager.cpp:834] Checkpointing UPDATE for status update TASK_LOST (UUID: 1bc4622e-9dd3-49ef-9bfd-a875fb36bcd9) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:15.673820 32557 status_update_manager.cpp:377] Forwarding update TASK_LOST (UUID: 1bc4622e-9dd3-49ef-9bfd-a875fb36bcd9) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 to the agent
I0912 05:40:15.674010 32552 slave.cpp:4880] Forwarding the update TASK_LOST (UUID: 1bc4622e-9dd3-49ef-9bfd-a875fb36bcd9) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 to master@172.17.0.2:58922
I0912 05:40:15.674181 32552 slave.cpp:4774] Status update manager successfully handled status update TASK_LOST (UUID: 1bc4622e-9dd3-49ef-9bfd-a875fb36bcd9) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:15.674340 32549 master.cpp:6841] Status update TASK_LOST (UUID: 1bc4622e-9dd3-49ef-9bfd-a875fb36bcd9) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 from agent c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0 at slave(199)@172.17.0.2:58922 (b909d5e22907)
I0912 05:40:15.674394 32549 master.cpp:6903] Forwarding status update TASK_LOST (UUID: 1bc4622e-9dd3-49ef-9bfd-a875fb36bcd9) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:15.674536 32549 master.cpp:8928] Updating the state of task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 (latest state: TASK_LOST, status update state: TASK_LOST)
I0912 05:40:15.674707 32553 sched.cpp:1041] Scheduler::statusUpdate took 23659ns
I0912 05:40:15.675499 32549 master.cpp:5479] Processing ACKNOWLEDGE call 1bc4622e-9dd3-49ef-9bfd-a875fb36bcd9 for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 (default) at scheduler-228abf3d-36ea-4900-94a1-8b18d253716c@172.17.0.2:58922 on agent c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0
I0912 05:40:15.675812 32548 hierarchical.cpp:1152] Recovered cpus(allocated: *):2; mem(allocated: *):1024; disk(allocated: *):1024; ports(allocated: *):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000], allocated: {}) on agent c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0 from framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:15.675567 32549 master.cpp:9022] Removing task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec with resources [{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}] of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 on agent c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0 at slave(199)@172.17.0.2:58922 (b909d5e22907)
I0912 05:40:15.676257 32560 status_update_manager.cpp:395] Received status update acknowledgement (UUID: 1bc4622e-9dd3-49ef-9bfd-a875fb36bcd9) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:15.676344 32560 status_update_manager.cpp:834] Checkpointing ACK for status update TASK_LOST (UUID: 1bc4622e-9dd3-49ef-9bfd-a875fb36bcd9) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:15.676432 32560 status_update_manager.cpp:531] Cleaning up status update stream for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:15.676857 32558 slave.cpp:3663] Status update manager successfully handled status update acknowledgement (UUID: 1bc4622e-9dd3-49ef-9bfd-a875fb36bcd9) for task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:15.676908 32558 slave.cpp:7738] Completing task 8fc99bc8-a2b6-498b-8bb2-af5d92e78cec
I0912 05:40:15.676949 32558 slave.cpp:5516] Cleaning up executor '8fc99bc8-a2b6-498b-8bb2-af5d92e78cec' of framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 at executor(1)@172.17.0.2:33722
I0912 05:40:15.677388 32555 gc.cpp:59] Scheduling '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_68fE8V/slaves/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0/frameworks/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000/executors/8fc99bc8-a2b6-498b-8bb2-af5d92e78cec/runs/69e9c3b3-65c9-4c04-b38d-ef2266c2cdf5' for gc 6.99999216112296days in the future
I0912 05:40:15.677546 32555 gc.cpp:59] Scheduling '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_68fE8V/slaves/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0/frameworks/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000/executors/8fc99bc8-a2b6-498b-8bb2-af5d92e78cec' for gc 6.99999215893333days in the future
I0912 05:40:15.677711 32555 gc.cpp:59] Scheduling '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_68fE8V/meta/slaves/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0/frameworks/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000/executors/8fc99bc8-a2b6-498b-8bb2-af5d92e78cec/runs/69e9c3b3-65c9-4c04-b38d-ef2266c2cdf5' for gc 6.99999215732444days in the future
I0912 05:40:15.677775 32558 slave.cpp:5612] Cleaning up framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:15.677812 32555 gc.cpp:59] Scheduling '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_68fE8V/meta/slaves/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0/frameworks/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000/executors/8fc99bc8-a2b6-498b-8bb2-af5d92e78cec' for gc 6.99999215597333days in the future
I0912 05:40:15.677863 32559 status_update_manager.cpp:285] Closing status update streams for framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:15.677960 32555 gc.cpp:59] Scheduling '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_68fE8V/slaves/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0/frameworks/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000' for gc 6.99999215403852days in the future
I0912 05:40:15.678086 32555 gc.cpp:59] Scheduling '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_68fE8V/meta/slaves/c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0/frameworks/c23ff8cf-cb2:
f-40d0-8f18-871a41f128cf-0000' for gc 6.99999215262519days in the future
I0912 05:40:16.571491 32549 hierarchical.cpp:2015] No inverse offers to send out!
I0912 05:40:16.571547 32549 hierarchical.cpp:1468] Performed allocation for 1 agents in 1.096296ms
I0912 05:40:16.572053 32554 master.cpp:7662] Sending 1 offers to framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 (default) at scheduler-228abf3d-36ea-4900-94a1-8b18d253716c@172.17.0.2:58922
I0912 05:40:16.572510 32560 sched.cpp:933] Scheduler::resourceOffers took 24477ns
I0912 05:40:17.573107 32562 hierarchical.cpp:1925] No allocations performed
I0912 05:40:17.573153 32562 hierarchical.cpp:2015] No inverse offers to send out!
I0912 05:40:17.573195 32562 hierarchical.cpp:1468] Performed allocation for 1 agents in 211498ns
I0912 05:40:18.574553 32548 hierarchical.cpp:1925] No allocations performed
I0912 05:40:18.574599 32548 hierarchical.cpp:2015] No inverse offers to send out!
I0912 05:40:18.574641 32548 hierarchical.cpp:1468] Performed allocation for 1 agents in 180072ns
I0912 05:40:19.576134 32562 hierarchical.cpp:1925] No allocations performed
I0912 05:40:19.576189 32562 hierarchical.cpp:2015] No inverse offers to send out!
I0912 05:40:19.576248 32562 hierarchical.cpp:1468] Performed allocation for 1 agents in 203826ns
I0912 05:40:20.576812 32555 hierarchical.cpp:1925] No allocations performed
I0912 05:40:20.576858 32555 hierarchical.cpp:2015] No inverse offers to send out!
I0912 05:40:20.576900 32555 hierarchical.cpp:1468] Performed allocation for 1 agents in 180929ns
I0912 05:40:21.577955 32560 hierarchical.cpp:1925] No allocations performed
I0912 05:40:21.578001 32560 hierarchical.cpp:2015] No inverse offers to send out!
I0912 05:40:21.578043 32560 hierarchical.cpp:1468] Performed allocation for 1 agents in 181224ns
I0912 05:40:22.579715 32553 hierarchical.cpp:1925] No allocations performed
I0912 05:40:22.579761 32553 hierarchical.cpp:2015] No inverse offers to send out!
I0912 05:40:22.579803 32553 hierarchical.cpp:1468] Performed allocation for 1 agents in 186117ns
I0912 05:40:23.581313 32561 hierarchical.cpp:1925] No allocations performed
I0912 05:40:23.581360 32561 hierarchical.cpp:2015] No inverse offers to send out!
I0912 05:40:23.581403 32561 hierarchical.cpp:1468] Performed allocation for 1 agents in 191563ns
I0912 05:40:24.582953 32559 hierarchical.cpp:1925] No allocations performed
I0912 05:40:24.583000 32559 hierarchical.cpp:2015] No inverse offers to send out!
I0912 05:40:24.583042 32559 hierarchical.cpp:1468] Performed allocation for 1 agents in 180449ns
I0912 05:40:25.584481 32551 hierarchical.cpp:1925] No allocations performed
I0912 05:40:25.584528 32551 hierarchical.cpp:2015] No inverse offers to send out!
I0912 05:40:25.584570 32551 hierarchical.cpp:1468] Performed allocation for 1 agents in 186677ns
I0912 05:40:26.585813 32552 hierarchical.cpp:1925] No allocations performed
I0912 05:40:26.585860 32552 hierarchical.cpp:2015] No inverse offers to send out!
I0912 05:40:26.585903 32552 hierarchical.cpp:1468] Performed allocation for 1 agents in 204077ns
I0912 05:40:27.586802 32556 hierarchical.cpp:1925] No allocations performed
I0912 05:40:27.586848 32556 hierarchical.cpp:2015] No inverse offers to send out!
I0912 05:40:27.586890 32556 hierarchical.cpp:1468] Performed allocation for 1 agents in 189229ns
I0912 05:40:28.588395 32559 hierarchical.cpp:1925] No allocations performed
I0912 05:40:28.588441 32559 hierarchical.cpp:2015] No inverse offers to send out!
I0912 05:40:28.588484 32559 hierarchical.cpp:1468] Performed allocation for 1 agents in 178527ns
I0912 05:40:29.590046 32551 hierarchical.cpp:1925] No allocations performed
I0912 05:40:29.590092 32551 hierarchical.cpp:2015] No inverse offers to send out!
I0912 05:40:29.590134 32551 hierarchical.cpp:1468] Performed allocation for 1 agents in 179207ns
I0912 05:40:30.574189 32550 slave.cpp:6477] Querying resource estimator for oversubscribable resources
I0912 05:40:30.574484 32557 slave.cpp:6491] Received oversubscribable resources {} from the resource estimator
/mesos/src/tests/slave_tests.cpp:5501: Failure
Failed to wait 15secs for executorToFrameworkMessage1
I0912 05:40:30.590958 32549 master.cpp:1432] Framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 (default) at scheduler-228abf3d-36ea-4900-94a1-8b18d253716c@172.17.0.2:58922 disconnected
I0912 05:40:30.591058 32549 master.cpp:3264] Deactivating framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 (default) at scheduler-228abf3d-36ea-4900-94a1-8b18d253716c@172.17.0.2:58922
I0912 05:40:30.591497 32555 hierarchical.cpp:412] Deactivated framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:30.591819 32555 hierarchical.cpp:1925] No allocations performed
I0912 05:40:30.591877 32555 hierarchical.cpp:2015] No inverse offers to send out!
I0912 05:40:30.592000 32555 hierarchical.cpp:1468] Performed allocation for 1 agents in 359046ns
I0912 05:40:30.592222 32549 master.cpp:9159] Removing offer c23ff8cf-cb2f-40d0-8f18-871a41f128cf-O1
I0912 05:40:30.592332 32549 master.cpp:3241] Disconnecting framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 (default) at scheduler-228abf3d-36ea-4900-94a1-8b18d253716c@172.17.0.2:58922
I0912 05:40:30.592635 32549 master.cpp:1447] Giving framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 (default) at scheduler-228abf3d-36ea-4900-94a1-8b18d253716c@172.17.0.2:58922 0ns to failover
I0912 05:40:30.593114 32562 slave.cpp:843] Agent terminating
I0912 05:40:30.593736 32555 hierarchical.cpp:1152] Recovered cpus(allocated: *):2; mem(allocated: *):1024; disk(allocated: *):1024; ports(allocated: *):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000], allocated: {}) on agent c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0 from framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:30.594408 32560 master.cpp:7494] Framework failover timeout, removing framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 (default) at scheduler-228abf3d-36ea-4900-94a1-8b18d253716c@172.17.0.2:58922
I0912 05:40:30.594449 32560 master.cpp:8355] Removing framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000 (default) at scheduler-228abf3d-36ea-4900-94a1-8b18d253716c@172.17.0.2:58922
I0912 05:40:30.595404 32548 hierarchical.cpp:355] Removed framework c23ff8cf-cb2f-40d0-8f18-871a41f128cf-0000
I0912 05:40:30.600559 32547 master.cpp:1160] Master terminating
I0912 05:40:30.601553 32559 hierarchical.cpp:626] Removed agent c23ff8cf-cb2f-40d0-8f18-871a41f128cf-S0
/mesos/3rdparty/libprocess/include/process/gmock.hpp:467: Failure
Actual function call count doesn't match EXPECT_CALL(filter->mock, filter(testing::A<const MessageEvent&>()))...
Expected args: message matcher (8-byte object <48-04 06-D4 37-2B 00-00>, 1, 1)
Expected: to be called once
Actual: never called - unsatisfied and active
/mesos/3rdparty/libprocess/include/process/gmock.hpp:467: Failure
Actual function call count doesn't match EXPECT_CALL(filter->mock, filter(testing::A<const MessageEvent&>()))...
Expected args: message matcher (8-byte object <48-04 06-D4 37-2B 00-00>, 1, 1-byte object <28>)
Expected: to be called once
Actual: never called - unsatisfied and active
[ FAILED ] SlaveTest.HTTPSchedulerSlaveRestart (15325 ms)
{code}
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)