You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "Benjamin Mahler (JIRA)" <ji...@apache.org> on 2019/04/19 20:12:00 UTC
[jira] [Commented] (MESOS-5804)
ExamplesTest.DynamicReservationFramework is flaky
[ https://issues.apache.org/jira/browse/MESOS-5804?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16822159#comment-16822159 ]
Benjamin Mahler commented on MESOS-5804:
----------------------------------------
The failure in [~vinodkone]'s logs is because of the following race:
# Framework launches task T, moves from RESERVED to TASK_RUNNING state.
# Allocation cycle triggers and will send the unreserved resources to the framework.
# Before the offer gets to the framework, task T finishes and framework moves from TASK_RUNNING to RESERVED.
# In the RESERVED state, the framework expects the reservation in the offer. But, it's coming in a later offer, and the one that arrives is for the unreserved resources since it was generated while the task was still running.
In general the state machine used is brittle (e.g. assumes status update will always come before offer). However, one fix for the specific issue leading to this failure is to use a 2 week filter rather than a 0 second filter. That would ensure that the unreserved resources do not get re-offered to the framework on their own. However, this fix would be blocked by MESOS-9616 cc [~chhsia0]
> ExamplesTest.DynamicReservationFramework is flaky
> -------------------------------------------------
>
> Key: MESOS-5804
> URL: https://issues.apache.org/jira/browse/MESOS-5804
> Project: Mesos
> Issue Type: Bug
> Components: allocation, test
> Reporter: Anand Mazumdar
> Assignee: Benjamin Mahler
> Priority: Major
> Labels: mesosphere, resource-management
> Attachments: ExamplesTest.DynamicReservationFramework-badrun2.txt
>
>
> Showed up on ASF CI:
> https://builds.apache.org/job/Mesos/BUILDTOOL=autotools,COMPILER=clang,CONFIGURATION=--verbose%20--enable-libevent%20--enable-ssl,ENVIRONMENT=GLOG_v=1%20MESOS_VERBOSE=1,OS=ubuntu%3A14.04,label_exp=(docker%7C%7CHadoop)&&(!ubuntu-us1)&&(!ubuntu-6)/2466/changes
> {code}
> [ RUN ] ExamplesTest.DynamicReservationFramework
> Using temporary directory '/tmp/ExamplesTest_DynamicReservationFramework_xp2TU9'
> /mesos/mesos-1.0.0/src/tests/dynamic_reservation_framework_test.sh: line 19: /mesos/mesos-1.0.0/_build/src/colors.sh: No such file or directory
> /mesos/mesos-1.0.0/src/tests/dynamic_reservation_framework_test.sh: line 20: /mesos/mesos-1.0.0/_build/src/atexit.sh: No such file or directory
> WARNING: Logging before InitGoogleLogging() is written to STDERR
> I0707 19:30:31.102650 29946 resources.cpp:572] Parsing resources as JSON failed: cpus:1;mem:128
> Trying semicolon-delimited string format instead
> I0707 19:30:31.125845 29946 process.cpp:1066] libprocess is initialized on 172.17.0.7:37568 with 16 worker threads
> I0707 19:30:31.125954 29946 logging.cpp:199] Logging to STDERR
> I0707 19:30:31.237936 29946 leveldb.cpp:174] Opened db in 101.67046ms
> I0707 19:30:31.272083 29946 leveldb.cpp:181] Compacted db in 34.088797ms
> I0707 19:30:31.272655 29946 leveldb.cpp:196] Created db iterator in 104307ns
> I0707 19:30:31.272855 29946 leveldb.cpp:202] Seeked to beginning of db in 20581ns
> I0707 19:30:31.273027 29946 leveldb.cpp:271] Iterated through 0 keys in the db in 13839ns
> I0707 19:30:31.273460 29946 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> I0707 19:30:31.277535 29979 recover.cpp:451] Starting replica recovery
> I0707 19:30:31.279044 29979 recover.cpp:477] Replica is in EMPTY status
> I0707 19:30:31.285576 29984 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from (3)@172.17.0.7:37568
> I0707 19:30:31.290812 29983 recover.cpp:197] Received a recover response from a replica in EMPTY status
> I0707 19:30:31.300268 29972 recover.cpp:568] Updating replica status to STARTING
> I0707 19:30:31.307143 29946 local.cpp:255] Creating default 'local' authorizer
> I0707 19:30:31.324632 29972 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 23.394808ms
> I0707 19:30:31.325036 29972 replica.cpp:320] Persisted replica status to STARTING
> I0707 19:30:31.325812 29972 recover.cpp:477] Replica is in STARTING status
> I0707 19:30:31.328284 29972 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from (5)@172.17.0.7:37568
> I0707 19:30:31.328945 29972 recover.cpp:197] Received a recover response from a replica in STARTING status
> I0707 19:30:31.329859 29972 recover.cpp:568] Updating replica status to VOTING
> I0707 19:30:31.335539 29974 master.cpp:382] Master 443ee691-d272-454c-90fe-959c95948252 (89b080073abb) started on 172.17.0.7:37568
> I0707 19:30:31.335839 29974 master.cpp:384] Flags at startup: --acls="permissive: true
> register_frameworks {
> principals {
> type: ANY
> }
> roles {
> type: SOME
> values: "test"
> }
> }
> " --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate_agents="false" --authenticate_frameworks="false" --authenticate_http="false" --authenticate_http_frameworks="false" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/ExamplesTest_DynamicReservationFramework_xp2TU9/credentials" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_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" --quiet="false" --recovery_agent_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_store_timeout="20secs" --registry_strict="false" --root_submissions="true" --user_sorter="drf" --version="false" --webui_dir="/mesos/mesos-1.0.0/src/webui" --work_dir="/tmp/mesos-zPIQS8" --zk_session_timeout="10secs"
> I0707 19:30:31.337158 29974 master.cpp:436] Master allowing unauthenticated frameworks to register
> I0707 19:30:31.337323 29974 master.cpp:450] Master allowing unauthenticated agents to register
> I0707 19:30:31.337527 29974 master.cpp:464] Master allowing HTTP frameworks to register without authentication
> I0707 19:30:31.337689 29974 credentials.hpp:37] Loading credentials for authentication from '/tmp/ExamplesTest_DynamicReservationFramework_xp2TU9/credentials'
> W0707 19:30:31.337962 29974 credentials.hpp:52] Permissions on credentials file '/tmp/ExamplesTest_DynamicReservationFramework_xp2TU9/credentials' are too open. It is recommended that your credentials file is NOT accessible by others.
> I0707 19:30:31.338336 29974 master.cpp:506] Using default 'crammd5' authenticator
> I0707 19:30:31.338723 29974 authenticator.cpp:519] Initializing server SASL
> I0707 19:30:31.340744 29974 auxprop.cpp:73] Initialized in-memory auxiliary property plugin
> I0707 19:30:31.341084 29974 master.cpp:705] Authorization enabled
> I0707 19:30:31.342696 29971 hierarchical.cpp:151] Initialized hierarchical allocator process
> I0707 19:30:31.342895 29977 whitelist_watcher.cpp:77] No whitelist given
> I0707 19:30:31.358129 29972 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 27.780299ms
> I0707 19:30:31.358496 29972 replica.cpp:320] Persisted replica status to VOTING
> I0707 19:30:31.358949 29972 recover.cpp:582] Successfully joined the Paxos group
> I0707 19:30:31.359601 29972 recover.cpp:466] Recover process terminated
> I0707 19:30:31.365345 29946 containerizer.cpp:196] Using isolation: filesystem/posix,posix/cpu,posix/mem,network/cni
> W0707 19:30:31.368975 29946 backend.cpp:75] Failed to create 'aufs' backend: AufsBackend requires root privileges, but is running as user mesos
> W0707 19:30:31.369699 29946 backend.cpp:75] Failed to create 'bind' backend: BindBackend requires root privileges
> I0707 19:30:31.393633 29977 slave.cpp:205] Agent started on 1)@172.17.0.7:37568
> I0707 19:30:31.394129 29977 slave.cpp:206] Flags at startup: --acls="permissive: true
> register_frameworks {
> principals {
> type: ANY
> }
> roles {
> type: SOME
> values: "test"
> }
> }
> " --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http="false" --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" --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="/tmp/mesos/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/mesos/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_command_executor="false" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="filesystem/posix,posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/mesos/mesos-1.0.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="1secs" --revocable_cpu_low_priority="true" --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/mesos-zPIQS8/0"
> I0707 19:30:31.395762 29977 resources.cpp:572] Parsing resources as JSON failed:
> Trying semicolon-delimited string format instead
> I0707 19:30:31.396198 29977 resources.cpp:572] Parsing resources as JSON failed:
> Trying semicolon-delimited string format instead
> I0707 19:30:31.397099 29977 slave.cpp:594] Agent resources: cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0707 19:30:31.397364 29977 slave.cpp:602] Agent attributes: [ ]
> I0707 19:30:31.397557 29977 slave.cpp:607] Agent hostname: 89b080073abb
> I0707 19:30:31.403342 29981 state.cpp:57] Recovering state from '/tmp/mesos-zPIQS8/0/meta'
> I0707 19:30:31.411643 29973 status_update_manager.cpp:200] Recovering status update manager
> I0707 19:30:31.412467 29983 containerizer.cpp:522] Recovering containerizer
> I0707 19:30:31.417868 29975 provisioner.cpp:253] Provisioner recovery complete
> I0707 19:30:31.419260 29977 slave.cpp:4856] Finished recovery
> I0707 19:30:31.420929 29977 slave.cpp:5028] Querying resource estimator for oversubscribable resources
> I0707 19:30:31.422238 29970 status_update_manager.cpp:174] Pausing sending status updates
> I0707 19:30:31.422533 29977 slave.cpp:969] New master detected at master@172.17.0.7:37568
> I0707 19:30:31.422721 29977 slave.cpp:990] No credentials provided. Attempting to register without authentication
> I0707 19:30:31.422902 29977 slave.cpp:1001] Detecting new master
> I0707 19:30:31.423362 29977 slave.cpp:5042] Received oversubscribable resources from the resource estimator
> I0707 19:30:31.429898 29974 master.cpp:1973] The newly elected leader is master@172.17.0.7:37568 with id 443ee691-d272-454c-90fe-959c95948252
> I0707 19:30:31.429949 29974 master.cpp:1986] Elected as the leading master!
> I0707 19:30:31.429968 29974 master.cpp:1673] Recovering from registrar
> I0707 19:30:31.431020 29976 registrar.cpp:332] Recovering registrar
> I0707 19:30:31.433168 29971 log.cpp:553] Attempting to start the writer
> I0707 19:30:31.439359 29982 replica.cpp:493] Replica received implicit promise request from (21)@172.17.0.7:37568 with proposal 1
> I0707 19:30:31.441862 29946 containerizer.cpp:196] Using isolation: filesystem/posix,posix/cpu,posix/mem,network/cni
> W0707 19:30:31.443104 29946 backend.cpp:75] Failed to create 'aufs' backend: AufsBackend requires root privileges, but is running as user mesos
> W0707 19:30:31.443366 29946 backend.cpp:75] Failed to create 'bind' backend: BindBackend requires root privileges
> I0707 19:30:31.457201 29975 slave.cpp:205] Agent started on 2)@172.17.0.7:37568
> I0707 19:30:31.457254 29975 slave.cpp:206] Flags at startup: --acls="permissive: true
> register_frameworks {
> principals {
> type: ANY
> }
> roles {
> type: SOME
> values: "test"
> }
> }
> " --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http="false" --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" --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="/tmp/mesos/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/mesos/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_command_executor="false" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="filesystem/posix,posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/mesos/mesos-1.0.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="1secs" --revocable_cpu_low_priority="true" --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/mesos-zPIQS8/1"
> I0707 19:30:31.458678 29982 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 19.283309ms
> I0707 19:30:31.458717 29982 replica.cpp:342] Persisted promised to 1
> I0707 19:30:31.461284 29969 coordinator.cpp:238] Coordinator attempting to fill missing positions
> I0707 19:30:31.461690 29975 resources.cpp:572] Parsing resources as JSON failed:
> Trying semicolon-delimited string format instead
> I0707 19:30:31.461866 29975 resources.cpp:572] Parsing resources as JSON failed:
> Trying semicolon-delimited string format instead
> I0707 19:30:31.462319 29975 slave.cpp:594] Agent resources: cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0707 19:30:31.462396 29975 slave.cpp:602] Agent attributes: [ ]
> I0707 19:30:31.464599 29975 slave.cpp:607] Agent hostname: 89b080073abb
> I0707 19:30:31.466464 29978 replica.cpp:388] Replica received explicit promise request from (33)@172.17.0.7:37568 for position 0 with proposal 2
> I0707 19:30:31.468361 29975 state.cpp:57] Recovering state from '/tmp/mesos-zPIQS8/1/meta'
> I0707 19:30:31.468951 29975 status_update_manager.cpp:200] Recovering status update manager
> I0707 19:30:31.469187 29975 containerizer.cpp:522] Recovering containerizer
> I0707 19:30:31.472386 29969 provisioner.cpp:253] Provisioner recovery complete
> I0707 19:30:31.473125 29969 slave.cpp:4856] Finished recovery
> I0707 19:30:31.473996 29969 slave.cpp:5028] Querying resource estimator for oversubscribable resources
> I0707 19:30:31.474643 29982 slave.cpp:969] New master detected at master@172.17.0.7:37568
> I0707 19:30:31.474673 29982 slave.cpp:990] No credentials provided. Attempting to register without authentication
> I0707 19:30:31.474726 29982 slave.cpp:1001] Detecting new master
> I0707 19:30:31.474833 29982 status_update_manager.cpp:174] Pausing sending status updates
> I0707 19:30:31.475157 29969 slave.cpp:5042] Received oversubscribable resources from the resource estimator
> I0707 19:30:31.479303 29946 containerizer.cpp:196] Using isolation: filesystem/posix,posix/cpu,posix/mem,network/cni
> W0707 19:30:31.484933 29946 backend.cpp:75] Failed to create 'aufs' backend: AufsBackend requires root privileges, but is running as user mesos
> W0707 19:30:31.485230 29946 backend.cpp:75] Failed to create 'bind' backend: BindBackend requires root privileges
> I0707 19:30:31.492482 29978 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 25.968225ms
> I0707 19:30:31.492543 29978 replica.cpp:712] Persisted action at 0
> I0707 19:30:31.495333 29972 replica.cpp:537] Replica received write request for position 0 from (46)@172.17.0.7:37568
> I0707 19:30:31.495918 29972 leveldb.cpp:436] Reading position from leveldb took 553942ns
> I0707 19:30:31.505445 29973 slave.cpp:205] Agent started on 3)@172.17.0.7:37568
> I0707 19:30:31.505492 29973 slave.cpp:206] Flags at startup: --acls="permissive: true
> register_frameworks {
> principals {
> type: ANY
> }
> roles {
> type: SOME
> values: "test"
> }
> }
> " --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http="false" --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" --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="/tmp/mesos/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/mesos/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_command_executor="false" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="filesystem/posix,posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/mesos/mesos-1.0.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="1secs" --revocable_cpu_low_priority="true" --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/mesos-zPIQS8/2"
> I0707 19:30:31.506813 29973 resources.cpp:572] Parsing resources as JSON failed:
> Trying semicolon-delimited string format instead
> I0707 19:30:31.506990 29973 resources.cpp:572] Parsing resources as JSON failed:
> Trying semicolon-delimited string format instead
> I0707 19:30:31.507602 29973 slave.cpp:594] Agent resources: cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0707 19:30:31.507680 29973 slave.cpp:602] Agent attributes: [ ]
> I0707 19:30:31.507695 29973 slave.cpp:607] Agent hostname: 89b080073abb
> I0707 19:30:31.510499 29973 state.cpp:57] Recovering state from '/tmp/mesos-zPIQS8/2/meta'
> I0707 19:30:31.511034 29973 status_update_manager.cpp:200] Recovering status update manager
> I0707 19:30:31.511270 29973 containerizer.cpp:522] Recovering containerizer
> I0707 19:30:31.514657 29984 provisioner.cpp:253] Provisioner recovery complete
> I0707 19:30:31.515745 29970 slave.cpp:4856] Finished recovery
> I0707 19:30:31.516332 29970 slave.cpp:5028] Querying resource estimator for oversubscribable resources
> I0707 19:30:31.517103 29970 slave.cpp:969] New master detected at master@172.17.0.7:37568
> I0707 19:30:31.517134 29970 slave.cpp:990] No credentials provided. Attempting to register without authentication
> I0707 19:30:31.517190 29970 slave.cpp:1001] Detecting new master
> I0707 19:30:31.517294 29970 slave.cpp:5042] Received oversubscribable resources from the resource estimator
> I0707 19:30:31.517375 29970 status_update_manager.cpp:174] Pausing sending status updates
> I0707 19:30:31.519979 29946 sched.cpp:226] Version: 1.0.0
> I0707 19:30:31.521474 29980 sched.cpp:330] New master detected at master@172.17.0.7:37568
> I0707 19:30:31.521586 29980 sched.cpp:341] No credentials provided. Attempting to register without authentication
> I0707 19:30:31.521613 29980 sched.cpp:820] Sending SUBSCRIBE call to master@172.17.0.7:37568
> I0707 19:30:31.521769 29980 sched.cpp:853] Will retry registration in 898.210224ms if necessary
> I0707 19:30:31.521977 29980 master.cpp:1500] Dropping 'mesos.scheduler.Call' message since not recovered yet
> I0707 19:30:31.522469 29972 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 26.469135ms
> I0707 19:30:31.522514 29972 replica.cpp:712] Persisted action at 0
> I0707 19:30:31.523948 29980 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0
> I0707 19:30:31.538797 29972 slave.cpp:1529] Will retry registration in 1.972934225secs if necessary
> I0707 19:30:31.538925 29972 master.cpp:1500] Dropping 'mesos.internal.RegisterSlaveMessage' message since not recovered yet
> I0707 19:30:31.555934 29980 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 31.978704ms
> I0707 19:30:31.556016 29980 replica.cpp:712] Persisted action at 0
> I0707 19:30:31.556066 29980 replica.cpp:697] Replica learned NOP action at position 0
> I0707 19:30:31.557960 29980 log.cpp:569] Writer started with ending position 0
> I0707 19:30:31.561957 29976 leveldb.cpp:436] Reading position from leveldb took 90775ns
> I0707 19:30:31.566825 29979 slave.cpp:1529] Will retry registration in 382.223275ms if necessary
> I0707 19:30:31.566967 29979 master.cpp:1500] Dropping 'mesos.internal.RegisterSlaveMessage' message since not recovered yet
> I0707 19:30:31.582073 29981 registrar.cpp:365] Successfully fetched the registry (0B) in 150.98496ms
> I0707 19:30:31.582437 29981 registrar.cpp:464] Applied 1 operations in 94170ns; attempting to update the 'registry'
> I0707 19:30:31.587924 29975 log.cpp:577] Attempting to append 168 bytes to the log
> I0707 19:30:31.588234 29975 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
> I0707 19:30:31.589561 29978 replica.cpp:537] Replica received write request for position 1 from (51)@172.17.0.7:37568
> I0707 19:30:31.621119 29978 leveldb.cpp:341] Persisting action (187 bytes) to leveldb took 31.540172ms
> I0707 19:30:31.621209 29978 replica.cpp:712] Persisted action at 1
> I0707 19:30:31.623564 29978 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
> I0707 19:30:31.656234 29978 leveldb.cpp:341] Persisting action (189 bytes) to leveldb took 32.657222ms
> I0707 19:30:31.656424 29978 replica.cpp:712] Persisted action at 1
> I0707 19:30:31.656786 29978 replica.cpp:697] Replica learned APPEND action at position 1
> I0707 19:30:31.660815 29978 registrar.cpp:509] Successfully updated the 'registry' in 78.219008ms
> I0707 19:30:31.661057 29978 registrar.cpp:395] Successfully recovered registrar
> I0707 19:30:31.661593 29978 log.cpp:596] Attempting to truncate the log to 1
> I0707 19:30:31.662271 29978 master.cpp:1781] Recovered 0 agents from the Registry (129B) ; allowing 10mins for agents to re-register
> I0707 19:30:31.662566 29978 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
> I0707 19:30:31.663004 29978 hierarchical.cpp:178] Skipping recovery of hierarchical allocator: nothing to recover
> I0707 19:30:31.664005 29975 replica.cpp:537] Replica received write request for position 2 from (52)@172.17.0.7:37568
> I0707 19:30:31.696493 29975 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 32.24974ms
> I0707 19:30:31.696583 29975 replica.cpp:712] Persisted action at 2
> I0707 19:30:31.698271 29984 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
> I0707 19:30:31.731513 29984 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 32.894448ms
> I0707 19:30:31.731775 29984 leveldb.cpp:399] Deleting ~1 keys from leveldb took 95908ns
> I0707 19:30:31.732022 29984 replica.cpp:712] Persisted action at 2
> I0707 19:30:31.732120 29984 replica.cpp:697] Replica learned TRUNCATE action at position 2
> I0707 19:30:31.950920 29984 slave.cpp:1529] Will retry registration in 3.638047644secs if necessary
> I0707 19:30:31.951601 29983 master.cpp:4676] Registering agent at slave(3)@172.17.0.7:37568 (89b080073abb) with id 443ee691-d272-454c-90fe-959c95948252-S0
> I0707 19:30:31.953089 29974 registrar.cpp:464] Applied 1 operations in 182983ns; attempting to update the 'registry'
> I0707 19:30:31.957223 29983 log.cpp:577] Attempting to append 337 bytes to the log
> I0707 19:30:31.957545 29983 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3
> I0707 19:30:31.958920 29983 replica.cpp:537] Replica received write request for position 3 from (53)@172.17.0.7:37568
> I0707 19:30:31.989977 29983 leveldb.cpp:341] Persisting action (356 bytes) to leveldb took 30.902846ms
> I0707 19:30:31.990154 29983 replica.cpp:712] Persisted action at 3
> I0707 19:30:31.991781 29974 replica.cpp:691] Replica received learned notice for position 3 from @0.0.0.0:0
> I0707 19:30:32.024132 29974 leveldb.cpp:341] Persisting action (358 bytes) to leveldb took 32.308737ms
> I0707 19:30:32.024305 29974 replica.cpp:712] Persisted action at 3
> I0707 19:30:32.024449 29974 replica.cpp:697] Replica learned APPEND action at position 3
> I0707 19:30:32.027683 29975 registrar.cpp:509] Successfully updated the 'registry' in 74.444032ms
> I0707 19:30:32.029734 29974 log.cpp:596] Attempting to truncate the log to 3
> I0707 19:30:32.030093 29974 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 4
> I0707 19:30:32.030804 29974 slave.cpp:3760] Received ping from slave-observer(1)@172.17.0.7:37568
> I0707 19:30:32.031373 29974 slave.cpp:1169] Registered with master master@172.17.0.7:37568; given agent ID 443ee691-d272-454c-90fe-959c95948252-S0
> I0707 19:30:32.031460 29974 fetcher.cpp:86] Clearing fetcher cache
> I0707 19:30:32.032008 29974 slave.cpp:1192] Checkpointing SlaveInfo to '/tmp/mesos-zPIQS8/2/meta/slaves/443ee691-d272-454c-90fe-959c95948252-S0/slave.info'
> I0707 19:30:32.031088 29975 master.cpp:4745] Registered agent 443ee691-d272-454c-90fe-959c95948252-S0 at slave(3)@172.17.0.7:37568 (89b080073abb) with cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0707 19:30:32.033082 29975 hierarchical.cpp:478] Added agent 443ee691-d272-454c-90fe-959c95948252-S0 (89b080073abb) with cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000] (allocated: )
> I0707 19:30:32.033608 29975 hierarchical.cpp:1537] No allocations performed
> I0707 19:30:32.033747 29975 hierarchical.cpp:1195] Performed allocation for agent 443ee691-d272-454c-90fe-959c95948252-S0 in 584676ns
> I0707 19:30:32.034116 29975 status_update_manager.cpp:181] Resuming sending status updates
> I0707 19:30:32.034010 29974 slave.cpp:1229] Forwarding total oversubscribed resources
> I0707 19:30:32.034950 29974 master.cpp:5128] Received update of agent 443ee691-d272-454c-90fe-959c95948252-S0 at slave(3)@172.17.0.7:37568 (89b080073abb) with total oversubscribed resources
> I0707 19:30:32.035320 29975 replica.cpp:537] Replica received write request for position 4 from (54)@172.17.0.7:37568
> I0707 19:30:32.036041 29971 hierarchical.cpp:542] Agent 443ee691-d272-454c-90fe-959c95948252-S0 (89b080073abb) updated with oversubscribed resources (total: cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: )
> I0707 19:30:32.036212 29971 hierarchical.cpp:1537] No allocations performed
> I0707 19:30:32.036327 29971 hierarchical.cpp:1195] Performed allocation for agent 443ee691-d272-454c-90fe-959c95948252-S0 in 212809ns
> I0707 19:30:32.196679 29976 master.cpp:4676] Registering agent at slave(2)@172.17.0.7:37568 (89b080073abb) with id 443ee691-d272-454c-90fe-959c95948252-S1
> I0707 19:30:32.196384 29979 slave.cpp:1529] Will retry registration in 1.893622708secs if necessary
> I0707 19:30:32.197633 29976 registrar.cpp:464] Applied 1 operations in 273890ns; attempting to update the 'registry'
> I0707 19:30:32.343791 29979 hierarchical.cpp:1537] No allocations performed
> I0707 19:30:32.344105 29979 hierarchical.cpp:1172] Performed allocation for 1 agents in 555357ns
> I0707 19:30:32.373800 29975 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 338.056804ms
> I0707 19:30:32.373987 29975 replica.cpp:712] Persisted action at 4
> I0707 19:30:32.387712 29973 replica.cpp:691] Replica received learned notice for position 4 from @0.0.0.0:0
> I0707 19:30:32.420934 29981 sched.cpp:820] Sending SUBSCRIBE call to master@172.17.0.7:37568
> I0707 19:30:32.421331 29981 sched.cpp:853] Will retry registration in 2.058099434secs if necessary
> I0707 19:30:32.421792 29981 master.cpp:2550] Received SUBSCRIBE call for framework 'Dynamic Reservation Framework (C++)' at scheduler-a956abb7-0f5d-46e3-a670-a3f684eccbb5@172.17.0.7:37568
> I0707 19:30:32.421934 29981 master.cpp:2012] Authorizing framework principal 'test' to receive offers for role 'test'
> I0707 19:30:32.423535 29981 master.cpp:2626] Subscribing framework Dynamic Reservation Framework (C++) with checkpointing disabled and capabilities [ ]
> I0707 19:30:32.425323 29976 hierarchical.cpp:271] Added framework 443ee691-d272-454c-90fe-959c95948252-0000
> I0707 19:30:32.426686 29973 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 38.63187ms
> I0707 19:30:32.426865 29973 leveldb.cpp:399] Deleting ~2 keys from leveldb took 95262ns
> I0707 19:30:32.426981 29973 replica.cpp:712] Persisted action at 4
> I0707 19:30:32.427096 29973 replica.cpp:697] Replica learned TRUNCATE action at position 4
> I0707 19:30:32.428614 29973 log.cpp:577] Attempting to append 503 bytes to the log
> I0707 19:30:32.426307 29981 sched.cpp:743] Framework registered with 443ee691-d272-454c-90fe-959c95948252-0000
> I0707 19:30:32.428905 29981 dynamic_reservation_framework.cpp:73] Registered!
> I0707 19:30:32.429059 29981 sched.cpp:757] Scheduler::registered took 167468ns
> I0707 19:30:32.429239 29981 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 5
> I0707 19:30:32.431745 29976 hierarchical.cpp:1632] No inverse offers to send out!
> I0707 19:30:32.432610 29984 master.cpp:5835] Sending 1 offers to framework 443ee691-d272-454c-90fe-959c95948252-0000 (Dynamic Reservation Framework (C++)) at scheduler-a956abb7-0f5d-46e3-a670-a3f684eccbb5@172.17.0.7:37568
> I0707 19:30:32.433627 29984 dynamic_reservation_framework.cpp:84] Received offer 443ee691-d272-454c-90fe-959c95948252-O0 with cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0707 19:30:32.434248 29984 sched.cpp:917] Scheduler::resourceOffers took 642030ns
> I0707 19:30:32.436048 29984 master.cpp:3468] Processing ACCEPT call for offers: [ 443ee691-d272-454c-90fe-959c95948252-O0 ] on agent 443ee691-d272-454c-90fe-959c95948252-S0 at slave(3)@172.17.0.7:37568 (89b080073abb) for framework 443ee691-d272-454c-90fe-959c95948252-0000 (Dynamic Reservation Framework (C++)) at scheduler-a956abb7-0f5d-46e3-a670-a3f684eccbb5@172.17.0.7:37568
> I0707 19:30:32.436368 29984 master.cpp:3144] Authorizing principal 'test' to reserve resources 'cpus(test, test):1; mem(test, test):128'
> I0707 19:30:32.438547 29976 hierarchical.cpp:1172] Performed allocation for 1 agents in 12.203221ms
> I0707 19:30:32.432860 29981 replica.cpp:537] Replica received write request for position 5 from (55)@172.17.0.7:37568
> I0707 19:30:32.439970 29984 master.cpp:3695] Applying RESERVE operation for resources cpus(test, test):1; mem(test, test):128 from framework 443ee691-d272-454c-90fe-959c95948252-0000 (Dynamic Reservation Framework (C++)) at scheduler-a956abb7-0f5d-46e3-a670-a3f684eccbb5@172.17.0.7:37568 to agent 443ee691-d272-454c-90fe-959c95948252-S0 at slave(3)@172.17.0.7:37568 (89b080073abb)
> I0707 19:30:32.440765 29984 master.cpp:7098] Sending checkpointed resources cpus(test, test):1; mem(test, test):128 to agent 443ee691-d272-454c-90fe-959c95948252-S0 at slave(3)@172.17.0.7:37568 (89b080073abb)
> I0707 19:30:32.444211 29976 hierarchical.cpp:683] Updated allocation of framework 443ee691-d272-454c-90fe-959c95948252-0000 on agent 443ee691-d272-454c-90fe-959c95948252-S0 from cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000] to cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]; cpus(test, test):1; mem(test, test):128
> I0707 19:30:32.444527 29984 slave.cpp:2600] Updated checkpointed resources from to cpus(test, test):1; mem(test, test):128
> I0707 19:30:32.445664 29976 hierarchical.cpp:924] Recovered cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]; cpus(test, test):1; mem(test, test):128 (total: cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]; cpus(test, test):1; mem(test, test):128, allocated: ) on agent 443ee691-d272-454c-90fe-959c95948252-S0 from framework 443ee691-d272-454c-90fe-959c95948252-0000
> I0707 19:30:32.467499 29981 leveldb.cpp:341] Persisting action (522 bytes) to leveldb took 28.613107ms
> I0707 19:30:32.467705 29981 replica.cpp:712] Persisted action at 5
> I0707 19:30:32.483840 29971 replica.cpp:691] Replica received learned notice for position 5 from @0.0.0.0:0
> I0707 19:30:32.511849 29971 leveldb.cpp:341] Persisting action (524 bytes) to leveldb took 27.859875ms
> I0707 19:30:32.512235 29971 replica.cpp:712] Persisted action at 5
> I0707 19:30:32.512511 29971 replica.cpp:697] Replica learned APPEND action at position 5
> I0707 19:30:32.516393 29971 registrar.cpp:509] Successfully updated the 'registry' in 318.636032ms
> I0707 19:30:32.517113 29971 log.cpp:596] Attempting to truncate the log to 5
> I0707 19:30:32.518293 29971 master.cpp:4745] Registered agent 443ee691-d272-454c-90fe-959c95948252-S1 at slave(2)@172.17.0.7:37568 (89b080073abb) with cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0707 19:30:32.518659 29971 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 6
> I0707 19:30:32.519564 29971 hierarchical.cpp:478] Added agent 443ee691-d272-454c-90fe-959c95948252-S1 (89b080073abb) with cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000] (allocated: )
> I0707 19:30:32.520804 29971 hierarchical.cpp:1632] No inverse offers to send out!
> I0707 19:30:32.521106 29971 hierarchical.cpp:1195] Performed allocation for agent 443ee691-d272-454c-90fe-959c95948252-S1 in 1.298948ms
> I0707 19:30:32.521436 29971 slave.cpp:1169] Registered with master master@172.17.0.7:37568; given agent ID 443ee691-d272-454c-90fe-959c95948252-S1
> I0707 19:30:32.521669 29971 fetcher.cpp:86] Clearing fetcher cache
> I0707 19:30:32.522266 29971 slave.cpp:1192] Checkpointing SlaveInfo to '/tmp/mesos-zPIQS8/1/meta/slaves/443ee691-d272-454c-90fe-959c95948252-S1/slave.info'
> I0707 19:30:32.523712 29971 slave.cpp:1229] Forwarding total oversubscribed resources
> I0707 19:30:32.523080 29981 master.cpp:5835] Sending 1 offers to framework 443ee691-d272-454c-90fe-959c95948252-0000 (Dynamic Reservation Framework (C++)) at scheduler-a956abb7-0f5d-46e3-a670-a3f684eccbb5@172.17.0.7:37568
> I0707 19:30:32.524303 29979 status_update_manager.cpp:181] Resuming sending status updates
> I0707 19:30:32.524688 29981 master.cpp:5128] Received update of agent 443ee691-d272-454c-90fe-959c95948252-S1 at slave(2)@172.17.0.7:37568 (89b080073abb) with total oversubscribed resources
> I0707 19:30:32.525228 29970 dynamic_reservation_framework.cpp:84] Received offer 443ee691-d272-454c-90fe-959c95948252-O1 with cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0707 19:30:32.525902 29970 sched.cpp:917] Scheduler::resourceOffers took 691140ns
> I0707 19:30:32.525388 29971 slave.cpp:3760] Received ping from slave-observer(2)@172.17.0.7:37568
> I0707 19:30:32.527039 29982 replica.cpp:537] Replica received write request for position 6 from (58)@172.17.0.7:37568
> I0707 19:30:32.528058 29981 master.cpp:3468] Processing ACCEPT call for offers: [ 443ee691-d272-454c-90fe-959c95948252-O1 ] on agent 443ee691-d272-454c-90fe-959c95948252-S1 at slave(2)@172.17.0.7:37568 (89b080073abb) for framework 443ee691-d272-454c-90fe-959c95948252-0000 (Dynamic Reservation Framework (C++)) at scheduler-a956abb7-0f5d-46e3-a670-a3f684eccbb5@172.17.0.7:37568
> I0707 19:30:32.528295 29979 hierarchical.cpp:542] Agent 443ee691-d272-454c-90fe-959c95948252-S1 (89b080073abb) updated with oversubscribed resources (total: cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000])
> I0707 19:30:32.529708 29979 hierarchical.cpp:1537] No allocations performed
> I0707 19:30:32.529754 29979 hierarchical.cpp:1632] No inverse offers to send out!
> I0707 19:30:32.529820 29979 hierarchical.cpp:1195] Performed allocation for agent 443ee691-d272-454c-90fe-959c95948252-S1 in 1.473485ms
> I0707 19:30:32.529899 29981 master.cpp:3144] Authorizing principal 'test' to reserve resources 'cpus(test, test):1; mem(test, test):128'
> I0707 19:30:32.531919 29984 master.cpp:3695] Applying RESERVE operation for resources cpus(test, test):1; mem(test, test):128 from framework 443ee691-d272-454c-90fe-959c95948252-0000 (Dynamic Reservation Framework (C++)) at scheduler-a956abb7-0f5d-46e3-a670-a3f684eccbb5@172.17.0.7:37568 to agent 443ee691-d272-454c-90fe-959c95948252-S1 at slave(2)@172.17.0.7:37568 (89b080073abb)
> I0707 19:30:32.532374 29984 master.cpp:7098] Sending checkpointed resources cpus(test, test):1; mem(test, test):128 to agent 443ee691-d272-454c-90fe-959c95948252-S1 at slave(2)@172.17.0.7:37568 (89b080073abb)
> I0707 19:30:32.534451 29977 hierarchical.cpp:683] Updated allocation of framework 443ee691-d272-454c-90fe-959c95948252-0000 on agent 443ee691-d272-454c-90fe-959c95948252-S1 from cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000] to cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]; cpus(test, test):1; mem(test, test):128
> I0707 19:30:32.537169 29980 hierarchical.cpp:924] Recovered cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]; cpus(test, test):1; mem(test, test):128 (total: cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]; cpus(test, test):1; mem(test, test):128, allocated: ) on agent 443ee691-d272-454c-90fe-959c95948252-S1 from framework 443ee691-d272-454c-90fe-959c95948252-0000
> I0707 19:30:32.535399 29984 slave.cpp:2600] Updated checkpointed resources from to cpus(test, test):1; mem(test, test):128
> I0707 19:30:32.554222 29982 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 27.170492ms
> I0707 19:30:32.554395 29982 replica.cpp:712] Persisted action at 6
> I0707 19:30:32.556767 29970 replica.cpp:691] Replica received learned notice for position 6 from @0.0.0.0:0
> I0707 19:30:32.579500 29970 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 22.578289ms
> I0707 19:30:32.579659 29970 leveldb.cpp:399] Deleting ~2 keys from leveldb took 86499ns
> I0707 19:30:32.579692 29970 replica.cpp:712] Persisted action at 6
> I0707 19:30:32.579746 29970 replica.cpp:697] Replica learned TRUNCATE action at position 6
> I0707 19:30:33.347929 29970 hierarchical.cpp:1632] No inverse offers to send out!
> I0707 19:30:33.349206 29970 hierarchical.cpp:1172] Performed allocation for 2 agents in 3.521151ms
> I0707 19:30:33.349076 29977 master.cpp:5835] Sending 2 offers to framework 443ee691-d272-454c-90fe-959c95948252-0000 (Dynamic Reservation Framework (C++)) at scheduler-a956abb7-0f5d-46e3-a670-a3f684eccbb5@172.17.0.7:37568
> I0707 19:30:33.350098 29977 dynamic_reservation_framework.cpp:84] Received offer 443ee691-d272-454c-90fe-959c95948252-O2 with cpus(test, test):1; mem(test, test):128; cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0707 19:30:33.350462 29977 dynamic_reservation_framework.cpp:150] Launching task 0 using offer 443ee691-d272-454c-90fe-959c95948252-O2
> I0707 19:30:33.350879 29977 dynamic_reservation_framework.cpp:84] Received offer 443ee691-d272-454c-90fe-959c95948252-O3 with cpus(test, test):1; mem(test, test):128; cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0707 19:30:33.351199 29977 dynamic_reservation_framework.cpp:150] Launching task 1 using offer 443ee691-d272-454c-90fe-959c95948252-O3
> I0707 19:30:33.351398 29977 sched.cpp:917] Scheduler::resourceOffers took 1.321372ms
> I0707 19:30:33.352967 29977 master.cpp:3468] Processing ACCEPT call for offers: [ 443ee691-d272-454c-90fe-959c95948252-O2 ] on agent 443ee691-d272-454c-90fe-959c95948252-S0 at slave(3)@172.17.0.7:37568 (89b080073abb) for framework 443ee691-d272-454c-90fe-959c95948252-0000 (Dynamic Reservation Framework (C++)) at scheduler-a956abb7-0f5d-46e3-a670-a3f684eccbb5@172.17.0.7:37568
> I0707 19:30:33.353111 29977 master.cpp:3106] Authorizing framework principal 'test' to launch task 0
> I0707 19:30:33.355710 29977 master.cpp:3468] Processing ACCEPT call for offers: [ 443ee691-d272-454c-90fe-959c95948252-O3 ] on agent 443ee691-d272-454c-90fe-959c95948252-S1 at slave(2)@172.17.0.7:37568 (89b080073abb) for framework 443ee691-d272-454c-90fe-959c95948252-0000 (Dynamic Reservation Framework (C++)) at scheduler-a956abb7-0f5d-46e3-a670-a3f684eccbb5@172.17.0.7:37568
> I0707 19:30:33.355829 29977 master.cpp:3106] Authorizing framework principal 'test' to launch task 1
> I0707 19:30:33.359690 29977 master.cpp:7565] Adding task 0 with resources cpus(test, test):1; mem(test, test):128 on agent 443ee691-d272-454c-90fe-959c95948252-S0 (89b080073abb)
> I0707 19:30:33.359900 29977 master.cpp:3957] Launching task 0 of framework 443ee691-d272-454c-90fe-959c95948252-0000 (Dynamic Reservation Framework (C++)) at scheduler-a956abb7-0f5d-46e3-a670-a3f684eccbb5@172.17.0.7:37568 with resources cpus(test, test):1; mem(test, test):128 on agent 443ee691-d272-454c-90fe-959c95948252-S0 at slave(3)@172.17.0.7:37568 (89b080073abb)
> I0707 19:30:33.360642 29970 slave.cpp:1569] Got assigned task 0 for framework 443ee691-d272-454c-90fe-959c95948252-0000
> I0707 19:30:33.361142 29970 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
> Trying semicolon-delimited string format instead
> I0707 19:30:33.362133 29983 hierarchical.cpp:924] Recovered ports(*):[31000-32000]; disk(*):3.70122e+06; cpus(*):15; mem(*):47142 (total: cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]; cpus(test, test):1; mem(test, test):128, allocated: cpus(test, test):1; mem(test, test):128) on agent 443ee691-d272-454c-90fe-959c95948252-S0 from framework 443ee691-d272-454c-90fe-959c95948252-0000
> I0707 19:30:33.362866 29970 slave.cpp:1688] Launching task 0 for framework 443ee691-d272-454c-90fe-959c95948252-0000
> I0707 19:30:33.362995 29970 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
> Trying semicolon-delimited string format instead
> I0707 19:30:33.367036 29977 master.cpp:7565] Adding task 1 with resources cpus(test, test):1; mem(test, test):128 on agent 443ee691-d272-454c-90fe-959c95948252-S1 (89b080073abb)
> I0707 19:30:33.367182 29977 master.cpp:3957] Launching task 1 of framework 443ee691-d272-454c-90fe-959c95948252-0000 (Dynamic Reservation Framework (C++)) at scheduler-a956abb7-0f5d-46e3-a670-a3f684eccbb5@172.17.0.7:37568 with resources cpus(test, test):1; mem(test, test):128 on agent 443ee691-d272-454c-90fe-959c95948252-S1 at slave(2)@172.17.0.7:37568 (89b080073abb)
> I0707 19:30:33.367564 29978 slave.cpp:1569] Got assigned task 1 for framework 443ee691-d272-454c-90fe-959c95948252-0000
> I0707 19:30:33.367811 29978 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
> Trying semicolon-delimited string format instead
> I0707 19:30:33.368335 29978 slave.cpp:1688] Launching task 1 for framework 443ee691-d272-454c-90fe-959c95948252-0000
> I0707 19:30:33.368511 29978 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
> Trying semicolon-delimited string format instead
> I0707 19:30:33.373251 29970 paths.cpp:528] Trying to chown '/tmp/mesos-zPIQS8/2/slaves/443ee691-d272-454c-90fe-959c95948252-S0/frameworks/443ee691-d272-454c-90fe-959c95948252-0000/executors/0/runs/5f6efb5e-5357-4514-964a-5af3d0ec33f1' to user 'mesos'
> I0707 19:30:33.376608 29977 hierarchical.cpp:924] Recovered ports(*):[31000-32000]; disk(*):3.70122e+06; cpus(*):15; mem(*):47142 (total: cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]; cpus(test, test):1; mem(test, test):128, allocated: cpus(test, test):1; mem(test, test):128) on agent 443ee691-d272-454c-90fe-959c95948252-S1 from framework 443ee691-d272-454c-90fe-959c95948252-0000
> I0707 19:30:33.376976 29978 paths.cpp:528] Trying to chown '/tmp/mesos-zPIQS8/1/slaves/443ee691-d272-454c-90fe-959c95948252-S1/frameworks/443ee691-d272-454c-90fe-959c95948252-0000/executors/1/runs/34287f06-c6d4-4ab6-b706-5abf0e314655' to user 'mesos'
> I0707 19:30:33.378888 29970 slave.cpp:5748] Launching executor 0 of framework 443ee691-d272-454c-90fe-959c95948252-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/mesos-zPIQS8/2/slaves/443ee691-d272-454c-90fe-959c95948252-S0/frameworks/443ee691-d272-454c-90fe-959c95948252-0000/executors/0/runs/5f6efb5e-5357-4514-964a-5af3d0ec33f1'
> I0707 19:30:33.380379 29980 containerizer.cpp:781] Starting container '5f6efb5e-5357-4514-964a-5af3d0ec33f1' for executor '0' of framework '443ee691-d272-454c-90fe-959c95948252-0000'
> I0707 19:30:33.383648 29978 slave.cpp:5748] Launching executor 1 of framework 443ee691-d272-454c-90fe-959c95948252-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/mesos-zPIQS8/1/slaves/443ee691-d272-454c-90fe-959c95948252-S1/frameworks/443ee691-d272-454c-90fe-959c95948252-0000/executors/1/runs/34287f06-c6d4-4ab6-b706-5abf0e314655'
> I0707 19:30:33.384750 29971 containerizer.cpp:781] Starting container '34287f06-c6d4-4ab6-b706-5abf0e314655' for executor '1' of framework '443ee691-d272-454c-90fe-959c95948252-0000'
> I0707 19:30:33.384395 29978 slave.cpp:1914] Queuing task '1' for executor '1' of framework 443ee691-d272-454c-90fe-959c95948252-0000
> I0707 19:30:33.385623 29978 slave.cpp:922] Successfully attached file '/tmp/mesos-zPIQS8/1/slaves/443ee691-d272-454c-90fe-959c95948252-S1/frameworks/443ee691-d272-454c-90fe-959c95948252-0000/executors/1/runs/34287f06-c6d4-4ab6-b706-5abf0e314655'
> I0707 19:30:33.399920 29979 containerizer.cpp:1284] Launching 'mesos-containerizer' with flags '--command="{"arguments":["mesos-executor","--launcher_dir=\/mesos\/mesos-1.0.0\/_build\/src"],"shell":false,"value":"\/mesos\/mesos-1.0.0\/_build\/src\/mesos-executor"}" --help="false" --pipe_read="9" --pipe_write="12" --pre_exec_commands="[]" --unshare_namespace_mnt="false" --user="mesos" --working_directory="/tmp/mesos-zPIQS8/2/slaves/443ee691-d272-454c-90fe-959c95948252-S0/frameworks/443ee691-d272-454c-90fe-959c95948252-0000/executors/0/runs/5f6efb5e-5357-4514-964a-5af3d0ec33f1"'
> I0707 19:30:33.403643 29971 containerizer.cpp:1284] Launching 'mesos-containerizer' with flags '--command="{"arguments":["mesos-executor","--launcher_dir=\/mesos\/mesos-1.0.0\/_build\/src"],"shell":false,"value":"\/mesos\/mesos-1.0.0\/_build\/src\/mesos-executor"}" --help="false" --pipe_read="13" --pipe_write="14" --pre_exec_commands="[]" --unshare_namespace_mnt="false" --user="mesos" --working_directory="/tmp/mesos-zPIQS8/1/slaves/443ee691-d272-454c-90fe-959c95948252-S1/frameworks/443ee691-d272-454c-90fe-959c95948252-0000/executors/1/runs/34287f06-c6d4-4ab6-b706-5abf0e314655"'
> I0707 19:30:33.406067 29979 launcher.cpp:126] Forked child with pid '29991' for container '5f6efb5e-5357-4514-964a-5af3d0ec33f1'
> I0707 19:30:33.407141 29971 launcher.cpp:126] Forked child with pid '29992' for container '34287f06-c6d4-4ab6-b706-5abf0e314655'
> I0707 19:30:33.405388 29970 slave.cpp:1914] Queuing task '0' for executor '0' of framework 443ee691-d272-454c-90fe-959c95948252-0000
> I0707 19:30:33.408761 29970 slave.cpp:922] Successfully attached file '/tmp/mesos-zPIQS8/2/slaves/443ee691-d272-454c-90fe-959c95948252-S0/frameworks/443ee691-d272-454c-90fe-959c95948252-0000/executors/0/runs/5f6efb5e-5357-4514-964a-5af3d0ec33f1'
> I0707 19:30:33.512244 29979 slave.cpp:1529] Will retry registration in 109.135061ms if necessary
> I0707 19:30:33.512642 29979 master.cpp:4676] Registering agent at slave(1)@172.17.0.7:37568 (89b080073abb) with id 443ee691-d272-454c-90fe-959c95948252-S2
> I0707 19:30:33.513365 29979 registrar.cpp:464] Applied 1 operations in 161276ns; attempting to update the 'registry'
> I0707 19:30:33.522032 29979 log.cpp:577] Attempting to append 669 bytes to the log
> I0707 19:30:33.522296 29979 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 7
> I0707 19:30:33.525583 29975 replica.cpp:537] Replica received write request for position 7 from (67)@172.17.0.7:37568
> I0707 19:30:33.556705 29975 leveldb.cpp:341] Persisting action (688 bytes) to leveldb took 31.103148ms
> I0707 19:30:33.556799 29975 replica.cpp:712] Persisted action at 7
> I0707 19:30:33.558219 29982 replica.cpp:691] Replica received learned notice for position 7 from @0.0.0.0:0
> I0707 19:30:33.590251 29982 leveldb.cpp:341] Persisting action (690 bytes) to leveldb took 32.026154ms
> I0707 19:30:33.590347 29982 replica.cpp:712] Persisted action at 7
> I0707 19:30:33.590395 29982 replica.cpp:697] Replica learned APPEND action at position 7
> I0707 19:30:33.595444 29975 log.cpp:596] Attempting to truncate the log to 7
> I0707 19:30:33.595649 29975 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 8
> I0707 19:30:33.596961 29975 replica.cpp:537] Replica received write request for position 8 from (68)@172.17.0.7:37568
> I0707 19:30:33.595394 29982 registrar.cpp:509] Successfully updated the 'registry' in 81.936128ms
> I0707 19:30:33.598295 29969 master.cpp:4745] Registered agent 443ee691-d272-454c-90fe-959c95948252-S2 at slave(1)@172.17.0.7:37568 (89b080073abb) with cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0707 19:30:33.599622 29984 hierarchical.cpp:478] Added agent 443ee691-d272-454c-90fe-959c95948252-S2 (89b080073abb) with cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000] (allocated: )
> I0707 19:30:33.600498 29978 slave.cpp:1169] Registered with master master@172.17.0.7:37568; given agent ID 443ee691-d272-454c-90fe-959c95948252-S2
> I0707 19:30:33.600530 29978 fetcher.cpp:86] Clearing fetcher cache
> I0707 19:30:33.601135 29978 slave.cpp:1192] Checkpointing SlaveInfo to '/tmp/mesos-zPIQS8/0/meta/slaves/443ee691-d272-454c-90fe-959c95948252-S2/slave.info'
> I0707 19:30:33.601351 29981 status_update_manager.cpp:181] Resuming sending status updates
> I0707 19:30:33.601753 29978 slave.cpp:1229] Forwarding total oversubscribed resources
> I0707 19:30:33.601856 29978 slave.cpp:3760] Received ping from slave-observer(3)@172.17.0.7:37568
> I0707 19:30:33.602028 29978 master.cpp:5128] Received update of agent 443ee691-d272-454c-90fe-959c95948252-S2 at slave(1)@172.17.0.7:37568 (89b080073abb) with total oversubscribed resources
> I0707 19:30:33.602550 29984 hierarchical.cpp:1632] No inverse offers to send out!
> I0707 19:30:33.602638 29984 hierarchical.cpp:1195] Performed allocation for agent 443ee691-d272-454c-90fe-959c95948252-S2 in 2.976114ms
> I0707 19:30:33.602772 29984 hierarchical.cpp:542] Agent 443ee691-d272-454c-90fe-959c95948252-S2 (89b080073abb) updated with oversubscribed resources (total: cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000])
> I0707 19:30:33.603118 29984 hierarchical.cpp:1537] No allocations performed
> I0707 19:30:33.603154 29984 hierarchical.cpp:1632] No inverse offers to send out!
> I0707 19:30:33.603205 29984 hierarchical.cpp:1195] Performed allocation for agent 443ee691-d272-454c-90fe-959c95948252-S2 in 384101ns
> I0707 19:30:33.604754 29984 master.cpp:5835] Sending 1 offers to framework 443ee691-d272-454c-90fe-959c95948252-0000 (Dynamic Reservation Framework (C++)) at scheduler-a956abb7-0f5d-46e3-a670-a3f684eccbb5@172.17.0.7:37568
> I0707 19:30:33.605154 29984 dynamic_reservation_framework.cpp:84] Received offer 443ee691-d272-454c-90fe-959c95948252-O4 with cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0707 19:30:33.605554 29984 sched.cpp:917] Scheduler::resourceOffers took 415259ns
> I0707 19:30:33.606514 29984 master.cpp:3468] Processing ACCEPT call for offers: [ 443ee691-d272-454c-90fe-959c95948252-O4 ] on agent 443ee691-d272-454c-90fe-959c95948252-S2 at slave(1)@172.17.0.7:37568 (89b080073abb) for framework 443ee691-d272-454c-90fe-959c95948252-0000 (Dynamic Reservation Framework (C++)) at scheduler-a956abb7-0f5d-46e3-a670-a3f684eccbb5@172.17.0.7:37568
> I0707 19:30:33.606920 29984 master.cpp:3144] Authorizing principal 'test' to reserve resources 'cpus(test, test):1; mem(test, test):128'
> I0707 19:30:33.616320 29979 master.cpp:3695] Applying RESERVE operation for resources cpus(test, test):1; mem(test, test):128 from framework 443ee691-d272-454c-90fe-959c95948252-0000 (Dynamic Reservation Framework (C++)) at scheduler-a956abb7-0f5d-46e3-a670-a3f684eccbb5@172.17.0.7:37568 to agent 443ee691-d272-454c-90fe-959c95948252-S2 at slave(1)@172.17.0.7:37568 (89b080073abb)
> I0707 19:30:33.616832 29979 master.cpp:7098] Sending checkpointed resources cpus(test, test):1; mem(test, test):128 to agent 443ee691-d272-454c-90fe-959c95948252-S2 at slave(1)@172.17.0.7:37568 (89b080073abb)
> I0707 19:30:33.620553 29979 hierarchical.cpp:683] Updated allocation of framework 443ee691-d272-454c-90fe-959c95948252-0000 on agent 443ee691-d272-454c-90fe-959c95948252-S2 from cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000] to cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]; cpus(test, test):1; mem(test, test):128
> I0707 19:30:33.621477 29979 hierarchical.cpp:924] Recovered cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]; cpus(test, test):1; mem(test, test):128 (total: cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]; cpus(test, test):1; mem(test, test):128, allocated: ) on agent 443ee691-d272-454c-90fe-959c95948252-S2 from framework 443ee691-d272-454c-90fe-959c95948252-0000
> I0707 19:30:33.626524 29969 slave.cpp:2600] Updated checkpointed resources from to cpus(test, test):1; mem(test, test):128
> I0707 19:30:33.632431 29975 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 35.442219ms
> I0707 19:30:33.632493 29975 replica.cpp:712] Persisted action at 8
> I0707 19:30:33.634073 29975 replica.cpp:691] Replica received learned notice for position 8 from @0.0.0.0:0
> I0707 19:30:33.662283 29975 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 28.207233ms
> I0707 19:30:33.662469 29975 leveldb.cpp:399] Deleting ~2 keys from leveldb took 111311ns
> I0707 19:30:33.662504 29975 replica.cpp:712] Persisted action at 8
> I0707 19:30:33.662557 29975 replica.cpp:697] Replica learned TRUNCATE action at position 8
> I0707 19:30:33.750787 29992 exec.cpp:161] Version: 1.0.0
> I0707 19:30:33.758561 29975 slave.cpp:2902] Got registration for executor '1' of framework 443ee691-d272-454c-90fe-959c95948252-0000 from executor(1)@172.17.0.7:38689
> I0707 19:30:33.766023 29975 slave.cpp:2079] Sending queued task '1' to executor '1' of framework 443ee691-d272-454c-90fe-959c95948252-0000 at executor(1)@172.17.0.7:38689
> I0707 19:30:33.774989 30060 exec.cpp:236] Executor registered on agent 443ee691-d272-454c-90fe-959c95948252-S1
> Received SUBSCRIBED event
> Subscribed executor on 89b080073abb
> Received LAUNCH event
> Starting task 1
> /mesos/mesos-1.0.0/_build/src/mesos-containerizer launch --command="{"shell":true,"value":"echo hello"}" --help="false" --unshare_namespace_mnt="false"
> Forked command at 30062
> I0707 19:30:33.842072 29981 slave.cpp:3285] Handling status update TASK_RUNNING (UUID: 1a550a5a-a5c4-4d37-9018-f6a41ca4eb14) for task 1 of framework 443ee691-d272-454c-90fe-959c95948252-0000 from executor(1)@172.17.0.7:38689
> I0707 19:30:33.847599 29974 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 1a550a5a-a5c4-4d37-9018-f6a41ca4eb14) for task 1 of framework 443ee691-d272-454c-90fe-959c95948252-0000
> I0707 19:30:33.847682 29974 status_update_manager.cpp:497] Creating StatusUpdate stream for task 1 of framework 443ee691-d272-454c-90fe-959c95948252-0000
> I0707 19:30:33.849678 29974 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: 1a550a5a-a5c4-4d37-9018-f6a41ca4eb14) for task 1 of framework 443ee691-d272-454c-90fe-959c95948252-0000 to the agent
> I0707 19:30:33.850505 29973 slave.cpp:3678] Forwarding the update TASK_RUNNING (UUID: 1a550a5a-a5c4-4d37-9018-f6a41ca4eb14) for task 1 of framework 443ee691-d272-454c-90fe-959c95948252-0000 to master@172.17.0.7:37568
> I0707 19:30:33.850747 29973 slave.cpp:3572] Status update manager successfully handled status update TASK_RUNNING (UUID: 1a550a5a-a5c4-4d37-9018-f6a41ca4eb14) for task 1 of framework 443ee691-d272-454c-90fe-959c95948252-0000
> I0707 19:30:33.850805 29973 slave.cpp:3588] Sending acknowledgement for status update TASK_RUNNING (UUID: 1a550a5a-a5c4-4d37-9018-f6a41ca4eb14) for task 1 of framework 443ee691-d272-454c-90fe-959c95948252-0000 to executor(1)@172.17.0.7:38689
> I0707 19:30:33.851368 29973 master.cpp:5273] Status update TASK_RUNNING (UUID: 1a550a5a-a5c4-4d37-9018-f6a41ca4eb14) for task 1 of framework 443ee691-d272-454c-90fe-959c95948252-0000 from agent 443ee691-d272-454c-90fe-959c95948252-S1 at slave(2)@172.17.0.7:37568 (89b080073abb)
> I0707 19:30:33.852810 29973 master.cpp:5321] Forwarding status update TASK_RUNNING (UUID: 1a550a5a-a5c4-4d37-9018-f6a41ca4eb14) for task 1 of framework 443ee691-d272-454c-90fe-959c95948252-0000
> I0707 19:30:33.853047 29973 master.cpp:6959] Updating the state of task 1 of framework 443ee691-d272-454c-90fe-959c95948252-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
> I0707 19:30:33.853245 29973 dynamic_reservation_framework.cpp:211] Task 1 is in state TASK_RUNNING
> I0707 19:30:33.853276 29973 sched.cpp:1025] Scheduler::statusUpdate took 41044ns
> I0707 19:30:33.854579 29970 master.cpp:4388] Processing ACKNOWLEDGE call 1a550a5a-a5c4-4d37-9018-f6a41ca4eb14 for task 1 of framework 443ee691-d272-454c-90fe-959c95948252-0000 (Dynamic Reservation Framework (C++)) at scheduler-a956abb7-0f5d-46e3-a670-a3f684eccbb5@172.17.0.7:37568 on agent 443ee691-d272-454c-90fe-959c95948252-S1
> I0707 19:30:33.855051 29970 status_update_manager.cpp:392] Received status update acknowledgement (UUID: 1a550a5a-a5c4-4d37-9018-f6a41ca4eb14) for task 1 of framework 443ee691-d272-454c-90fe-959c95948252-0000
> I0707 19:30:33.855461 29972 slave.cpp:2671] Status update manager successfully handled status update acknowledgement (UUID: 1a550a5a-a5c4-4d37-9018-f6a41ca4eb14) for task 1 of framework 443ee691-d272-454c-90fe-959c95948252-0000
> I0707 19:30:34.054215 30083 exec.cpp:161] Version: 1.0.0
> I0707 19:30:34.069156 29972 slave.cpp:2902] Got registration for executor '0' of framework 443ee691-d272-454c-90fe-959c95948252-0000 from executor(1)@172.17.0.7:37892
> I0707 19:30:34.077040 29972 slave.cpp:2079] Sending queued task '0' to executor '0' of framework 443ee691-d272-454c-90fe-959c95948252-0000 at executor(1)@172.17.0.7:37892
> I0707 19:30:34.082531 30081 exec.cpp:236] Executor registered on agent 443ee691-d272-454c-90fe-959c95948252-S0
> Received SUBSCRIBED event
> Subscribed executor on 89b080073abb
> Received LAUNCH event
> Starting task 0
> /mesos/mesos-1.0.0/_build/src/mesos-containerizer launch --command="{"shell":true,"value":"echo hello"}" --help="false" --unshare_namespace_mnt="false"
> Forked command at 30093
> I0707 19:30:34.121834 29971 slave.cpp:3285] Handling status update TASK_RUNNING (UUID: 4b52fae2-8c9c-4dd5-8459-729d84b86a2e) for task 0 of framework 443ee691-d272-454c-90fe-959c95948252-0000 from executor(1)@172.17.0.7:37892
> I0707 19:30:34.125562 29982 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 4b52fae2-8c9c-4dd5-8459-729d84b86a2e) for task 0 of framework 443ee691-d272-454c-90fe-959c95948252-0000
> I0707 19:30:34.125622 29982 status_update_manager.cpp:497] Creating StatusUpdate stream for task 0 of framework 443ee691-d272-454c-90fe-959c95948252-0000
> I0707 19:30:34.126216 29982 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: 4b52fae2-8c9c-4dd5-8459-729d84b86a2e) for task 0 of framework 443ee691-d272-454c-90fe-959c95948252-0000 to the agent
> I0707 19:30:34.126847 29971 slave.cpp:3678] Forwarding the update TASK_RUNNING (UUID: 4b52fae2-8c9c-4dd5-8459-729d84b86a2e) for task 0 of framework 443ee691-d272-454c-90fe-959c95948252-0000 to master@172.17.0.7:37568
> I0707 19:30:34.127034 29971 slave.cpp:3572] Status update manager successfully handled status update TASK_RUNNING (UUID: 4b52fae2-8c9c-4dd5-8459-729d84b86a2e) for task 0 of framework 443ee691-d272-454c-90fe-959c95948252-0000
> I0707 19:30:34.127084 29971 slave.cpp:3588] Sending acknowledgement for status update TASK_RUNNING (UUID: 4b52fae2-8c9c-4dd5-8459-729d84b86a2e) for task 0 of framework 443ee691-d272-454c-90fe-959c95948252-0000 to executor(1)@172.17.0.7:37892
> I0707 19:30:34.128938 29971 master.cpp:5273] Status update TASK_RUNNING (UUID: 4b52fae2-8c9c-4dd5-8459-729d84b86a2e) for task 0 of framework 443ee691-d272-454c-90fe-959c95948252-0000 from agent 443ee691-d272-454c-90fe-959c95948252-S0 at slave(3)@172.17.0.7:37568 (89b080073abb)
> I0707 19:30:34.128993 29971 master.cpp:5321] Forwarding status update TASK_RUNNING (UUID: 4b52fae2-8c9c-4dd5-8459-729d84b86a2e) for task 0 of framework 443ee691-d272-454c-90fe-959c95948252-0000
> I0707 19:30:34.129176 29971 master.cpp:6959] Updating the state of task 0 of framework 443ee691-d272-454c-90fe-959c95948252-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
> I0707 19:30:34.129348 29971 dynamic_reservation_framework.cpp:211] Task 0 is in state TASK_RUNNING
> I0707 19:30:34.129369 29971 sched.cpp:1025] Scheduler::statusUpdate took 31771ns
> I0707 19:30:34.130749 29971 master.cpp:4388] Processing ACKNOWLEDGE call 4b52fae2-8c9c-4dd5-8459-729d84b86a2e for task 0 of framework 443ee691-d272-454c-90fe-959c95948252-0000 (Dynamic Reservation Framework (C++)) at scheduler-a956abb7-0f5d-46e3-a670-a3f684eccbb5@172.17.0.7:37568 on agent 443ee691-d272-454c-90fe-959c95948252-S0
> I0707 19:30:34.131034 29971 status_update_manager.cpp:392] Received status update acknowledgement (UUID: 4b52fae2-8c9c-4dd5-8459-729d84b86a2e) for task 0 of framework 443ee691-d272-454c-90fe-959c95948252-0000
> I0707 19:30:34.131378 29971 slave.cpp:2671] Status update manager successfully handled status update acknowledgement (UUID: 4b52fae2-8c9c-4dd5-8459-729d84b86a2e) for task 0 of framework 443ee691-d272-454c-90fe-959c95948252-0000
> hello
> Command exited with status 0 (pid: 30062)
> I0707 19:30:34.343664 29977 slave.cpp:3285] Handling status update TASK_FINISHED (UUID: 08fecbb0-8539-4123-916a-37cda28ec934) for task 1 of framework 443ee691-d272-454c-90fe-959c95948252-0000 from executor(1)@172.17.0.7:38689
> I0707 19:30:34.346058 29984 slave.cpp:6088] Terminating task 1
> I0707 19:30:34.350986 29984 status_update_manager.cpp:320] Received status update TASK_FINISHED (UUID: 08fecbb0-8539-4123-916a-37cda28ec934) for task 1 of framework 443ee691-d272-454c-90fe-959c95948252-0000
> I0707 19:30:34.351263 29984 status_update_manager.cpp:374] Forwarding update TASK_FINISHED (UUID: 08fecbb0-8539-4123-916a-37cda28ec934) for task 1 of framework 443ee691-d272-454c-90fe-959c95948252-0000 to the agent
> I0707 19:30:34.353025 29984 slave.cpp:3678] Forwarding the update TASK_FINISHED (UUID: 08fecbb0-8539-4123-916a-37cda28ec934) for task 1 of framework 443ee691-d272-454c-90fe-959c95948252-0000 to master@172.17.0.7:37568
> I0707 19:30:34.353231 29984 slave.cpp:3572] Status update manager successfully handled status update TASK_FINISHED (UUID: 08fecbb0-8539-4123-916a-37cda28ec934) for task 1 of framework 443ee691-d272-454c-90fe-959c95948252-0000
> I0707 19:30:34.353282 29984 slave.cpp:3588] Sending acknowledgement for status update TASK_FINISHED (UUID: 08fecbb0-8539-4123-916a-37cda28ec934) for task 1 of framework 443ee691-d272-454c-90fe-959c95948252-0000 to executor(1)@172.17.0.7:38689
> I0707 19:30:34.353657 29969 master.cpp:5273] Status update TASK_FINISHED (UUID: 08fecbb0-8539-4123-916a-37cda28ec934) for task 1 of framework 443ee691-d272-454c-90fe-959c95948252-0000 from agent 443ee691-d272-454c-90fe-959c95948252-S1 at slave(2)@172.17.0.7:37568 (89b080073abb)
> I0707 19:30:34.353708 29969 master.cpp:5321] Forwarding status update TASK_FINISHED (UUID: 08fecbb0-8539-4123-916a-37cda28ec934) for task 1 of framework 443ee691-d272-454c-90fe-959c95948252-0000
> I0707 19:30:34.353883 29969 master.cpp:6959] Updating the state of task 1 of framework 443ee691-d272-454c-90fe-959c95948252-0000 (latest state: TASK_FINISHED, status update state: TASK_FINISHED)
> I0707 19:30:34.354302 29969 dynamic_reservation_framework.cpp:208] Task 1 is finished at agent 443ee691-d272-454c-90fe-959c95948252-S1
> I0707 19:30:34.354327 29969 sched.cpp:1025] Scheduler::statusUpdate took 42112ns
> I0707 19:30:34.354652 29969 master.cpp:4388] Processing ACKNOWLEDGE call 08fecbb0-8539-4123-916a-37cda28ec934 for task 1 of framework 443ee691-d272-454c-90fe-959c95948252-0000 (Dynamic Reservation Framework (C++)) at scheduler-a956abb7-0f5d-46e3-a670-a3f684eccbb5@172.17.0.7:37568 on agent 443ee691-d272-454c-90fe-959c95948252-S1
> I0707 19:30:34.354730 29969 master.cpp:7025] Removing task 1 with resources cpus(test, test):1; mem(test, test):128 of framework 443ee691-d272-454c-90fe-959c95948252-0000 on agent 443ee691-d272-454c-90fe-959c95948252-S1 at slave(2)@172.17.0.7:37568 (89b080073abb)
> I0707 19:30:34.357210 29977 hierarchical.cpp:1632] No inverse offers to send out!
> I0707 19:30:34.357326 29977 hierarchical.cpp:1172] Performed allocation for 3 agents in 7.731795ms
> I0707 19:30:34.358654 29969 master.cpp:5835] Sending 3 offers to framework 443ee691-d272-454c-90fe-959c95948252-0000 (Dynamic Reservation Framework (C++)) at scheduler-a956abb7-0f5d-46e3-a670-a3f684eccbb5@172.17.0.7:37568
> I0707 19:30:34.359386 29969 dynamic_reservation_framework.cpp:84] Received offer 443ee691-d272-454c-90fe-959c95948252-O5 with cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0707 19:30:34.359557 29969 dynamic_reservation_framework.cpp:164] The task on 443ee691-d272-454c-90fe-959c95948252-S0 is running, waiting for task done
> I0707 19:30:34.359571 29969 dynamic_reservation_framework.cpp:84] Received offer 443ee691-d272-454c-90fe-959c95948252-O6 with cpus(test, test):1; mem(test, test):128; cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0707 19:30:34.359845 29969 dynamic_reservation_framework.cpp:150] Launching task 2 using offer 443ee691-d272-454c-90fe-959c95948252-O6
> I0707 19:30:34.360051 29969 dynamic_reservation_framework.cpp:84] Received offer 443ee691-d272-454c-90fe-959c95948252-O7 with cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]
> F0707 19:30:34.360167 29969 dynamic_reservation_framework.cpp:135] Check failed: reserved.contains(taskResources)
> *** Check failure stack trace: ***
> I0707 19:30:34.361974 29975 status_update_manager.cpp:392] Received status update acknowledgement (UUID: 08fecbb0-8539-4123-916a-37cda28ec934) for task 1 of framework 443ee691-d272-454c-90fe-959c95948252-0000
> I0707 19:30:34.362541 29975 status_update_manager.cpp:528] Cleaning up status update stream for task 1 of framework 443ee691-d272-454c-90fe-959c95948252-0000
> I0707 19:30:34.362946 29977 hierarchical.cpp:924] Recovered cpus(test, test):1; mem(test, test):128 (total: cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]; cpus(test, test):1; mem(test, test):128, allocated: ports(*):[31000-32000]; disk(*):3.70122e+06; cpus(*):15; mem(*):47142) on agent 443ee691-d272-454c-90fe-959c95948252-S1 from framework 443ee691-d272-454c-90fe-959c95948252-0000
> I0707 19:30:34.363346 29975 slave.cpp:2671] Status update manager successfully handled status update acknowledgement (UUID: 08fecbb0-8539-4123-916a-37cda28ec934) for task 1 of framework 443ee691-d272-454c-90fe-959c95948252-0000
> I0707 19:30:34.363533 29975 slave.cpp:6129] Completing task 1
> hello
> Command exited with status 0 (pid: 30093)
> I0707 19:30:34.421588 29981 slave.cpp:3285] Handling status update TASK_FINISHED (UUID: 14598eb7-e5a3-4aec-9b92-abe6c26957c9) for task 0 of framework 443ee691-d272-454c-90fe-959c95948252-0000 from executor(1)@172.17.0.7:37892
> I0707 19:30:34.424176 29981 slave.cpp:6088] Terminating task 0
> I0707 19:30:34.427489 29970 status_update_manager.cpp:320] Received status update TASK_FINISHED (UUID: 14598eb7-e5a3-4aec-9b92-abe6c26957c9) for task 0 of framework 443ee691-d272-454c-90fe-959c95948252-0000
> I0707 19:30:34.427922 29970 status_update_manager.cpp:374] Forwarding update TASK_FINISHED (UUID: 14598eb7-e5a3-4aec-9b92-abe6c26957c9) for task 0 of framework 443ee691-d272-454c-90fe-959c95948252-0000 to the agent
> I0707 19:30:34.428794 29970 slave.cpp:3678] Forwarding the update TASK_FINISHED (UUID: 14598eb7-e5a3-4aec-9b92-abe6c26957c9) for task 0 of framework 443ee691-d272-454c-90fe-959c95948252-0000 to master@172.17.0.7:37568
> I0707 19:30:34.429209 29970 slave.cpp:3572] Status update manager successfully handled status update TASK_FINISHED (UUID: 14598eb7-e5a3-4aec-9b92-abe6c26957c9) for task 0 of framework 443ee691-d272-454c-90fe-959c95948252-0000
> I0707 19:30:34.429819 29970 slave.cpp:3588] Sending acknowledgement for status update TASK_FINISHED (UUID: 14598eb7-e5a3-4aec-9b92-abe6c26957c9) for task 0 of framework 443ee691-d272-454c-90fe-959c95948252-0000 to executor(1)@172.17.0.7:37892
> I0707 19:30:34.429739 29971 master.cpp:5273] Status update TASK_FINISHED (UUID: 14598eb7-e5a3-4aec-9b92-abe6c26957c9) for task 0 of framework 443ee691-d272-454c-90fe-959c95948252-0000 from agent 443ee691-d272-454c-90fe-959c95948252-S0 at slave(3)@172.17.0.7:37568 (89b080073abb)
> I0707 19:30:34.430163 29971 master.cpp:5321] Forwarding status update TASK_FINISHED (UUID: 14598eb7-e5a3-4aec-9b92-abe6c26957c9) for task 0 of framework 443ee691-d272-454c-90fe-959c95948252-0000
> I0707 19:30:34.430559 29971 master.cpp:6959] Updating the state of task 0 of framework 443ee691-d272-454c-90fe-959c95948252-0000 (latest state: TASK_FINISHED, status update state: TASK_FINISHED)
> I0707 19:30:34.432127 29971 hierarchical.cpp:924] Recovered cpus(test, test):1; mem(test, test):128 (total: cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]; cpus(test, test):1; mem(test, test):128, allocated: ports(*):[31000-32000]; disk(*):3.70122e+06; cpus(*):15; mem(*):47142) on agent 443ee691-d272-454c-90fe-959c95948252-S0 from framework 443ee691-d272-454c-90fe-959c95948252-0000
> @ 0x2b569c2093ed google::LogMessage::Fail()
> @ 0x2b569c2087ce google::LogMessage::SendToLog()
> @ 0x2b569c2090ad google::LogMessage::Flush()
> @ 0x2b569c20c528 google::LogMessageFatal::~LogMessageFatal()
> @ 0x45dba0 DynamicReservationScheduler::resourceOffers()
> @ 0x2b569b0a75d8 mesos::internal::SchedulerProcess::resourceOffers()
> @ 0x2b569b0bb3cf ProtobufProcess<>::handler2<>()
> @ 0x2b569b0bcdcd _ZNSt5_BindIFPFvPN5mesos8internal16SchedulerProcessEMS2_FvRKN7process4UPIDERKSt6vectorINS0_5OfferESaIS9_EERKS8_ISsSaISsEEEMNS1_21ResourceOffersMessageEKFRKN6google8protobuf16RepeatedPtrFieldIS9_EEvEMSK_KFRKNSN_ISsEEvES7_RKSsES3_SJ_SS_SX_St12_PlaceholderILi1EES12_ILi2EEEE6__callIvJS7_SZ_EJLm0ELm1ELm2ELm3ELm4ELm5EEEET_OSt5tupleIJDpT0_EESt12_Index_tupleIJXspT1_EEE
> @ 0x2b569b0bcc16 _ZNSt5_BindIFPFvPN5mesos8internal16SchedulerProcessEMS2_FvRKN7process4UPIDERKSt6vectorINS0_5OfferESaIS9_EERKS8_ISsSaISsEEEMNS1_21ResourceOffersMessageEKFRKN6google8protobuf16RepeatedPtrFieldIS9_EEvEMSK_KFRKNSN_ISsEEvES7_RKSsES3_SJ_SS_SX_St12_PlaceholderILi1EES12_ILi2EEEEclIJS7_SZ_EvEET0_DpOT_
> @ 0x2b569b0bc9b7 std::_Function_handler<>::_M_invoke()
> @ 0x2b569a964bb0 std::function<>::operator()()
> @ 0x2b569b0a2acb ProtobufProcess<>::visit()
> @ 0x2b569b0a2be7 ProtobufProcess<>::visit()
> @ 0x2b569af25d8e process::MessageEvent::visit()
> @ 0x2b569a95aad1 process::ProcessBase::serve()
> @ 0x2b569c120984 process::ProcessManager::resume()
> @ 0x2b569c12b6fc process::ProcessManager::init_threads()::$_0::operator()()
> @ 0x2b569c12b605 _ZNSt12_Bind_simpleIFZN7process14ProcessManager12init_threadsEvE3$_0vEE9_M_invokeIJEEEvSt12_Index_tupleIJXspT_EEE
> @ 0x2b569c12b5d5 std::_Bind_simple<>::operator()()
> @ 0x2b569c12b5ac std::thread::_Impl<>::_M_run()
> @ 0x2b569d80aa60 (unknown)
> @ 0x2b569df81184 start_thread
> @ 0x2b569e29137d (unknown)
> ../../src/tests/script.cpp:80: Failure
> Failed
> dynamic_reservation_framework_test.sh terminated with signal Aborted
> [ FAILED ] ExamplesTest.DynamicReservationFramework (7146 ms)
> {code}
> Logs from a previous good run:
> {code}
> [ RUN ] ExamplesTest.DynamicReservationFramework
> Using temporary directory '/tmp/ExamplesTest_DynamicReservationFramework_mXcx0v'
> /mesos/mesos-1.0.0/src/tests/dynamic_reservation_framework_test.sh: line 19: /mesos/mesos-1.0.0/_build/src/colors.sh: No such file or directory
> /mesos/mesos-1.0.0/src/tests/dynamic_reservation_framework_test.sh: line 20: /mesos/mesos-1.0.0/_build/src/atexit.sh: No such file or directory
> WARNING: Logging before InitGoogleLogging() is written to STDERR
> I0707 18:06:58.103094 31500 resources.cpp:572] Parsing resources as JSON failed: cpus:1;mem:128
> Trying semicolon-delimited string format instead
> I0707 18:06:58.116397 31500 process.cpp:1066] libprocess is initialized on 172.17.0.7:39581 with 16 worker threads
> I0707 18:06:58.116585 31500 logging.cpp:199] Logging to STDERR
> I0707 18:06:58.206984 31500 leveldb.cpp:174] Opened db in 84.981237ms
> I0707 18:06:58.240731 31500 leveldb.cpp:181] Compacted db in 33.702091ms
> I0707 18:06:58.240833 31500 leveldb.cpp:196] Created db iterator in 66372ns
> I0707 18:06:58.240985 31500 leveldb.cpp:202] Seeked to beginning of db in 4465ns
> I0707 18:06:58.241019 31500 leveldb.cpp:271] Iterated through 0 keys in the db in 450ns
> I0707 18:06:58.241217 31500 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> I0707 18:06:58.244328 31500 local.cpp:255] Creating default 'local' authorizer
> I0707 18:06:58.244483 31529 recover.cpp:451] Starting replica recovery
> I0707 18:06:58.245290 31529 recover.cpp:477] Replica is in EMPTY status
> I0707 18:06:58.248134 31529 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from (4)@172.17.0.7:39581
> I0707 18:06:58.249553 31534 recover.cpp:197] Received a recover response from a replica in EMPTY status
> I0707 18:06:58.250586 31525 recover.cpp:568] Updating replica status to STARTING
> I0707 18:06:58.252516 31533 master.cpp:382] Master 7892fbb2-1ac1-450f-8576-10c1df35f765 (753c2ae3a486) started on 172.17.0.7:39581
> I0707 18:06:58.252545 31533 master.cpp:384] Flags at startup: --acls="permissive: true
> register_frameworks {
> principals {
> type: ANY
> }
> roles {
> type: SOME
> values: "test"
> }
> }
> " --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate_agents="false" --authenticate_frameworks="false" --authenticate_http="false" --authenticate_http_frameworks="false" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/ExamplesTest_DynamicReservationFramework_mXcx0v/credentials" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_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" --quiet="false" --recovery_agent_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_store_timeout="20secs" --registry_strict="false" --root_submissions="true" --user_sorter="drf" --version="false" --webui_dir="/mesos/mesos-1.0.0/src/webui" --work_dir="/tmp/mesos-IFR4rG" --zk_session_timeout="10secs"
> I0707 18:06:58.253370 31533 master.cpp:436] Master allowing unauthenticated frameworks to register
> I0707 18:06:58.253386 31533 master.cpp:450] Master allowing unauthenticated agents to register
> I0707 18:06:58.253397 31533 master.cpp:464] Master allowing HTTP frameworks to register without authentication
> I0707 18:06:58.253464 31533 credentials.hpp:37] Loading credentials for authentication from '/tmp/ExamplesTest_DynamicReservationFramework_mXcx0v/credentials'
> W0707 18:06:58.253582 31533 credentials.hpp:52] Permissions on credentials file '/tmp/ExamplesTest_DynamicReservationFramework_mXcx0v/credentials' are too open. It is recommended that your credentials file is NOT accessible by others.
> I0707 18:06:58.253777 31533 master.cpp:506] Using default 'crammd5' authenticator
> I0707 18:06:58.253957 31533 authenticator.cpp:519] Initializing server SASL
> I0707 18:06:58.259035 31533 auxprop.cpp:73] Initialized in-memory auxiliary property plugin
> I0707 18:06:58.259171 31533 master.cpp:705] Authorization enabled
> I0707 18:06:58.260638 31538 hierarchical.cpp:151] Initialized hierarchical allocator process
> I0707 18:06:58.260769 31538 whitelist_watcher.cpp:77] No whitelist given
> I0707 18:06:58.261309 31500 containerizer.cpp:196] Using isolation: filesystem/posix,posix/cpu,posix/mem,network/cni
> W0707 18:06:58.266885 31500 backend.cpp:75] Failed to create 'aufs' backend: AufsBackend requires root privileges, but is running as user mesos
> W0707 18:06:58.267235 31500 backend.cpp:75] Failed to create 'bind' backend: BindBackend requires root privileges
> I0707 18:06:58.274190 31525 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 23.019016ms
> I0707 18:06:58.274230 31525 replica.cpp:320] Persisted replica status to STARTING
> I0707 18:06:58.274695 31527 recover.cpp:477] Replica is in STARTING status
> I0707 18:06:58.276667 31531 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from (15)@172.17.0.7:39581
> I0707 18:06:58.277261 31538 recover.cpp:197] Received a recover response from a replica in STARTING status
> I0707 18:06:58.277840 31536 recover.cpp:568] Updating replica status to VOTING
> I0707 18:06:58.279667 31532 slave.cpp:205] Agent started on 1)@172.17.0.7:39581
> I0707 18:06:58.279690 31532 slave.cpp:206] Flags at startup: --acls="permissive: true
> register_frameworks {
> principals {
> type: ANY
> }
> roles {
> type: SOME
> values: "test"
> }
> }
> " --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http="false" --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" --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="/tmp/mesos/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/mesos/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_command_executor="false" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="filesystem/posix,posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/mesos/mesos-1.0.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="1secs" --revocable_cpu_low_priority="true" --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/mesos-IFR4rG/0"
> I0707 18:06:58.280802 31532 resources.cpp:572] Parsing resources as JSON failed:
> Trying semicolon-delimited string format instead
> I0707 18:06:58.280975 31532 resources.cpp:572] Parsing resources as JSON failed:
> Trying semicolon-delimited string format instead
> I0707 18:06:58.281785 31532 slave.cpp:594] Agent resources: cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0707 18:06:58.281886 31532 slave.cpp:602] Agent attributes: [ ]
> I0707 18:06:58.281918 31532 slave.cpp:607] Agent hostname: 753c2ae3a486
> I0707 18:06:58.285878 31500 containerizer.cpp:196] Using isolation: filesystem/posix,posix/cpu,posix/mem,network/cni
> I0707 18:06:58.286325 31535 state.cpp:57] Recovering state from '/tmp/mesos-IFR4rG/0/meta'
> I0707 18:06:58.289796 31525 master.cpp:1973] The newly elected leader is master@172.17.0.7:39581 with id 7892fbb2-1ac1-450f-8576-10c1df35f765
> I0707 18:06:58.289837 31525 master.cpp:1986] Elected as the leading master!
> I0707 18:06:58.289881 31525 master.cpp:1673] Recovering from registrar
> I0707 18:06:58.290081 31528 registrar.cpp:332] Recovering registrar
> I0707 18:06:58.298210 31532 status_update_manager.cpp:200] Recovering status update manager
> I0707 18:06:58.298463 31532 containerizer.cpp:522] Recovering containerizer
> I0707 18:06:58.310628 31530 provisioner.cpp:253] Provisioner recovery complete
> I0707 18:06:58.311688 31531 slave.cpp:4856] Finished recovery
> I0707 18:06:58.314482 31538 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 36.508519ms
> I0707 18:06:58.314538 31538 replica.cpp:320] Persisted replica status to VOTING
> I0707 18:06:58.314743 31538 recover.cpp:582] Successfully joined the Paxos group
> I0707 18:06:58.315083 31538 recover.cpp:466] Recover process terminated
> I0707 18:06:58.316979 31538 log.cpp:553] Attempting to start the writer
> W0707 18:06:58.319859 31500 backend.cpp:75] Failed to create 'aufs' backend: AufsBackend requires root privileges, but is running as user mesos
> W0707 18:06:58.320173 31500 backend.cpp:75] Failed to create 'bind' backend: BindBackend requires root privileges
> I0707 18:06:58.325480 31531 slave.cpp:5028] Querying resource estimator for oversubscribable resources
> I0707 18:06:58.326918 31525 slave.cpp:5042] Received oversubscribable resources from the resource estimator
> I0707 18:06:58.332331 31531 status_update_manager.cpp:174] Pausing sending status updates
> I0707 18:06:58.332393 31534 slave.cpp:969] New master detected at master@172.17.0.7:39581
> I0707 18:06:58.332491 31534 slave.cpp:990] No credentials provided. Attempting to register without authentication
> I0707 18:06:58.332593 31534 slave.cpp:1001] Detecting new master
> I0707 18:06:58.333231 31539 replica.cpp:493] Replica received implicit promise request from (30)@172.17.0.7:39581 with proposal 1
> I0707 18:06:58.340519 31527 slave.cpp:205] Agent started on 2)@172.17.0.7:39581
> I0707 18:06:58.340543 31527 slave.cpp:206] Flags at startup: --acls="permissive: true
> register_frameworks {
> principals {
> type: ANY
> }
> roles {
> type: SOME
> values: "test"
> }
> }
> " --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http="false" --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" --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="/tmp/mesos/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/mesos/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_command_executor="false" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="filesystem/posix,posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/mesos/mesos-1.0.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="1secs" --revocable_cpu_low_priority="true" --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/mesos-IFR4rG/1"
> I0707 18:06:58.341367 31527 resources.cpp:572] Parsing resources as JSON failed:
> Trying semicolon-delimited string format instead
> I0707 18:06:58.343765 31527 resources.cpp:572] Parsing resources as JSON failed:
> Trying semicolon-delimited string format instead
> I0707 18:06:58.582685 31527 slave.cpp:594] Agent resources: cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0707 18:06:58.582808 31527 slave.cpp:602] Agent attributes: [ ]
> I0707 18:06:58.582825 31527 slave.cpp:607] Agent hostname: 753c2ae3a486
> I0707 18:06:58.583901 31536 slave.cpp:1529] Will retry registration in 1.442011578secs if necessary
> I0707 18:06:58.584017 31536 master.cpp:1500] Dropping 'mesos.internal.RegisterSlaveMessage' message since not recovered yet
> I0707 18:06:58.586772 31527 state.cpp:57] Recovering state from '/tmp/mesos-IFR4rG/1/meta'
> I0707 18:06:58.587353 31527 status_update_manager.cpp:200] Recovering status update manager
> I0707 18:06:58.587736 31525 containerizer.cpp:522] Recovering containerizer
> I0707 18:06:58.590937 31500 containerizer.cpp:196] Using isolation: filesystem/posix,posix/cpu,posix/mem,network/cni
> I0707 18:06:58.592527 31529 provisioner.cpp:253] Provisioner recovery complete
> I0707 18:06:58.594597 31527 slave.cpp:4856] Finished recovery
> I0707 18:06:58.595170 31527 slave.cpp:5028] Querying resource estimator for oversubscribable resources
> I0707 18:06:58.596602 31529 slave.cpp:5042] Received oversubscribable resources from the resource estimator
> W0707 18:06:58.597026 31500 backend.cpp:75] Failed to create 'aufs' backend: AufsBackend requires root privileges, but is running as user mesos
> I0707 18:06:58.597048 31527 slave.cpp:969] New master detected at master@172.17.0.7:39581
> I0707 18:06:58.597074 31527 slave.cpp:990] No credentials provided. Attempting to register without authentication
> I0707 18:06:58.597183 31529 status_update_manager.cpp:174] Pausing sending status updates
> W0707 18:06:58.597195 31500 backend.cpp:75] Failed to create 'bind' backend: BindBackend requires root privileges
> I0707 18:06:58.597316 31527 slave.cpp:1001] Detecting new master
> I0707 18:06:58.622475 31528 slave.cpp:205] Agent started on 3)@172.17.0.7:39581
> I0707 18:06:58.622517 31528 slave.cpp:206] Flags at startup: --acls="permissive: true
> register_frameworks {
> principals {
> type: ANY
> }
> roles {
> type: SOME
> values: "test"
> }
> }
> " --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http="false" --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" --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="/tmp/mesos/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/mesos/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="true" --hostname_lookup="true" --http_authenticators="basic" --http_command_executor="false" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="filesystem/posix,posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/mesos/mesos-1.0.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="1secs" --revocable_cpu_low_priority="true" --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/mesos-IFR4rG/2"
> I0707 18:06:58.623533 31528 resources.cpp:572] Parsing resources as JSON failed:
> Trying semicolon-delimited string format instead
> I0707 18:06:58.623703 31528 resources.cpp:572] Parsing resources as JSON failed:
> Trying semicolon-delimited string format instead
> I0707 18:06:58.624135 31528 slave.cpp:594] Agent resources: cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0707 18:06:58.624209 31528 slave.cpp:602] Agent attributes: [ ]
> I0707 18:06:58.624224 31528 slave.cpp:607] Agent hostname: 753c2ae3a486
> I0707 18:06:58.628917 31533 state.cpp:57] Recovering state from '/tmp/mesos-IFR4rG/2/meta'
> I0707 18:06:58.629308 31533 status_update_manager.cpp:200] Recovering status update manager
> I0707 18:06:58.629530 31533 containerizer.cpp:522] Recovering containerizer
> I0707 18:06:58.631003 31500 sched.cpp:226] Version: 1.0.0
> I0707 18:06:58.632382 31536 provisioner.cpp:253] Provisioner recovery complete
> I0707 18:06:58.632655 31530 sched.cpp:330] New master detected at master@172.17.0.7:39581
> I0707 18:06:58.632758 31530 sched.cpp:341] No credentials provided. Attempting to register without authentication
> I0707 18:06:58.632786 31530 sched.cpp:820] Sending SUBSCRIBE call to master@172.17.0.7:39581
> I0707 18:06:58.632921 31530 sched.cpp:853] Will retry registration in 1.972934225secs if necessary
> I0707 18:06:58.633108 31535 master.cpp:1500] Dropping 'mesos.scheduler.Call' message since not recovered yet
> I0707 18:06:58.633489 31530 slave.cpp:4856] Finished recovery
> I0707 18:06:58.633956 31530 slave.cpp:5028] Querying resource estimator for oversubscribable resources
> I0707 18:06:58.634172 31530 slave.cpp:969] New master detected at master@172.17.0.7:39581
> I0707 18:06:58.634199 31530 slave.cpp:990] No credentials provided. Attempting to register without authentication
> I0707 18:06:58.634241 31530 slave.cpp:1001] Detecting new master
> I0707 18:06:58.634254 31538 status_update_manager.cpp:174] Pausing sending status updates
> I0707 18:06:58.634354 31530 slave.cpp:5042] Received oversubscribable resources from the resource estimator
> I0707 18:06:58.646832 31538 slave.cpp:1529] Will retry registration in 421.765838ms if necessary
> I0707 18:06:58.647001 31538 master.cpp:1500] Dropping 'mesos.internal.RegisterSlaveMessage' message since not recovered yet
> I0707 18:06:58.814708 31539 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 481.415169ms
> I0707 18:06:58.814787 31539 replica.cpp:342] Persisted promised to 1
> I0707 18:06:58.816249 31539 coordinator.cpp:238] Coordinator attempting to fill missing positions
> I0707 18:06:58.820055 31525 replica.cpp:388] Replica received explicit promise request from (49)@172.17.0.7:39581 for position 0 with proposal 2
> I0707 18:06:58.865041 31525 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 44.725594ms
> I0707 18:06:58.865135 31525 replica.cpp:712] Persisted action at 0
> I0707 18:06:58.868293 31531 replica.cpp:537] Replica received write request for position 0 from (50)@172.17.0.7:39581
> I0707 18:06:58.868521 31531 leveldb.cpp:436] Reading position from leveldb took 71896ns
> I0707 18:06:58.901504 31531 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 32.785731ms
> I0707 18:06:58.901585 31531 replica.cpp:712] Persisted action at 0
> I0707 18:06:58.903040 31534 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0
> I0707 18:06:58.934504 31534 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 31.403773ms
> I0707 18:06:58.934590 31534 replica.cpp:712] Persisted action at 0
> I0707 18:06:58.934640 31534 replica.cpp:697] Replica learned NOP action at position 0
> I0707 18:06:58.936309 31534 log.cpp:569] Writer started with ending position 0
> I0707 18:06:58.941576 31534 leveldb.cpp:436] Reading position from leveldb took 74550ns
> I0707 18:06:58.950364 31534 registrar.cpp:365] Successfully fetched the registry (0B) in 660.20608ms
> I0707 18:06:58.952555 31534 registrar.cpp:464] Applied 1 operations in 61140ns; attempting to update the 'registry'
> I0707 18:06:58.955271 31535 log.cpp:577] Attempting to append 168 bytes to the log
> I0707 18:06:58.955555 31534 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
> I0707 18:06:58.958256 31534 replica.cpp:537] Replica received write request for position 1 from (51)@172.17.0.7:39581
> I0707 18:06:59.000967 31534 leveldb.cpp:341] Persisting action (187 bytes) to leveldb took 42.408267ms
> I0707 18:06:59.001049 31534 replica.cpp:712] Persisted action at 1
> I0707 18:06:59.004665 31535 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
> I0707 18:06:59.051337 31535 leveldb.cpp:341] Persisting action (189 bytes) to leveldb took 46.611618ms
> I0707 18:06:59.051431 31535 replica.cpp:712] Persisted action at 1
> I0707 18:06:59.051483 31535 replica.cpp:697] Replica learned APPEND action at position 1
> I0707 18:06:59.054003 31537 registrar.cpp:509] Successfully updated the 'registry' in 101.27104ms
> I0707 18:06:59.054268 31537 registrar.cpp:395] Successfully recovered registrar
> I0707 18:06:59.054762 31525 log.cpp:596] Attempting to truncate the log to 1
> I0707 18:06:59.055158 31537 master.cpp:1781] Recovered 0 agents from the Registry (129B) ; allowing 10mins for agents to re-register
> I0707 18:06:59.055218 31539 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
> I0707 18:06:59.055346 31525 hierarchical.cpp:178] Skipping recovery of hierarchical allocator: nothing to recover
> I0707 18:06:59.056404 31539 replica.cpp:537] Replica received write request for position 2 from (52)@172.17.0.7:39581
> I0707 18:06:59.069908 31537 slave.cpp:1529] Will retry registration in 2.057528722secs if necessary
> I0707 18:06:59.070539 31530 master.cpp:4676] Registering agent at slave(2)@172.17.0.7:39581 (753c2ae3a486) with id 7892fbb2-1ac1-450f-8576-10c1df35f765-S0
> I0707 18:06:59.071838 31530 registrar.cpp:464] Applied 1 operations in 139897ns; attempting to update the 'registry'
> I0707 18:06:59.101510 31539 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 44.978496ms
> I0707 18:06:59.101680 31539 replica.cpp:712] Persisted action at 2
> I0707 18:06:59.102838 31527 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
> I0707 18:06:59.165279 31527 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 62.339577ms
> I0707 18:06:59.165451 31527 leveldb.cpp:399] Deleting ~1 keys from leveldb took 89301ns
> I0707 18:06:59.165479 31527 replica.cpp:712] Persisted action at 2
> I0707 18:06:59.165531 31527 replica.cpp:697] Replica learned TRUNCATE action at position 2
> I0707 18:06:59.167273 31533 log.cpp:577] Attempting to append 337 bytes to the log
> I0707 18:06:59.167647 31526 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3
> I0707 18:06:59.169075 31526 replica.cpp:537] Replica received write request for position 3 from (53)@172.17.0.7:39581
> I0707 18:06:59.224467 31526 leveldb.cpp:341] Persisting action (356 bytes) to leveldb took 55.235676ms
> I0707 18:06:59.224548 31526 replica.cpp:712] Persisted action at 3
> I0707 18:06:59.226044 31526 replica.cpp:691] Replica received learned notice for position 3 from @0.0.0.0:0
> I0707 18:06:59.262912 31525 hierarchical.cpp:1537] No allocations performed
> I0707 18:06:59.263056 31525 hierarchical.cpp:1172] Performed allocation for 0 agents in 345421ns
> I0707 18:06:59.283505 31526 leveldb.cpp:341] Persisting action (358 bytes) to leveldb took 57.362529ms
> I0707 18:06:59.283589 31526 replica.cpp:712] Persisted action at 3
> I0707 18:06:59.283638 31526 replica.cpp:697] Replica learned APPEND action at position 3
> I0707 18:06:59.287037 31538 registrar.cpp:509] Successfully updated the 'registry' in 215.051008ms
> I0707 18:06:59.287451 31533 log.cpp:596] Attempting to truncate the log to 3
> I0707 18:06:59.288493 31539 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 4
> I0707 18:06:59.289965 31532 replica.cpp:537] Replica received write request for position 4 from (54)@172.17.0.7:39581
> I0707 18:06:59.291105 31533 master.cpp:4745] Registered agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S0 at slave(2)@172.17.0.7:39581 (753c2ae3a486) with cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0707 18:06:59.291481 31533 slave.cpp:1169] Registered with master master@172.17.0.7:39581; given agent ID 7892fbb2-1ac1-450f-8576-10c1df35f765-S0
> I0707 18:06:59.291512 31533 fetcher.cpp:86] Clearing fetcher cache
> I0707 18:06:59.291749 31539 hierarchical.cpp:478] Added agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S0 (753c2ae3a486) with cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000] (allocated: )
> I0707 18:06:59.292026 31533 slave.cpp:1192] Checkpointing SlaveInfo to '/tmp/mesos-IFR4rG/1/meta/slaves/7892fbb2-1ac1-450f-8576-10c1df35f765-S0/slave.info'
> I0707 18:06:59.292233 31525 status_update_manager.cpp:181] Resuming sending status updates
> I0707 18:06:59.292330 31539 hierarchical.cpp:1537] No allocations performed
> I0707 18:06:59.292726 31533 slave.cpp:1229] Forwarding total oversubscribed resources
> I0707 18:06:59.292819 31539 hierarchical.cpp:1195] Performed allocation for agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S0 in 968472ns
> I0707 18:06:59.292860 31533 slave.cpp:3760] Received ping from slave-observer(1)@172.17.0.7:39581
> I0707 18:06:59.293042 31525 master.cpp:5128] Received update of agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S0 at slave(2)@172.17.0.7:39581 (753c2ae3a486) with total oversubscribed resources
> I0707 18:06:59.293349 31525 hierarchical.cpp:542] Agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S0 (753c2ae3a486) updated with oversubscribed resources (total: cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: )
> I0707 18:06:59.294507 31525 hierarchical.cpp:1537] No allocations performed
> I0707 18:06:59.294569 31525 hierarchical.cpp:1195] Performed allocation for agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S0 in 1.17629ms
> I0707 18:06:59.343272 31539 slave.cpp:1529] Will retry registration in 1.912221755secs if necessary
> I0707 18:06:59.343785 31528 master.cpp:4676] Registering agent at slave(3)@172.17.0.7:39581 (753c2ae3a486) with id 7892fbb2-1ac1-450f-8576-10c1df35f765-S1
> I0707 18:06:59.344733 31528 registrar.cpp:464] Applied 1 operations in 125766ns; attempting to update the 'registry'
> I0707 18:06:59.362001 31532 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 71.968888ms
> I0707 18:06:59.362097 31532 replica.cpp:712] Persisted action at 4
> I0707 18:06:59.363359 31527 replica.cpp:691] Replica received learned notice for position 4 from @0.0.0.0:0
> I0707 18:06:59.412232 31527 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 48.705675ms
> I0707 18:06:59.412684 31527 leveldb.cpp:399] Deleting ~2 keys from leveldb took 95246ns
> I0707 18:06:59.412853 31527 replica.cpp:712] Persisted action at 4
> I0707 18:06:59.413059 31527 replica.cpp:697] Replica learned TRUNCATE action at position 4
> I0707 18:06:59.414814 31536 log.cpp:577] Attempting to append 503 bytes to the log
> I0707 18:06:59.414932 31527 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 5
> I0707 18:06:59.415906 31536 replica.cpp:537] Replica received write request for position 5 from (55)@172.17.0.7:39581
> I0707 18:06:59.462564 31536 leveldb.cpp:341] Persisting action (522 bytes) to leveldb took 46.531781ms
> I0707 18:06:59.462729 31536 replica.cpp:712] Persisted action at 5
> I0707 18:06:59.463939 31536 replica.cpp:691] Replica received learned notice for position 5 from @0.0.0.0:0
> I0707 18:06:59.534988 31536 leveldb.cpp:341] Persisting action (524 bytes) to leveldb took 70.884462ms
> I0707 18:06:59.535076 31536 replica.cpp:712] Persisted action at 5
> I0707 18:06:59.535125 31536 replica.cpp:697] Replica learned APPEND action at position 5
> I0707 18:06:59.540696 31533 registrar.cpp:509] Successfully updated the 'registry' in 195.819008ms
> I0707 18:06:59.541802 31533 log.cpp:596] Attempting to truncate the log to 5
> I0707 18:06:59.544545 31533 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 6
> I0707 18:06:59.545786 31536 master.cpp:4745] Registered agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S1 at slave(3)@172.17.0.7:39581 (753c2ae3a486) with cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0707 18:06:59.546710 31536 hierarchical.cpp:478] Added agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S1 (753c2ae3a486) with cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000] (allocated: )
> I0707 18:06:59.547562 31536 hierarchical.cpp:1537] No allocations performed
> I0707 18:06:59.547972 31536 hierarchical.cpp:1195] Performed allocation for agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S1 in 540048ns
> I0707 18:06:59.547883 31533 slave.cpp:1169] Registered with master master@172.17.0.7:39581; given agent ID 7892fbb2-1ac1-450f-8576-10c1df35f765-S1
> I0707 18:06:59.549479 31533 fetcher.cpp:86] Clearing fetcher cache
> I0707 18:06:59.549988 31533 slave.cpp:1192] Checkpointing SlaveInfo to '/tmp/mesos-IFR4rG/2/meta/slaves/7892fbb2-1ac1-450f-8576-10c1df35f765-S1/slave.info'
> I0707 18:06:59.550889 31533 slave.cpp:1229] Forwarding total oversubscribed resources
> I0707 18:06:59.551502 31533 slave.cpp:3760] Received ping from slave-observer(2)@172.17.0.7:39581
> I0707 18:06:59.550431 31536 replica.cpp:537] Replica received write request for position 6 from (56)@172.17.0.7:39581
> I0707 18:06:59.551846 31533 status_update_manager.cpp:181] Resuming sending status updates
> I0707 18:06:59.552496 31533 master.cpp:5128] Received update of agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S1 at slave(3)@172.17.0.7:39581 (753c2ae3a486) with total oversubscribed resources
> I0707 18:06:59.552784 31533 hierarchical.cpp:542] Agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S1 (753c2ae3a486) updated with oversubscribed resources (total: cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: )
> I0707 18:06:59.553241 31533 hierarchical.cpp:1537] No allocations performed
> I0707 18:06:59.553311 31533 hierarchical.cpp:1195] Performed allocation for agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S1 in 481606ns
> I0707 18:06:59.586164 31536 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 34.414546ms
> I0707 18:06:59.586247 31536 replica.cpp:712] Persisted action at 6
> I0707 18:06:59.587699 31536 replica.cpp:691] Replica received learned notice for position 6 from @0.0.0.0:0
> I0707 18:06:59.619674 31536 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 31.87307ms
> I0707 18:06:59.619837 31536 leveldb.cpp:399] Deleting ~2 keys from leveldb took 82424ns
> I0707 18:06:59.619864 31536 replica.cpp:712] Persisted action at 6
> I0707 18:06:59.619913 31536 replica.cpp:697] Replica learned TRUNCATE action at position 6
> I0707 18:07:00.026949 31524 slave.cpp:1529] Will retry registration in 2.762006963secs if necessary
> I0707 18:07:00.027307 31524 master.cpp:4676] Registering agent at slave(1)@172.17.0.7:39581 (753c2ae3a486) with id 7892fbb2-1ac1-450f-8576-10c1df35f765-S2
> I0707 18:07:00.028275 31525 registrar.cpp:464] Applied 1 operations in 158666ns; attempting to update the 'registry'
> I0707 18:07:00.032213 31524 log.cpp:577] Attempting to append 669 bytes to the log
> I0707 18:07:00.032482 31525 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 7
> I0707 18:07:00.034119 31525 replica.cpp:537] Replica received write request for position 7 from (57)@172.17.0.7:39581
> I0707 18:07:00.048461 31525 leveldb.cpp:341] Persisting action (688 bytes) to leveldb took 14.18893ms
> I0707 18:07:00.048629 31525 replica.cpp:712] Persisted action at 7
> I0707 18:07:00.050050 31530 replica.cpp:691] Replica received learned notice for position 7 from @0.0.0.0:0
> I0707 18:07:00.113382 31530 leveldb.cpp:341] Persisting action (690 bytes) to leveldb took 63.230657ms
> I0707 18:07:00.113576 31530 replica.cpp:712] Persisted action at 7
> I0707 18:07:00.113853 31530 replica.cpp:697] Replica learned APPEND action at position 7
> I0707 18:07:00.117030 31526 registrar.cpp:509] Successfully updated the 'registry' in 88.66816ms
> I0707 18:07:00.117674 31530 log.cpp:596] Attempting to truncate the log to 7
> I0707 18:07:00.117910 31528 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 8
> I0707 18:07:00.118896 31526 master.cpp:4745] Registered agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S2 at slave(1)@172.17.0.7:39581 (753c2ae3a486) with cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0707 18:07:00.119174 31526 replica.cpp:537] Replica received write request for position 8 from (58)@172.17.0.7:39581
> I0707 18:07:00.119213 31531 slave.cpp:1169] Registered with master master@172.17.0.7:39581; given agent ID 7892fbb2-1ac1-450f-8576-10c1df35f765-S2
> I0707 18:07:00.119254 31531 fetcher.cpp:86] Clearing fetcher cache
> I0707 18:07:00.119482 31527 status_update_manager.cpp:181] Resuming sending status updates
> I0707 18:07:00.119736 31531 slave.cpp:1192] Checkpointing SlaveInfo to '/tmp/mesos-IFR4rG/0/meta/slaves/7892fbb2-1ac1-450f-8576-10c1df35f765-S2/slave.info'
> I0707 18:07:00.120182 31531 slave.cpp:1229] Forwarding total oversubscribed resources
> I0707 18:07:00.120273 31531 slave.cpp:3760] Received ping from slave-observer(3)@172.17.0.7:39581
> I0707 18:07:00.120461 31531 master.cpp:5128] Received update of agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S2 at slave(1)@172.17.0.7:39581 (753c2ae3a486) with total oversubscribed resources
> I0707 18:07:00.120740 31539 hierarchical.cpp:478] Added agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S2 (753c2ae3a486) with cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000] (allocated: )
> I0707 18:07:00.120904 31539 hierarchical.cpp:1537] No allocations performed
> I0707 18:07:00.121006 31539 hierarchical.cpp:1195] Performed allocation for agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S2 in 222368ns
> I0707 18:07:00.121196 31539 hierarchical.cpp:542] Agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S2 (753c2ae3a486) updated with oversubscribed resources (total: cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: )
> I0707 18:07:00.121511 31539 hierarchical.cpp:1537] No allocations performed
> I0707 18:07:00.121609 31539 hierarchical.cpp:1195] Performed allocation for agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S2 in 178299ns
> I0707 18:07:00.168759 31526 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 49.379822ms
> I0707 18:07:00.168941 31526 replica.cpp:712] Persisted action at 8
> I0707 18:07:00.173840 31535 replica.cpp:691] Replica received learned notice for position 8 from @0.0.0.0:0
> I0707 18:07:00.227267 31535 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 53.368171ms
> I0707 18:07:00.227453 31535 leveldb.cpp:399] Deleting ~2 keys from leveldb took 98129ns
> I0707 18:07:00.227483 31535 replica.cpp:712] Persisted action at 8
> I0707 18:07:00.227536 31535 replica.cpp:697] Replica learned TRUNCATE action at position 8
> I0707 18:07:00.264490 31537 hierarchical.cpp:1537] No allocations performed
> I0707 18:07:00.264606 31537 hierarchical.cpp:1172] Performed allocation for 3 agents in 410062ns
> I0707 18:07:00.606685 31537 sched.cpp:820] Sending SUBSCRIBE call to master@172.17.0.7:39581
> I0707 18:07:00.606863 31537 sched.cpp:853] Will retry registration in 3.19389747secs if necessary
> I0707 18:07:00.607161 31537 master.cpp:2550] Received SUBSCRIBE call for framework 'Dynamic Reservation Framework (C++)' at scheduler-c51aa6e6-f5b6-4bfc-982c-9a71ea56a862@172.17.0.7:39581
> I0707 18:07:00.607316 31537 master.cpp:2012] Authorizing framework principal 'test' to receive offers for role 'test'
> I0707 18:07:00.608633 31537 master.cpp:2626] Subscribing framework Dynamic Reservation Framework (C++) with checkpointing disabled and capabilities [ ]
> I0707 18:07:00.610199 31535 hierarchical.cpp:271] Added framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:00.611109 31537 sched.cpp:743] Framework registered with 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:00.611136 31537 dynamic_reservation_framework.cpp:73] Registered!
> I0707 18:07:00.611152 31537 sched.cpp:757] Scheduler::registered took 18259ns
> I0707 18:07:00.613695 31535 hierarchical.cpp:1632] No inverse offers to send out!
> I0707 18:07:00.613819 31535 hierarchical.cpp:1172] Performed allocation for 3 agents in 3.590355ms
> I0707 18:07:00.615160 31535 master.cpp:5835] Sending 3 offers to framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (Dynamic Reservation Framework (C++)) at scheduler-c51aa6e6-f5b6-4bfc-982c-9a71ea56a862@172.17.0.7:39581
> I0707 18:07:00.616071 31535 dynamic_reservation_framework.cpp:84] Received offer 7892fbb2-1ac1-450f-8576-10c1df35f765-O0 with cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0707 18:07:00.616686 31535 dynamic_reservation_framework.cpp:84] Received offer 7892fbb2-1ac1-450f-8576-10c1df35f765-O1 with cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0707 18:07:00.617288 31535 dynamic_reservation_framework.cpp:84] Received offer 7892fbb2-1ac1-450f-8576-10c1df35f765-O2 with cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0707 18:07:00.617588 31535 sched.cpp:917] Scheduler::resourceOffers took 1.516257ms
> I0707 18:07:00.619355 31531 master.cpp:3468] Processing ACCEPT call for offers: [ 7892fbb2-1ac1-450f-8576-10c1df35f765-O0 ] on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S2 at slave(1)@172.17.0.7:39581 (753c2ae3a486) for framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (Dynamic Reservation Framework (C++)) at scheduler-c51aa6e6-f5b6-4bfc-982c-9a71ea56a862@172.17.0.7:39581
> I0707 18:07:00.619647 31531 master.cpp:3144] Authorizing principal 'test' to reserve resources 'cpus(test, test):1; mem(test, test):128'
> I0707 18:07:00.621302 31531 master.cpp:3468] Processing ACCEPT call for offers: [ 7892fbb2-1ac1-450f-8576-10c1df35f765-O1 ] on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S1 at slave(3)@172.17.0.7:39581 (753c2ae3a486) for framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (Dynamic Reservation Framework (C++)) at scheduler-c51aa6e6-f5b6-4bfc-982c-9a71ea56a862@172.17.0.7:39581
> I0707 18:07:00.621472 31531 master.cpp:3144] Authorizing principal 'test' to reserve resources 'cpus(test, test):1; mem(test, test):128'
> I0707 18:07:00.622601 31531 master.cpp:3468] Processing ACCEPT call for offers: [ 7892fbb2-1ac1-450f-8576-10c1df35f765-O2 ] on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S0 at slave(2)@172.17.0.7:39581 (753c2ae3a486) for framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (Dynamic Reservation Framework (C++)) at scheduler-c51aa6e6-f5b6-4bfc-982c-9a71ea56a862@172.17.0.7:39581
> I0707 18:07:00.622714 31531 master.cpp:3144] Authorizing principal 'test' to reserve resources 'cpus(test, test):1; mem(test, test):128'
> I0707 18:07:00.623579 31531 master.cpp:3695] Applying RESERVE operation for resources cpus(test, test):1; mem(test, test):128 from framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (Dynamic Reservation Framework (C++)) at scheduler-c51aa6e6-f5b6-4bfc-982c-9a71ea56a862@172.17.0.7:39581 to agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S2 at slave(1)@172.17.0.7:39581 (753c2ae3a486)
> I0707 18:07:00.624171 31531 master.cpp:7098] Sending checkpointed resources cpus(test, test):1; mem(test, test):128 to agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S2 at slave(1)@172.17.0.7:39581 (753c2ae3a486)
> I0707 18:07:00.624826 31531 master.cpp:3695] Applying RESERVE operation for resources cpus(test, test):1; mem(test, test):128 from framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (Dynamic Reservation Framework (C++)) at scheduler-c51aa6e6-f5b6-4bfc-982c-9a71ea56a862@172.17.0.7:39581 to agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S1 at slave(3)@172.17.0.7:39581 (753c2ae3a486)
> I0707 18:07:00.625102 31524 slave.cpp:2600] Updated checkpointed resources from to cpus(test, test):1; mem(test, test):128
> I0707 18:07:00.625347 31531 master.cpp:7098] Sending checkpointed resources cpus(test, test):1; mem(test, test):128 to agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S1 at slave(3)@172.17.0.7:39581 (753c2ae3a486)
> I0707 18:07:00.625932 31531 master.cpp:3695] Applying RESERVE operation for resources cpus(test, test):1; mem(test, test):128 from framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (Dynamic Reservation Framework (C++)) at scheduler-c51aa6e6-f5b6-4bfc-982c-9a71ea56a862@172.17.0.7:39581 to agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S0 at slave(2)@172.17.0.7:39581 (753c2ae3a486)
> I0707 18:07:00.626421 31531 master.cpp:7098] Sending checkpointed resources cpus(test, test):1; mem(test, test):128 to agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S0 at slave(2)@172.17.0.7:39581 (753c2ae3a486)
> I0707 18:07:00.626845 31537 slave.cpp:2600] Updated checkpointed resources from to cpus(test, test):1; mem(test, test):128
> I0707 18:07:00.627255 31538 hierarchical.cpp:683] Updated allocation of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S2 from cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000] to cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]; cpus(test, test):1; mem(test, test):128
> I0707 18:07:00.627341 31531 slave.cpp:2600] Updated checkpointed resources from to cpus(test, test):1; mem(test, test):128
> I0707 18:07:00.628175 31538 hierarchical.cpp:924] Recovered cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]; cpus(test, test):1; mem(test, test):128 (total: cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]; cpus(test, test):1; mem(test, test):128, allocated: ) on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S2 from framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:00.630285 31538 hierarchical.cpp:683] Updated allocation of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S1 from cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000] to cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]; cpus(test, test):1; mem(test, test):128
> I0707 18:07:00.631186 31538 hierarchical.cpp:924] Recovered cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]; cpus(test, test):1; mem(test, test):128 (total: cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]; cpus(test, test):1; mem(test, test):128, allocated: ) on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S1 from framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:00.633533 31538 hierarchical.cpp:683] Updated allocation of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S0 from cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000] to cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]; cpus(test, test):1; mem(test, test):128
> I0707 18:07:00.634449 31538 hierarchical.cpp:924] Recovered cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]; cpus(test, test):1; mem(test, test):128 (total: cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]; cpus(test, test):1; mem(test, test):128, allocated: ) on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S0 from framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.268144 31537 hierarchical.cpp:1632] No inverse offers to send out!
> I0707 18:07:01.268594 31537 hierarchical.cpp:1172] Performed allocation for 3 agents in 3.471848ms
> I0707 18:07:01.269795 31532 master.cpp:5835] Sending 3 offers to framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (Dynamic Reservation Framework (C++)) at scheduler-c51aa6e6-f5b6-4bfc-982c-9a71ea56a862@172.17.0.7:39581
> I0707 18:07:01.272722 31532 dynamic_reservation_framework.cpp:84] Received offer 7892fbb2-1ac1-450f-8576-10c1df35f765-O3 with cpus(test, test):1; mem(test, test):128; cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0707 18:07:01.273185 31532 dynamic_reservation_framework.cpp:150] Launching task 0 using offer 7892fbb2-1ac1-450f-8576-10c1df35f765-O3
> I0707 18:07:01.274802 31532 dynamic_reservation_framework.cpp:84] Received offer 7892fbb2-1ac1-450f-8576-10c1df35f765-O4 with cpus(test, test):1; mem(test, test):128; cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0707 18:07:01.275229 31532 dynamic_reservation_framework.cpp:150] Launching task 1 using offer 7892fbb2-1ac1-450f-8576-10c1df35f765-O4
> I0707 18:07:01.275583 31532 dynamic_reservation_framework.cpp:84] Received offer 7892fbb2-1ac1-450f-8576-10c1df35f765-O5 with cpus(test, test):1; mem(test, test):128; cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0707 18:07:01.276630 31532 dynamic_reservation_framework.cpp:150] Launching task 2 using offer 7892fbb2-1ac1-450f-8576-10c1df35f765-O5
> I0707 18:07:01.277556 31532 sched.cpp:917] Scheduler::resourceOffers took 4.841343ms
> I0707 18:07:01.279577 31529 master.cpp:3468] Processing ACCEPT call for offers: [ 7892fbb2-1ac1-450f-8576-10c1df35f765-O3 ] on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S0 at slave(2)@172.17.0.7:39581 (753c2ae3a486) for framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (Dynamic Reservation Framework (C++)) at scheduler-c51aa6e6-f5b6-4bfc-982c-9a71ea56a862@172.17.0.7:39581
> I0707 18:07:01.279718 31529 master.cpp:3106] Authorizing framework principal 'test' to launch task 0
> I0707 18:07:01.282876 31529 master.cpp:3468] Processing ACCEPT call for offers: [ 7892fbb2-1ac1-450f-8576-10c1df35f765-O4 ] on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S1 at slave(3)@172.17.0.7:39581 (753c2ae3a486) for framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (Dynamic Reservation Framework (C++)) at scheduler-c51aa6e6-f5b6-4bfc-982c-9a71ea56a862@172.17.0.7:39581
> I0707 18:07:01.282953 31529 master.cpp:3106] Authorizing framework principal 'test' to launch task 1
> I0707 18:07:01.287205 31529 master.cpp:3468] Processing ACCEPT call for offers: [ 7892fbb2-1ac1-450f-8576-10c1df35f765-O5 ] on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S2 at slave(1)@172.17.0.7:39581 (753c2ae3a486) for framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (Dynamic Reservation Framework (C++)) at scheduler-c51aa6e6-f5b6-4bfc-982c-9a71ea56a862@172.17.0.7:39581
> I0707 18:07:01.287295 31529 master.cpp:3106] Authorizing framework principal 'test' to launch task 2
> I0707 18:07:01.292567 31529 master.cpp:7565] Adding task 0 with resources cpus(test, test):1; mem(test, test):128 on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S0 (753c2ae3a486)
> I0707 18:07:01.292743 31529 master.cpp:3957] Launching task 0 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (Dynamic Reservation Framework (C++)) at scheduler-c51aa6e6-f5b6-4bfc-982c-9a71ea56a862@172.17.0.7:39581 with resources cpus(test, test):1; mem(test, test):128 on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S0 at slave(2)@172.17.0.7:39581 (753c2ae3a486)
> I0707 18:07:01.294683 31539 slave.cpp:1569] Got assigned task 0 for framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.295222 31539 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
> Trying semicolon-delimited string format instead
> I0707 18:07:01.297250 31532 hierarchical.cpp:924] Recovered ports(*):[31000-32000]; disk(*):3.70122e+06; cpus(*):15; mem(*):47142 (total: cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]; cpus(test, test):1; mem(test, test):128, allocated: cpus(test, test):1; mem(test, test):128) on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S0 from framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.298192 31539 slave.cpp:1688] Launching task 0 for framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.298318 31539 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
> Trying semicolon-delimited string format instead
> I0707 18:07:01.302230 31529 master.cpp:7565] Adding task 1 with resources cpus(test, test):1; mem(test, test):128 on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S1 (753c2ae3a486)
> I0707 18:07:01.303160 31539 paths.cpp:528] Trying to chown '/tmp/mesos-IFR4rG/1/slaves/7892fbb2-1ac1-450f-8576-10c1df35f765-S0/frameworks/7892fbb2-1ac1-450f-8576-10c1df35f765-0000/executors/0/runs/bdca1a15-bdb1-45bb-b19e-df07fb74e5db' to user 'mesos'
> I0707 18:07:01.302377 31529 master.cpp:3957] Launching task 1 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (Dynamic Reservation Framework (C++)) at scheduler-c51aa6e6-f5b6-4bfc-982c-9a71ea56a862@172.17.0.7:39581 with resources cpus(test, test):1; mem(test, test):128 on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S1 at slave(3)@172.17.0.7:39581 (753c2ae3a486)
> I0707 18:07:01.304913 31527 slave.cpp:1569] Got assigned task 1 for framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.305199 31527 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
> Trying semicolon-delimited string format instead
> I0707 18:07:01.307775 31539 slave.cpp:5748] Launching executor 0 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/mesos-IFR4rG/1/slaves/7892fbb2-1ac1-450f-8576-10c1df35f765-S0/frameworks/7892fbb2-1ac1-450f-8576-10c1df35f765-0000/executors/0/runs/bdca1a15-bdb1-45bb-b19e-df07fb74e5db'
> I0707 18:07:01.309219 31527 slave.cpp:1688] Launching task 1 for framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.309334 31527 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
> Trying semicolon-delimited string format instead
> I0707 18:07:01.309659 31536 containerizer.cpp:781] Starting container 'bdca1a15-bdb1-45bb-b19e-df07fb74e5db' for executor '0' of framework '7892fbb2-1ac1-450f-8576-10c1df35f765-0000'
> I0707 18:07:01.312726 31539 slave.cpp:1914] Queuing task '0' for executor '0' of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.312937 31539 slave.cpp:922] Successfully attached file '/tmp/mesos-IFR4rG/1/slaves/7892fbb2-1ac1-450f-8576-10c1df35f765-S0/frameworks/7892fbb2-1ac1-450f-8576-10c1df35f765-0000/executors/0/runs/bdca1a15-bdb1-45bb-b19e-df07fb74e5db'
> I0707 18:07:01.317831 31528 hierarchical.cpp:924] Recovered ports(*):[31000-32000]; disk(*):3.70122e+06; cpus(*):15; mem(*):47142 (total: cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]; cpus(test, test):1; mem(test, test):128, allocated: cpus(test, test):1; mem(test, test):128) on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S1 from framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.319255 31529 master.cpp:7565] Adding task 2 with resources cpus(test, test):1; mem(test, test):128 on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S2 (753c2ae3a486)
> I0707 18:07:01.319463 31529 master.cpp:3957] Launching task 2 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (Dynamic Reservation Framework (C++)) at scheduler-c51aa6e6-f5b6-4bfc-982c-9a71ea56a862@172.17.0.7:39581 with resources cpus(test, test):1; mem(test, test):128 on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S2 at slave(1)@172.17.0.7:39581 (753c2ae3a486)
> I0707 18:07:01.319934 31526 slave.cpp:1569] Got assigned task 2 for framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.320222 31526 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
> Trying semicolon-delimited string format instead
> I0707 18:07:01.320818 31526 slave.cpp:1688] Launching task 2 for framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.320926 31526 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
> Trying semicolon-delimited string format instead
> I0707 18:07:01.322808 31524 containerizer.cpp:1284] Launching 'mesos-containerizer' with flags '--command="{"arguments":["mesos-executor","--launcher_dir=\/mesos\/mesos-1.0.0\/_build\/src"],"shell":false,"value":"\/mesos\/mesos-1.0.0\/_build\/src\/mesos-executor"}" --help="false" --pipe_read="12" --pipe_write="13" --pre_exec_commands="[]" --unshare_namespace_mnt="false" --user="mesos" --working_directory="/tmp/mesos-IFR4rG/1/slaves/7892fbb2-1ac1-450f-8576-10c1df35f765-S0/frameworks/7892fbb2-1ac1-450f-8576-10c1df35f765-0000/executors/0/runs/bdca1a15-bdb1-45bb-b19e-df07fb74e5db"'
> I0707 18:07:01.325748 31524 launcher.cpp:126] Forked child with pid '31544' for container 'bdca1a15-bdb1-45bb-b19e-df07fb74e5db'
> I0707 18:07:01.328867 31533 hierarchical.cpp:924] Recovered ports(*):[31000-32000]; disk(*):3.70122e+06; cpus(*):15; mem(*):47142 (total: cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]; cpus(test, test):1; mem(test, test):128, allocated: cpus(test, test):1; mem(test, test):128) on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S2 from framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.351835 31526 paths.cpp:528] Trying to chown '/tmp/mesos-IFR4rG/0/slaves/7892fbb2-1ac1-450f-8576-10c1df35f765-S2/frameworks/7892fbb2-1ac1-450f-8576-10c1df35f765-0000/executors/2/runs/cffaea8f-effc-4388-902d-1ae39d1e5bfb' to user 'mesos'
> I0707 18:07:01.353647 31527 paths.cpp:528] Trying to chown '/tmp/mesos-IFR4rG/2/slaves/7892fbb2-1ac1-450f-8576-10c1df35f765-S1/frameworks/7892fbb2-1ac1-450f-8576-10c1df35f765-0000/executors/1/runs/cde8072a-fc80-426d-833f-57e3cf50f368' to user 'mesos'
> I0707 18:07:01.360844 31526 slave.cpp:5748] Launching executor 2 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/mesos-IFR4rG/0/slaves/7892fbb2-1ac1-450f-8576-10c1df35f765-S2/frameworks/7892fbb2-1ac1-450f-8576-10c1df35f765-0000/executors/2/runs/cffaea8f-effc-4388-902d-1ae39d1e5bfb'
> I0707 18:07:01.362640 31525 containerizer.cpp:781] Starting container 'cffaea8f-effc-4388-902d-1ae39d1e5bfb' for executor '2' of framework '7892fbb2-1ac1-450f-8576-10c1df35f765-0000'
> I0707 18:07:01.370136 31525 containerizer.cpp:1284] Launching 'mesos-containerizer' with flags '--command="{"arguments":["mesos-executor","--launcher_dir=\/mesos\/mesos-1.0.0\/_build\/src"],"shell":false,"value":"\/mesos\/mesos-1.0.0\/_build\/src\/mesos-executor"}" --help="false" --pipe_read="9" --pipe_write="12" --pre_exec_commands="[]" --unshare_namespace_mnt="false" --user="mesos" --working_directory="/tmp/mesos-IFR4rG/0/slaves/7892fbb2-1ac1-450f-8576-10c1df35f765-S2/frameworks/7892fbb2-1ac1-450f-8576-10c1df35f765-0000/executors/2/runs/cffaea8f-effc-4388-902d-1ae39d1e5bfb"'
> I0707 18:07:01.370545 31526 slave.cpp:1914] Queuing task '2' for executor '2' of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.370671 31526 slave.cpp:922] Successfully attached file '/tmp/mesos-IFR4rG/0/slaves/7892fbb2-1ac1-450f-8576-10c1df35f765-S2/frameworks/7892fbb2-1ac1-450f-8576-10c1df35f765-0000/executors/2/runs/cffaea8f-effc-4388-902d-1ae39d1e5bfb'
> I0707 18:07:01.372215 31525 launcher.cpp:126] Forked child with pid '31562' for container 'cffaea8f-effc-4388-902d-1ae39d1e5bfb'
> I0707 18:07:01.385299 31527 slave.cpp:5748] Launching executor 1 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/mesos-IFR4rG/2/slaves/7892fbb2-1ac1-450f-8576-10c1df35f765-S1/frameworks/7892fbb2-1ac1-450f-8576-10c1df35f765-0000/executors/1/runs/cde8072a-fc80-426d-833f-57e3cf50f368'
> I0707 18:07:01.386274 31527 slave.cpp:1914] Queuing task '1' for executor '1' of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.387212 31527 slave.cpp:922] Successfully attached file '/tmp/mesos-IFR4rG/2/slaves/7892fbb2-1ac1-450f-8576-10c1df35f765-S1/frameworks/7892fbb2-1ac1-450f-8576-10c1df35f765-0000/executors/1/runs/cde8072a-fc80-426d-833f-57e3cf50f368'
> I0707 18:07:01.386729 31536 containerizer.cpp:781] Starting container 'cde8072a-fc80-426d-833f-57e3cf50f368' for executor '1' of framework '7892fbb2-1ac1-450f-8576-10c1df35f765-0000'
> I0707 18:07:01.393424 31530 containerizer.cpp:1284] Launching 'mesos-containerizer' with flags '--command="{"arguments":["mesos-executor","--launcher_dir=\/mesos\/mesos-1.0.0\/_build\/src"],"shell":false,"value":"\/mesos\/mesos-1.0.0\/_build\/src\/mesos-executor"}" --help="false" --pipe_read="9" --pipe_write="12" --pre_exec_commands="[]" --unshare_namespace_mnt="false" --user="mesos" --working_directory="/tmp/mesos-IFR4rG/2/slaves/7892fbb2-1ac1-450f-8576-10c1df35f765-S1/frameworks/7892fbb2-1ac1-450f-8576-10c1df35f765-0000/executors/1/runs/cde8072a-fc80-426d-833f-57e3cf50f368"'
> I0707 18:07:01.395277 31530 launcher.cpp:126] Forked child with pid '31567' for container 'cde8072a-fc80-426d-833f-57e3cf50f368'
> I0707 18:07:01.597575 31544 exec.cpp:161] Version: 1.0.0
> I0707 18:07:01.603597 31530 slave.cpp:2902] Got registration for executor '0' of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 from executor(1)@172.17.0.7:59475
> I0707 18:07:01.610890 31530 slave.cpp:2079] Sending queued task '0' to executor '0' of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 at executor(1)@172.17.0.7:59475
> I0707 18:07:01.610896 31623 exec.cpp:236] Executor registered on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S0
> Received SUBSCRIBED event
> Subscribed executor on 753c2ae3a486
> Received LAUNCH event
> Starting task 0
> /mesos/mesos-1.0.0/_build/src/mesos-containerizer launch --command="{"shell":true,"value":"echo hello"}" --help="false" --unshare_namespace_mnt="false"
> Forked command at 31646
> I0707 18:07:01.638350 31527 slave.cpp:3285] Handling status update TASK_RUNNING (UUID: 24b1f98c-f325-4ecc-b839-07580dcccd52) for task 0 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 from executor(1)@172.17.0.7:59475
> I0707 18:07:01.643460 31532 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 24b1f98c-f325-4ecc-b839-07580dcccd52) for task 0 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.643530 31532 status_update_manager.cpp:497] Creating StatusUpdate stream for task 0 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.644738 31532 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: 24b1f98c-f325-4ecc-b839-07580dcccd52) for task 0 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 to the agent
> I0707 18:07:01.646585 31527 slave.cpp:3678] Forwarding the update TASK_RUNNING (UUID: 24b1f98c-f325-4ecc-b839-07580dcccd52) for task 0 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 to master@172.17.0.7:39581
> I0707 18:07:01.646842 31527 slave.cpp:3572] Status update manager successfully handled status update TASK_RUNNING (UUID: 24b1f98c-f325-4ecc-b839-07580dcccd52) for task 0 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.646900 31527 slave.cpp:3588] Sending acknowledgement for status update TASK_RUNNING (UUID: 24b1f98c-f325-4ecc-b839-07580dcccd52) for task 0 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 to executor(1)@172.17.0.7:59475
> I0707 18:07:01.647038 31538 master.cpp:5273] Status update TASK_RUNNING (UUID: 24b1f98c-f325-4ecc-b839-07580dcccd52) for task 0 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 from agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S0 at slave(2)@172.17.0.7:39581 (753c2ae3a486)
> I0707 18:07:01.647094 31538 master.cpp:5321] Forwarding status update TASK_RUNNING (UUID: 24b1f98c-f325-4ecc-b839-07580dcccd52) for task 0 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.647313 31538 master.cpp:6959] Updating the state of task 0 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
> I0707 18:07:01.647377 31527 dynamic_reservation_framework.cpp:211] Task 0 is in state TASK_RUNNING
> I0707 18:07:01.647423 31527 sched.cpp:1025] Scheduler::statusUpdate took 33812ns
> I0707 18:07:01.647711 31527 master.cpp:4388] Processing ACKNOWLEDGE call 24b1f98c-f325-4ecc-b839-07580dcccd52 for task 0 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (Dynamic Reservation Framework (C++)) at scheduler-c51aa6e6-f5b6-4bfc-982c-9a71ea56a862@172.17.0.7:39581 on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S0
> I0707 18:07:01.648241 31529 status_update_manager.cpp:392] Received status update acknowledgement (UUID: 24b1f98c-f325-4ecc-b839-07580dcccd52) for task 0 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.648927 31529 slave.cpp:2671] Status update manager successfully handled status update acknowledgement (UUID: 24b1f98c-f325-4ecc-b839-07580dcccd52) for task 0 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.688079 31670 exec.cpp:161] Version: 1.0.0
> I0707 18:07:01.701555 31529 slave.cpp:2902] Got registration for executor '2' of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 from executor(1)@172.17.0.7:51409
> I0707 18:07:01.716229 31668 exec.cpp:236] Executor registered on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S2
> I0707 18:07:01.719995 31529 slave.cpp:2079] Sending queued task '2' to executor '2' of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 at executor(1)@172.17.0.7:51409
> I0707 18:07:01.740218 31567 exec.cpp:161] Version: 1.0.0
> I0707 18:07:01.745529 31534 slave.cpp:2902] Got registration for executor '1' of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 from executor(1)@172.17.0.7:34513
> hello
> I0707 18:07:01.747939 31539 slave.cpp:2079] Sending queued task '1' to executor '1' of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 at executor(1)@172.17.0.7:34513
> I0707 18:07:01.749034 31677 exec.cpp:236] Executor registered on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S1
> Received SUBSCRIBED event
> Subscribed executor on 753c2ae3a486
> Received LAUNCH event
> Starting task 2
> /mesos/mesos-1.0.0/_build/src/mesos-containerizer launch --command="{"shell":true,"value":"echo hello"}" --help="false" --unshare_namespace_mnt="false"
> Forked command at 31694
> I0707 18:07:01.763070 31533 slave.cpp:3285] Handling status update TASK_RUNNING (UUID: c30ef1c4-d5f2-4556-875b-df44c8e586d5) for task 2 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 from executor(1)@172.17.0.7:51409
> I0707 18:07:01.765763 31531 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: c30ef1c4-d5f2-4556-875b-df44c8e586d5) for task 2 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.765916 31531 status_update_manager.cpp:497] Creating StatusUpdate stream for task 2 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.766629 31531 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: c30ef1c4-d5f2-4556-875b-df44c8e586d5) for task 2 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 to the agent
> I0707 18:07:01.767174 31531 slave.cpp:3678] Forwarding the update TASK_RUNNING (UUID: c30ef1c4-d5f2-4556-875b-df44c8e586d5) for task 2 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 to master@172.17.0.7:39581
> I0707 18:07:01.767484 31531 slave.cpp:3572] Status update manager successfully handled status update TASK_RUNNING (UUID: c30ef1c4-d5f2-4556-875b-df44c8e586d5) for task 2 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.767638 31531 slave.cpp:3588] Sending acknowledgement for status update TASK_RUNNING (UUID: c30ef1c4-d5f2-4556-875b-df44c8e586d5) for task 2 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 to executor(1)@172.17.0.7:51409
> I0707 18:07:01.767709 31529 master.cpp:5273] Status update TASK_RUNNING (UUID: c30ef1c4-d5f2-4556-875b-df44c8e586d5) for task 2 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 from agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S2 at slave(1)@172.17.0.7:39581 (753c2ae3a486)
> I0707 18:07:01.768045 31529 master.cpp:5321] Forwarding status update TASK_RUNNING (UUID: c30ef1c4-d5f2-4556-875b-df44c8e586d5) for task 2 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.768604 31535 dynamic_reservation_framework.cpp:211] Task 2 is in state TASK_RUNNING
> I0707 18:07:01.768832 31535 sched.cpp:1025] Scheduler::statusUpdate took 272020ns
> I0707 18:07:01.769253 31529 master.cpp:6959] Updating the state of task 2 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
> I0707 18:07:01.769649 31529 master.cpp:4388] Processing ACKNOWLEDGE call c30ef1c4-d5f2-4556-875b-df44c8e586d5 for task 2 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (Dynamic Reservation Framework (C++)) at scheduler-c51aa6e6-f5b6-4bfc-982c-9a71ea56a862@172.17.0.7:39581 on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S2
> I0707 18:07:01.770125 31529 status_update_manager.cpp:392] Received status update acknowledgement (UUID: c30ef1c4-d5f2-4556-875b-df44c8e586d5) for task 2 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.770845 31524 slave.cpp:2671] Status update manager successfully handled status update acknowledgement (UUID: c30ef1c4-d5f2-4556-875b-df44c8e586d5) for task 2 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> Received SUBSCRIBED event
> Subscribed executor on 753c2ae3a486
> Received LAUNCH event
> Starting task 1
> /mesos/mesos-1.0.0/_build/src/mesos-containerizer launch --command="{"shell":true,"value":"echo hello"}" --help="false" --unshare_namespace_mnt="false"
> Forked command at 31702
> I0707 18:07:01.786492 31528 slave.cpp:3285] Handling status update TASK_RUNNING (UUID: 41438479-6ebc-417c-a357-9446db661f27) for task 1 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 from executor(1)@172.17.0.7:34513
> I0707 18:07:01.789589 31535 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 41438479-6ebc-417c-a357-9446db661f27) for task 1 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.789639 31535 status_update_manager.cpp:497] Creating StatusUpdate stream for task 1 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.790278 31535 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: 41438479-6ebc-417c-a357-9446db661f27) for task 1 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 to the agent
> I0707 18:07:01.790938 31539 slave.cpp:3678] Forwarding the update TASK_RUNNING (UUID: 41438479-6ebc-417c-a357-9446db661f27) for task 1 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 to master@172.17.0.7:39581
> I0707 18:07:01.791113 31539 slave.cpp:3572] Status update manager successfully handled status update TASK_RUNNING (UUID: 41438479-6ebc-417c-a357-9446db661f27) for task 1 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.791162 31539 slave.cpp:3588] Sending acknowledgement for status update TASK_RUNNING (UUID: 41438479-6ebc-417c-a357-9446db661f27) for task 1 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 to executor(1)@172.17.0.7:34513
> I0707 18:07:01.792708 31539 master.cpp:5273] Status update TASK_RUNNING (UUID: 41438479-6ebc-417c-a357-9446db661f27) for task 1 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 from agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S1 at slave(3)@172.17.0.7:39581 (753c2ae3a486)
> I0707 18:07:01.792759 31539 master.cpp:5321] Forwarding status update TASK_RUNNING (UUID: 41438479-6ebc-417c-a357-9446db661f27) for task 1 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.792935 31539 master.cpp:6959] Updating the state of task 1 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
> I0707 18:07:01.793094 31539 dynamic_reservation_framework.cpp:211] Task 1 is in state TASK_RUNNING
> I0707 18:07:01.793119 31539 sched.cpp:1025] Scheduler::statusUpdate took 26767ns
> I0707 18:07:01.793341 31539 master.cpp:4388] Processing ACKNOWLEDGE call 41438479-6ebc-417c-a357-9446db661f27 for task 1 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (Dynamic Reservation Framework (C++)) at scheduler-c51aa6e6-f5b6-4bfc-982c-9a71ea56a862@172.17.0.7:39581 on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S1
> I0707 18:07:01.793712 31539 status_update_manager.cpp:392] Received status update acknowledgement (UUID: 41438479-6ebc-417c-a357-9446db661f27) for task 1 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.794035 31539 slave.cpp:2671] Status update manager successfully handled status update acknowledgement (UUID: 41438479-6ebc-417c-a357-9446db661f27) for task 1 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> Command exited with status 0 (pid: 31646)
> I0707 18:07:01.849810 31535 slave.cpp:3285] Handling status update TASK_FINISHED (UUID: 2c0ce9f5-7167-4fb9-8636-ae0e465d08fc) for task 0 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 from executor(1)@172.17.0.7:59475
> I0707 18:07:01.854346 31535 slave.cpp:6088] Terminating task 0
> I0707 18:07:01.860373 31530 status_update_manager.cpp:320] Received status update TASK_FINISHED (UUID: 2c0ce9f5-7167-4fb9-8636-ae0e465d08fc) for task 0 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.861690 31530 status_update_manager.cpp:374] Forwarding update TASK_FINISHED (UUID: 2c0ce9f5-7167-4fb9-8636-ae0e465d08fc) for task 0 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 to the agent
> I0707 18:07:01.862217 31530 slave.cpp:3678] Forwarding the update TASK_FINISHED (UUID: 2c0ce9f5-7167-4fb9-8636-ae0e465d08fc) for task 0 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 to master@172.17.0.7:39581
> I0707 18:07:01.863664 31533 master.cpp:5273] Status update TASK_FINISHED (UUID: 2c0ce9f5-7167-4fb9-8636-ae0e465d08fc) for task 0 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 from agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S0 at slave(2)@172.17.0.7:39581 (753c2ae3a486)
> I0707 18:07:01.863718 31533 master.cpp:5321] Forwarding status update TASK_FINISHED (UUID: 2c0ce9f5-7167-4fb9-8636-ae0e465d08fc) for task 0 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.863888 31533 master.cpp:6959] Updating the state of task 0 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (latest state: TASK_FINISHED, status update state: TASK_FINISHED)
> I0707 18:07:01.864351 31533 dynamic_reservation_framework.cpp:208] Task 0 is finished at agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S0
> I0707 18:07:01.864377 31533 sched.cpp:1025] Scheduler::statusUpdate took 42319ns
> I0707 18:07:01.865952 31533 hierarchical.cpp:924] Recovered cpus(test, test):1; mem(test, test):128 (total: cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]; cpus(test, test):1; mem(test, test):128, allocated: ) on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S0 from framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.866158 31533 master.cpp:4388] Processing ACKNOWLEDGE call 2c0ce9f5-7167-4fb9-8636-ae0e465d08fc for task 0 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (Dynamic Reservation Framework (C++)) at scheduler-c51aa6e6-f5b6-4bfc-982c-9a71ea56a862@172.17.0.7:39581 on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S0
> I0707 18:07:01.866231 31533 master.cpp:7025] Removing task 0 with resources cpus(test, test):1; mem(test, test):128 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S0 at slave(2)@172.17.0.7:39581 (753c2ae3a486)
> I0707 18:07:01.866461 31530 slave.cpp:3572] Status update manager successfully handled status update TASK_FINISHED (UUID: 2c0ce9f5-7167-4fb9-8636-ae0e465d08fc) for task 0 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.866519 31530 slave.cpp:3588] Sending acknowledgement for status update TASK_FINISHED (UUID: 2c0ce9f5-7167-4fb9-8636-ae0e465d08fc) for task 0 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 to executor(1)@172.17.0.7:59475
> I0707 18:07:01.869339 31533 status_update_manager.cpp:392] Received status update acknowledgement (UUID: 2c0ce9f5-7167-4fb9-8636-ae0e465d08fc) for task 0 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.869580 31533 status_update_manager.cpp:528] Cleaning up status update stream for task 0 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.870098 31533 slave.cpp:2671] Status update manager successfully handled status update acknowledgement (UUID: 2c0ce9f5-7167-4fb9-8636-ae0e465d08fc) for task 0 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.870162 31533 slave.cpp:6129] Completing task 0
> hello
> Command exited with status 0 (pid: 31694)
> hello
> I0707 18:07:01.965605 31533 slave.cpp:3285] Handling status update TASK_FINISHED (UUID: 60c0ce74-18df-458f-bef4-1f82fb03412e) for task 2 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 from executor(1)@172.17.0.7:51409
> I0707 18:07:01.968528 31535 slave.cpp:6088] Terminating task 2
> I0707 18:07:01.970181 31539 status_update_manager.cpp:320] Received status update TASK_FINISHED (UUID: 60c0ce74-18df-458f-bef4-1f82fb03412e) for task 2 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.970440 31539 status_update_manager.cpp:374] Forwarding update TASK_FINISHED (UUID: 60c0ce74-18df-458f-bef4-1f82fb03412e) for task 2 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 to the agent
> I0707 18:07:01.970832 31533 slave.cpp:3678] Forwarding the update TASK_FINISHED (UUID: 60c0ce74-18df-458f-bef4-1f82fb03412e) for task 2 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 to master@172.17.0.7:39581
> I0707 18:07:01.971072 31533 slave.cpp:3572] Status update manager successfully handled status update TASK_FINISHED (UUID: 60c0ce74-18df-458f-bef4-1f82fb03412e) for task 2 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.971158 31533 slave.cpp:3588] Sending acknowledgement for status update TASK_FINISHED (UUID: 60c0ce74-18df-458f-bef4-1f82fb03412e) for task 2 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 to executor(1)@172.17.0.7:51409
> I0707 18:07:01.971346 31535 master.cpp:5273] Status update TASK_FINISHED (UUID: 60c0ce74-18df-458f-bef4-1f82fb03412e) for task 2 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 from agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S2 at slave(1)@172.17.0.7:39581 (753c2ae3a486)
> I0707 18:07:01.971515 31535 master.cpp:5321] Forwarding status update TASK_FINISHED (UUID: 60c0ce74-18df-458f-bef4-1f82fb03412e) for task 2 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.971796 31535 master.cpp:6959] Updating the state of task 2 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (latest state: TASK_FINISHED, status update state: TASK_FINISHED)
> I0707 18:07:01.971863 31539 dynamic_reservation_framework.cpp:208] Task 2 is finished at agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S2
> I0707 18:07:01.971887 31539 sched.cpp:1025] Scheduler::statusUpdate took 36513ns
> I0707 18:07:01.972437 31535 master.cpp:4388] Processing ACKNOWLEDGE call 60c0ce74-18df-458f-bef4-1f82fb03412e for task 2 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (Dynamic Reservation Framework (C++)) at scheduler-c51aa6e6-f5b6-4bfc-982c-9a71ea56a862@172.17.0.7:39581 on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S2
> I0707 18:07:01.972524 31528 hierarchical.cpp:924] Recovered cpus(test, test):1; mem(test, test):128 (total: cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]; cpus(test, test):1; mem(test, test):128, allocated: ) on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S2 from framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.972553 31535 master.cpp:7025] Removing task 2 with resources cpus(test, test):1; mem(test, test):128 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S2 at slave(1)@172.17.0.7:39581 (753c2ae3a486)
> I0707 18:07:01.973103 31535 status_update_manager.cpp:392] Received status update acknowledgement (UUID: 60c0ce74-18df-458f-bef4-1f82fb03412e) for task 2 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.973393 31535 status_update_manager.cpp:528] Cleaning up status update stream for task 2 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.973930 31535 slave.cpp:2671] Status update manager successfully handled status update acknowledgement (UUID: 60c0ce74-18df-458f-bef4-1f82fb03412e) for task 2 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.974081 31535 slave.cpp:6129] Completing task 2
> Command exited with status 0 (pid: 31702)
> I0707 18:07:01.988955 31530 slave.cpp:3285] Handling status update TASK_FINISHED (UUID: 9e47c164-0f30-4b73-aab4-249a77bdc04d) for task 1 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 from executor(1)@172.17.0.7:34513
> I0707 18:07:01.990218 31534 slave.cpp:6088] Terminating task 1
> I0707 18:07:01.991665 31534 status_update_manager.cpp:320] Received status update TASK_FINISHED (UUID: 9e47c164-0f30-4b73-aab4-249a77bdc04d) for task 1 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.991874 31534 status_update_manager.cpp:374] Forwarding update TASK_FINISHED (UUID: 9e47c164-0f30-4b73-aab4-249a77bdc04d) for task 1 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 to the agent
> I0707 18:07:01.992138 31531 slave.cpp:3678] Forwarding the update TASK_FINISHED (UUID: 9e47c164-0f30-4b73-aab4-249a77bdc04d) for task 1 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 to master@172.17.0.7:39581
> I0707 18:07:01.992455 31531 slave.cpp:3572] Status update manager successfully handled status update TASK_FINISHED (UUID: 9e47c164-0f30-4b73-aab4-249a77bdc04d) for task 1 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.992539 31531 slave.cpp:3588] Sending acknowledgement for status update TASK_FINISHED (UUID: 9e47c164-0f30-4b73-aab4-249a77bdc04d) for task 1 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 to executor(1)@172.17.0.7:34513
> I0707 18:07:01.992573 31535 master.cpp:5273] Status update TASK_FINISHED (UUID: 9e47c164-0f30-4b73-aab4-249a77bdc04d) for task 1 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 from agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S1 at slave(3)@172.17.0.7:39581 (753c2ae3a486)
> I0707 18:07:01.992619 31535 master.cpp:5321] Forwarding status update TASK_FINISHED (UUID: 9e47c164-0f30-4b73-aab4-249a77bdc04d) for task 1 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.992776 31535 master.cpp:6959] Updating the state of task 1 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (latest state: TASK_FINISHED, status update state: TASK_FINISHED)
> I0707 18:07:01.993170 31535 dynamic_reservation_framework.cpp:208] Task 1 is finished at agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S1
> I0707 18:07:01.993191 31535 sched.cpp:1025] Scheduler::statusUpdate took 32857ns
> I0707 18:07:01.993369 31535 master.cpp:4388] Processing ACKNOWLEDGE call 9e47c164-0f30-4b73-aab4-249a77bdc04d for task 1 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (Dynamic Reservation Framework (C++)) at scheduler-c51aa6e6-f5b6-4bfc-982c-9a71ea56a862@172.17.0.7:39581 on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S1
> I0707 18:07:01.993633 31531 hierarchical.cpp:924] Recovered cpus(test, test):1; mem(test, test):128 (total: cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]; cpus(test, test):1; mem(test, test):128, allocated: ) on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S1 from framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.994060 31535 master.cpp:7025] Removing task 1 with resources cpus(test, test):1; mem(test, test):128 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S1 at slave(3)@172.17.0.7:39581 (753c2ae3a486)
> I0707 18:07:01.994530 31535 status_update_manager.cpp:392] Received status update acknowledgement (UUID: 9e47c164-0f30-4b73-aab4-249a77bdc04d) for task 1 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.994729 31535 status_update_manager.cpp:528] Cleaning up status update stream for task 1 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.995079 31537 slave.cpp:2671] Status update manager successfully handled status update acknowledgement (UUID: 9e47c164-0f30-4b73-aab4-249a77bdc04d) for task 1 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:01.995172 31537 slave.cpp:6129] Completing task 1
> I0707 18:07:02.274876 31537 hierarchical.cpp:1632] No inverse offers to send out!
> I0707 18:07:02.275038 31537 hierarchical.cpp:1172] Performed allocation for 3 agents in 4.318297ms
> I0707 18:07:02.278640 31537 master.cpp:5835] Sending 3 offers to framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (Dynamic Reservation Framework (C++)) at scheduler-c51aa6e6-f5b6-4bfc-982c-9a71ea56a862@172.17.0.7:39581
> I0707 18:07:02.280704 31524 dynamic_reservation_framework.cpp:84] Received offer 7892fbb2-1ac1-450f-8576-10c1df35f765-O6 with cpus(test, test):1; mem(test, test):128; cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0707 18:07:02.280966 31524 dynamic_reservation_framework.cpp:150] Launching task 3 using offer 7892fbb2-1ac1-450f-8576-10c1df35f765-O6
> I0707 18:07:02.281510 31524 dynamic_reservation_framework.cpp:84] Received offer 7892fbb2-1ac1-450f-8576-10c1df35f765-O7 with cpus(test, test):1; mem(test, test):128; cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0707 18:07:02.281695 31524 dynamic_reservation_framework.cpp:150] Launching task 4 using offer 7892fbb2-1ac1-450f-8576-10c1df35f765-O7
> I0707 18:07:02.282440 31524 dynamic_reservation_framework.cpp:84] Received offer 7892fbb2-1ac1-450f-8576-10c1df35f765-O8 with cpus(test, test):1; mem(test, test):128; cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0707 18:07:02.282804 31524 sched.cpp:917] Scheduler::resourceOffers took 2.103878ms
> I0707 18:07:02.285826 31537 master.cpp:3468] Processing ACCEPT call for offers: [ 7892fbb2-1ac1-450f-8576-10c1df35f765-O6 ] on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S0 at slave(2)@172.17.0.7:39581 (753c2ae3a486) for framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (Dynamic Reservation Framework (C++)) at scheduler-c51aa6e6-f5b6-4bfc-982c-9a71ea56a862@172.17.0.7:39581
> I0707 18:07:02.285923 31537 master.cpp:3106] Authorizing framework principal 'test' to launch task 3
> I0707 18:07:02.291869 31537 master.cpp:3468] Processing ACCEPT call for offers: [ 7892fbb2-1ac1-450f-8576-10c1df35f765-O7 ] on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S2 at slave(1)@172.17.0.7:39581 (753c2ae3a486) for framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (Dynamic Reservation Framework (C++)) at scheduler-c51aa6e6-f5b6-4bfc-982c-9a71ea56a862@172.17.0.7:39581
> I0707 18:07:02.291971 31537 master.cpp:3106] Authorizing framework principal 'test' to launch task 4
> I0707 18:07:02.297622 31537 master.cpp:3468] Processing ACCEPT call for offers: [ 7892fbb2-1ac1-450f-8576-10c1df35f765-O8 ] on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S1 at slave(3)@172.17.0.7:39581 (753c2ae3a486) for framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (Dynamic Reservation Framework (C++)) at scheduler-c51aa6e6-f5b6-4bfc-982c-9a71ea56a862@172.17.0.7:39581
> I0707 18:07:02.299481 31537 master.cpp:3201] Authorizing principal 'test' to unreserve resources 'cpus(test, test):1; mem(test, test):128'
> I0707 18:07:02.304149 31537 master.cpp:7565] Adding task 3 with resources cpus(test, test):1; mem(test, test):128 on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S0 (753c2ae3a486)
> I0707 18:07:02.304298 31537 master.cpp:3957] Launching task 3 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (Dynamic Reservation Framework (C++)) at scheduler-c51aa6e6-f5b6-4bfc-982c-9a71ea56a862@172.17.0.7:39581 with resources cpus(test, test):1; mem(test, test):128 on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S0 at slave(2)@172.17.0.7:39581 (753c2ae3a486)
> I0707 18:07:02.305838 31532 slave.cpp:1569] Got assigned task 3 for framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:02.306040 31532 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
> Trying semicolon-delimited string format instead
> I0707 18:07:02.307746 31532 slave.cpp:1688] Launching task 3 for framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:02.307853 31532 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
> Trying semicolon-delimited string format instead
> I0707 18:07:02.312942 31532 paths.cpp:528] Trying to chown '/tmp/mesos-IFR4rG/1/slaves/7892fbb2-1ac1-450f-8576-10c1df35f765-S0/frameworks/7892fbb2-1ac1-450f-8576-10c1df35f765-0000/executors/3/runs/e31dfccd-5f2a-40e1-95a0-b5b253fac912' to user 'mesos'
> I0707 18:07:02.317132 31531 hierarchical.cpp:924] Recovered ports(*):[31000-32000]; disk(*):3.70122e+06; cpus(*):15; mem(*):47142 (total: cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]; cpus(test, test):1; mem(test, test):128, allocated: cpus(test, test):1; mem(test, test):128) on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S0 from framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:02.318964 31532 slave.cpp:5748] Launching executor 3 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/mesos-IFR4rG/1/slaves/7892fbb2-1ac1-450f-8576-10c1df35f765-S0/frameworks/7892fbb2-1ac1-450f-8576-10c1df35f765-0000/executors/3/runs/e31dfccd-5f2a-40e1-95a0-b5b253fac912'
> I0707 18:07:02.319262 31537 master.cpp:7565] Adding task 4 with resources cpus(test, test):1; mem(test, test):128 on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S2 (753c2ae3a486)
> I0707 18:07:02.319537 31537 master.cpp:3957] Launching task 4 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (Dynamic Reservation Framework (C++)) at scheduler-c51aa6e6-f5b6-4bfc-982c-9a71ea56a862@172.17.0.7:39581 with resources cpus(test, test):1; mem(test, test):128 on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S2 at slave(1)@172.17.0.7:39581 (753c2ae3a486)
> I0707 18:07:02.319990 31527 slave.cpp:1569] Got assigned task 4 for framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:02.320173 31537 master.cpp:3747] Applying UNRESERVE operation for resources cpus(test, test):1; mem(test, test):128 from framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (Dynamic Reservation Framework (C++)) at scheduler-c51aa6e6-f5b6-4bfc-982c-9a71ea56a862@172.17.0.7:39581 to agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S1 at slave(3)@172.17.0.7:39581 (753c2ae3a486)
> I0707 18:07:02.321169 31539 hierarchical.cpp:924] Recovered ports(*):[31000-32000]; disk(*):3.70122e+06; cpus(*):15; mem(*):47142 (total: cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]; cpus(test, test):1; mem(test, test):128, allocated: cpus(test, test):1; mem(test, test):128) on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S2 from framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:02.321388 31527 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
> Trying semicolon-delimited string format instead
> I0707 18:07:02.322088 31537 master.cpp:7098] Sending checkpointed resources to agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S1 at slave(3)@172.17.0.7:39581 (753c2ae3a486)
> I0707 18:07:02.322193 31527 slave.cpp:1688] Launching task 4 for framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:02.322312 31527 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
> Trying semicolon-delimited string format instead
> I0707 18:07:02.322660 31537 slave.cpp:2600] Updated checkpointed resources from cpus(test, test):1; mem(test, test):128 to
> I0707 18:07:02.323094 31527 paths.cpp:528] Trying to chown '/tmp/mesos-IFR4rG/0/slaves/7892fbb2-1ac1-450f-8576-10c1df35f765-S2/frameworks/7892fbb2-1ac1-450f-8576-10c1df35f765-0000/executors/4/runs/f4bdc7d6-e7b1-4bd7-84e3-a7353f8b3e84' to user 'mesos'
> I0707 18:07:02.324539 31532 slave.cpp:1914] Queuing task '3' for executor '3' of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:02.324769 31528 containerizer.cpp:781] Starting container 'e31dfccd-5f2a-40e1-95a0-b5b253fac912' for executor '3' of framework '7892fbb2-1ac1-450f-8576-10c1df35f765-0000'
> I0707 18:07:02.324848 31532 slave.cpp:922] Successfully attached file '/tmp/mesos-IFR4rG/1/slaves/7892fbb2-1ac1-450f-8576-10c1df35f765-S0/frameworks/7892fbb2-1ac1-450f-8576-10c1df35f765-0000/executors/3/runs/e31dfccd-5f2a-40e1-95a0-b5b253fac912'
> I0707 18:07:02.326263 31539 hierarchical.cpp:683] Updated allocation of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S1 from cpus(test, test):1; mem(test, test):128; cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000] to ports(*):[31000-32000]; disk(*):3.70122e+06; cpus(*):16; mem(*):47270
> I0707 18:07:02.327944 31539 hierarchical.cpp:924] Recovered ports(*):[31000-32000]; disk(*):3.70122e+06; cpus(*):16; mem(*):47270 (total: cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: ) on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S1 from framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:02.330935 31527 slave.cpp:5748] Launching executor 4 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/mesos-IFR4rG/0/slaves/7892fbb2-1ac1-450f-8576-10c1df35f765-S2/frameworks/7892fbb2-1ac1-450f-8576-10c1df35f765-0000/executors/4/runs/f4bdc7d6-e7b1-4bd7-84e3-a7353f8b3e84'
> I0707 18:07:02.331660 31527 slave.cpp:1914] Queuing task '4' for executor '4' of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:02.331791 31527 slave.cpp:922] Successfully attached file '/tmp/mesos-IFR4rG/0/slaves/7892fbb2-1ac1-450f-8576-10c1df35f765-S2/frameworks/7892fbb2-1ac1-450f-8576-10c1df35f765-0000/executors/4/runs/f4bdc7d6-e7b1-4bd7-84e3-a7353f8b3e84'
> I0707 18:07:02.331665 31536 containerizer.cpp:781] Starting container 'f4bdc7d6-e7b1-4bd7-84e3-a7353f8b3e84' for executor '4' of framework '7892fbb2-1ac1-450f-8576-10c1df35f765-0000'
> I0707 18:07:02.334722 31530 containerizer.cpp:1284] Launching 'mesos-containerizer' with flags '--command="{"arguments":["mesos-executor","--launcher_dir=\/mesos\/mesos-1.0.0\/_build\/src"],"shell":false,"value":"\/mesos\/mesos-1.0.0\/_build\/src\/mesos-executor"}" --help="false" --pipe_read="17" --pipe_write="18" --pre_exec_commands="[]" --unshare_namespace_mnt="false" --user="mesos" --working_directory="/tmp/mesos-IFR4rG/1/slaves/7892fbb2-1ac1-450f-8576-10c1df35f765-S0/frameworks/7892fbb2-1ac1-450f-8576-10c1df35f765-0000/executors/3/runs/e31dfccd-5f2a-40e1-95a0-b5b253fac912"'
> I0707 18:07:02.335965 31530 launcher.cpp:126] Forked child with pid '31726' for container 'e31dfccd-5f2a-40e1-95a0-b5b253fac912'
> I0707 18:07:02.340095 31536 containerizer.cpp:1284] Launching 'mesos-containerizer' with flags '--command="{"arguments":["mesos-executor","--launcher_dir=\/mesos\/mesos-1.0.0\/_build\/src"],"shell":false,"value":"\/mesos\/mesos-1.0.0\/_build\/src\/mesos-executor"}" --help="false" --pipe_read="19" --pipe_write="20" --pre_exec_commands="[]" --unshare_namespace_mnt="false" --user="mesos" --working_directory="/tmp/mesos-IFR4rG/0/slaves/7892fbb2-1ac1-450f-8576-10c1df35f765-S2/frameworks/7892fbb2-1ac1-450f-8576-10c1df35f765-0000/executors/4/runs/f4bdc7d6-e7b1-4bd7-84e3-a7353f8b3e84"'
> I0707 18:07:02.341588 31536 launcher.cpp:126] Forked child with pid '31727' for container 'f4bdc7d6-e7b1-4bd7-84e3-a7353f8b3e84'
> I0707 18:07:02.587986 31726 exec.cpp:161] Version: 1.0.0
> I0707 18:07:02.592061 31727 exec.cpp:161] Version: 1.0.0
> I0707 18:07:02.592990 31535 slave.cpp:2902] Got registration for executor '3' of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 from executor(1)@172.17.0.7:55420
> I0707 18:07:02.595854 31533 slave.cpp:2902] Got registration for executor '4' of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 from executor(1)@172.17.0.7:56283
> I0707 18:07:02.599692 31535 slave.cpp:2079] Sending queued task '3' to executor '3' of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 at executor(1)@172.17.0.7:55420
> I0707 18:07:02.600880 31811 exec.cpp:236] Executor registered on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S2
> I0707 18:07:02.601768 31533 slave.cpp:2079] Sending queued task '4' to executor '4' of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 at executor(1)@172.17.0.7:56283
> I0707 18:07:02.603651 31792 exec.cpp:236] Executor registered on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S0
> Received SUBSCRIBED event
> Subscribed executor on 753c2ae3a486
> Received LAUNCH event
> Starting task 3
> Received SUBSCRIBED event
> Subscribed executor on 753c2ae3a486
> Received LAUNCH event
> Starting task 4
> /mesos/mesos-1.0.0/_build/src/mesos-containerizer launch --command="{"shell":true,"value":"echo hello"}" --help="false" --unshare_namespace_mnt="false"
> Forked command at 31815
> /mesos/mesos-1.0.0/_build/src/mesos-containerizer launch --command="{"shell":true,"value":"echo hello"}" --help="false" --unshare_namespace_mnt="false"
> Forked command at 31814
> I0707 18:07:02.632139 31530 slave.cpp:3285] Handling status update TASK_RUNNING (UUID: 58bae39d-f2fa-4160-84d2-ddf3d1c728bf) for task 3 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 from executor(1)@172.17.0.7:55420
> I0707 18:07:02.634009 31537 slave.cpp:3285] Handling status update TASK_RUNNING (UUID: f7349218-9f36-4867-8b7e-b980f525c673) for task 4 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 from executor(1)@172.17.0.7:56283
> I0707 18:07:02.636554 31527 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: f7349218-9f36-4867-8b7e-b980f525c673) for task 4 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:02.636744 31527 status_update_manager.cpp:497] Creating StatusUpdate stream for task 4 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:02.637475 31527 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: f7349218-9f36-4867-8b7e-b980f525c673) for task 4 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 to the agent
> I0707 18:07:02.640130 31527 slave.cpp:3678] Forwarding the update TASK_RUNNING (UUID: f7349218-9f36-4867-8b7e-b980f525c673) for task 4 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 to master@172.17.0.7:39581
> I0707 18:07:02.641506 31527 slave.cpp:3572] Status update manager successfully handled status update TASK_RUNNING (UUID: f7349218-9f36-4867-8b7e-b980f525c673) for task 4 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:02.643518 31527 slave.cpp:3588] Sending acknowledgement for status update TASK_RUNNING (UUID: f7349218-9f36-4867-8b7e-b980f525c673) for task 4 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 to executor(1)@172.17.0.7:56283
> I0707 18:07:02.642694 31529 master.cpp:5273] Status update TASK_RUNNING (UUID: f7349218-9f36-4867-8b7e-b980f525c673) for task 4 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 from agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S2 at slave(1)@172.17.0.7:39581 (753c2ae3a486)
> I0707 18:07:02.644038 31529 master.cpp:5321] Forwarding status update TASK_RUNNING (UUID: f7349218-9f36-4867-8b7e-b980f525c673) for task 4 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:02.644603 31524 dynamic_reservation_framework.cpp:211] Task 4 is in state TASK_RUNNING
> I0707 18:07:02.644876 31524 sched.cpp:1025] Scheduler::statusUpdate took 310563ns
> I0707 18:07:02.645233 31529 master.cpp:6959] Updating the state of task 4 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
> I0707 18:07:02.645633 31529 master.cpp:4388] Processing ACKNOWLEDGE call f7349218-9f36-4867-8b7e-b980f525c673 for task 4 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (Dynamic Reservation Framework (C++)) at scheduler-c51aa6e6-f5b6-4bfc-982c-9a71ea56a862@172.17.0.7:39581 on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S2
> I0707 18:07:02.648191 31530 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 58bae39d-f2fa-4160-84d2-ddf3d1c728bf) for task 3 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:02.648598 31530 status_update_manager.cpp:497] Creating StatusUpdate stream for task 3 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:02.648950 31527 status_update_manager.cpp:392] Received status update acknowledgement (UUID: f7349218-9f36-4867-8b7e-b980f525c673) for task 4 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:02.649775 31527 slave.cpp:2671] Status update manager successfully handled status update acknowledgement (UUID: f7349218-9f36-4867-8b7e-b980f525c673) for task 4 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:02.650616 31530 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: 58bae39d-f2fa-4160-84d2-ddf3d1c728bf) for task 3 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 to the agent
> I0707 18:07:02.651362 31530 slave.cpp:3678] Forwarding the update TASK_RUNNING (UUID: 58bae39d-f2fa-4160-84d2-ddf3d1c728bf) for task 3 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 to master@172.17.0.7:39581
> I0707 18:07:02.651851 31530 slave.cpp:3572] Status update manager successfully handled status update TASK_RUNNING (UUID: 58bae39d-f2fa-4160-84d2-ddf3d1c728bf) for task 3 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:02.652447 31530 slave.cpp:3588] Sending acknowledgement for status update TASK_RUNNING (UUID: 58bae39d-f2fa-4160-84d2-ddf3d1c728bf) for task 3 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 to executor(1)@172.17.0.7:55420
> I0707 18:07:02.652318 31538 master.cpp:5273] Status update TASK_RUNNING (UUID: 58bae39d-f2fa-4160-84d2-ddf3d1c728bf) for task 3 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 from agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S0 at slave(2)@172.17.0.7:39581 (753c2ae3a486)
> I0707 18:07:02.652909 31538 master.cpp:5321] Forwarding status update TASK_RUNNING (UUID: 58bae39d-f2fa-4160-84d2-ddf3d1c728bf) for task 3 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:02.653316 31538 master.cpp:6959] Updating the state of task 3 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
> I0707 18:07:02.653714 31526 dynamic_reservation_framework.cpp:211] Task 3 is in state TASK_RUNNING
> I0707 18:07:02.653985 31526 sched.cpp:1025] Scheduler::statusUpdate took 274166ns
> I0707 18:07:02.654438 31526 master.cpp:4388] Processing ACKNOWLEDGE call 58bae39d-f2fa-4160-84d2-ddf3d1c728bf for task 3 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (Dynamic Reservation Framework (C++)) at scheduler-c51aa6e6-f5b6-4bfc-982c-9a71ea56a862@172.17.0.7:39581 on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S0
> I0707 18:07:02.656904 31525 status_update_manager.cpp:392] Received status update acknowledgement (UUID: 58bae39d-f2fa-4160-84d2-ddf3d1c728bf) for task 3 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:02.657546 31530 slave.cpp:2671] Status update manager successfully handled status update acknowledgement (UUID: 58bae39d-f2fa-4160-84d2-ddf3d1c728bf) for task 3 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> hello
> hello
> Command exited with status 0 (pid: 31814)
> Command exited with status 0 (pid: 31815)
> I0707 18:07:02.834297 31526 slave.cpp:3285] Handling status update TASK_FINISHED (UUID: 5c12302d-6330-4df9-bf8f-d3443e6bccc6) for task 3 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 from executor(1)@172.17.0.7:55420
> I0707 18:07:02.836560 31529 slave.cpp:6088] Terminating task 3
> I0707 18:07:02.837365 31526 slave.cpp:3285] Handling status update TASK_FINISHED (UUID: 7e8d7fb0-613e-4a73-b07f-d3eee49496d5) for task 4 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 from executor(1)@172.17.0.7:56283
> I0707 18:07:02.838392 31534 status_update_manager.cpp:320] Received status update TASK_FINISHED (UUID: 5c12302d-6330-4df9-bf8f-d3443e6bccc6) for task 3 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:02.838690 31534 status_update_manager.cpp:374] Forwarding update TASK_FINISHED (UUID: 5c12302d-6330-4df9-bf8f-d3443e6bccc6) for task 3 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 to the agent
> I0707 18:07:02.839052 31537 slave.cpp:3678] Forwarding the update TASK_FINISHED (UUID: 5c12302d-6330-4df9-bf8f-d3443e6bccc6) for task 3 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 to master@172.17.0.7:39581
> I0707 18:07:02.839562 31537 slave.cpp:3572] Status update manager successfully handled status update TASK_FINISHED (UUID: 5c12302d-6330-4df9-bf8f-d3443e6bccc6) for task 3 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:02.839733 31526 master.cpp:5273] Status update TASK_FINISHED (UUID: 5c12302d-6330-4df9-bf8f-d3443e6bccc6) for task 3 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 from agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S0 at slave(2)@172.17.0.7:39581 (753c2ae3a486)
> I0707 18:07:02.839855 31526 master.cpp:5321] Forwarding status update TASK_FINISHED (UUID: 5c12302d-6330-4df9-bf8f-d3443e6bccc6) for task 3 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:02.839866 31537 slave.cpp:3588] Sending acknowledgement for status update TASK_FINISHED (UUID: 5c12302d-6330-4df9-bf8f-d3443e6bccc6) for task 3 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 to executor(1)@172.17.0.7:55420
> I0707 18:07:02.840096 31526 master.cpp:6959] Updating the state of task 3 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (latest state: TASK_FINISHED, status update state: TASK_FINISHED)
> I0707 18:07:02.840512 31535 dynamic_reservation_framework.cpp:208] Task 3 is finished at agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S0
> I0707 18:07:02.840540 31535 sched.cpp:1025] Scheduler::statusUpdate took 46734ns
> I0707 18:07:02.840790 31535 master.cpp:4388] Processing ACKNOWLEDGE call 5c12302d-6330-4df9-bf8f-d3443e6bccc6 for task 3 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (Dynamic Reservation Framework (C++)) at scheduler-c51aa6e6-f5b6-4bfc-982c-9a71ea56a862@172.17.0.7:39581 on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S0
> I0707 18:07:02.840873 31535 master.cpp:7025] Removing task 3 with resources cpus(test, test):1; mem(test, test):128 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S0 at slave(2)@172.17.0.7:39581 (753c2ae3a486)
> I0707 18:07:02.841006 31526 hierarchical.cpp:924] Recovered cpus(test, test):1; mem(test, test):128 (total: cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]; cpus(test, test):1; mem(test, test):128, allocated: ) on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S0 from framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:02.841898 31532 slave.cpp:6088] Terminating task 4
> I0707 18:07:02.843639 31535 status_update_manager.cpp:392] Received status update acknowledgement (UUID: 5c12302d-6330-4df9-bf8f-d3443e6bccc6) for task 3 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:02.843842 31535 status_update_manager.cpp:528] Cleaning up status update stream for task 3 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:02.844398 31535 slave.cpp:2671] Status update manager successfully handled status update acknowledgement (UUID: 5c12302d-6330-4df9-bf8f-d3443e6bccc6) for task 3 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:02.844481 31535 slave.cpp:6129] Completing task 3
> I0707 18:07:02.845114 31532 status_update_manager.cpp:320] Received status update TASK_FINISHED (UUID: 7e8d7fb0-613e-4a73-b07f-d3eee49496d5) for task 4 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:02.845590 31532 status_update_manager.cpp:374] Forwarding update TASK_FINISHED (UUID: 7e8d7fb0-613e-4a73-b07f-d3eee49496d5) for task 4 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 to the agent
> I0707 18:07:02.846128 31532 slave.cpp:3678] Forwarding the update TASK_FINISHED (UUID: 7e8d7fb0-613e-4a73-b07f-d3eee49496d5) for task 4 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 to master@172.17.0.7:39581
> I0707 18:07:02.846406 31532 slave.cpp:3572] Status update manager successfully handled status update TASK_FINISHED (UUID: 7e8d7fb0-613e-4a73-b07f-d3eee49496d5) for task 4 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:02.846519 31532 slave.cpp:3588] Sending acknowledgement for status update TASK_FINISHED (UUID: 7e8d7fb0-613e-4a73-b07f-d3eee49496d5) for task 4 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 to executor(1)@172.17.0.7:56283
> I0707 18:07:02.846554 31527 master.cpp:5273] Status update TASK_FINISHED (UUID: 7e8d7fb0-613e-4a73-b07f-d3eee49496d5) for task 4 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 from agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S2 at slave(1)@172.17.0.7:39581 (753c2ae3a486)
> I0707 18:07:02.846730 31527 master.cpp:5321] Forwarding status update TASK_FINISHED (UUID: 7e8d7fb0-613e-4a73-b07f-d3eee49496d5) for task 4 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:02.846974 31527 master.cpp:6959] Updating the state of task 4 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (latest state: TASK_FINISHED, status update state: TASK_FINISHED)
> I0707 18:07:02.847877 31524 hierarchical.cpp:924] Recovered cpus(test, test):1; mem(test, test):128 (total: cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]; cpus(test, test):1; mem(test, test):128, allocated: ) on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S2 from framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:02.848093 31532 dynamic_reservation_framework.cpp:208] Task 4 is finished at agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S2
> I0707 18:07:02.848188 31532 dynamic_reservation_framework.cpp:226] All tasks done, waiting for unreserving resources
> I0707 18:07:02.848259 31532 sched.cpp:1025] Scheduler::statusUpdate took 173818ns
> I0707 18:07:02.848578 31532 master.cpp:4388] Processing ACKNOWLEDGE call 7e8d7fb0-613e-4a73-b07f-d3eee49496d5 for task 4 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (Dynamic Reservation Framework (C++)) at scheduler-c51aa6e6-f5b6-4bfc-982c-9a71ea56a862@172.17.0.7:39581 on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S2
> I0707 18:07:02.848701 31532 master.cpp:7025] Removing task 4 with resources cpus(test, test):1; mem(test, test):128 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S2 at slave(1)@172.17.0.7:39581 (753c2ae3a486)
> I0707 18:07:02.849139 31532 slave.cpp:3806] executor(1)@172.17.0.7:59475 exited
> I0707 18:07:02.849176 31532 status_update_manager.cpp:392] Received status update acknowledgement (UUID: 7e8d7fb0-613e-4a73-b07f-d3eee49496d5) for task 4 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:02.849354 31532 status_update_manager.cpp:528] Cleaning up status update stream for task 4 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:02.850083 31532 slave.cpp:2671] Status update manager successfully handled status update acknowledgement (UUID: 7e8d7fb0-613e-4a73-b07f-d3eee49496d5) for task 4 of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:02.850138 31532 slave.cpp:6129] Completing task 4
> I0707 18:07:02.947499 31529 containerizer.cpp:1863] Executor for container 'bdca1a15-bdb1-45bb-b19e-df07fb74e5db' has exited
> I0707 18:07:02.947567 31529 containerizer.cpp:1622] Destroying container 'bdca1a15-bdb1-45bb-b19e-df07fb74e5db'
> I0707 18:07:02.960427 31539 provisioner.cpp:411] Ignoring destroy request for unknown container bdca1a15-bdb1-45bb-b19e-df07fb74e5db
> I0707 18:07:02.961381 31526 slave.cpp:4163] Executor '0' of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 exited with status 0
> I0707 18:07:02.961753 31526 slave.cpp:4267] Cleaning up executor '0' of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 at executor(1)@172.17.0.7:59475
> I0707 18:07:02.962579 31535 gc.cpp:55] Scheduling '/tmp/mesos-IFR4rG/1/slaves/7892fbb2-1ac1-450f-8576-10c1df35f765-S0/frameworks/7892fbb2-1ac1-450f-8576-10c1df35f765-0000/executors/0/runs/bdca1a15-bdb1-45bb-b19e-df07fb74e5db' for gc 6.99998886310222days in the future
> I0707 18:07:02.963564 31535 gc.cpp:55] Scheduling '/tmp/mesos-IFR4rG/1/slaves/7892fbb2-1ac1-450f-8576-10c1df35f765-S0/frameworks/7892fbb2-1ac1-450f-8576-10c1df35f765-0000/executors/0' for gc 6.99998885004741days in the future
> I0707 18:07:02.973430 31538 slave.cpp:3806] executor(1)@172.17.0.7:51409 exited
> I0707 18:07:02.995627 31536 slave.cpp:3806] executor(1)@172.17.0.7:34513 exited
> I0707 18:07:03.050102 31538 containerizer.cpp:1863] Executor for container 'cffaea8f-effc-4388-902d-1ae39d1e5bfb' has exited
> I0707 18:07:03.050295 31538 containerizer.cpp:1622] Destroying container 'cffaea8f-effc-4388-902d-1ae39d1e5bfb'
> I0707 18:07:03.052471 31531 containerizer.cpp:1863] Executor for container 'cde8072a-fc80-426d-833f-57e3cf50f368' has exited
> I0707 18:07:03.052614 31531 containerizer.cpp:1622] Destroying container 'cde8072a-fc80-426d-833f-57e3cf50f368'
> I0707 18:07:03.068886 31533 provisioner.cpp:411] Ignoring destroy request for unknown container cffaea8f-effc-4388-902d-1ae39d1e5bfb
> I0707 18:07:03.069725 31524 slave.cpp:4163] Executor '2' of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 exited with status 0
> I0707 18:07:03.069861 31524 slave.cpp:4267] Cleaning up executor '2' of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 at executor(1)@172.17.0.7:51409
> I0707 18:07:03.071491 31524 gc.cpp:55] Scheduling '/tmp/mesos-IFR4rG/0/slaves/7892fbb2-1ac1-450f-8576-10c1df35f765-S2/frameworks/7892fbb2-1ac1-450f-8576-10c1df35f765-0000/executors/2/runs/cffaea8f-effc-4388-902d-1ae39d1e5bfb' for gc 6.9999991881837days in the future
> I0707 18:07:03.071869 31524 gc.cpp:55] Scheduling '/tmp/mesos-IFR4rG/0/slaves/7892fbb2-1ac1-450f-8576-10c1df35f765-S2/frameworks/7892fbb2-1ac1-450f-8576-10c1df35f765-0000/executors/2' for gc 6.99999918568296days in the future
> I0707 18:07:03.084206 31528 provisioner.cpp:411] Ignoring destroy request for unknown container cde8072a-fc80-426d-833f-57e3cf50f368
> I0707 18:07:03.084844 31530 slave.cpp:4163] Executor '1' of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 exited with status 0
> I0707 18:07:03.085223 31530 slave.cpp:4267] Cleaning up executor '1' of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 at executor(1)@172.17.0.7:34513
> I0707 18:07:03.085597 31526 gc.cpp:55] Scheduling '/tmp/mesos-IFR4rG/2/slaves/7892fbb2-1ac1-450f-8576-10c1df35f765-S1/frameworks/7892fbb2-1ac1-450f-8576-10c1df35f765-0000/executors/1/runs/cde8072a-fc80-426d-833f-57e3cf50f368' for gc 6.99999901009185days in the future
> I0707 18:07:03.085814 31530 slave.cpp:4355] Cleaning up framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:03.086110 31530 status_update_manager.cpp:282] Closing status update streams for framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:03.086287 31526 gc.cpp:55] Scheduling '/tmp/mesos-IFR4rG/2/slaves/7892fbb2-1ac1-450f-8576-10c1df35f765-S1/frameworks/7892fbb2-1ac1-450f-8576-10c1df35f765-0000/executors/1' for gc 6.99999900754667days in the future
> I0707 18:07:03.086448 31526 gc.cpp:55] Scheduling '/tmp/mesos-IFR4rG/2/slaves/7892fbb2-1ac1-450f-8576-10c1df35f765-S1/frameworks/7892fbb2-1ac1-450f-8576-10c1df35f765-0000' for gc 6.99999900508148days in the future
> I0707 18:07:03.282027 31534 hierarchical.cpp:1632] No inverse offers to send out!
> I0707 18:07:03.282196 31534 hierarchical.cpp:1172] Performed allocation for 3 agents in 6.269452ms
> I0707 18:07:03.285627 31534 master.cpp:5835] Sending 3 offers to framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (Dynamic Reservation Framework (C++)) at scheduler-c51aa6e6-f5b6-4bfc-982c-9a71ea56a862@172.17.0.7:39581
> I0707 18:07:03.288548 31534 dynamic_reservation_framework.cpp:84] Received offer 7892fbb2-1ac1-450f-8576-10c1df35f765-O9 with cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0707 18:07:03.288714 31534 dynamic_reservation_framework.cpp:84] Received offer 7892fbb2-1ac1-450f-8576-10c1df35f765-O10 with cpus(test, test):1; mem(test, test):128; cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0707 18:07:03.289059 31534 dynamic_reservation_framework.cpp:84] Received offer 7892fbb2-1ac1-450f-8576-10c1df35f765-O11 with cpus(test, test):1; mem(test, test):128; cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0707 18:07:03.289353 31534 sched.cpp:917] Scheduler::resourceOffers took 808575ns
> I0707 18:07:03.295822 31534 master.cpp:3468] Processing ACCEPT call for offers: [ 7892fbb2-1ac1-450f-8576-10c1df35f765-O10 ] on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S0 at slave(2)@172.17.0.7:39581 (753c2ae3a486) for framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (Dynamic Reservation Framework (C++)) at scheduler-c51aa6e6-f5b6-4bfc-982c-9a71ea56a862@172.17.0.7:39581
> I0707 18:07:03.296022 31534 master.cpp:3201] Authorizing principal 'test' to unreserve resources 'cpus(test, test):1; mem(test, test):128'
> I0707 18:07:03.299430 31534 master.cpp:3468] Processing ACCEPT call for offers: [ 7892fbb2-1ac1-450f-8576-10c1df35f765-O11 ] on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S2 at slave(1)@172.17.0.7:39581 (753c2ae3a486) for framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (Dynamic Reservation Framework (C++)) at scheduler-c51aa6e6-f5b6-4bfc-982c-9a71ea56a862@172.17.0.7:39581
> I0707 18:07:03.299563 31534 master.cpp:3201] Authorizing principal 'test' to unreserve resources 'cpus(test, test):1; mem(test, test):128'
> I0707 18:07:03.300375 31534 master.cpp:3747] Applying UNRESERVE operation for resources cpus(test, test):1; mem(test, test):128 from framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (Dynamic Reservation Framework (C++)) at scheduler-c51aa6e6-f5b6-4bfc-982c-9a71ea56a862@172.17.0.7:39581 to agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S0 at slave(2)@172.17.0.7:39581 (753c2ae3a486)
> I0707 18:07:03.302352 31534 master.cpp:7098] Sending checkpointed resources to agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S0 at slave(2)@172.17.0.7:39581 (753c2ae3a486)
> I0707 18:07:03.303211 31534 master.cpp:3747] Applying UNRESERVE operation for resources cpus(test, test):1; mem(test, test):128 from framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (Dynamic Reservation Framework (C++)) at scheduler-c51aa6e6-f5b6-4bfc-982c-9a71ea56a862@172.17.0.7:39581 to agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S2 at slave(1)@172.17.0.7:39581 (753c2ae3a486)
> I0707 18:07:03.303390 31527 slave.cpp:2600] Updated checkpointed resources from cpus(test, test):1; mem(test, test):128 to
> I0707 18:07:03.304319 31528 hierarchical.cpp:683] Updated allocation of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S0 from cpus(test, test):1; mem(test, test):128; cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000] to ports(*):[31000-32000]; disk(*):3.70122e+06; cpus(*):16; mem(*):47270
> I0707 18:07:03.305121 31534 master.cpp:7098] Sending checkpointed resources to agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S2 at slave(1)@172.17.0.7:39581 (753c2ae3a486)
> I0707 18:07:03.305532 31531 slave.cpp:2600] Updated checkpointed resources from cpus(test, test):1; mem(test, test):128 to
> I0707 18:07:03.306602 31528 hierarchical.cpp:924] Recovered ports(*):[31000-32000]; disk(*):3.70122e+06; cpus(*):16; mem(*):47270 (total: cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: ) on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S0 from framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:03.311444 31528 hierarchical.cpp:683] Updated allocation of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S2 from cpus(test, test):1; mem(test, test):128; cpus(*):15; mem(*):47142; disk(*):3.70122e+06; ports(*):[31000-32000] to ports(*):[31000-32000]; disk(*):3.70122e+06; cpus(*):16; mem(*):47270
> I0707 18:07:03.312047 31528 hierarchical.cpp:924] Recovered ports(*):[31000-32000]; disk(*):3.70122e+06; cpus(*):16; mem(*):47270 (total: cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: ) on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S2 from framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:03.841215 31530 slave.cpp:3806] executor(1)@172.17.0.7:55420 exited
> I0707 18:07:03.841861 31533 slave.cpp:3806] executor(1)@172.17.0.7:56283 exited
> I0707 18:07:03.857960 31525 containerizer.cpp:1863] Executor for container 'e31dfccd-5f2a-40e1-95a0-b5b253fac912' has exited
> I0707 18:07:03.858224 31525 containerizer.cpp:1622] Destroying container 'e31dfccd-5f2a-40e1-95a0-b5b253fac912'
> I0707 18:07:03.858165 31537 containerizer.cpp:1863] Executor for container 'f4bdc7d6-e7b1-4bd7-84e3-a7353f8b3e84' has exited
> I0707 18:07:03.858378 31537 containerizer.cpp:1622] Destroying container 'f4bdc7d6-e7b1-4bd7-84e3-a7353f8b3e84'
> I0707 18:07:03.866737 31532 provisioner.cpp:411] Ignoring destroy request for unknown container f4bdc7d6-e7b1-4bd7-84e3-a7353f8b3e84
> I0707 18:07:03.867043 31527 slave.cpp:4163] Executor '4' of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 exited with status 0
> I0707 18:07:03.867420 31527 slave.cpp:4267] Cleaning up executor '4' of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 at executor(1)@172.17.0.7:56283
> I0707 18:07:03.867700 31536 provisioner.cpp:411] Ignoring destroy request for unknown container e31dfccd-5f2a-40e1-95a0-b5b253fac912
> I0707 18:07:03.868448 31538 gc.cpp:55] Scheduling '/tmp/mesos-IFR4rG/0/slaves/7892fbb2-1ac1-450f-8576-10c1df35f765-S2/frameworks/7892fbb2-1ac1-450f-8576-10c1df35f765-0000/executors/4/runs/f4bdc7d6-e7b1-4bd7-84e3-a7353f8b3e84' for gc 6.99998995501037days in the future
> I0707 18:07:03.868978 31531 slave.cpp:4163] Executor '3' of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 exited with status 0
> I0707 18:07:03.869102 31531 slave.cpp:4267] Cleaning up executor '3' of framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 at executor(1)@172.17.0.7:55420
> I0707 18:07:03.869125 31533 gc.cpp:55] Scheduling '/tmp/mesos-IFR4rG/0/slaves/7892fbb2-1ac1-450f-8576-10c1df35f765-S2/frameworks/7892fbb2-1ac1-450f-8576-10c1df35f765-0000/executors/4' for gc 6.99998994908444days in the future
> I0707 18:07:03.869405 31533 gc.cpp:55] Scheduling '/tmp/mesos-IFR4rG/1/slaves/7892fbb2-1ac1-450f-8576-10c1df35f765-S0/frameworks/7892fbb2-1ac1-450f-8576-10c1df35f765-0000/executors/3/runs/e31dfccd-5f2a-40e1-95a0-b5b253fac912' for gc 6.99998993851852days in the future
> I0707 18:07:03.869010 31527 slave.cpp:4355] Cleaning up framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:03.869788 31526 status_update_manager.cpp:282] Closing status update streams for framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:03.869946 31531 slave.cpp:4355] Cleaning up framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:03.870136 31539 status_update_manager.cpp:282] Closing status update streams for framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:03.870043 31538 gc.cpp:55] Scheduling '/tmp/mesos-IFR4rG/1/slaves/7892fbb2-1ac1-450f-8576-10c1df35f765-S0/frameworks/7892fbb2-1ac1-450f-8576-10c1df35f765-0000/executors/3' for gc 6.99998993607704days in the future
> I0707 18:07:03.870403 31538 gc.cpp:55] Scheduling '/tmp/mesos-IFR4rG/1/slaves/7892fbb2-1ac1-450f-8576-10c1df35f765-S0/frameworks/7892fbb2-1ac1-450f-8576-10c1df35f765-0000' for gc 6.99998992845926days in the future
> I0707 18:07:03.870625 31533 gc.cpp:55] Scheduling '/tmp/mesos-IFR4rG/0/slaves/7892fbb2-1ac1-450f-8576-10c1df35f765-S2/frameworks/7892fbb2-1ac1-450f-8576-10c1df35f765-0000' for gc 6.99998993375111days in the future
> I0707 18:07:04.284621 31537 hierarchical.cpp:1632] No inverse offers to send out!
> I0707 18:07:04.284754 31537 hierarchical.cpp:1172] Performed allocation for 3 agents in 1.977235ms
> I0707 18:07:04.285658 31534 master.cpp:5835] Sending 2 offers to framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (Dynamic Reservation Framework (C++)) at scheduler-c51aa6e6-f5b6-4bfc-982c-9a71ea56a862@172.17.0.7:39581
> I0707 18:07:04.286209 31534 dynamic_reservation_framework.cpp:84] Received offer 7892fbb2-1ac1-450f-8576-10c1df35f765-O12 with cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0707 18:07:04.286334 31534 dynamic_reservation_framework.cpp:84] Received offer 7892fbb2-1ac1-450f-8576-10c1df35f765-O13 with cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0707 18:07:04.286553 31534 sched.cpp:1987] Asked to stop the driver
> I0707 18:07:04.286667 31534 sched.cpp:917] Scheduler::resourceOffers took 458638ns
> I0707 18:07:04.286797 31534 sched.cpp:1187] Stopping framework '7892fbb2-1ac1-450f-8576-10c1df35f765-0000'
> I0707 18:07:04.287029 31539 master.cpp:6410] Processing TEARDOWN call for framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (Dynamic Reservation Framework (C++)) at scheduler-c51aa6e6-f5b6-4bfc-982c-9a71ea56a862@172.17.0.7:39581
> I0707 18:07:04.287063 31539 master.cpp:6422] Removing framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 (Dynamic Reservation Framework (C++)) at scheduler-c51aa6e6-f5b6-4bfc-982c-9a71ea56a862@172.17.0.7:39581
> I0707 18:07:04.288715 31539 hierarchical.cpp:382] Deactivated framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:04.289376 31539 hierarchical.cpp:924] Recovered cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000] (total: cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: ) on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S0 from framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:04.290086 31539 hierarchical.cpp:924] Recovered cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000] (total: cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: ) on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S2 from framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:04.290809 31539 hierarchical.cpp:924] Recovered cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000] (total: cpus(*):16; mem(*):47270; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: ) on agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S1 from framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:04.291211 31539 hierarchical.cpp:333] Removed framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:04.291306 31539 slave.cpp:2292] Asked to shut down framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 by master@172.17.0.7:39581
> W0707 18:07:04.291337 31539 slave.cpp:2307] Cannot shut down unknown framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:04.291376 31539 slave.cpp:2292] Asked to shut down framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 by master@172.17.0.7:39581
> W0707 18:07:04.291400 31539 slave.cpp:2307] Cannot shut down unknown framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:04.291467 31539 slave.cpp:2292] Asked to shut down framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000 by master@172.17.0.7:39581
> W0707 18:07:04.291494 31539 slave.cpp:2307] Cannot shut down unknown framework 7892fbb2-1ac1-450f-8576-10c1df35f765-0000
> I0707 18:07:04.292186 31500 sched.cpp:1987] Asked to stop the driver
> I0707 18:07:04.292228 31500 sched.cpp:1990] Ignoring stop because the status of the driver is DRIVER_STOPPED
> I0707 18:07:04.292887 31537 master.cpp:1218] Master terminating
> I0707 18:07:04.293656 31525 hierarchical.cpp:510] Removed agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S2
> I0707 18:07:04.293948 31525 hierarchical.cpp:510] Removed agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S1
> I0707 18:07:04.294634 31526 hierarchical.cpp:510] Removed agent 7892fbb2-1ac1-450f-8576-10c1df35f765-S0
> I0707 18:07:04.295132 31535 slave.cpp:3806] master@172.17.0.7:39581 exited
> I0707 18:07:04.295198 31534 slave.cpp:3806] master@172.17.0.7:39581 exited
> I0707 18:07:04.295245 31526 slave.cpp:3806] master@172.17.0.7:39581 exited
> W0707 18:07:04.300513 31535 slave.cpp:3811] Master disconnected! Waiting for a new master to be elected
> W0707 18:07:04.300745 31534 slave.cpp:3811] Master disconnected! Waiting for a new master to be elected
> W0707 18:07:04.300839 31526 slave.cpp:3811] Master disconnected! Waiting for a new master to be elected
> I0707 18:07:04.300978 31534 slave.cpp:841] Agent terminating
> I0707 18:07:04.305454 31538 slave.cpp:841] Agent terminating
> I0707 18:07:04.308804 31500 slave.cpp:841] Agent terminating
> [ OK ] ExamplesTest.DynamicReservationFramework (10418 ms)
> {code}
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)