[MESOS-4257] ExamplesTest.NoExecutorFramework runs forever.

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Duplicate
• Labels: tech-debt
• Sprint: Mesosphere Sprint 27, Mesosphere Sprint 28
• Story Points: 3
• Assignee: Jörg Schad
• Reporter: Benjamin Mahler
• Shepherd: Bernd Mathiske
• Created: 29/Dec/15 19:49
• Updated: 12/Mar/19 14:15
• Resolved: 10/Feb/16 09:03

Description

Good Run

[ RUN      ] ExamplesTest.NoExecutorFramework
I1221 23:10:02.721617 32528 exec.cpp:444] Ignoring exited event because the driver is aborted!
Using temporary directory '/tmp/ExamplesTest_NoExecutorFramework_fCmFLn'
I1221 23:10:02.721675 32539 exec.cpp:444] Ignoring exited event because the driver is aborted!
I1221 23:10:02.722024 32554 exec.cpp:444] Ignoring exited event because the driver is aborted!
WARNING: Logging before InitGoogleLogging() is written to STDERR
I1221 23:10:05.179466 32569 resources.cpp:478] Parsing resources as JSON failed: cpus:0.1;mem:32;disk:32
Trying semicolon-delimited string format instead
I1221 23:10:05.180269 32569 logging.cpp:172] Logging to STDERR
I1221 23:10:05.185768 32569 process.cpp:998] libprocess is initialized on 172.17.0.2:40874 for 16 cpus
I1221 23:10:05.200728 32569 leveldb.cpp:174] Opened db in 4.184362ms
I1221 23:10:05.202234 32569 leveldb.cpp:181] Compacted db in 1.459268ms
I1221 23:10:05.202353 32569 leveldb.cpp:196] Created db iterator in 73761ns
I1221 23:10:05.202383 32569 leveldb.cpp:202] Seeked to beginning of db in 3382ns
I1221 23:10:05.202405 32569 leveldb.cpp:271] Iterated through 0 keys in the db in 633ns
I1221 23:10:05.202674 32569 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I1221 23:10:05.205301 32604 recover.cpp:447] Starting replica recovery
I1221 23:10:05.206414 32569 local.cpp:239] Using 'local' authorizer
I1221 23:10:05.206405 32604 recover.cpp:473] Replica is in EMPTY status
I1221 23:10:05.209595 32594 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from (4)@172.17.0.2:40874
I1221 23:10:05.210916 32596 recover.cpp:193] Received a recover response from a replica in EMPTY status
I1221 23:10:05.211515 32597 master.cpp:365] Master 3931c1a8-1cd6-49eb-94c8-d01b33bb008e (6ccf2ee56b13) started on 172.17.0.2:40874
I1221 23:10:05.211699 32605 recover.cpp:564] Updating replica status to STARTING
I1221 23:10:05.211539 32597 master.cpp:367] Flags at startup: --acls="permissive: false
register_frameworks {
  principals {
    type: SOME
    values: "test-principal"
  }
  roles {
    type: SOME
    values: "*"
  }
}
run_tasks {
  principals {
    type: SOME
    values: "test-principal"
  }
  users {
    type: SOME
    values: "mesos"
  }
}
" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="true" --authenticate_slaves="false" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/ExamplesTest_NoExecutorFramework_fCmFLn/credentials" --framework_sorter="drf" --help="true" --hostname_lookup="true" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_slave_ping_timeouts="5" --quiet="false" --recovery_slave_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_store_timeout="5secs" --registry_strict="false" --root_submissions="true" --slave_ping_timeout="15secs" --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false" --webui_dir="/mesos/mesos-0.27.0/src/webui" --work_dir="/tmp/mesos-otpdch" --zk_session_timeout="10secs"
I1221 23:10:05.212323 32597 master.cpp:412] Master only allowing authenticated frameworks to register
I1221 23:10:05.212337 32597 master.cpp:419] Master allowing unauthenticated slaves to register
I1221 23:10:05.212347 32597 credentials.hpp:35] Loading credentials for authentication from '/tmp/ExamplesTest_NoExecutorFramework_fCmFLn/credentials'
W1221 23:10:05.212442 32597 credentials.hpp:50] Permissions on credentials file '/tmp/ExamplesTest_NoExecutorFramework_fCmFLn/credentials' are too open. It is recommended that your credentials file is NOT accessible by others.
I1221 23:10:05.212606 32600 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 656857ns
I1221 23:10:05.212620 32597 master.cpp:456] Using default 'crammd5' authenticator
I1221 23:10:05.212631 32600 replica.cpp:320] Persisted replica status to STARTING
I1221 23:10:05.212893 32597 authenticator.cpp:518] Initializing server SASL
I1221 23:10:05.213091 32608 recover.cpp:473] Replica is in STARTING status
I1221 23:10:05.213958 32595 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from (5)@172.17.0.2:40874
I1221 23:10:05.214323 32594 recover.cpp:193] Received a recover response from a replica in STARTING status
I1221 23:10:05.214689 32595 recover.cpp:564] Updating replica status to VOTING
I1221 23:10:05.215353 32596 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 487419ns
I1221 23:10:05.215384 32596 replica.cpp:320] Persisted replica status to VOTING
I1221 23:10:05.215481 32605 recover.cpp:578] Successfully joined the Paxos group
I1221 23:10:05.215867 32605 recover.cpp:462] Recover process terminated
I1221 23:10:05.216111 32569 containerizer.cpp:141] Using isolation: filesystem/posix,posix/cpu,posix/mem
W1221 23:10:05.217021 32569 backend.cpp:48] Failed to create 'bind' backend: BindBackend requires root privileges
I1221 23:10:05.221482 32608 slave.cpp:191] Slave started on 1)@172.17.0.2:40874
I1221 23:10:05.221521 32608 slave.cpp:192] Flags at startup: --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_auth_server="auth.docker.io" --docker_auth_server_port="443" --docker_kill_orphans="true" --docker_local_archives_dir="/tmp/mesos/images/docker" --docker_puller="local" --docker_puller_timeout="60" --docker_registry="registry-1.docker.io" --docker_registry_port="443" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/mesos/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="filesystem/posix,posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/mesos/mesos-0.27.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" --resources="cpus:2;mem:10240" --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/mesos-otpdch/0"
I1221 23:10:05.222578 32608 resources.cpp:478] Parsing resources as JSON failed: cpus:2;mem:10240
Trying semicolon-delimited string format instead
I1221 23:10:05.223465 32608 slave.cpp:392] Slave resources: cpus(*):2; mem(*):10240; disk(*):3.70122e+06; ports(*):[31000-32000]
I1221 23:10:05.223621 32569 containerizer.cpp:141] Using isolation: filesystem/posix,posix/cpu,posix/mem
I1221 23:10:05.223610 32608 slave.cpp:400] Slave attributes: [  ]
I1221 23:10:05.223677 32608 slave.cpp:405] Slave hostname: 6ccf2ee56b13
I1221 23:10:05.223697 32608 slave.cpp:410] Slave checkpoint: true
W1221 23:10:05.224143 32569 backend.cpp:48] Failed to create 'bind' backend: BindBackend requires root privileges
I1221 23:10:05.226668 32604 slave.cpp:191] Slave started on 2)@172.17.0.2:40874
I1221 23:10:05.226692 32604 slave.cpp:192] Flags at startup: --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_auth_server="auth.docker.io" --docker_auth_server_port="443" --docker_kill_orphans="true" --docker_local_archives_dir="/tmp/mesos/images/docker" --docker_puller="local" --docker_puller_timeout="60" --docker_registry="registry-1.docker.io" --docker_registry_port="443" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/mesos/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="filesystem/posix,posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/mesos/mesos-0.27.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" --resources="cpus:2;mem:10240" --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/mesos-otpdch/1"
I1221 23:10:05.227520 32604 resources.cpp:478] Parsing resources as JSON failed: cpus:2;mem:10240
Trying semicolon-delimited string format instead
I1221 23:10:05.228037 32604 slave.cpp:392] Slave resources: cpus(*):2; mem(*):10240; disk(*):3.70122e+06; ports(*):[31000-32000]
I1221 23:10:05.228148 32604 slave.cpp:400] Slave attributes: [  ]
I1221 23:10:05.228169 32604 slave.cpp:405] Slave hostname: 6ccf2ee56b13
I1221 23:10:05.228184 32604 slave.cpp:410] Slave checkpoint: true
I1221 23:10:05.229123 32569 containerizer.cpp:141] Using isolation: filesystem/posix,posix/cpu,posix/mem
I1221 23:10:05.229641 32605 state.cpp:58] Recovering state from '/tmp/mesos-otpdch/0/meta'
W1221 23:10:05.229645 32569 backend.cpp:48] Failed to create 'bind' backend: BindBackend requires root privileges
I1221 23:10:05.229636 32595 state.cpp:58] Recovering state from '/tmp/mesos-otpdch/1/meta'
I1221 23:10:05.230242 32605 status_update_manager.cpp:200] Recovering status update manager
I1221 23:10:05.230254 32598 status_update_manager.cpp:200] Recovering status update manager
I1221 23:10:05.230515 32601 containerizer.cpp:383] Recovering containerizer
I1221 23:10:05.230562 32602 containerizer.cpp:383] Recovering containerizer
I1221 23:10:05.232681 32597 auxprop.cpp:71] Initialized in-memory auxiliary property plugin
I1221 23:10:05.232803 32597 master.cpp:493] Authorization enabled
I1221 23:10:05.232867 32600 slave.cpp:4427] Finished recovery
I1221 23:10:05.232980 32598 slave.cpp:191] Slave started on 3)@172.17.0.2:40874
I1221 23:10:05.233039 32594 slave.cpp:4427] Finished recovery
I1221 23:10:05.233376 32599 whitelist_watcher.cpp:77] No whitelist given
I1221 23:10:05.233428 32601 hierarchical.cpp:147] Initialized hierarchical allocator process
I1221 23:10:05.233003 32598 slave.cpp:192] Flags at startup: --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_auth_server="auth.docker.io" --docker_auth_server_port="443" --docker_kill_orphans="true" --docker_local_archives_dir="/tmp/mesos/images/docker" --docker_puller="local" --docker_puller_timeout="60" --docker_registry="registry-1.docker.io" --docker_registry_port="443" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/mesos/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="filesystem/posix,posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/mesos/mesos-0.27.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" --resources="cpus:2;mem:10240" --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/mesos-otpdch/2"
I1221 23:10:05.233744 32600 slave.cpp:4599] Querying resource estimator for oversubscribable resources
I1221 23:10:05.233749 32598 resources.cpp:478] Parsing resources as JSON failed: cpus:2;mem:10240
Trying semicolon-delimited string format instead
I1221 23:10:05.234222 32598 slave.cpp:392] Slave resources: cpus(*):2; mem(*):10240; disk(*):3.70122e+06; ports(*):[31000-32000]
I1221 23:10:05.234284 32598 slave.cpp:400] Slave attributes: [  ]
I1221 23:10:05.234299 32598 slave.cpp:405] Slave hostname: 6ccf2ee56b13
I1221 23:10:05.234311 32598 slave.cpp:410] Slave checkpoint: true
I1221 23:10:05.234338 32600 slave.cpp:729] New master detected at master@172.17.0.2:40874
I1221 23:10:05.234376 32604 status_update_manager.cpp:174] Pausing sending status updates
I1221 23:10:05.234424 32600 slave.cpp:754] No credentials provided. Attempting to register without authentication
I1221 23:10:05.234522 32600 slave.cpp:765] Detecting new master
I1221 23:10:05.234616 32569 sched.cpp:164] Version: 0.27.0
I1221 23:10:05.234658 32600 slave.cpp:4613] Received oversubscribable resources  from the resource estimator
I1221 23:10:05.234671 32594 slave.cpp:4599] Querying resource estimator for oversubscribable resources
I1221 23:10:05.234884 32606 slave.cpp:4613] Received oversubscribable resources  from the resource estimator
I1221 23:10:05.235038 32595 status_update_manager.cpp:174] Pausing sending status updates
I1221 23:10:05.235043 32606 slave.cpp:729] New master detected at master@172.17.0.2:40874
I1221 23:10:05.235111 32606 slave.cpp:754] No credentials provided. Attempting to register without authentication
I1221 23:10:05.235147 32606 slave.cpp:765] Detecting new master
I1221 23:10:05.235240 32594 state.cpp:58] Recovering state from '/tmp/mesos-otpdch/2/meta'
I1221 23:10:05.235443 32608 status_update_manager.cpp:200] Recovering status update manager
I1221 23:10:05.235625 32594 containerizer.cpp:383] Recovering containerizer
I1221 23:10:05.236549 32599 slave.cpp:4427] Finished recovery
I1221 23:10:05.236984 32593 sched.cpp:262] New master detected at master@172.17.0.2:40874
I1221 23:10:05.237004 32599 slave.cpp:4599] Querying resource estimator for oversubscribable resources
I1221 23:10:05.237221 32593 sched.cpp:318] Authenticating with master master@172.17.0.2:40874
I1221 23:10:05.237277 32593 sched.cpp:325] Using default CRAM-MD5 authenticatee
I1221 23:10:05.237285 32604 status_update_manager.cpp:174] Pausing sending status updates
I1221 23:10:05.237288 32599 slave.cpp:729] New master detected at master@172.17.0.2:40874
I1221 23:10:05.237361 32599 slave.cpp:754] No credentials provided. Attempting to register without authentication
I1221 23:10:05.237433 32599 slave.cpp:765] Detecting new master
I1221 23:10:05.237565 32599 slave.cpp:4613] Received oversubscribable resources  from the resource estimator
I1221 23:10:05.238154 32605 authenticatee.cpp:97] Initializing client SASL
I1221 23:10:05.238315 32605 authenticatee.cpp:121] Creating new client SASL connection
I1221 23:10:05.239640 32597 master.cpp:1200] Dropping 'mesos.internal.AuthenticateMessage' message since not elected yet
I1221 23:10:05.239765 32597 master.cpp:1629] The newly elected leader is master@172.17.0.2:40874 with id 3931c1a8-1cd6-49eb-94c8-d01b33bb008e
I1221 23:10:05.239794 32597 master.cpp:1642] Elected as the leading master!
I1221 23:10:05.239843 32597 master.cpp:1387] Recovering from registrar
I1221 23:10:05.240056 32600 registrar.cpp:307] Recovering registrar
I1221 23:10:05.241477 32608 log.cpp:659] Attempting to start the writer
I1221 23:10:05.244540 32600 replica.cpp:493] Replica received implicit promise request from (39)@172.17.0.2:40874 with proposal 1
I1221 23:10:05.245358 32600 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 776937ns
I1221 23:10:05.245393 32600 replica.cpp:342] Persisted promised to 1
I1221 23:10:05.246625 32601 coordinator.cpp:238] Coordinator attempting to fill missing positions
I1221 23:10:05.248757 32605 replica.cpp:388] Replica received explicit promise request from (40)@172.17.0.2:40874 for position 0 with proposal 2
I1221 23:10:05.249214 32605 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 366567ns
I1221 23:10:05.249246 32605 replica.cpp:712] Persisted action at 0
I1221 23:10:05.250998 32599 replica.cpp:537] Replica received write request for position 0 from (41)@172.17.0.2:40874
I1221 23:10:05.251111 32599 leveldb.cpp:436] Reading position from leveldb took 66773ns
I1221 23:10:05.251734 32599 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 379612ns
I1221 23:10:05.251759 32599 replica.cpp:712] Persisted action at 0
I1221 23:10:05.252555 32601 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0
I1221 23:10:05.253010 32601 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 381858ns
I1221 23:10:05.253036 32601 replica.cpp:712] Persisted action at 0
I1221 23:10:05.253068 32601 replica.cpp:697] Replica learned NOP action at position 0
I1221 23:10:05.254043 32595 log.cpp:675] Writer started with ending position 0
I1221 23:10:05.256741 32595 leveldb.cpp:436] Reading position from leveldb took 48607ns
I1221 23:10:05.260617 32601 registrar.cpp:340] Successfully fetched the registry (0B) in 20.47616ms
I1221 23:10:05.260988 32601 registrar.cpp:439] Applied 1 operations in 103123ns; attempting to update the 'registry'
I1221 23:10:05.264700 32604 log.cpp:683] Attempting to append 170 bytes to the log
I1221 23:10:05.265138 32601 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
I1221 23:10:05.266208 32603 replica.cpp:537] Replica received write request for position 1 from (42)@172.17.0.2:40874
I1221 23:10:05.266829 32603 leveldb.cpp:341] Persisting action (189 bytes) to leveldb took 551087ns
I1221 23:10:05.266861 32603 replica.cpp:712] Persisted action at 1
I1221 23:10:05.267918 32605 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
I1221 23:10:05.268442 32605 leveldb.cpp:341] Persisting action (191 bytes) to leveldb took 453416ns
I1221 23:10:05.268470 32605 replica.cpp:712] Persisted action at 1
I1221 23:10:05.268506 32605 replica.cpp:697] Replica learned APPEND action at position 1
I1221 23:10:05.270512 32606 registrar.cpp:484] Successfully updated the 'registry' in 9.375232ms
I1221 23:10:05.270705 32606 registrar.cpp:370] Successfully recovered registrar
I1221 23:10:05.271045 32602 log.cpp:702] Attempting to truncate the log to 1
I1221 23:10:05.271178 32603 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
I1221 23:10:05.271695 32605 master.cpp:1439] Recovered 0 slaves from the Registry (131B) ; allowing 10mins for slaves to re-register
I1221 23:10:05.271751 32603 hierarchical.cpp:165] Skipping recovery of hierarchical allocator: nothing to recover
I1221 23:10:05.272274 32596 replica.cpp:537] Replica received write request for position 2 from (43)@172.17.0.2:40874
I1221 23:10:05.272838 32596 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 451122ns
I1221 23:10:05.272867 32596 replica.cpp:712] Persisted action at 2
I1221 23:10:05.273483 32607 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
I1221 23:10:05.273919 32607 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 405444ns
I1221 23:10:05.273977 32607 leveldb.cpp:399] Deleting ~1 keys from leveldb took 33953ns
I1221 23:10:05.273998 32607 replica.cpp:712] Persisted action at 2
I1221 23:10:05.274024 32607 replica.cpp:697] Replica learned TRUNCATE action at position 2
I1221 23:10:05.288020 32593 slave.cpp:1254] Will retry registration in 1.091568855secs if necessary
I1221 23:10:05.288321 32605 master.cpp:4132] Registering slave at slave(3)@172.17.0.2:40874 (6ccf2ee56b13) with id 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S0
I1221 23:10:05.289105 32607 registrar.cpp:439] Applied 1 operations in 104776ns; attempting to update the 'registry'
I1221 23:10:05.291494 32605 log.cpp:683] Attempting to append 339 bytes to the log
I1221 23:10:05.291594 32595 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3
I1221 23:10:05.292273 32602 replica.cpp:537] Replica received write request for position 3 from (44)@172.17.0.2:40874
I1221 23:10:05.292811 32602 leveldb.cpp:341] Persisting action (358 bytes) to leveldb took 499449ns
I1221 23:10:05.292845 32602 replica.cpp:712] Persisted action at 3
I1221 23:10:05.293373 32594 replica.cpp:691] Replica received learned notice for position 3 from @0.0.0.0:0
I1221 23:10:05.293776 32594 leveldb.cpp:341] Persisting action (360 bytes) to leveldb took 376184ns
I1221 23:10:05.293799 32594 replica.cpp:712] Persisted action at 3
I1221 23:10:05.293833 32594 replica.cpp:697] Replica learned APPEND action at position 3
I1221 23:10:05.295142 32603 registrar.cpp:484] Successfully updated the 'registry' in 5.945088ms
I1221 23:10:05.295403 32602 log.cpp:702] Attempting to truncate the log to 3
I1221 23:10:05.295513 32603 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 4
I1221 23:10:05.296146 32598 replica.cpp:537] Replica received write request for position 4 from (45)@172.17.0.2:40874
I1221 23:10:05.296443 32608 slave.cpp:3371] Received ping from slave-observer(1)@172.17.0.2:40874
I1221 23:10:05.296552 32598 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 368428ns
I1221 23:10:05.296604 32598 replica.cpp:712] Persisted action at 4
I1221 23:10:05.296744 32594 master.cpp:4200] Registered slave 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S0 at slave(3)@172.17.0.2:40874 (6ccf2ee56b13) with cpus(*):2; mem(*):10240; disk(*):3.70122e+06; ports(*):[31000-32000]
I1221 23:10:05.297025 32597 slave.cpp:904] Registered with master master@172.17.0.2:40874; given slave ID 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S0
I1221 23:10:05.297056 32597 fetcher.cpp:81] Clearing fetcher cache
I1221 23:10:05.297175 32599 status_update_manager.cpp:181] Resuming sending status updates
I1221 23:10:05.297184 32600 hierarchical.cpp:465] Added slave 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S0 (6ccf2ee56b13) with cpus(*):2; mem(*):10240; disk(*):3.70122e+06; ports(*):[31000-32000] (allocated: )
I1221 23:10:05.297473 32597 slave.cpp:927] Checkpointing SlaveInfo to '/tmp/mesos-otpdch/2/meta/slaves/3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S0/slave.info'
I1221 23:10:05.297618 32600 hierarchical.cpp:1329] No resources available to allocate!
I1221 23:10:05.297688 32600 hierarchical.cpp:1101] Performed allocation for slave 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S0 in 454887ns
I1221 23:10:05.298058 32597 slave.cpp:963] Forwarding total oversubscribed resources 
I1221 23:10:05.298235 32597 master.cpp:4542] Received update of slave 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S0 at slave(3)@172.17.0.2:40874 (6ccf2ee56b13) with total oversubscribed resources 
I1221 23:10:05.298396 32604 replica.cpp:691] Replica received learned notice for position 4 from @0.0.0.0:0
I1221 23:10:05.298765 32597 hierarchical.cpp:521] Slave 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S0 (6ccf2ee56b13) updated with oversubscribed resources  (total: cpus(*):2; mem(*):10240; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: )
I1221 23:10:05.298907 32597 hierarchical.cpp:1329] No resources available to allocate!
I1221 23:10:05.298933 32597 hierarchical.cpp:1101] Performed allocation for slave 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S0 in 134328ns
I1221 23:10:05.298965 32604 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 505213ns
I1221 23:10:05.299031 32604 leveldb.cpp:399] Deleting ~2 keys from leveldb took 37007ns
I1221 23:10:05.299054 32604 replica.cpp:712] Persisted action at 4
I1221 23:10:05.299103 32604 replica.cpp:697] Replica learned TRUNCATE action at position 4
I1221 23:10:05.350281 32598 slave.cpp:1254] Will retry registration in 1.181298785secs if necessary
I1221 23:10:05.350510 32608 master.cpp:4132] Registering slave at slave(1)@172.17.0.2:40874 (6ccf2ee56b13) with id 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S1
I1221 23:10:05.351222 32607 registrar.cpp:439] Applied 1 operations in 118623ns; attempting to update the 'registry'
I1221 23:10:05.352174 32604 log.cpp:683] Attempting to append 505 bytes to the log
I1221 23:10:05.352375 32595 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 5
I1221 23:10:05.353365 32601 replica.cpp:537] Replica received write request for position 5 from (46)@172.17.0.2:40874
I1221 23:10:05.353960 32601 leveldb.cpp:341] Persisting action (524 bytes) to leveldb took 552132ns
I1221 23:10:05.353986 32601 replica.cpp:712] Persisted action at 5
I1221 23:10:05.354867 32606 replica.cpp:691] Replica received learned notice for position 5 from @0.0.0.0:0
I1221 23:10:05.355370 32606 leveldb.cpp:341] Persisting action (526 bytes) to leveldb took 456354ns
I1221 23:10:05.355399 32606 replica.cpp:712] Persisted action at 5
I1221 23:10:05.355432 32606 replica.cpp:697] Replica learned APPEND action at position 5
I1221 23:10:05.357318 32595 registrar.cpp:484] Successfully updated the 'registry' in 6.016768ms
I1221 23:10:05.357708 32595 log.cpp:702] Attempting to truncate the log to 5
I1221 23:10:05.357805 32606 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 6
I1221 23:10:05.358273 32602 slave.cpp:3371] Received ping from slave-observer(2)@172.17.0.2:40874
I1221 23:10:05.358331 32599 master.cpp:4200] Registered slave 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S1 at slave(1)@172.17.0.2:40874 (6ccf2ee56b13) with cpus(*):2; mem(*):10240; disk(*):3.70122e+06; ports(*):[31000-32000]
I1221 23:10:05.358405 32602 slave.cpp:904] Registered with master master@172.17.0.2:40874; given slave ID 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S1
I1221 23:10:05.358428 32602 fetcher.cpp:81] Clearing fetcher cache
I1221 23:10:05.358722 32599 status_update_manager.cpp:181] Resuming sending status updates
I1221 23:10:05.358736 32606 hierarchical.cpp:465] Added slave 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S1 (6ccf2ee56b13) with cpus(*):2; mem(*):10240; disk(*):3.70122e+06; ports(*):[31000-32000] (allocated: )
I1221 23:10:05.358813 32599 replica.cpp:537] Replica received write request for position 6 from (47)@172.17.0.2:40874
I1221 23:10:05.358952 32602 slave.cpp:927] Checkpointing SlaveInfo to '/tmp/mesos-otpdch/0/meta/slaves/3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S1/slave.info'
I1221 23:10:05.358969 32606 hierarchical.cpp:1329] No resources available to allocate!
I1221 23:10:05.358996 32606 hierarchical.cpp:1101] Performed allocation for slave 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S1 in 217083ns
I1221 23:10:05.359350 32599 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 464454ns
I1221 23:10:05.359374 32599 replica.cpp:712] Persisted action at 6
I1221 23:10:05.359591 32602 slave.cpp:963] Forwarding total oversubscribed resources 
I1221 23:10:05.359740 32606 master.cpp:4542] Received update of slave 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S1 at slave(1)@172.17.0.2:40874 (6ccf2ee56b13) with total oversubscribed resources 
I1221 23:10:05.360227 32605 replica.cpp:691] Replica received learned notice for position 6 from @0.0.0.0:0
I1221 23:10:05.360288 32606 hierarchical.cpp:521] Slave 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S1 (6ccf2ee56b13) updated with oversubscribed resources  (total: cpus(*):2; mem(*):10240; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: )
I1221 23:10:05.360539 32606 hierarchical.cpp:1329] No resources available to allocate!
I1221 23:10:05.360591 32606 hierarchical.cpp:1101] Performed allocation for slave 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S1 in 256841ns
I1221 23:10:05.360702 32605 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 444736ns
I1221 23:10:05.360759 32605 leveldb.cpp:399] Deleting ~2 keys from leveldb took 30869ns
I1221 23:10:05.360777 32605 replica.cpp:712] Persisted action at 6
I1221 23:10:05.360800 32605 replica.cpp:697] Replica learned TRUNCATE action at position 6
I1221 23:10:05.957257 32601 slave.cpp:1254] Will retry registration in 627.120173ms if necessary
I1221 23:10:05.957504 32597 master.cpp:4132] Registering slave at slave(2)@172.17.0.2:40874 (6ccf2ee56b13) with id 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S2
I1221 23:10:05.958284 32607 registrar.cpp:439] Applied 1 operations in 174321ns; attempting to update the 'registry'
I1221 23:10:05.959336 32594 log.cpp:683] Attempting to append 671 bytes to the log
I1221 23:10:05.959477 32606 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 7
I1221 23:10:05.960484 32604 replica.cpp:537] Replica received write request for position 7 from (48)@172.17.0.2:40874
I1221 23:10:05.960891 32604 leveldb.cpp:341] Persisting action (690 bytes) to leveldb took 362101ns
I1221 23:10:05.960917 32604 replica.cpp:712] Persisted action at 7
I1221 23:10:05.961642 32597 replica.cpp:691] Replica received learned notice for position 7 from @0.0.0.0:0
I1221 23:10:05.962502 32597 leveldb.cpp:341] Persisting action (692 bytes) to leveldb took 828414ns
I1221 23:10:05.962532 32597 replica.cpp:712] Persisted action at 7
I1221 23:10:05.962563 32597 replica.cpp:697] Replica learned APPEND action at position 7
I1221 23:10:05.964241 32598 registrar.cpp:484] Successfully updated the 'registry' in 5.87392ms
I1221 23:10:05.964552 32593 log.cpp:702] Attempting to truncate the log to 7
I1221 23:10:05.964643 32606 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 8
I1221 23:10:05.964964 32593 slave.cpp:3371] Received ping from slave-observer(3)@172.17.0.2:40874
I1221 23:10:05.965152 32602 slave.cpp:904] Registered with master master@172.17.0.2:40874; given slave ID 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S2
I1221 23:10:05.965111 32600 master.cpp:4200] Registered slave 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S2 at slave(2)@172.17.0.2:40874 (6ccf2ee56b13) with cpus(*):2; mem(*):10240; disk(*):3.70122e+06; ports(*):[31000-32000]
I1221 23:10:05.965178 32602 fetcher.cpp:81] Clearing fetcher cache
I1221 23:10:05.965293 32607 status_update_manager.cpp:181] Resuming sending status updates
I1221 23:10:05.965293 32593 replica.cpp:537] Replica received write request for position 8 from (49)@172.17.0.2:40874
I1221 23:10:05.965637 32603 hierarchical.cpp:465] Added slave 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S2 (6ccf2ee56b13) with cpus(*):2; mem(*):10240; disk(*):3.70122e+06; ports(*):[31000-32000] (allocated: )
I1221 23:10:05.965734 32602 slave.cpp:927] Checkpointing SlaveInfo to '/tmp/mesos-otpdch/1/meta/slaves/3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S2/slave.info'
I1221 23:10:05.965751 32593 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 424617ns
I1221 23:10:05.965772 32593 replica.cpp:712] Persisted action at 8
I1221 23:10:05.965847 32603 hierarchical.cpp:1329] No resources available to allocate!
I1221 23:10:05.965880 32603 hierarchical.cpp:1101] Performed allocation for slave 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S2 in 209313ns
I1221 23:10:05.966145 32602 slave.cpp:963] Forwarding total oversubscribed resources 
I1221 23:10:05.966325 32601 replica.cpp:691] Replica received learned notice for position 8 from @0.0.0.0:0
I1221 23:10:05.966342 32596 master.cpp:4542] Received update of slave 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S2 at slave(2)@172.17.0.2:40874 (6ccf2ee56b13) with total oversubscribed resources 
I1221 23:10:05.966703 32601 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 347667ns
I1221 23:10:05.966753 32601 leveldb.cpp:399] Deleting ~2 keys from leveldb took 29042ns
I1221 23:10:05.966770 32601 replica.cpp:712] Persisted action at 8
I1221 23:10:05.966791 32601 replica.cpp:697] Replica learned TRUNCATE action at position 8
I1221 23:10:05.966792 32602 hierarchical.cpp:521] Slave 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S2 (6ccf2ee56b13) updated with oversubscribed resources  (total: cpus(*):2; mem(*):10240; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: )
I1221 23:10:05.966943 32602 hierarchical.cpp:1329] No resources available to allocate!
I1221 23:10:05.966969 32602 hierarchical.cpp:1101] Performed allocation for slave 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S2 in 137680ns
I1221 23:10:06.235074 32595 hierarchical.cpp:1329] No resources available to allocate!
I1221 23:10:06.235142 32595 hierarchical.cpp:1079] Performed allocation for 3 slaves in 594477ns
I1221 23:10:07.237238 32599 hierarchical.cpp:1329] No resources available to allocate!
I1221 23:10:07.237309 32599 hierarchical.cpp:1079] Performed allocation for 3 slaves in 506418ns
I1221 23:10:07.702738 32564 exec.cpp:88] Committing suicide by killing the process group
II1221 23:10:07.703501 32546 exec.cpp:88] Committing suicide by killing the process group
1221 23:10:07.703501 32525 exec.cpp:88] Committing suicide by killing the process group
I1221 23:10:08.239282 32608 hierarchical.cpp:1329] No resources available to allocate!
I1221 23:10:08.239356 32608 hierarchical.cpp:1079] Performed allocation for 3 slaves in 671976ns
I1221 23:10:09.241236 32600 hierarchical.cpp:1329] No resources available to allocate!
I1221 23:10:09.241303 32600 hierarchical.cpp:1079] Performed allocation for 3 slaves in 520741ns
W1221 23:10:10.239298 32601 sched.cpp:429] Authentication timed out
I1221 23:10:10.239653 32596 sched.cpp:387] Failed to authenticate with master master@172.17.0.2:40874: Authentication discarded
I1221 23:10:10.239714 32596 sched.cpp:318] Authenticating with master master@172.17.0.2:40874

...
...
...
I1221 23:10:10.432864 32597 slave.cpp:1796] Sending queued task '0' to executor '0' of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 at executor(1)@172.17.0.2:60995
I1221 23:10:10.433215 32765 exec.cpp:208] Executor registered on slave 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S1
I1221 23:10:10.435856 32765 exec.cpp:220] Executor::registered took 343507ns
Registered executor on 6ccf2ee56b13
I1221 23:10:10.436198 32765 exec.cpp:295] Executor asked to run task '0'
I1221 23:10:10.436317 32765 exec.cpp:304] Executor::launchTask took 86293ns
Starting task 0
Forked command at 361
sh -c 'echo hello'
I1221 23:10:10.437671   335 exec.cpp:184] Executor started at: executor(1)@172.17.0.2:33894 with pid 32696
I1221 23:10:10.438062   315 exec.cpp:184] Executor started at: executor(1)@172.17.0.2:51530 with pid 32695
hello
I1221 23:10:10.440052 32599 slave.cpp:2578] Got registration for executor '2' of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 from executor(1)@172.17.0.2:33894
I1221 23:10:10.440507 32599 slave.cpp:2664] Checkpointing executor pid 'executor(1)@172.17.0.2:33894' to '/tmp/mesos-otpdch/0/meta/slaves/3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S1/frameworks/3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000/executors/2/runs/63bf8626-189d-44f9-a961-b51b046d5057/pids/libprocess.pid'
WARNING: Logging before InitGoogleLogging() is written to STDERR
I1221 23:10:10.440497 32733 process.cpp:998] libprocess is initialized on 172.17.0.2:33285 for 16 cpus
I1221 23:10:10.441426 32733 logging.cpp:172] Logging to STDERR
I1221 23:10:10.441916 32599 slave.cpp:2578] Got registration for executor '1' of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 from executor(1)@172.17.0.2:51530
I1221 23:10:10.442277 32599 slave.cpp:2664] Checkpointing executor pid 'executor(1)@172.17.0.2:51530' to '/tmp/mesos-otpdch/0/meta/slaves/3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S1/frameworks/3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000/executors/1/runs/468fb0f8-4dd0-448c-8e64-207cc4c81c63/pids/libprocess.pid'
I1221 23:10:10.442314   303 exec.cpp:517] Executor sending status update TASK_RUNNING (UUID: 61620dd2-95c0-4570-b174-24ed26e0a289) for task 0 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.442684   339 exec.cpp:208] Executor registered on slave 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S1
I1221 23:10:10.443305 32599 slave.cpp:1796] Sending queued task '2' to executor '2' of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 at executor(1)@172.17.0.2:33894
I1221 23:10:10.443668 32733 exec.cpp:134] Version: 0.27.0
I1221 23:10:10.443768 32599 slave.cpp:2937] Handling status update TASK_RUNNING (UUID: 61620dd2-95c0-4570-b174-24ed26e0a289) for task 0 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 from executor(1)@172.17.0.2:60995
I1221 23:10:10.444797   320 exec.cpp:208] Executor registered on slave 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S1
I1221 23:10:10.445159   339 exec.cpp:220] Executor::registered took 241955ns
Registered executor on 6ccf2ee56b13
I1221 23:10:10.445430   339 exec.cpp:295] Executor asked to run task '2'
Starting task 2
I1221 23:10:10.445519   339 exec.cpp:304] Executor::launchTask took 65600ns
I1221 23:10:10.445794 32598 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 61620dd2-95c0-4570-b174-24ed26e0a289) for task 0 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.445888 32598 status_update_manager.cpp:497] Creating StatusUpdate stream for task 0 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.446015 32599 slave.cpp:1796] Sending queued task '1' to executor '1' of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 at executor(1)@172.17.0.2:51530
Forked command at 362
I1221 23:10:10.446622 32598 status_update_manager.cpp:824] Checkpointing UPDATE for status update TASK_RUNNING (UUID: 61620dd2-95c0-4570-b174-24ed26e0a289) for task 0 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.446990   320 exec.cpp:220] Executor::registered took 324561ns
sh -c 'echo hello'
Registered executor on 6ccf2ee56b13
I1221 23:10:10.447427   320 exec.cpp:295] Executor asked to run task '1'
Starting task 1
I1221 23:10:10.447540   320 exec.cpp:304] Executor::launchTask took 84828ns
Forked command at 363
sh -c 'echo hello'
hello
I1221 23:10:10.449244   334 exec.cpp:517] Executor sending status update TASK_RUNNING (UUID: b774dc4c-940c-41d5-be2a-ed3a9e8379a7) for task 2 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
hello
I1221 23:10:10.450145 32597 slave.cpp:2937] Handling status update TASK_RUNNING (UUID: b774dc4c-940c-41d5-be2a-ed3a9e8379a7) for task 2 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 from executor(1)@172.17.0.2:33894
I1221 23:10:10.451092 32598 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: 61620dd2-95c0-4570-b174-24ed26e0a289) for task 0 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 to the slave
I1221 23:10:10.451117   324 exec.cpp:517] Executor sending status update TASK_RUNNING (UUID: 7a5d5a7f-975d-4970-949e-cfa4d08a4a30) for task 1 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.451370 32595 slave.cpp:3289] Forwarding the update TASK_RUNNING (UUID: 61620dd2-95c0-4570-b174-24ed26e0a289) for task 0 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 to master@172.17.0.2:40874
I1221 23:10:10.451637 32598 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: b774dc4c-940c-41d5-be2a-ed3a9e8379a7) for task 2 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.451710 32598 status_update_manager.cpp:497] Creating StatusUpdate stream for task 2 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.451652 32595 slave.cpp:3183] Status update manager successfully handled status update TASK_RUNNING (UUID: 61620dd2-95c0-4570-b174-24ed26e0a289) for task 0 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.451838 32593 master.cpp:4687] Status update TASK_RUNNING (UUID: 61620dd2-95c0-4570-b174-24ed26e0a289) for task 0 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 from slave 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S1 at slave(1)@172.17.0.2:40874 (6ccf2ee56b13)
I1221 23:10:10.451974 32593 master.cpp:4735] Forwarding status update TASK_RUNNING (UUID: 61620dd2-95c0-4570-b174-24ed26e0a289) for task 0 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.452203 32593 master.cpp:6347] Updating the state of task 0 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
I1221 23:10:10.451875 32595 slave.cpp:3199] Sending acknowledgement for status update TASK_RUNNING (UUID: 61620dd2-95c0-4570-b174-24ed26e0a289) for task 0 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 to executor(1)@172.17.0.2:60995
I1221 23:10:10.452308 32598 status_update_manager.cpp:824] Checkpointing UPDATE for status update TASK_RUNNING (UUID: b774dc4c-940c-41d5-be2a-ed3a9e8379a7) for task 2 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.452432 32603 no_executor_framework.cpp:160] Task '0' is in state TASK_RUNNING
I1221 23:10:10.452468 32603 sched.cpp:919] Scheduler::statusUpdate took 46157ns
I1221 23:10:10.452905 32606 slave.cpp:2937] Handling status update TASK_RUNNING (UUID: 7a5d5a7f-975d-4970-949e-cfa4d08a4a30) for task 1 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 from executor(1)@172.17.0.2:51530
I1221 23:10:10.453151 32598 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: b774dc4c-940c-41d5-be2a-ed3a9e8379a7) for task 2 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 to the slave
I1221 23:10:10.453403   302 exec.cpp:341] Executor received status update acknowledgement 61620dd2-95c0-4570-b174-24ed26e0a289 for task 0 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.453454 32598 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 7a5d5a7f-975d-4970-949e-cfa4d08a4a30) for task 1 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.453496 32598 status_update_manager.cpp:497] Creating StatusUpdate stream for task 1 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.453488 32606 slave.cpp:3289] Forwarding the update TASK_RUNNING (UUID: b774dc4c-940c-41d5-be2a-ed3a9e8379a7) for task 2 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 to master@172.17.0.2:40874
I1221 23:10:10.453840 32598 status_update_manager.cpp:824] Checkpointing UPDATE for status update TASK_RUNNING (UUID: 7a5d5a7f-975d-4970-949e-cfa4d08a4a30) for task 1 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.453954 32603 master.cpp:3844] Processing ACKNOWLEDGE call 61620dd2-95c0-4570-b174-24ed26e0a289 for task 0 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 (No Executor Framework) at scheduler-7caeff0b-9ca0-4c4c-935b-843b0edf2650@172.17.0.2:40874 on slave 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S1
I1221 23:10:10.454144 32606 slave.cpp:3183] Status update manager successfully handled status update TASK_RUNNING (UUID: b774dc4c-940c-41d5-be2a-ed3a9e8379a7) for task 2 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.454195 32606 slave.cpp:3199] Sending acknowledgement for status update TASK_RUNNING (UUID: b774dc4c-940c-41d5-be2a-ed3a9e8379a7) for task 2 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 to executor(1)@172.17.0.2:33894
I1221 23:10:10.454293 32600 master.cpp:4687] Status update TASK_RUNNING (UUID: b774dc4c-940c-41d5-be2a-ed3a9e8379a7) for task 2 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 from slave 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S1 at slave(1)@172.17.0.2:40874 (6ccf2ee56b13)
I1221 23:10:10.454344 32600 master.cpp:4735] Forwarding status update TASK_RUNNING (UUID: b774dc4c-940c-41d5-be2a-ed3a9e8379a7) for task 2 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.454502 32600 master.cpp:6347] Updating the state of task 2 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
I1221 23:10:10.454665 32600 no_executor_framework.cpp:160] Task '2' is in state TASK_RUNNING
I1221 23:10:10.454691 32600 sched.cpp:919] Scheduler::statusUpdate took 31056ns
I1221 23:10:10.454856   335 exec.cpp:341] Executor received status update acknowledgement b774dc4c-940c-41d5-be2a-ed3a9e8379a7 for task 2 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.454898 32598 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: 7a5d5a7f-975d-4970-949e-cfa4d08a4a30) for task 1 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 to the slave
I1221 23:10:10.455098 32600 master.cpp:3844] Processing ACKNOWLEDGE call b774dc4c-940c-41d5-be2a-ed3a9e8379a7 for task 2 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 (No Executor Framework) at scheduler-7caeff0b-9ca0-4c4c-935b-843b0edf2650@172.17.0.2:40874 on slave 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S1
I1221 23:10:10.455250 32605 slave.cpp:3289] Forwarding the update TASK_RUNNING (UUID: 7a5d5a7f-975d-4970-949e-cfa4d08a4a30) for task 1 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 to master@172.17.0.2:40874
I1221 23:10:10.455487 32598 status_update_manager.cpp:392] Received status update acknowledgement (UUID: 61620dd2-95c0-4570-b174-24ed26e0a289) for task 0 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.455533 32605 slave.cpp:3183] Status update manager successfully handled status update TASK_RUNNING (UUID: 7a5d5a7f-975d-4970-949e-cfa4d08a4a30) for task 1 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.455538 32607 master.cpp:4687] Status update TASK_RUNNING (UUID: 7a5d5a7f-975d-4970-949e-cfa4d08a4a30) for task 1 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 from slave 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S1 at slave(1)@172.17.0.2:40874 (6ccf2ee56b13)
I1221 23:10:10.455574 32607 master.cpp:4735] Forwarding status update TASK_RUNNING (UUID: 7a5d5a7f-975d-4970-949e-cfa4d08a4a30) for task 1 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.455574 32605 slave.cpp:3199] Sending acknowledgement for status update TASK_RUNNING (UUID: 7a5d5a7f-975d-4970-949e-cfa4d08a4a30) for task 1 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 to executor(1)@172.17.0.2:51530
I1221 23:10:10.455685 32598 status_update_manager.cpp:824] Checkpointing ACK for status update TASK_RUNNING (UUID: 61620dd2-95c0-4570-b174-24ed26e0a289) for task 0 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.455713 32607 master.cpp:6347] Updating the state of task 1 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
I1221 23:10:10.455813 32606 no_executor_framework.cpp:160] Task '1' is in state TASK_RUNNING
I1221 23:10:10.455916 32606 sched.cpp:919] Scheduler::statusUpdate took 105226ns
I1221 23:10:10.455812   344 exec.cpp:184] Executor started at: executor(1)@172.17.0.2:33285 with pid 32733
I1221 23:10:10.456140 32607 master.cpp:3844] Processing ACKNOWLEDGE call 7a5d5a7f-975d-4970-949e-cfa4d08a4a30 for task 1 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 (No Executor Framework) at scheduler-7caeff0b-9ca0-4c4c-935b-843b0edf2650@172.17.0.2:40874 on slave 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S1
I1221 23:10:10.456163   312 exec.cpp:341] Executor received status update acknowledgement 7a5d5a7f-975d-4970-949e-cfa4d08a4a30 for task 1 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.456812 32598 status_update_manager.cpp:392] Received status update acknowledgement (UUID: b774dc4c-940c-41d5-be2a-ed3a9e8379a7) for task 2 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.456807 32606 slave.cpp:2348] Status update manager successfully handled status update acknowledgement (UUID: 61620dd2-95c0-4570-b174-24ed26e0a289) for task 0 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.457012 32598 status_update_manager.cpp:824] Checkpointing ACK for status update TASK_RUNNING (UUID: b774dc4c-940c-41d5-be2a-ed3a9e8379a7) for task 2 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.457720 32598 status_update_manager.cpp:392] Received status update acknowledgement (UUID: 7a5d5a7f-975d-4970-949e-cfa4d08a4a30) for task 1 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.457751 32607 slave.cpp:2348] Status update manager successfully handled status update acknowledgement (UUID: b774dc4c-940c-41d5-be2a-ed3a9e8379a7) for task 2 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.457883 32598 status_update_manager.cpp:824] Checkpointing ACK for status update TASK_RUNNING (UUID: 7a5d5a7f-975d-4970-949e-cfa4d08a4a30) for task 1 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.458319 32604 slave.cpp:2578] Got registration for executor '3' of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 from executor(1)@172.17.0.2:33285
I1221 23:10:10.458766 32604 slave.cpp:2664] Checkpointing executor pid 'executor(1)@172.17.0.2:33285' to '/tmp/mesos-otpdch/0/meta/slaves/3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S1/frameworks/3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000/executors/3/runs/7f37bf6f-50f1-45a9-ae7a-20b1b829cc38/pids/libprocess.pid'
I1221 23:10:10.460311 32604 slave.cpp:2348] Status update manager successfully handled status update acknowledgement (UUID: 7a5d5a7f-975d-4970-949e-cfa4d08a4a30) for task 1 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.461024   349 exec.cpp:208] Executor registered on slave 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S1
I1221 23:10:10.461304 32603 slave.cpp:1796] Sending queued task '3' to executor '3' of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 at executor(1)@172.17.0.2:33285
I1221 23:10:10.462968   349 exec.cpp:220] Executor::registered took 273965ns
Registered executor on 6ccf2ee56b13
I1221 23:10:10.463317   349 exec.cpp:295] Executor asked to run task '3'
Starting task 3
I1221 23:10:10.463429   349 exec.cpp:304] Executor::launchTask took 87510ns
Forked command at 381
sh -c 'echo hello'
hello
WARNING: Logging before InitGoogleLogging() is written to STDERR
I1221 23:10:10.466104 32747 process.cpp:998] libprocess is initialized on 172.17.0.2:39520 for 16 cpus
I1221 23:10:10.466836   351 exec.cpp:517] Executor sending status update TASK_RUNNING (UUID: f4c28f0e-5d99-46e2-8e97-be35f47a8447) for task 3 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.467958 32604 slave.cpp:2937] Handling status update TASK_RUNNING (UUID: f4c28f0e-5d99-46e2-8e97-be35f47a8447) for task 3 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 from executor(1)@172.17.0.2:33285
I1221 23:10:10.468389 32595 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: f4c28f0e-5d99-46e2-8e97-be35f47a8447) for task 3 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.468441 32595 status_update_manager.cpp:497] Creating StatusUpdate stream for task 3 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.469084 32595 status_update_manager.cpp:824] Checkpointing UPDATE for status update TASK_RUNNING (UUID: f4c28f0e-5d99-46e2-8e97-be35f47a8447) for task 3 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.470094 32595 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: f4c28f0e-5d99-46e2-8e97-be35f47a8447) for task 3 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 to the slave
I1221 23:10:10.470365 32597 slave.cpp:3289] Forwarding the update TASK_RUNNING (UUID: f4c28f0e-5d99-46e2-8e97-be35f47a8447) for task 3 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 to master@172.17.0.2:40874
I1221 23:10:10.470433 32747 logging.cpp:172] Logging to STDERR
I1221 23:10:10.470557 32597 slave.cpp:3183] Status update manager successfully handled status update TASK_RUNNING (UUID: f4c28f0e-5d99-46e2-8e97-be35f47a8447) for task 3 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.470603 32597 slave.cpp:3199] Sending acknowledgement for status update TASK_RUNNING (UUID: f4c28f0e-5d99-46e2-8e97-be35f47a8447) for task 3 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 to executor(1)@172.17.0.2:33285
I1221 23:10:10.470706 32604 master.cpp:4687] Status update TASK_RUNNING (UUID: f4c28f0e-5d99-46e2-8e97-be35f47a8447) for task 3 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 from slave 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S1 at slave(1)@172.17.0.2:40874 (6ccf2ee56b13)
I1221 23:10:10.470757 32604 master.cpp:4735] Forwarding status update TASK_RUNNING (UUID: f4c28f0e-5d99-46e2-8e97-be35f47a8447) for task 3 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.470984 32604 master.cpp:6347] Updating the state of task 3 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
I1221 23:10:10.471132 32595 no_executor_framework.cpp:160] Task '3' is in state TASK_RUNNING
I1221 23:10:10.471163 32595 sched.cpp:919] Scheduler::statusUpdate took 46297ns
I1221 23:10:10.471405 32595 master.cpp:3844] Processing ACKNOWLEDGE call f4c28f0e-5d99-46e2-8e97-be35f47a8447 for task 3 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 (No Executor Framework) at scheduler-7caeff0b-9ca0-4c4c-935b-843b0edf2650@172.17.0.2:40874 on slave 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S1
I1221 23:10:10.471519   346 exec.cpp:341] Executor received status update acknowledgement f4c28f0e-5d99-46e2-8e97-be35f47a8447 for task 3 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.471691 32595 status_update_manager.cpp:392] Received status update acknowledgement (UUID: f4c28f0e-5d99-46e2-8e97-be35f47a8447) for task 3 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.471897 32595 status_update_manager.cpp:824] Checkpointing ACK for status update TASK_RUNNING (UUID: f4c28f0e-5d99-46e2-8e97-be35f47a8447) for task 3 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.472843 32608 slave.cpp:2348] Status update manager successfully handled status update acknowledgement (UUID: f4c28f0e-5d99-46e2-8e97-be35f47a8447) for task 3 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.476374 32747 exec.cpp:134] Version: 0.27.0
I1221 23:10:10.478024   373 exec.cpp:184] Executor started at: executor(1)@172.17.0.2:39520 with pid 32747
I1221 23:10:10.480216 32607 slave.cpp:2578] Got registration for executor '4' of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 from executor(1)@172.17.0.2:39520
I1221 23:10:10.480746 32607 slave.cpp:2664] Checkpointing executor pid 'executor(1)@172.17.0.2:39520' to '/tmp/mesos-otpdch/0/meta/slaves/3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S1/frameworks/3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000/executors/4/runs/bc8306b3-d4ba-4bd6-b5f5-03dfb4759738/pids/libprocess.pid'
I1221 23:10:10.482753 32597 slave.cpp:1796] Sending queued task '4' to executor '4' of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 at executor(1)@172.17.0.2:39520
I1221 23:10:10.483325   379 exec.cpp:208] Executor registered on slave 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S1
Registered executor on 6ccf2ee56b13
I1221 23:10:10.485102   379 exec.cpp:220] Executor::registered took 269656ns
I1221 23:10:10.485415   379 exec.cpp:295] Executor asked to run task '4'
Starting task 4
I1221 23:10:10.485508   379 exec.cpp:304] Executor::launchTask took 63624ns
sh -c 'echo hello'
Forked command at 382
hello
I1221 23:10:10.488653   377 exec.cpp:517] Executor sending status update TASK_RUNNING (UUID: c8c2c7b7-8040-48e9-84d6-75b9fbbb3419) for task 4 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.489480 32593 slave.cpp:2937] Handling status update TASK_RUNNING (UUID: c8c2c7b7-8040-48e9-84d6-75b9fbbb3419) for task 4 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 from executor(1)@172.17.0.2:39520
I1221 23:10:10.489858 32595 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: c8c2c7b7-8040-48e9-84d6-75b9fbbb3419) for task 4 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.489914 32595 status_update_manager.cpp:497] Creating StatusUpdate stream for task 4 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.490532 32595 status_update_manager.cpp:824] Checkpointing UPDATE for status update TASK_RUNNING (UUID: c8c2c7b7-8040-48e9-84d6-75b9fbbb3419) for task 4 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.491937 32595 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: c8c2c7b7-8040-48e9-84d6-75b9fbbb3419) for task 4 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 to the slave
I1221 23:10:10.492247 32597 slave.cpp:3289] Forwarding the update TASK_RUNNING (UUID: c8c2c7b7-8040-48e9-84d6-75b9fbbb3419) for task 4 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 to master@172.17.0.2:40874
I1221 23:10:10.492422 32597 slave.cpp:3183] Status update manager successfully handled status update TASK_RUNNING (UUID: c8c2c7b7-8040-48e9-84d6-75b9fbbb3419) for task 4 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.492470 32597 slave.cpp:3199] Sending acknowledgement for status update TASK_RUNNING (UUID: c8c2c7b7-8040-48e9-84d6-75b9fbbb3419) for task 4 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 to executor(1)@172.17.0.2:39520
I1221 23:10:10.492741 32606 master.cpp:4687] Status update TASK_RUNNING (UUID: c8c2c7b7-8040-48e9-84d6-75b9fbbb3419) for task 4 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 from slave 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S1 at slave(1)@172.17.0.2:40874 (6ccf2ee56b13)
I1221 23:10:10.492871 32606 master.cpp:4735] Forwarding status update TASK_RUNNING (UUID: c8c2c7b7-8040-48e9-84d6-75b9fbbb3419) for task 4 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.493093   372 exec.cpp:341] Executor received status update acknowledgement c8c2c7b7-8040-48e9-84d6-75b9fbbb3419 for task 4 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.493377 32606 master.cpp:6347] Updating the state of task 4 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
I1221 23:10:10.493441 32595 no_executor_framework.cpp:160] Task '4' is in state TASK_RUNNING
I1221 23:10:10.493469 32595 sched.cpp:919] Scheduler::statusUpdate took 37984ns
I1221 23:10:10.493696 32595 master.cpp:3844] Processing ACKNOWLEDGE call c8c2c7b7-8040-48e9-84d6-75b9fbbb3419 for task 4 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 (No Executor Framework) at scheduler-7caeff0b-9ca0-4c4c-935b-843b0edf2650@172.17.0.2:40874 on slave 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S1
I1221 23:10:10.493988 32599 status_update_manager.cpp:392] Received status update acknowledgement (UUID: c8c2c7b7-8040-48e9-84d6-75b9fbbb3419) for task 4 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.494120 32599 status_update_manager.cpp:824] Checkpointing ACK for status update TASK_RUNNING (UUID: c8c2c7b7-8040-48e9-84d6-75b9fbbb3419) for task 4 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.495306 32598 slave.cpp:2348] Status update manager successfully handled status update acknowledgement (UUID: c8c2c7b7-8040-48e9-84d6-75b9fbbb3419) for task 4 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
Command exited with status 0 (pid: 361)
I1221 23:10:10.543287   304 exec.cpp:517] Executor sending status update TASK_FINISHED (UUID: 133ecf74-5795-4890-a47d-02b397e9084c) for task 0 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.544509 32593 slave.cpp:2937] Handling status update TASK_FINISHED (UUID: 133ecf74-5795-4890-a47d-02b397e9084c) for task 0 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 from executor(1)@172.17.0.2:60995
I1221 23:10:10.544711 32593 slave.cpp:5520] Terminating task 0
I1221 23:10:10.546165 32608 status_update_manager.cpp:320] Received status update TASK_FINISHED (UUID: 133ecf74-5795-4890-a47d-02b397e9084c) for task 0 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.546311 32608 status_update_manager.cpp:824] Checkpointing UPDATE for status update TASK_FINISHED (UUID: 133ecf74-5795-4890-a47d-02b397e9084c) for task 0 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.547626 32608 status_update_manager.cpp:374] Forwarding update TASK_FINISHED (UUID: 133ecf74-5795-4890-a47d-02b397e9084c) for task 0 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 to the slave
I1221 23:10:10.547925 32594 slave.cpp:3289] Forwarding the update TASK_FINISHED (UUID: 133ecf74-5795-4890-a47d-02b397e9084c) for task 0 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 to master@172.17.0.2:40874
I1221 23:10:10.548090 32594 slave.cpp:3183] Status update manager successfully handled status update TASK_FINISHED (UUID: 133ecf74-5795-4890-a47d-02b397e9084c) for task 0 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.548177 32594 slave.cpp:3199] Sending acknowledgement for status update TASK_FINISHED (UUID: 133ecf74-5795-4890-a47d-02b397e9084c) for task 0 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 to executor(1)@172.17.0.2:60995
I1221 23:10:10.548307 32605 master.cpp:4687] Status update TASK_FINISHED (UUID: 133ecf74-5795-4890-a47d-02b397e9084c) for task 0 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 from slave 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S1 at slave(1)@172.17.0.2:40874 (6ccf2ee56b13)
I1221 23:10:10.548375 32605 master.cpp:4735] Forwarding status update TASK_FINISHED (UUID: 133ecf74-5795-4890-a47d-02b397e9084c) for task 0 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.548635 32605 master.cpp:6347] Updating the state of task 0 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 (latest state: TASK_FINISHED, status update state: TASK_FINISHED)
I1221 23:10:10.548717 32608 no_executor_framework.cpp:160] Task '0' is in state TASK_FINISHED
I1221 23:10:10.548748 32608 sched.cpp:919] Scheduler::statusUpdate took 39141ns
I1221 23:10:10.549018   301 exec.cpp:341] Executor received status update acknowledgement 133ecf74-5795-4890-a47d-02b397e9084c for task 0 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.549098 32605 master.cpp:3844] Processing ACKNOWLEDGE call 133ecf74-5795-4890-a47d-02b397e9084c for task 0 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 (No Executor Framework) at scheduler-7caeff0b-9ca0-4c4c-935b-843b0edf2650@172.17.0.2:40874 on slave 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S1
I1221 23:10:10.549120 32607 hierarchical.cpp:880] Recovered cpus(*):0.1; mem(*):32; disk(*):32 (total: cpus(*):2; mem(*):10240; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: cpus(*):0.4; mem(*):128; disk(*):128) on slave 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S1 from framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.549159 32605 master.cpp:6413] Removing task 0 with resources cpus(*):0.1; mem(*):32; disk(*):32 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000 on slave 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-S1 at slave(1)@172.17.0.2:40874 (6ccf2ee56b13)
I1221 23:10:10.549618 32593 status_update_manager.cpp:392] Received status update acknowledgement (UUID: 133ecf74-5795-4890-a47d-02b397e9084c) for task 0 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
Command exited with status 0 (pid: 362)
Command exited with status 0 (pid: 363)
I1221 23:10:10.550003 32593 status_update_manager.cpp:824] Checkpointing ACK for status update TASK_FINISHED (UUID: 133ecf74-5795-4890-a47d-02b397e9084c) for task 0 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.550715 32593 status_update_manager.cpp:528] Cleaning up status update stream for task 0 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.551157 32599 slave.cpp:2348] Status update manager successfully handled status update acknowledgement (UUID: 133ecf74-5795-4890-a47d-02b397e9084c) for task 0 of framework 3931c1a8-1cd6-49eb-94c8-d01b33bb008e-0000
I1221 23:10:10.551211 32599 slave.cpp:5561] Completing task 0

...
...
...
I1221 23:10:10.598156   374 exec.cpp:396] Executor::shutdown took 14264ns
I1221 23:10:10.598224 32605 slave.cpp:3417] master@172.17.0.2:40874 exited
W1221 23:10:10.598253 32605 slave.cpp:3420] Master disconnected! Waiting for a new master to be elected
I1221 23:10:10.598274   374 exec.cpp:80] Scheduling shutdown of the executor
I1221 23:10:10.600291 32593 slave.cpp:601] Slave terminating
I1221 23:10:10.603379 32569 slave.cpp:601] Slave terminating
I1221 23:10:10.605034 32604 slave.cpp:601] Slave terminating
[       OK ] ExamplesTest.NoExecutorFramework (7895 ms)

Bad Run

[ RUN      ] ExamplesTest.NoExecutorFramework
WARNING: Logging before InitGoogleLogging() is written to STDERR
I1221 17:48:57.199091 32567 resources.cpp:478] Parsing resources as JSON failed: cpus:0.1;mem:32;disk:32
Trying semicolon-delimited string format instead
I1221 17:48:57.200100 32567 logging.cpp:172] Logging to STDERR
I1221 17:48:57.207792 32567 process.cpp:998] libprocess is initialized on 172.17.0.2:34597 for 16 cpus
I1221 17:48:57.235429 32567 leveldb.cpp:174] Opened db in 3.93451ms
I1221 17:48:57.236927 32567 leveldb.cpp:181] Compacted db in 1.417647ms
I1221 17:48:57.237071 32567 leveldb.cpp:196] Created db iterator in 92710ns
I1221 17:48:57.237102 32567 leveldb.cpp:202] Seeked to beginning of db in 6258ns
I1221 17:48:57.237119 32567 leveldb.cpp:271] Iterated through 0 keys in the db in 473ns
I1221 17:48:57.237413 32567 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I1221 17:48:57.240393 32594 recover.cpp:447] Starting replica recovery
I1221 17:48:57.241396 32594 recover.cpp:473] Replica is in EMPTY status
I1221 17:48:57.242455 32567 local.cpp:239] Using 'local' authorizer
I1221 17:48:57.245549 32600 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from (4)@172.17.0.2:34597
I1221 17:48:57.246796 32592 recover.cpp:193] Received a recover response from a replica in EMPTY status
I1221 17:48:57.247524 32595 master.cpp:365] Master f9d7159c-0e99-4adc-8090-abc4b60b98f5 (be9bd3a71092) started on 172.17.0.2:34597
I1221 17:48:57.247854 32601 recover.cpp:564] Updating replica status to STARTING
I1221 17:48:57.247812 32595 master.cpp:367] Flags at startup: --acls="permissive: false
register_frameworks {
  principals {
    type: SOME
    values: "test-principal"
  }
  roles {
    type: SOME
    values: "*"
  }
}
run_tasks {
  principals {
    type: SOME
    values: "test-principal"
  }
  users {
    type: SOME
    values: "mesos"
  }
}
" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="true" --authenticate_slaves="false" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/ExamplesTest_NoExecutorFramework_2wDEhF/credentials" --framework_sorter="drf" --help="true" --hostname_lookup="true" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_slave_ping_timeouts="5" --quiet="false" --recovery_slave_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_store_timeout="5secs" --registry_strict="false" --root_submissions="true" --slave_ping_timeout="15secs" --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false" --webui_dir="/mesos/mesos-0.27.0/src/webui" --work_dir="/tmp/mesos-Alzbfe" --zk_session_timeout="10secs"
I1221 17:48:57.248754 32595 master.cpp:412] Master only allowing authenticated frameworks to register
I1221 17:48:57.248770 32595 master.cpp:419] Master allowing unauthenticated slaves to register
I1221 17:48:57.248783 32595 credentials.hpp:35] Loading credentials for authentication from '/tmp/ExamplesTest_NoExecutorFramework_2wDEhF/credentials'
W1221 17:48:57.248898 32595 credentials.hpp:50] Permissions on credentials file '/tmp/ExamplesTest_NoExecutorFramework_2wDEhF/credentials' are too open. It is recommended that your credentials file is NOT accessible by others.
I1221 17:48:57.249059 32592 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 890391ns
I1221 17:48:57.249110 32595 master.cpp:456] Using default 'crammd5' authenticator
I1221 17:48:57.249126 32592 replica.cpp:320] Persisted replica status to STARTING
I1221 17:48:57.249439 32595 authenticator.cpp:518] Initializing server SASL
I1221 17:48:57.249902 32592 recover.cpp:473] Replica is in STARTING status
I1221 17:48:57.251363 32600 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from (5)@172.17.0.2:34597
I1221 17:48:57.251474 32595 auxprop.cpp:71] Initialized in-memory auxiliary property plugin
I1221 17:48:57.251765 32595 master.cpp:493] Authorization enabled
I1221 17:48:57.251787 32592 recover.cpp:193] Received a recover response from a replica in STARTING status
I1221 17:48:57.252167 32567 containerizer.cpp:141] Using isolation: filesystem/posix,posix/cpu,posix/mem
I1221 17:48:57.252354 32592 recover.cpp:564] Updating replica status to VOTING
I1221 17:48:57.252828 32596 hierarchical.cpp:147] Initialized hierarchical allocator process
I1221 17:48:57.253104 32597 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 602231ns
I1221 17:48:57.253137 32597 replica.cpp:320] Persisted replica status to VOTING
W1221 17:48:57.253180 32567 backend.cpp:48] Failed to create 'bind' backend: BindBackend requires root privileges
I1221 17:48:57.253304 32597 whitelist_watcher.cpp:77] No whitelist given
I1221 17:48:57.253336 32597 recover.cpp:578] Successfully joined the Paxos group
I1221 17:48:57.253697 32597 recover.cpp:462] Recover process terminated
I1221 17:48:57.268092 32595 master.cpp:1629] The newly elected leader is master@172.17.0.2:34597 with id f9d7159c-0e99-4adc-8090-abc4b60b98f5
I1221 17:48:57.268255 32595 master.cpp:1642] Elected as the leading master!
I1221 17:48:57.268411 32595 master.cpp:1387] Recovering from registrar
I1221 17:48:57.268937 32603 registrar.cpp:307] Recovering registrar
I1221 17:48:57.271054 32600 log.cpp:659] Attempting to start the writer
I1221 17:48:57.271824 32595 slave.cpp:191] Slave started on 1)@172.17.0.2:34597
I1221 17:48:57.271908 32595 slave.cpp:192] Flags at startup: --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_auth_server="auth.docker.io" --docker_auth_server_port="443" --docker_kill_orphans="true" --docker_local_archives_dir="/tmp/mesos/images/docker" --docker_puller="local" --docker_puller_timeout="60" --docker_registry="registry-1.docker.io" --docker_registry_port="443" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/mesos/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="filesystem/posix,posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/mesos/mesos-0.27.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" --resources="cpus:2;mem:10240" --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/mesos-Alzbfe/0"
I1221 17:48:57.273372 32595 resources.cpp:478] Parsing resources as JSON failed: cpus:2;mem:10240
Trying semicolon-delimited string format instead
I1221 17:48:57.274093 32567 containerizer.cpp:141] Using isolation: filesystem/posix,posix/cpu,posix/mem
W1221 17:48:57.275342 32567 backend.cpp:48] Failed to create 'bind' backend: BindBackend requires root privileges
I1221 17:48:57.275346 32595 slave.cpp:392] Slave resources: cpus(*):2; mem(*):10240; disk(*):3.70122e+06; ports(*):[31000-32000]
I1221 17:48:57.275511 32595 slave.cpp:400] Slave attributes: [  ]
I1221 17:48:57.275542 32595 slave.cpp:405] Slave hostname: be9bd3a71092
I1221 17:48:57.275553 32595 slave.cpp:410] Slave checkpoint: true
I1221 17:48:57.276523 32594 replica.cpp:493] Replica received implicit promise request from (19)@172.17.0.2:34597 with proposal 1
I1221 17:48:57.277181 32594 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 616640ns
I1221 17:48:57.277209 32594 replica.cpp:342] Persisted promised to 1
I1221 17:48:57.279067 32604 state.cpp:58] Recovering state from '/tmp/mesos-Alzbfe/0/meta'
I1221 17:48:57.279417 32604 slave.cpp:191] Slave started on 2)@172.17.0.2:34597
I1221 17:48:57.279439 32604 slave.cpp:192] Flags at startup: --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_auth_server="auth.docker.io" --docker_auth_server_port="443" --docker_kill_orphans="true" --docker_local_archives_dir="/tmp/mesos/images/docker" --docker_puller="local" --docker_puller_timeout="60" --docker_registry="registry-1.docker.io" --docker_registry_port="443" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/mesos/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="filesystem/posix,posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/mesos/mesos-0.27.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" --resources="cpus:2;mem:10240" --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/mesos-Alzbfe/1"
I1221 17:48:57.280268 32604 resources.cpp:478] Parsing resources as JSON failed: cpus:2;mem:10240
Trying semicolon-delimited string format instead
I1221 17:48:57.280439 32601 status_update_manager.cpp:200] Recovering status update manager
I1221 17:48:57.280815 32603 containerizer.cpp:383] Recovering containerizer
I1221 17:48:57.280939 32604 slave.cpp:392] Slave resources: cpus(*):2; mem(*):10240; disk(*):3.70122e+06; ports(*):[31000-32000]
I1221 17:48:57.281018 32604 slave.cpp:400] Slave attributes: [  ]
I1221 17:48:57.281033 32604 slave.cpp:405] Slave hostname: be9bd3a71092
I1221 17:48:57.281041 32604 slave.cpp:410] Slave checkpoint: true
I1221 17:48:57.281885 32567 containerizer.cpp:141] Using isolation: filesystem/posix,posix/cpu,posix/mem
I1221 17:48:57.282161 32597 state.cpp:58] Recovering state from '/tmp/mesos-Alzbfe/1/meta'
W1221 17:48:57.282383 32567 backend.cpp:48] Failed to create 'bind' backend: BindBackend requires root privileges
I1221 17:48:57.282456 32604 status_update_manager.cpp:200] Recovering status update manager
I1221 17:48:57.282768 32604 containerizer.cpp:383] Recovering containerizer
I1221 17:48:57.284574 32596 slave.cpp:4427] Finished recovery
I1221 17:48:57.284680 32594 coordinator.cpp:238] Coordinator attempting to fill missing positions
I1221 17:48:57.284574 32602 slave.cpp:4427] Finished recovery
I1221 17:48:57.286054 32602 slave.cpp:4599] Querying resource estimator for oversubscribable resources
I1221 17:48:57.286500 32596 slave.cpp:4599] Querying resource estimator for oversubscribable resources
I1221 17:48:57.287051 32596 slave.cpp:729] New master detected at master@172.17.0.2:34597
I1221 17:48:57.287382 32596 slave.cpp:754] No credentials provided. Attempting to register without authentication
I1221 17:48:57.288478 32596 slave.cpp:765] Detecting new master
I1221 17:48:57.288810 32596 slave.cpp:4613] Received oversubscribable resources  from the resource estimator
I1221 17:48:57.289193 32604 replica.cpp:388] Replica received explicit promise request from (37)@172.17.0.2:34597 for position 0 with proposal 2
I1221 17:48:57.289732 32602 slave.cpp:729] New master detected at master@172.17.0.2:34597
I1221 17:48:57.289877 32602 slave.cpp:754] No credentials provided. Attempting to register without authentication
I1221 17:48:57.290024 32602 slave.cpp:765] Detecting new master
I1221 17:48:57.287452 32601 status_update_manager.cpp:174] Pausing sending status updates
I1221 17:48:57.290153 32604 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 870482ns
I1221 17:48:57.290181 32604 replica.cpp:712] Persisted action at 0
I1221 17:48:57.290182 32601 status_update_manager.cpp:174] Pausing sending status updates
I1221 17:48:57.290633 32602 slave.cpp:4613] Received oversubscribable resources  from the resource estimator
I1221 17:48:57.290832 32601 slave.cpp:191] Slave started on 3)@172.17.0.2:34597
I1221 17:48:57.290853 32601 slave.cpp:192] Flags at startup: --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_auth_server="auth.docker.io" --docker_auth_server_port="443" --docker_kill_orphans="true" --docker_local_archives_dir="/tmp/mesos/images/docker" --docker_puller="local" --docker_puller_timeout="60" --docker_registry="registry-1.docker.io" --docker_registry_port="443" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/mesos/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="true" --hostname_lookup="true" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="filesystem/posix,posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/mesos/mesos-0.27.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" --resources="cpus:2;mem:10240" --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/mesos-Alzbfe/2"
I1221 17:48:57.291916 32601 resources.cpp:478] Parsing resources as JSON failed: cpus:2;mem:10240
Trying semicolon-delimited string format instead
I1221 17:48:57.293606 32592 replica.cpp:537] Replica received write request for position 0 from (40)@172.17.0.2:34597
I1221 17:48:57.293800 32592 leveldb.cpp:436] Reading position from leveldb took 85274ns
I1221 17:48:57.294116 32601 slave.cpp:392] Slave resources: cpus(*):2; mem(*):10240; disk(*):3.70122e+06; ports(*):[31000-32000]
I1221 17:48:57.294201 32601 slave.cpp:400] Slave attributes: [  ]
I1221 17:48:57.294216 32601 slave.cpp:405] Slave hostname: be9bd3a71092
I1221 17:48:57.294226 32601 slave.cpp:410] Slave checkpoint: true
I1221 17:48:57.294476 32592 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 574132ns
...
...
...
I1221 17:49:02.770455 32598 no_executor_framework.cpp:160] Task '0' is in state TASK_FINISHED
I1221 17:49:02.770493 32598 sched.cpp:919] Scheduler::statusUpdate took 62688ns
I1221 17:49:02.770823 32602 hierarchical.cpp:880] Recovered cpus(*):0.1; mem(*):32; disk(*):32 (total: cpus(*):2; mem(*):10240; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: cpus(*):0.3; mem(*):96; disk(*):96) on slave f9d7159c-0e99-4adc-8090-abc4b60b98f5-S0 from framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000
I1221 17:49:02.771128 32598 master.cpp:3844] Processing ACKNOWLEDGE call b6352200-525b-4124-a654-2ab82cdf2af2 for task 0 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000 (No Executor Framework) at scheduler-bf375f84-4668-4cc7-9788-476575858f38@172.17.0.2:34597 on slave f9d7159c-0e99-4adc-8090-abc4b60b98f5-S0
I1221 17:49:02.771245 32598 master.cpp:6413] Removing task 0 with resources cpus(*):0.1; mem(*):32; disk(*):32 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000 on slave f9d7159c-0e99-4adc-8090-abc4b60b98f5-S0 at slave(3)@172.17.0.2:34597 (be9bd3a71092)
I1221 17:49:02.770465 32592 status_update_manager.cpp:528] Cleaning up status update stream for task 1 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000
I1221 17:49:02.771577   301 exec.cpp:341] Executor received status update acknowledgement b6352200-525b-4124-a654-2ab82cdf2af2 for task 0 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000
I1221 17:49:02.771955 32592 status_update_manager.cpp:392] Received status update acknowledgement (UUID: b6352200-525b-4124-a654-2ab82cdf2af2) for task 0 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000
I1221 17:49:02.772097 32592 status_update_manager.cpp:824] Checkpointing ACK for status update TASK_FINISHED (UUID: b6352200-525b-4124-a654-2ab82cdf2af2) for task 0 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000
I1221 17:49:02.772390 32591 slave.cpp:2937] Handling status update TASK_FINISHED (UUID: 6bdc8f1d-5969-495a-b1dc-c8d1d17df8fd) for task 2 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000 from executor(1)@172.17.0.2:44314
I1221 17:49:02.772554 32591 slave.cpp:5520] Terminating task 2
I1221 17:49:02.772975 32591 slave.cpp:2348] Status update manager successfully handled status update acknowledgement (UUID: 104773bb-c486-4864-aa71-37fa14c444bb) for task 1 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000
I1221 17:49:02.773069 32591 slave.cpp:5561] Completing task 1
I1221 17:49:02.774068 32592 status_update_manager.cpp:528] Cleaning up status update stream for task 0 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000
I1221 17:49:02.774581 32592 slave.cpp:2348] Status update manager successfully handled status update acknowledgement (UUID: b6352200-525b-4124-a654-2ab82cdf2af2) for task 0 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000
I1221 17:49:02.774747 32592 slave.cpp:5561] Completing task 0
I1221 17:49:02.775277 32595 status_update_manager.cpp:320] Received status update TASK_FINISHED (UUID: 6bdc8f1d-5969-495a-b1dc-c8d1d17df8fd) for task 2 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000
I1221 17:49:02.775414 32595 status_update_manager.cpp:824] Checkpointing UPDATE for status update TASK_FINISHED (UUID: 6bdc8f1d-5969-495a-b1dc-c8d1d17df8fd) for task 2 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000
I1221 17:49:02.778640 32595 status_update_manager.cpp:374] Forwarding update TASK_FINISHED (UUID: 6bdc8f1d-5969-495a-b1dc-c8d1d17df8fd) for task 2 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000 to the slave
I1221 17:49:02.779016 32592 slave.cpp:3289] Forwarding the update TASK_FINISHED (UUID: 6bdc8f1d-5969-495a-b1dc-c8d1d17df8fd) for task 2 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000 to master@172.17.0.2:34597
I1221 17:49:02.779219 32592 slave.cpp:3183] Status update manager successfully handled status update TASK_FINISHED (UUID: 6bdc8f1d-5969-495a-b1dc-c8d1d17df8fd) for task 2 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000
I1221 17:49:02.779268 32592 slave.cpp:3199] Sending acknowledgement for status update TASK_FINISHED (UUID: 6bdc8f1d-5969-495a-b1dc-c8d1d17df8fd) for task 2 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000 to executor(1)@172.17.0.2:44314
I1221 17:49:02.779527 32595 master.cpp:4687] Status update TASK_FINISHED (UUID: 6bdc8f1d-5969-495a-b1dc-c8d1d17df8fd) for task 2 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000 from slave f9d7159c-0e99-4adc-8090-abc4b60b98f5-S0 at slave(3)@172.17.0.2:34597 (be9bd3a71092)
I1221 17:49:02.779698 32595 master.cpp:4735] Forwarding status update TASK_FINISHED (UUID: 6bdc8f1d-5969-495a-b1dc-c8d1d17df8fd) for task 2 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000
I1221 17:49:02.779952 32595 master.cpp:6347] Updating the state of task 2 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000 (latest state: TASK_FINISHED, status update state: TASK_FINISHED)
I1221 17:49:02.780423 32595 no_executor_framework.cpp:160] Task '2' is in state TASK_FINISHED
I1221 17:49:02.780583   338 exec.cpp:341] Executor received status update acknowledgement 6bdc8f1d-5969-495a-b1dc-c8d1d17df8fd for task 2 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000
I1221 17:49:02.780850 32595 sched.cpp:919] Scheduler::statusUpdate took 432956ns
I1221 17:49:02.781097 32591 hierarchical.cpp:880] Recovered cpus(*):0.1; mem(*):32; disk(*):32 (total: cpus(*):2; mem(*):10240; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: cpus(*):0.2; mem(*):64; disk(*):64) on slave f9d7159c-0e99-4adc-8090-abc4b60b98f5-S0 from framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000
I1221 17:49:02.781183 32601 master.cpp:3844] Processing ACKNOWLEDGE call 6bdc8f1d-5969-495a-b1dc-c8d1d17df8fd for task 2 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000 (No Executor Framework) at scheduler-bf375f84-4668-4cc7-9788-476575858f38@172.17.0.2:34597 on slave f9d7159c-0e99-4adc-8090-abc4b60b98f5-S0
I1221 17:49:02.781383 32601 master.cpp:6413] Removing task 2 with resources cpus(*):0.1; mem(*):32; disk(*):32 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000 on slave f9d7159c-0e99-4adc-8090-abc4b60b98f5-S0 at slave(3)@172.17.0.2:34597 (be9bd3a71092)
I1221 17:49:02.782066 32601 status_update_manager.cpp:392] Received status update acknowledgement (UUID: 6bdc8f1d-5969-495a-b1dc-c8d1d17df8fd) for task 2 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000
I1221 17:49:02.782419 32601 status_update_manager.cpp:824] Checkpointing ACK for status update TASK_FINISHED (UUID: 6bdc8f1d-5969-495a-b1dc-c8d1d17df8fd) for task 2 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000
I1221 17:49:02.783466 32601 status_update_manager.cpp:528] Cleaning up status update stream for task 2 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000
I1221 17:49:02.784078 32602 slave.cpp:2348] Status update manager successfully handled status update acknowledgement (UUID: 6bdc8f1d-5969-495a-b1dc-c8d1d17df8fd) for task 2 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000
I1221 17:49:02.784178 32602 slave.cpp:5561] Completing task 2
Command exited with status 0 (pid: 379)
I1221 17:49:02.801833   358 exec.cpp:517] Executor sending status update TASK_FINISHED (UUID: e54772f7-bf6f-477c-a76d-00c874928fa0) for task 4 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000
I1221 17:49:02.803642 32601 slave.cpp:2937] Handling status update TASK_FINISHED (UUID: e54772f7-bf6f-477c-a76d-00c874928fa0) for task 4 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000 from executor(1)@172.17.0.2:52442
I1221 17:49:02.803870 32601 slave.cpp:5520] Terminating task 4
I1221 17:49:02.806363 32601 status_update_manager.cpp:320] Received status update TASK_FINISHED (UUID: e54772f7-bf6f-477c-a76d-00c874928fa0) for task 4 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000
I1221 17:49:02.806607 32601 status_update_manager.cpp:824] Checkpointing UPDATE for status update TASK_FINISHED (UUID: e54772f7-bf6f-477c-a76d-00c874928fa0) for task 4 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000
I1221 17:49:02.808573 32601 status_update_manager.cpp:374] Forwarding update TASK_FINISHED (UUID: e54772f7-bf6f-477c-a76d-00c874928fa0) for task 4 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000 to the slave
I1221 17:49:02.809147 32601 slave.cpp:3289] Forwarding the update TASK_FINISHED (UUID: e54772f7-bf6f-477c-a76d-00c874928fa0) for task 4 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000 to master@172.17.0.2:34597
I1221 17:49:02.809331 32601 slave.cpp:3183] Status update manager successfully handled status update TASK_FINISHED (UUID: e54772f7-bf6f-477c-a76d-00c874928fa0) for task 4 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000
I1221 17:49:02.809659 32593 master.cpp:4687] Status update TASK_FINISHED (UUID: e54772f7-bf6f-477c-a76d-00c874928fa0) for task 4 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000 from slave f9d7159c-0e99-4adc-8090-abc4b60b98f5-S0 at slave(3)@172.17.0.2:34597 (be9bd3a71092)
I1221 17:49:02.809711 32593 master.cpp:4735] Forwarding status update TASK_FINISHED (UUID: e54772f7-bf6f-477c-a76d-00c874928fa0) for task 4 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000
I1221 17:49:02.809882 32593 master.cpp:6347] Updating the state of task 4 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000 (latest state: TASK_FINISHED, status update state: TASK_FINISHED)
I1221 17:49:02.810335 32593 no_executor_framework.cpp:160] Task '4' is in state TASK_FINISHED
I1221 17:49:02.810369 32593 sched.cpp:919] Scheduler::statusUpdate took 40498ns
I1221 17:49:02.811712 32604 hierarchical.cpp:880] Recovered cpus(*):0.1; mem(*):32; disk(*):32 (total: cpus(*):2; mem(*):10240; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: cpus(*):0.1; mem(*):32; disk(*):32) on slave f9d7159c-0e99-4adc-8090-abc4b60b98f5-S0 from framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000
I1221 17:49:02.812052 32593 master.cpp:3844] Processing ACKNOWLEDGE call e54772f7-bf6f-477c-a76d-00c874928fa0 for task 4 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000 (No Executor Framework) at scheduler-bf375f84-4668-4cc7-9788-476575858f38@172.17.0.2:34597 on slave f9d7159c-0e99-4adc-8090-abc4b60b98f5-S0
I1221 17:49:02.812126 32593 master.cpp:6413] Removing task 4 with resources cpus(*):0.1; mem(*):32; disk(*):32 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000 on slave f9d7159c-0e99-4adc-8090-abc4b60b98f5-S0 at slave(3)@172.17.0.2:34597 (be9bd3a71092)
I1221 17:49:02.809386 32601 slave.cpp:3199] Sending acknowledgement for status update TASK_FINISHED (UUID: e54772f7-bf6f-477c-a76d-00c874928fa0) for task 4 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000 to executor(1)@172.17.0.2:52442
I1221 17:49:02.813179 32601 status_update_manager.cpp:392] Received status update acknowledgement (UUID: e54772f7-bf6f-477c-a76d-00c874928fa0) for task 4 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000
I1221 17:49:02.813343 32601 status_update_manager.cpp:824] Checkpointing ACK for status update TASK_FINISHED (UUID: e54772f7-bf6f-477c-a76d-00c874928fa0) for task 4 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000
I1221 17:49:02.813365   345 exec.cpp:341] Executor received status update acknowledgement e54772f7-bf6f-477c-a76d-00c874928fa0 for task 4 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000
I1221 17:49:02.815651 32601 status_update_manager.cpp:528] Cleaning up status update stream for task 4 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000
I1221 17:49:02.816185 32606 slave.cpp:2348] Status update manager successfully handled status update acknowledgement (UUID: e54772f7-bf6f-477c-a76d-00c874928fa0) for task 4 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000
I1221 17:49:02.816253 32606 slave.cpp:5561] Completing task 4
Command exited with status 0 (pid: 380)
I1221 17:49:02.821643   374 exec.cpp:517] Executor sending status update TASK_FINISHED (UUID: f7609151-4f05-4f8c-9fc1-98ee76dac298) for task 3 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000
I1221 17:49:02.823426 32601 slave.cpp:2937] Handling status update TASK_FINISHED (UUID: f7609151-4f05-4f8c-9fc1-98ee76dac298) for task 3 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000 from executor(1)@172.17.0.2:60087
I1221 17:49:02.823643 32601 slave.cpp:5520] Terminating task 3
I1221 17:49:02.825294 32602 status_update_manager.cpp:320] Received status update TASK_FINISHED (UUID: f7609151-4f05-4f8c-9fc1-98ee76dac298) for task 3 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000
I1221 17:49:02.825374 32602 status_update_manager.cpp:824] Checkpointing UPDATE for status update TASK_FINISHED (UUID: f7609151-4f05-4f8c-9fc1-98ee76dac298) for task 3 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000
I1221 17:49:02.827564 32602 status_update_manager.cpp:374] Forwarding update TASK_FINISHED (UUID: f7609151-4f05-4f8c-9fc1-98ee76dac298) for task 3 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000 to the slave
I1221 17:49:02.827869 32591 slave.cpp:3289] Forwarding the update TASK_FINISHED (UUID: f7609151-4f05-4f8c-9fc1-98ee76dac298) for task 3 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000 to master@172.17.0.2:34597
I1221 17:49:02.828033 32591 slave.cpp:3183] Status update manager successfully handled status update TASK_FINISHED (UUID: f7609151-4f05-4f8c-9fc1-98ee76dac298) for task 3 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000
I1221 17:49:02.828075 32591 slave.cpp:3199] Sending acknowledgement for status update TASK_FINISHED (UUID: f7609151-4f05-4f8c-9fc1-98ee76dac298) for task 3 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000 to executor(1)@172.17.0.2:60087
I1221 17:49:02.828188 32602 master.cpp:4687] Status update TASK_FINISHED (UUID: f7609151-4f05-4f8c-9fc1-98ee76dac298) for task 3 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000 from slave f9d7159c-0e99-4adc-8090-abc4b60b98f5-S0 at slave(3)@172.17.0.2:34597 (be9bd3a71092)
I1221 17:49:02.828230 32602 master.cpp:4735] Forwarding status update TASK_FINISHED (UUID: f7609151-4f05-4f8c-9fc1-98ee76dac298) for task 3 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000
I1221 17:49:02.828552 32606 no_executor_framework.cpp:160] Task '3' is in state TASK_FINISHED
I1221 17:49:02.828582 32606 sched.cpp:1803] Asked to stop the driver
I1221 17:49:02.828631 32606 sched.cpp:919] Scheduler::statusUpdate took 96503ns
I1221 17:49:02.828649 32606 sched.cpp:926] Not sending status update acknowledgment message because the driver is not running!
I1221 17:49:02.828696 32606 sched.cpp:1041] Stopping framework 'f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000'
I1221 17:49:02.828698 32602 master.cpp:6347] Updating the state of task 3 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000 (latest state: TASK_FINISHED, status update state: TASK_FINISHED)
I1221 17:49:02.829473 32567 sched.cpp:1803] Asked to stop the driver
I1221 17:49:02.829541 32567 sched.cpp:1806] Ignoring stop because the status of the driver is DRIVER_STOPPED
I1221 17:49:02.829524   372 exec.cpp:341] Executor received status update acknowledgement f7609151-4f05-4f8c-9fc1-98ee76dac298 for task 3 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000
I1221 17:49:02.829692 32602 master.cpp:5823] Processing TEARDOWN call for framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000 (No Executor Framework) at scheduler-bf375f84-4668-4cc7-9788-476575858f38@172.17.0.2:34597
I1221 17:49:02.829725 32602 master.cpp:5835] Removing framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000 (No Executor Framework) at scheduler-bf375f84-4668-4cc7-9788-476575858f38@172.17.0.2:34597
I1221 17:49:02.829743 32591 hierarchical.cpp:880] Recovered cpus(*):0.1; mem(*):32; disk(*):32 (total: cpus(*):2; mem(*):10240; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: cpus(*):4.71845e-16) on slave f9d7159c-0e99-4adc-8090-abc4b60b98f5-S0 from framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000
I1221 17:49:02.829884 32591 hierarchical.cpp:366] Deactivated framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000
I1221 17:49:02.830040 32602 master.cpp:6347] Updating the state of task 3 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000 (latest state: TASK_FINISHED, status update state: TASK_KILLED)
I1221 17:49:02.830144 32591 slave.cpp:2012] Asked to shut down framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000 by master@172.17.0.2:34597
W1221 17:49:02.830174 32591 slave.cpp:2027] Cannot shut down unknown framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000
I1221 17:49:02.830214 32591 slave.cpp:2012] Asked to shut down framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000 by master@172.17.0.2:34597
W1221 17:49:02.830231 32591 slave.cpp:2027] Cannot shut down unknown framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000
I1221 17:49:02.830263 32591 slave.cpp:2012] Asked to shut down framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000 by master@172.17.0.2:34597
I1221 17:49:02.830288 32591 slave.cpp:2037] Shutting down framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000
I1221 17:49:02.830116 32602 master.cpp:6413] Removing task 3 with resources cpus(*):0.1; mem(*):32; disk(*):32 of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000 on slave f9d7159c-0e99-4adc-8090-abc4b60b98f5-S0 at slave(3)@172.17.0.2:34597 (be9bd3a71092)
I1221 17:49:02.830490 32591 slave.cpp:4060] Shutting down executor '0' of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000 at executor(1)@172.17.0.2:41236
I1221 17:49:02.830888 32591 slave.cpp:4060] Shutting down executor '1' of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000 at executor(1)@172.17.0.2:40805
I1221 17:49:02.831028 32602 master.cpp:930] Master terminating
I1221 17:49:02.831089 32591 slave.cpp:4060] Shutting down executor '2' of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000 at executor(1)@172.17.0.2:44314
I1221 17:49:02.831279 32591 slave.cpp:4060] Shutting down executor '3' of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000 at executor(1)@172.17.0.2:60087
I1221 17:49:02.831519   301 exec.cpp:381] Executor asked to shutdown
I1221 17:49:02.831696   301 exec.cpp:396] Executor::shutdown took 12788ns
I1221 17:49:02.831830   301 exec.cpp:80] Scheduling shutdown of the executor
I1221 17:49:02.831900 32595 hierarchical.cpp:321] Removed framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000
I1221 17:49:02.832252 32595 hierarchical.cpp:496] Removed slave f9d7159c-0e99-4adc-8090-abc4b60b98f5-S2
I1221 17:49:02.832567 32591 slave.cpp:4060] Shutting down executor '4' of framework f9d7159c-0e99-4adc-8090-abc4b60b98f5-0000 at executor(1)@172.17.0.2:52442
I1221 17:49:02.832967 32595 hierarchical.cpp:496] Removed slave f9d7159c-0e99-4adc-8090-abc4b60b98f5-S1
II1221 17:49:02.833258 32595 hierarchical.cpp:496] Removed slave f9d7159c-0e99-4adc-8090-abc4b60b98f5-S0
1221 17:49:02.833251   372 exec.cpp:381] Executor asked to shutdown
I1221 17:49:02.833380   372 exec.cpp:396] Executor::shutdown took 12276ns
I1221 17:49:02.833453   369 exec.cpp:80] Scheduling shutdown of the executor
I1221 17:49:02.833497   314 exec.cpp:381] Executor asked to shutdown
I1221 17:49:02.833633   314 exec.cpp:396] Executor::shutdown took 14634ns
I1221 17:49:02.833751   314 exec.cpp:80] Scheduling shutdown of the executor
I1221 17:49:02.834023   335 exec.cpp:381] Executor asked to shutdown
I1221 17:49:02.834144   335 exec.cpp:396] Executor::shutdown took 11303ns
I1221 17:49:02.834262   335 exec.cpp:80] Scheduling shutdown of the executor
I1221 17:49:02.834300   345 exec.cpp:381] Executor asked to shutdown
I1221 17:49:02.834462   345 exec.cpp:396] Executor::shutdown took 14263ns
I1221 17:49:02.834502   345 exec.cpp:80] Scheduling shutdown of the executor
I1221 17:49:02.834887 32602 slave.cpp:3417] master@172.17.0.2:34597 exited
W1221 17:49:02.834947 32602 slave.cpp:3420] Master disconnected! Waiting for a new master to be elected
I1221 17:49:02.835018 32602 slave.cpp:3417] master@172.17.0.2:34597 exited
W1221 17:49:02.835083 32602 slave.cpp:3420] Master disconnected! Waiting for a new master to be elected
I1221 17:49:02.835146 32602 slave.cpp:3417] master@172.17.0.2:34597 exited
W1221 17:49:02.835213 32602 slave.cpp:3420] Master disconnected! Waiting for a new master to be elected
I1221 17:49:02.839617 32593 slave.cpp:601] Slave terminating
I1221 17:49:02.845129 32567 slave.cpp:601] Slave terminating
I1221 17:49:02.847450 32603 slave.cpp:601] Slave terminating
I1221 17:49:02.879467   314 exec.cpp:444] Ignoring exited event because the driver is aborted!
I1221 17:49:02.879524   301 exec.cpp:444] Ignoring exited event because the driver is aborted!
I[       OK ] ExamplesTest.NoExecutorFramework (8717 ms)
[ RUN      ] ExamplesTest.EventCallFramework
I1221 17:49:02.881482   352 exec.cpp:444] Ignoring exited event because the driver is aborted!
Using temporary directory '/tmp/ExamplesTest_EventCallFramework_9TX8jH'
1221 17:49:02.881122   335 exec.cpp:444] Ignoring exited event because the driver is aborted!
I1221 17:49:02.882071   372 exec.cpp:444] Ignoring exited event because the driver is aborted!
Shutting down
Shutting down
Sending SIGTERM to process tree at pid 343
Sending SIGTERM to process tree at pid 342
Killing the following process trees:
[ 

]
Killing the following process trees:
[ 

]
Shutting down
Sending SIGTERM to process tree at pid 361
Killing the following process trees:
[ 

]
Shutting down
Sending SIGTERM to process tree at pid 379
Killing the following process trees:
[ 

]
Shutting down
Sending SIGTERM to process tree at pid 380
Killing the following process trees:
[ 

]
WARNING: Logging before InitGoogleLogging() is written to STDERR
I1221 17:49:05.786998   381 process.cpp:998] libprocess is initialized on 172.17.0.2:60254 for 16 cpus
I1221 17:49:05.787230   381 logging.cpp:172] Logging to STDERR
I1221 17:49:05.788791   381 scheduler.cpp:154] Version: 0.27.0
I1221 17:49:05.809587   381 leveldb.cpp:174] Opened db in 3.241758ms
I1221 17:49:05.811599   381 leveldb.cpp:181] Compacted db in 1.820335ms
I1221 17:49:05.811724   381 leveldb.cpp:196] Created db iterator in 74530ns
I1221 17:49:05.811749   381 leveldb.cpp:202] Seeked to beginning of db in 5247ns
I1221 17:49:05.811760   381 leveldb.cpp:271] Iterated through 0 keys in the db in 324ns
I1221 17:49:05.811980   381 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I1221 17:49:05.816004   381 local.cpp:239] Using 'local' authorizer
I1221 17:49:05.818006   411 recover.cpp:447] Starting replica recovery
I1221 17:49:05.819463   406 recover.cpp:473] Replica is in EMPTY status
I1221 17:49:05.825531   413 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from (5)@172.17.0.2:60254
I1221 17:49:05.831326   412 recover.cpp:193] Received a recover response from a replica in EMPTY status
I1221 17:49:05.832586   418 recover.cpp:564] Updating replica status to STARTING
I1221 17:49:05.834460   418 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 1.082224ms
I1221 17:49:05.834507   418 replica.cpp:320] Persisted replica status to STARTING
I1221 17:49:05.835194   417 recover.cpp:473] Replica is in STARTING status
I1221 17:49:05.838433   417 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from (6)@172.17.0.2:60254
I1221 17:49:05.838778   405 master.cpp:365] Master 19baa4c9-78aa-4ffb-abb3-e4daf634ec63 (be9bd3a71092) started on 172.17.0.2:60254
I1221 17:49:05.838824   405 master.cpp:367] Flags at startup: --acls="permissive: false
register_frameworks {
  principals {
    type: SOME
    values: "test-principal"
  }
  roles {
    type: SOME
    values: "*"
  }
}
run_tasks {
  principals {
    type: SOME
    values: "test-principal"
  }
  users {
    type: SOME
    values: "mesos"
  }
}
" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="false" --authenticate_slaves="false" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/ExamplesTest_EventCallFramework_9TX8jH/credentials" --framework_sorter="drf" --help="true" --hostname_lookup="true" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_slave_ping_timeouts="5" --quiet="false" --recovery_slave_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_store_timeout="5secs" --registry_strict="false" --root_submissions="true" --slave_ping_timeout="15secs" --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false" --webui_dir="/mesos/mesos-0.27.0/src/webui" --work_dir="/tmp/mesos-WEDoSa" --zk_session_timeout="10secs"
I1221 17:49:05.839956   405 master.cpp:414] Master allowing unauthenticated frameworks to register
I1221 17:49:05.839974   405 master.cpp:419] Master allowing unauthenticated slaves to register
I1221 17:49:05.839990   405 credentials.hpp:35] Loading credentials for authentication from '/tmp/ExamplesTest_EventCallFramework_9TX8jH/credentials'
W1221 17:49:05.840143   405 credentials.hpp:50] Permissions on credentials file '/tmp/ExamplesTest_EventCallFramework_9TX8jH/credentials' are too open. It is recommended that your credentials file is NOT accessible by others.
I1221 17:49:05.840260   418 recover.cpp:193] Received a recover response from a replica in STARTING status
I1221 17:49:05.840479   405 master.cpp:456] Using default 'crammd5' authenticator
I1221 17:49:05.840912   405 authenticator.cpp:518] Initializing server SASL
I1221 17:49:05.841112   412 recover.cpp:564] Updating replica status to VOTING
I1221 17:49:05.841882   413 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 641489ns
I1221 17:49:05.841920   413 replica.cpp:320] Persisted replica status to VOTING
I1221 17:49:05.842102   406 recover.cpp:578] Successfully joined the Paxos group
I1221 17:49:05.842471   406 recover.cpp:462] Recover process terminated
I1221 17:49:05.843750   405 auxprop.cpp:71] Initialized in-memory auxiliary property plugin
I1221 17:49:05.843941   405 master.cpp:493] Authorization enabled
I1221 17:49:05.844133   381 containerizer.cpp:141] Using isolation: filesystem/posix,posix/cpu,posix/mem
I1221 17:49:05.844813   410 hierarchical.cpp:147] Initialized hierarchical allocator process
W1221 17:49:05.845093   381 backend.cpp:48] Failed to create 'bind' backend: BindBackend requires root privileges
I1221 17:49:05.845433   416 whitelist_watcher.cpp:77] No whitelist given
I1221 17:49:05.850373   411 slave.cpp:191] Slave started on 1)@172.17.0.2:60254
I1221 17:49:05.850433   411 slave.cpp:192] Flags at startup: --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_auth_server="auth.docker.io" --docker_auth_server_port="443" --docker_kill_orphans="true" --docker_local_archives_dir="/tmp/mesos/images/docker" --docker_puller="local" --docker_puller_timeout="60" --docker_registry="registry-1.docker.io" --docker_registry_port="443" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/mesos/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="filesystem/posix,posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/mesos/mesos-0.27.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" --resources="cpus:2;mem:10240" --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/mesos-WEDoSa/0"
I1221 17:49:05.851650   411 resources.cpp:478] Parsing resources as JSON failed: cpus:2;mem:10240
Trying semicolon-delimited string format instead
I1221 17:49:05.854473   411 slave.cpp:392] Slave resources: cpus(*):2; mem(*):10240; disk(*):3.70122e+06; ports(*):[31000-32000]
I1221 17:49:05.854701   411 slave.cpp:400] Slave attributes: [  ]
I1221 17:49:05.854821   411 slave.cpp:405] Slave hostname: be9bd3a71092
I1221 17:49:05.854907   411 slave.cpp:410] Slave checkpoint: true
I1221 17:49:05.855715   381 containerizer.cpp:141] Using isolation: filesystem/posix,posix/cpu,posix/mem
W1221 17:49:05.856274   381 backend.cpp:48] Failed to create 'bind' backend: BindBackend requires root privileges
I1221 17:49:05.861232   407 slave.cpp:191] Slave started on 2)@172.17.0.2:60254
I1221 17:49:05.861279   407 slave.cpp:192] Flags at startup: --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_auth_server="auth.docker.io" --docker_auth_server_port="443" --docker_kill_orphans="true" --docker_local_archives_dir="/tmp/mesos/images/docker" --docker_puller="local" --docker_puller_timeout="60" --docker_registry="registry-1.docker.io" --docker_registry_port="443" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/mesos/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="filesystem/posix,posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/mesos/mesos-0.27.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" --resources="cpus:2;mem:10240" --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/mesos-WEDoSa/1"
I1221 17:49:05.862290   407 resources.cpp:478] Parsing resources as JSON failed: cpus:2;mem:10240
Trying semicolon-delimited string format instead
I1221 17:49:05.862937   407 slave.cpp:392] Slave resources: cpus(*):2; mem(*):10240; disk(*):3.70122e+06; ports(*):[31000-32000]
I1221 17:49:05.863024   407 slave.cpp:400] Slave attributes: [  ]
I1221 17:49:05.863040   407 slave.cpp:405] Slave hostname: be9bd3a71092
I1221 17:49:05.863049   407 slave.cpp:410] Slave checkpoint: true
I1221 17:49:05.863625   418 state.cpp:58] Recovering state from '/tmp/mesos-WEDoSa/0/meta'
I1221 17:49:05.863787   381 containerizer.cpp:141] Using isolation: filesystem/posix,posix/cpu,posix/mem
I1221 17:49:05.864229   420 state.cpp:58] Recovering state from '/tmp/mesos-WEDoSa/1/meta'
W1221 17:49:05.864358   381 backend.cpp:48] Failed to create 'bind' backend: BindBackend requires root privileges
I1221 17:49:05.864397   418 status_update_manager.cpp:200] Recovering status update manager
I1221 17:49:05.865824   411 status_update_manager.cpp:200] Recovering status update manager
I1221 17:49:05.866319   411 containerizer.cpp:383] Recovering containerizer
I1221 17:49:05.866439   410 containerizer.cpp:383] Recovering containerizer
I1221 17:49:05.867146   416 master.cpp:1629] The newly elected leader is master@172.17.0.2:60254 with id 19baa4c9-78aa-4ffb-abb3-e4daf634ec63
I1221 17:49:05.867189   416 master.cpp:1642] Elected as the leading master!
I1221 17:49:05.867229   416 master.cpp:1387] Recovering from registrar
I1221 17:49:05.867583   409 registrar.cpp:307] Recovering registrar
I1221 17:49:05.868595   420 slave.cpp:4427] Finished recovery
I1221 17:49:05.869122   406 slave.cpp:4427] Finished recovery
I1221 17:49:05.869529   420 slave.cpp:4599] Querying resource estimator for oversubscribable resources
I1221 17:49:05.869848   411 log.cpp:659] Attempting to start the writer
I1221 17:49:05.870846   413 status_update_manager.cpp:174] Pausing sending status updates
I1221 17:49:05.870885   420 slave.cpp:729] New master detected at master@172.17.0.2:60254
I1221 17:49:05.870996   420 slave.cpp:754] No credentials provided. Attempting to register without authentication
I1221 17:49:05.871129   420 slave.cpp:765] Detecting new master
I1221 17:49:05.871261   420 slave.cpp:4613] Received oversubscribable resources  from the resource estimator
I1221 17:49:05.872555   406 slave.cpp:4599] Querying resource estimator for oversubscribable resources
I1221 17:49:05.872836   406 status_update_manager.cpp:174] Pausing sending status updates
I1221 17:49:05.872849   420 slave.cpp:729] New master detected at master@172.17.0.2:60254
I1221 17:49:05.872915   420 slave.cpp:754] No credentials provided. Attempting to register without authentication
I1221 17:49:05.872956   420 slave.cpp:765] Detecting new master
I1221 17:49:05.873045   420 slave.cpp:4613] Received oversubscribable resources  from the resource estimator
I1221 17:49:05.873503   408 replica.cpp:493] Replica received implicit promise request from (37)@172.17.0.2:60254 with proposal 1
I1221 17:49:05.874140   408 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 594758ns
I1221 17:49:05.874171   408 replica.cpp:342] Persisted promised to 1
I1221 17:49:05.875378   408 slave.cpp:191] Slave started on 3)@172.17.0.2:60254
I1221 17:49:05.875962   412 coordinator.cpp:238] Coordinator attempting to fill missing positions
I1221 17:49:05.875965   414 scheduler.cpp:236] New master detected at master@172.17.0.2:60254
I1221 17:49:05.875458   408 slave.cpp:192] Flags at startup: --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_auth_server="auth.docker.io" --docker_auth_server_port="443" --docker_kill_orphans="true" --docker_local_archives_dir="/tmp/mesos/images/docker" --docker_puller="local" --docker_puller_timeout="60" --docker_registry="registry-1.docker.io" --docker_registry_port="443" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/mesos/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="true" --hostname_lookup="true" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="filesystem/posix,posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/mesos/mesos-0.27.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" --resources="cpus:2;mem:10240" --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/mesos-WEDoSa/2"
I1221 17:49:05.877544   408 resources.cpp:478] Parsing resources as JSON failed: cpus:2;mem:10240
Trying semicolon-delimited string format instead
I1221 17:49:05.878088   410 replica.cpp:388] Replica received explicit promise request from (40)@172.17.0.2:60254 for position 0 with proposal 2
I1221 17:49:05.878116   408 slave.cpp:392] Slave resources: cpus(*):2; mem(*):10240; disk(*):3.70122e+06; ports(*):[31000-32000]
I1221 17:49:05.878209   408 slave.cpp:400] Slave attributes: [  ]
I1221 17:49:05.878226   408 slave.cpp:405] Slave hostname: be9bd3a71092
I1221 17:49:05.878237   408 slave.cpp:410] Slave checkpoint: true
I1221 17:49:05.878959   410 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 769060ns
I1221 17:49:05.878995   410 replica.cpp:712] Persisted action at 0
I1221 17:49:05.880889   419 state.cpp:58] Recovering state from '/tmp/mesos-WEDoSa/2/meta'
I1221 17:49:05.881033   418 replica.cpp:537] Replica received write request for position 0 from (41)@172.17.0.2:60254
I1221 17:49:05.881433   418 leveldb.cpp:436] Reading position from leveldb took 163395ns
I1221 17:49:05.881222   416 status_update_manager.cpp:200] Recovering status update manager
I1221 17:49:05.881892   419 containerizer.cpp:383] Recovering containerizer
I1221 17:49:05.882032   418 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 486145ns
I1221 17:49:05.882069   418 replica.cpp:712] Persisted action at 0
I1221 17:49:05.882983   419 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0
I1221 17:49:05.883849   419 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 829258ns
I1221 17:49:05.883955   413 slave.cpp:4427] Finished recovery
I1221 17:49:05.883960   419 replica.cpp:712] Persisted action at 0
I1221 17:49:05.884121   419 replica.cpp:697] Replica learned NOP action at position 0
I1221 17:49:05.884806   413 slave.cpp:4599] Querying resource estimator for oversubscribable resources
I1221 17:49:05.884945   409 log.cpp:675] Writer started with ending position 0
I1221 17:49:05.885113   419 status_update_manager.cpp:174] Pausing sending status updates
I1221 17:49:05.885149   413 slave.cpp:729] New master detected at master@172.17.0.2:60254
I1221 17:49:05.885241   413 slave.cpp:754] No credentials provided. Attempting to register without authentication
I1221 17:49:05.885354   413 slave.cpp:765] Detecting new master
I1221 17:49:05.885524   413 slave.cpp:4613] Received oversubscribable resources  from the resource estimator
I1221 17:49:05.888422   409 leveldb.cpp:436] Reading position from leveldb took 76121ns
I1221 17:49:05.893468   420 registrar.cpp:340] Successfully fetched the registry (0B) in 25.776896ms
I1221 17:49:05.893851   420 registrar.cpp:439] Applied 1 operations in 117027ns; attempting to update the 'registry'
I1221 17:49:05.896961   412 log.cpp:683] Attempting to append 170 bytes to the log
I1221 17:49:05.897126   418 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
I1221 17:49:05.898660   412 replica.cpp:537] Replica received write request for position 1 from (43)@172.17.0.2:60254
I1221 17:49:05.899444   412 leveldb.cpp:341] Persisting action (189 bytes) to leveldb took 711265ns
I1221 17:49:05.899479   412 replica.cpp:712] Persisted action at 1
I1221 17:49:05.900216   410 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0

...
...
...
I1221 17:49:29.890243   414 hierarchical.cpp:1329] No resources available to allocate!
I1221 17:49:29.890316   414 hierarchical.cpp:1079] Performed allocation for 3 slaves in 624179ns
I1221 17:49:30.892174   414 hierarchical.cpp:1329] No resources available to allocate!
I1221 17:49:30.892246   414 hierarchical.cpp:1079] Performed allocation for 3 slaves in 564425ns
I1221 17:49:31.894242   414 hierarchical.cpp:1329] No resources available to allocate!
I1221 17:49:31.894316   414 hierarchical.cpp:1079] Performed allocation for 3 slaves in 625358ns
I1221 17:49:32.896178   414 hierarchical.cpp:1329] No resources available to allocate!
I1221 17:49:32.896248   414 hierarchical.cpp:1079] Performed allocation for 3 slaves in 564486ns
I1221 17:49:33.898360   414 hierarchical.cpp:1329] No resources available to allocate!
I1221 17:49:33.898444   414 hierarchical.cpp:1079] Performed allocation for 3 slaves in 664324ns
I1221 17:49:34.900513   409 hierarchical.cpp:1329] No resources available to allocate!
I1221 17:49:34.900584   409 hierarchical.cpp:1079] Performed allocation for 3 slaves in 584647ns
I1221 17:49:35.875272   416 slave.cpp:4599] Querying resource estimator for oversubscribable resources
I1221 17:49:35.875267   418 slave.cpp:4599] Querying resource estimator for oversubscribable resources
I1221 17:49:35.875730   409 slave.cpp:4613] Received oversubscribable resources  from the resource estimator
I1221 17:49:35.875766   412 slave.cpp:4613] Received oversubscribable resources  from the resource estimator
I1221 17:49:35.887620   419 slave.cpp:4599] Querying resource estimator for oversubscribable resources
I1221 17:49:35.887943   413 slave.cpp:4613] Received oversubscribable resources  from the resource estimator
I1221 17:49:35.901360   412 hierarchical.cpp:1329] No resources available to allocate!
I1221 17:49:35.901435   412 hierarchical.cpp:1079] Performed allocation for 3 slaves in 552395ns
I1221 17:49:35.950346   416 slave.cpp:3371] Received ping from slave-observer(1)@172.17.0.2:60254
I1221 17:49:35.995688   416 slave.cpp:3371] Received ping from slave-observer(2)@172.17.0.2:60254
I1221 17:49:36.609561   418 slave.cpp:3371] Received ping from slave-observer(3)@172.17.0.2:60254

Issue Links

• duplicates: MESOS-3273 EventCall Test Framework is flaky