[MESOS-5804] ExamplesTest.DynamicReservationFramework is flaky - ASF JIRA

XML

Word

Printable

JSON

Details

Type: Bug
Status: Resolved
Priority: Major
Resolution: Fixed
Affects Version/s: None
Fix Version/s: 1.9.0
Component/s: allocation, test
Labels:
- mesosphere
- resource-management

Sprint:
Resource Mgmt RI12 Sp 42, Resource Mgmt RI12 Sp 43, Resource Mgmt: RI-13 Sp 44, Resource Mgmt: RI13 Sp 45
Story Points:
3

Description

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

[ 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)

Logs from a previous good run:

[ 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)

Attachments

- Sort By Name
- Sort By Date
- Ascending
- Descending

ExamplesTest.DynamicReservationFramework-badrun2.txt
19/Sep/18 07:09
167 kB
Alex R

Issue Links

is blocked by

MESOS-9616 `Filters.refuse_seconds` declines resources not in offers.

Resolved

is duplicated by

MESOS-9408 ExamplesTest.DynamicReservationFramework is flaky.

Resolved

Activity

People

Assignee:: Benjamin Mahler

Reporter:: Anand Mazumdar

Votes:: 0 Vote for this issue

Watchers:: 5 Start watching this issue

Dates

Created:: 07/Jul/16 20:15

Updated:: 02/May/19 03:24

Resolved:: 02/May/19 03:24