You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "Till Toenshoff (JIRA)" <ji...@apache.org> on 2015/11/30 23:58:11 UTC
[jira] [Commented] (MESOS-3273) EventCall Test Framework is flaky
[ https://issues.apache.org/jira/browse/MESOS-3273?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15032665#comment-15032665 ]
Till Toenshoff commented on MESOS-3273:
---------------------------------------
This does still happen - definitely catchable.
System: [Ubuntu14.04 Vagrant Image|https://github.com/tillt/mesos-vagrant-ci/blob/master/ubuntu14/setup.sh]
SSL build (enable-ssl, enable-libevent), root test-run, verbose
{noformat}
[ RUN ] ExamplesTest.EventCallFramework
Using temporary directory '/tmp/ExamplesTest_EventCallFramework_MUpzLQ'
I1130 22:47:23.059108 15950 scheduler.cpp:156] Version: 0.26.0
I1130 22:47:23.107734 15950 leveldb.cpp:176] Opened db in 41.560489ms
I1130 22:47:23.109232 15950 leveldb.cpp:183] Compacted db in 1.42992ms
I1130 22:47:23.109333 15950 leveldb.cpp:198] Created db iterator in 37301ns
I1130 22:47:23.109355 15950 leveldb.cpp:204] Seeked to beginning of db in 2008ns
I1130 22:47:23.109367 15950 leveldb.cpp:273] Iterated through 0 keys in the db in 170ns
I1130 22:47:23.109491 15950 replica.cpp:780] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I1130 22:47:23.111325 15974 recover.cpp:449] Starting replica recovery
I1130 22:47:23.112205 15974 recover.cpp:475] Replica is in EMPTY status
I1130 22:47:23.112306 15950 local.cpp:241] Using 'local' authorizer
I1130 22:47:23.114205 15973 replica.cpp:676] Replica in EMPTY status received a broadcasted recover request from (5)@127.0.1.1:51177
I1130 22:47:23.114904 15970 recover.cpp:195] Received a recover response from a replica in EMPTY status
I1130 22:47:23.118305 15970 recover.cpp:566] Updating replica status to STARTING
I1130 22:47:23.118458 15972 master.cpp:367] Master edbdc635-adf5-40f6-bc27-15b19e69f8cd (ubuntu14) started on 127.0.1.1:51177
I1130 22:47:23.119215 15972 master.cpp:369] 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: "vagrant"
}
}
" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="false" --authenticate_slaves="false" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/ExamplesTest_EventCallFramework_MUpzLQ/credentials" --framework_sorter="drf" --help="false" --hostname_lookup="true" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_slave_ping_timeouts="5" --quiet="false" --recovery_slave_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_store_timeout="5secs" --registry_strict="false" --root_submissions="true" --slave_ping_timeout="15secs" --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false" --webui_dir="/home/vagrant/mesos/src/webui" --work_dir="/tmp/mesos-cqOgRP" --zk_session_timeout="10secs"
I1130 22:47:23.119771 15972 master.cpp:416] Master allowing unauthenticated frameworks to register
I1130 22:47:23.119787 15972 master.cpp:421] Master allowing unauthenticated slaves to register
I1130 22:47:23.119798 15972 credentials.hpp:37] Loading credentials for authentication from '/tmp/ExamplesTest_EventCallFramework_MUpzLQ/credentials'
W1130 22:47:23.119976 15972 credentials.hpp:52] Permissions on credentials file '/tmp/ExamplesTest_EventCallFramework_MUpzLQ/credentials' are too open. It is recommended that your credentials file is NOT accessible by others.
I1130 22:47:23.120127 15972 master.cpp:458] Using default 'crammd5' authenticator
I1130 22:47:23.120285 15972 authenticator.cpp:520] Initializing server SASL
I1130 22:47:23.121831 15950 containerizer.cpp:142] Using isolation: filesystem/posix,posix/cpu,posix/mem
I1130 22:47:23.121846 15972 master.cpp:495] Authorization enabled
W1130 22:47:23.122547 15950 backend.cpp:50] Failed to create 'bind' backend: BindBackend requires root privileges
I1130 22:47:23.126610 15970 slave.cpp:191] Slave started on 1)@127.0.1.1:51177
I1130 22:47:23.126672 15970 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="/home/vagrant/mesos/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-cqOgRP/0"
I1130 22:47:23.127595 15950 containerizer.cpp:142] Using isolation: filesystem/posix,posix/cpu,posix/mem
I1130 22:47:23.127796 15974 master.cpp:1606] The newly elected leader is master@127.0.1.1:51177 with id edbdc635-adf5-40f6-bc27-15b19e69f8cd
I1130 22:47:23.127905 15974 master.cpp:1619] Elected as the leading master!
I1130 22:47:23.128002 15974 master.cpp:1379] Recovering from registrar
I1130 22:47:23.128363 15970 slave.cpp:392] Slave resources: cpus(*):2; mem(*):10240; disk(*):34068; ports(*):[31000-32000]
I1130 22:47:23.128432 15971 registrar.cpp:309] Recovering registrar
I1130 22:47:23.128494 15970 slave.cpp:400] Slave attributes: [ ]
I1130 22:47:23.128540 15970 slave.cpp:405] Slave hostname: ubuntu14
I1130 22:47:23.128551 15970 slave.cpp:410] Slave checkpoint: true
W1130 22:47:23.129720 15950 backend.cpp:50] Failed to create 'bind' backend: BindBackend requires root privileges
I1130 22:47:23.130424 15972 state.cpp:54] Recovering state from '/tmp/mesos-cqOgRP/0/meta'
I1130 22:47:23.130970 15972 status_update_manager.cpp:202] Recovering status update manager
I1130 22:47:23.131469 15976 containerizer.cpp:384] Recovering containerizer
I1130 22:47:23.133054 15975 slave.cpp:4230] Finished recovery
I1130 22:47:23.133693 15976 slave.cpp:191] Slave started on 2)@127.0.1.1:51177
I1130 22:47:23.133766 15975 slave.cpp:729] New master detected at master@127.0.1.1:51177
I1130 22:47:23.133836 15975 slave.cpp:754] No credentials provided. Attempting to register without authentication
I1130 22:47:23.133941 15975 slave.cpp:765] Detecting new master
I1130 22:47:23.133754 15976 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="/home/vagrant/mesos/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-cqOgRP/1"
I1130 22:47:23.133738 15972 status_update_manager.cpp:176] Pausing sending status updates
I1130 22:47:23.134950 15976 slave.cpp:392] Slave resources: cpus(*):2; mem(*):10240; disk(*):34068; ports(*):[31000-32000]
I1130 22:47:23.135027 15976 slave.cpp:400] Slave attributes: [ ]
I1130 22:47:23.135051 15976 slave.cpp:405] Slave hostname: ubuntu14
I1130 22:47:23.135063 15976 slave.cpp:410] Slave checkpoint: true
I1130 22:47:23.135736 15950 containerizer.cpp:142] Using isolation: filesystem/posix,posix/cpu,posix/mem
I1130 22:47:23.135828 15975 state.cpp:54] Recovering state from '/tmp/mesos-cqOgRP/1/meta'
I1130 22:47:23.136504 15975 status_update_manager.cpp:202] Recovering status update manager
W1130 22:47:23.136520 15950 backend.cpp:50] Failed to create 'bind' backend: BindBackend requires root privileges
I1130 22:47:23.136754 15974 containerizer.cpp:384] Recovering containerizer
I1130 22:47:23.137874 15972 slave.cpp:4230] Finished recovery
I1130 22:47:23.138635 15974 status_update_manager.cpp:176] Pausing sending status updates
I1130 22:47:23.138628 15970 slave.cpp:729] New master detected at master@127.0.1.1:51177
I1130 22:47:23.138841 15970 slave.cpp:754] No credentials provided. Attempting to register without authentication
I1130 22:47:23.138906 15970 slave.cpp:765] Detecting new master
I1130 22:47:23.138696 15973 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 20.024076ms
I1130 22:47:23.139665 15973 replica.cpp:323] Persisted replica status to STARTING
I1130 22:47:23.139986 15973 recover.cpp:475] Replica is in STARTING status
I1130 22:47:23.141146 15973 replica.cpp:676] Replica in STARTING status received a broadcasted recover request from (36)@127.0.1.1:51177
I1130 22:47:23.141532 15975 recover.cpp:195] Received a recover response from a replica in STARTING status
I1130 22:47:23.141597 15970 slave.cpp:191] Slave started on 3)@127.0.1.1:51177
I1130 22:47:23.141633 15970 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="/home/vagrant/mesos/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-cqOgRP/2"
I1130 22:47:23.142415 15972 recover.cpp:566] Updating replica status to VOTING
I1130 22:47:23.142632 15970 slave.cpp:392] Slave resources: cpus(*):2; mem(*):10240; disk(*):34068; ports(*):[31000-32000]
I1130 22:47:23.142706 15970 slave.cpp:400] Slave attributes: [ ]
I1130 22:47:23.142757 15970 slave.cpp:405] Slave hostname: ubuntu14
I1130 22:47:23.142771 15970 slave.cpp:410] Slave checkpoint: true
2015-11-30 22:47:23,143:15722(0x7fac4de51700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:59080] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
I1130 22:47:23.145202 15972 state.cpp:54] Recovering state from '/tmp/mesos-cqOgRP/2/meta'
I1130 22:47:23.145670 15971 status_update_manager.cpp:202] Recovering status update manager
I1130 22:47:23.145854 15971 containerizer.cpp:384] Recovering containerizer
I1130 22:47:23.146724 15973 slave.cpp:4230] Finished recovery
I1130 22:47:23.147203 15975 slave.cpp:729] New master detected at master@127.0.1.1:51177
I1130 22:47:23.147258 15973 status_update_manager.cpp:176] Pausing sending status updates
I1130 22:47:23.147320 15975 slave.cpp:754] No credentials provided. Attempting to register without authentication
I1130 22:47:23.147452 15975 slave.cpp:765] Detecting new master
I1130 22:47:23.159584 15974 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 16.845187ms
I1130 22:47:23.159698 15974 replica.cpp:323] Persisted replica status to VOTING
I1130 22:47:23.159997 15974 recover.cpp:580] Successfully joined the Paxos group
I1130 22:47:23.160423 15974 recover.cpp:464] Recover process terminated
I1130 22:47:23.160991 15974 log.cpp:661] Attempting to start the writer
I1130 22:47:23.163434 15973 replica.cpp:496] Replica received implicit promise request from (40)@127.0.1.1:51177 with proposal 1
I1130 22:47:23.174804 15973 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 11.290243ms
I1130 22:47:23.174859 15973 replica.cpp:345] Persisted promised to 1
I1130 22:47:23.176043 15973 coordinator.cpp:240] Coordinator attempting to fill missing positions
I1130 22:47:23.177855 15972 replica.cpp:391] Replica received explicit promise request from (41)@127.0.1.1:51177 for position 0 with proposal 2
I1130 22:47:23.180476 15972 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 2.537426ms
I1130 22:47:23.180531 15972 replica.cpp:715] Persisted action at 0
I1130 22:47:23.182282 15971 replica.cpp:540] Replica received write request for position 0 from (42)@127.0.1.1:51177
I1130 22:47:23.182375 15971 leveldb.cpp:438] Reading position from leveldb took 36138ns
I1130 22:47:23.204586 15971 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 22.150405ms
I1130 22:47:23.204653 15971 replica.cpp:715] Persisted action at 0
I1130 22:47:23.205488 15976 replica.cpp:694] Replica received learned notice for position 0 from @0.0.0.0:0
I1130 22:47:23.215785 15976 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 9.991989ms
I1130 22:47:23.215850 15976 replica.cpp:715] Persisted action at 0
I1130 22:47:23.215875 15976 replica.cpp:700] Replica learned NOP action at position 0
I1130 22:47:23.216578 15972 log.cpp:677] Writer started with ending position 0
I1130 22:47:23.218617 15969 leveldb.cpp:438] Reading position from leveldb took 34179ns
I1130 22:47:23.221410 15973 registrar.cpp:342] Successfully fetched the registry (0B) in 92.845824ms
I1130 22:47:23.221622 15973 registrar.cpp:441] Applied 1 operations in 54823ns; attempting to update the 'registry'
I1130 22:47:23.223924 15976 log.cpp:685] Attempting to append 158 bytes to the log
I1130 22:47:23.224053 15975 coordinator.cpp:350] Coordinator attempting to write APPEND action at position 1
I1130 22:47:23.225028 15971 replica.cpp:540] Replica received write request for position 1 from (43)@127.0.1.1:51177
I1130 22:47:23.240402 15971 leveldb.cpp:343] Persisting action (177 bytes) to leveldb took 15.317491ms
I1130 22:47:23.240471 15971 replica.cpp:715] Persisted action at 1
I1130 22:47:23.241024 15974 replica.cpp:694] Replica received learned notice for position 1 from @0.0.0.0:0
I1130 22:47:23.257127 15974 leveldb.cpp:343] Persisting action (179 bytes) to leveldb took 15.979931ms
I1130 22:47:23.257261 15974 replica.cpp:715] Persisted action at 1
I1130 22:47:23.257338 15974 replica.cpp:700] Replica learned APPEND action at position 1
I1130 22:47:23.258764 15974 registrar.cpp:486] Successfully updated the 'registry' in 37.036032ms
I1130 22:47:23.259004 15974 registrar.cpp:372] Successfully recovered registrar
I1130 22:47:23.259340 15971 log.cpp:704] Attempting to truncate the log to 1
I1130 22:47:23.259637 15976 coordinator.cpp:350] Coordinator attempting to write TRUNCATE action at position 2
I1130 22:47:23.260030 15972 master.cpp:1416] Recovered 0 slaves from the Registry (120B) ; allowing 10mins for slaves to re-register
I1130 22:47:23.260810 15975 replica.cpp:540] Replica received write request for position 2 from (44)@127.0.1.1:51177
I1130 22:47:23.273692 15975 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 12.840856ms
I1130 22:47:23.273748 15975 replica.cpp:715] Persisted action at 2
I1130 22:47:23.274708 15972 replica.cpp:694] Replica received learned notice for position 2 from @0.0.0.0:0
I1130 22:47:23.291226 15972 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 16.42524ms
I1130 22:47:23.291388 15972 leveldb.cpp:401] Deleting ~1 keys from leveldb took 31496ns
I1130 22:47:23.291468 15972 replica.cpp:715] Persisted action at 2
I1130 22:47:23.291543 15972 replica.cpp:700] Replica learned TRUNCATE action at position 2
Shutting down
Sending SIGTERM to process tree at pid 15945
Killing the following process trees:
[
]
Shutting down
Sending SIGTERM to process tree at pid 15946
Shutting down
Sending SIGTERM to process tree at pid 15948
Shutting down
Sending SIGTERM to process tree at pid 15947
Killing the following process trees:
[
]
Shutting down
Sending SIGTERM to process tree at pid 15949
Killing the following process trees:
[
]
Killing the following process trees:
[
]
Killing the following process trees:
[
]
I1130 22:47:23.868094 15975 master.cpp:3859] Registering slave at slave(2)@127.0.1.1:51177 (ubuntu14) with id edbdc635-adf5-40f6-bc27-15b19e69f8cd-S0
I1130 22:47:23.868902 15975 registrar.cpp:441] Applied 1 operations in 83801ns; attempting to update the 'registry'
I1130 22:47:23.871341 15975 log.cpp:685] Attempting to append 324 bytes to the log
I1130 22:47:23.871618 15976 coordinator.cpp:350] Coordinator attempting to write APPEND action at position 3
I1130 22:47:23.872496 15970 replica.cpp:540] Replica received write request for position 3 from (45)@127.0.1.1:51177
I1130 22:47:23.890398 15970 leveldb.cpp:343] Persisting action (343 bytes) to leveldb took 17.833464ms
I1130 22:47:23.890465 15970 replica.cpp:715] Persisted action at 3
I1130 22:47:23.891302 15969 replica.cpp:694] Replica received learned notice for position 3 from @0.0.0.0:0
I1130 22:47:23.916492 15969 leveldb.cpp:343] Persisting action (345 bytes) to leveldb took 25.076422ms
I1130 22:47:23.916555 15969 replica.cpp:715] Persisted action at 3
I1130 22:47:23.916581 15969 replica.cpp:700] Replica learned APPEND action at position 3
I1130 22:47:23.917907 15969 registrar.cpp:486] Successfully updated the 'registry' in 48.825088ms
I1130 22:47:23.918125 15971 log.cpp:704] Attempting to truncate the log to 3
I1130 22:47:23.918313 15969 coordinator.cpp:350] Coordinator attempting to write TRUNCATE action at position 4
I1130 22:47:23.919076 15971 replica.cpp:540] Replica received write request for position 4 from (46)@127.0.1.1:51177
I1130 22:47:23.919075 15972 master.cpp:3927] Registered slave edbdc635-adf5-40f6-bc27-15b19e69f8cd-S0 at slave(2)@127.0.1.1:51177 (ubuntu14) with cpus(*):2; mem(*):10240; disk(*):34068; ports(*):[31000-32000]
I1130 22:47:23.919356 15969 hierarchical.cpp:344] Added slave edbdc635-adf5-40f6-bc27-15b19e69f8cd-S0 (ubuntu14) with cpus(*):2; mem(*):10240; disk(*):34068; ports(*):[31000-32000] (allocated: )
I1130 22:47:23.919670 15974 slave.cpp:904] Registered with master master@127.0.1.1:51177; given slave ID edbdc635-adf5-40f6-bc27-15b19e69f8cd-S0
I1130 22:47:23.919860 15975 status_update_manager.cpp:183] Resuming sending status updates
I1130 22:47:23.920243 15974 slave.cpp:963] Forwarding total oversubscribed resources
I1130 22:47:23.920426 15974 master.cpp:4269] Received update of slave edbdc635-adf5-40f6-bc27-15b19e69f8cd-S0 at slave(2)@127.0.1.1:51177 (ubuntu14) with total oversubscribed resources
I1130 22:47:23.920732 15974 hierarchical.cpp:400] Slave edbdc635-adf5-40f6-bc27-15b19e69f8cd-S0 (ubuntu14) updated with oversubscribed resources (total: cpus(*):2; mem(*):10240; disk(*):34068; ports(*):[31000-32000], allocated: )
I1130 22:47:23.930485 15971 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 11.225812ms
I1130 22:47:23.930588 15971 replica.cpp:715] Persisted action at 4
I1130 22:47:23.931483 15971 replica.cpp:694] Replica received learned notice for position 4 from @0.0.0.0:0
I1130 22:47:23.946909 15971 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 15.365585ms
I1130 22:47:23.947005 15971 leveldb.cpp:401] Deleting ~2 keys from leveldb took 33233ns
I1130 22:47:23.947026 15971 replica.cpp:715] Persisted action at 4
I1130 22:47:23.947062 15971 replica.cpp:700] Replica learned TRUNCATE action at position 4
2015-11-30 22:47:23,976:15722(0x7fac4e652700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:49113] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
2015-11-30 22:47:24,140:15722(0x7fac84bc4700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:44051] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
I1130 22:47:24.173096 15970 master.cpp:3859] Registering slave at slave(1)@127.0.1.1:51177 (ubuntu14) with id edbdc635-adf5-40f6-bc27-15b19e69f8cd-S1
I1130 22:47:24.173475 15970 registrar.cpp:441] Applied 1 operations in 60030ns; attempting to update the 'registry'
I1130 22:47:24.174414 15970 log.cpp:685] Attempting to append 486 bytes to the log
I1130 22:47:24.174617 15970 coordinator.cpp:350] Coordinator attempting to write APPEND action at position 5
I1130 22:47:24.175302 15970 replica.cpp:540] Replica received write request for position 5 from (47)@127.0.1.1:51177
I1130 22:47:24.194605 15970 leveldb.cpp:343] Persisting action (505 bytes) to leveldb took 19.220068ms
I1130 22:47:24.194659 15970 replica.cpp:715] Persisted action at 5
I1130 22:47:24.195379 15976 replica.cpp:694] Replica received learned notice for position 5 from @0.0.0.0:0
I1130 22:47:24.224751 15976 leveldb.cpp:343] Persisting action (507 bytes) to leveldb took 29.20734ms
I1130 22:47:24.224807 15976 replica.cpp:715] Persisted action at 5
I1130 22:47:24.224833 15976 replica.cpp:700] Replica learned APPEND action at position 5
I1130 22:47:24.226043 15974 registrar.cpp:486] Successfully updated the 'registry' in 52.468992ms
I1130 22:47:24.226249 15974 log.cpp:704] Attempting to truncate the log to 5
I1130 22:47:24.226369 15974 coordinator.cpp:350] Coordinator attempting to write TRUNCATE action at position 6
I1130 22:47:24.226654 15976 master.cpp:3927] Registered slave edbdc635-adf5-40f6-bc27-15b19e69f8cd-S1 at slave(1)@127.0.1.1:51177 (ubuntu14) with cpus(*):2; mem(*):10240; disk(*):34068; ports(*):[31000-32000]
I1130 22:47:24.226811 15976 slave.cpp:904] Registered with master master@127.0.1.1:51177; given slave ID edbdc635-adf5-40f6-bc27-15b19e69f8cd-S1
I1130 22:47:24.226981 15972 status_update_manager.cpp:183] Resuming sending status updates
I1130 22:47:24.226809 15974 hierarchical.cpp:344] Added slave edbdc635-adf5-40f6-bc27-15b19e69f8cd-S1 (ubuntu14) with cpus(*):2; mem(*):10240; disk(*):34068; ports(*):[31000-32000] (allocated: )
I1130 22:47:24.227459 15971 replica.cpp:540] Replica received write request for position 6 from (48)@127.0.1.1:51177
I1130 22:47:24.227530 15976 slave.cpp:963] Forwarding total oversubscribed resources
I1130 22:47:24.228521 15973 master.cpp:4269] Received update of slave edbdc635-adf5-40f6-bc27-15b19e69f8cd-S1 at slave(1)@127.0.1.1:51177 (ubuntu14) with total oversubscribed resources
I1130 22:47:24.228770 15973 hierarchical.cpp:400] Slave edbdc635-adf5-40f6-bc27-15b19e69f8cd-S1 (ubuntu14) updated with oversubscribed resources (total: cpus(*):2; mem(*):10240; disk(*):34068; ports(*):[31000-32000], allocated: )
I1130 22:47:24.241744 15971 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 13.475397ms
I1130 22:47:24.241809 15971 replica.cpp:715] Persisted action at 6
I1130 22:47:24.242728 15973 replica.cpp:694] Replica received learned notice for position 6 from @0.0.0.0:0
I1130 22:47:24.257985 15973 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 15.20455ms
I1130 22:47:24.258081 15973 leveldb.cpp:401] Deleting ~2 keys from leveldb took 31813ns
I1130 22:47:24.258116 15973 replica.cpp:715] Persisted action at 6
I1130 22:47:24.258139 15973 replica.cpp:700] Replica learned TRUNCATE action at position 6
2015-11-30 22:47:24,387:15722(0x7fac0e7fc700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:50280] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
2015-11-30 22:47:24,666:15722(0x7fac4d650700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:58836] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
I1130 22:47:25.172317 15969 master.cpp:3859] Registering slave at slave(3)@127.0.1.1:51177 (ubuntu14) with id edbdc635-adf5-40f6-bc27-15b19e69f8cd-S2
I1130 22:47:25.172703 15969 registrar.cpp:441] Applied 1 operations in 59601ns; attempting to update the 'registry'
I1130 22:47:25.174685 15969 log.cpp:685] Attempting to append 648 bytes to the log
I1130 22:47:25.174819 15976 coordinator.cpp:350] Coordinator attempting to write APPEND action at position 7
I1130 22:47:25.175757 15972 replica.cpp:540] Replica received write request for position 7 from (49)@127.0.1.1:51177
I1130 22:47:25.202685 15972 leveldb.cpp:343] Persisting action (667 bytes) to leveldb took 26.833493ms
I1130 22:47:25.202808 15972 replica.cpp:715] Persisted action at 7
I1130 22:47:25.203387 15972 replica.cpp:694] Replica received learned notice for position 7 from @0.0.0.0:0
I1130 22:47:25.221983 15972 leveldb.cpp:343] Persisting action (669 bytes) to leveldb took 18.510109ms
I1130 22:47:25.222126 15972 replica.cpp:715] Persisted action at 7
I1130 22:47:25.222199 15972 replica.cpp:700] Replica learned APPEND action at position 7
I1130 22:47:25.223793 15969 registrar.cpp:486] Successfully updated the 'registry' in 50.982144ms
I1130 22:47:25.224144 15971 log.cpp:704] Attempting to truncate the log to 7
I1130 22:47:25.224392 15971 coordinator.cpp:350] Coordinator attempting to write TRUNCATE action at position 8
I1130 22:47:25.224444 15969 master.cpp:3927] Registered slave edbdc635-adf5-40f6-bc27-15b19e69f8cd-S2 at slave(3)@127.0.1.1:51177 (ubuntu14) with cpus(*):2; mem(*):10240; disk(*):34068; ports(*):[31000-32000]
I1130 22:47:25.224606 15974 hierarchical.cpp:344] Added slave edbdc635-adf5-40f6-bc27-15b19e69f8cd-S2 (ubuntu14) with cpus(*):2; mem(*):10240; disk(*):34068; ports(*):[31000-32000] (allocated: )
I1130 22:47:25.224686 15972 slave.cpp:904] Registered with master master@127.0.1.1:51177; given slave ID edbdc635-adf5-40f6-bc27-15b19e69f8cd-S2
I1130 22:47:25.225249 15976 status_update_manager.cpp:183] Resuming sending status updates
I1130 22:47:25.225592 15972 slave.cpp:963] Forwarding total oversubscribed resources
I1130 22:47:25.226097 15969 master.cpp:4269] Received update of slave edbdc635-adf5-40f6-bc27-15b19e69f8cd-S2 at slave(3)@127.0.1.1:51177 (ubuntu14) with total oversubscribed resources
I1130 22:47:25.226299 15971 replica.cpp:540] Replica received write request for position 8 from (50)@127.0.1.1:51177
I1130 22:47:25.226444 15974 hierarchical.cpp:400] Slave edbdc635-adf5-40f6-bc27-15b19e69f8cd-S2 (ubuntu14) updated with oversubscribed resources (total: cpus(*):2; mem(*):10240; disk(*):34068; ports(*):[31000-32000], allocated: )
I1130 22:47:25.229393 15971 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 3.030976ms
I1130 22:47:25.229516 15971 replica.cpp:715] Persisted action at 8
I1130 22:47:25.230015 15971 replica.cpp:694] Replica received learned notice for position 8 from @0.0.0.0:0
I1130 22:47:25.245934 15971 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 15.818898ms
I1130 22:47:25.246071 15971 leveldb.cpp:401] Deleting ~2 keys from leveldb took 32062ns
I1130 22:47:25.246158 15971 replica.cpp:715] Persisted action at 8
I1130 22:47:25.246229 15971 replica.cpp:700] Replica learned TRUNCATE action at position 8
2015-11-30 22:47:25,512:15722(0x7fac4f257700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:37362] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
2015-11-30 22:47:25,546:15722(0x7fac0effd700):ZOO_WARN@zookeeper_interest@1557: Exceeded deadline by 12ms
2015-11-30 22:47:25,547:15722(0x7fac0effd700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:38547] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
2015-11-30 22:47:25,608:15722(0x7fac853c5700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:51060] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
2015-11-30 22:47:26,089:15722(0x7fac1ffff700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:36764] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
2015-11-30 22:47:26,480:15722(0x7fac4de51700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:59080] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
2015-11-30 22:47:27,314:15722(0x7fac4e652700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:49113] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
2015-11-30 22:47:27,477:15722(0x7fac84bc4700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:44051] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
2015-11-30 22:47:27,725:15722(0x7fac0e7fc700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:50280] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
2015-11-30 22:47:28,006:15722(0x7fac4d650700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:58836] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
2015-11-30 22:47:28,862:15722(0x7fac4f257700):ZOO_WARN@zookeeper_interest@1557: Exceeded deadline by 16ms
{noformat}
> EventCall Test Framework is flaky
> ---------------------------------
>
> Key: MESOS-3273
> URL: https://issues.apache.org/jira/browse/MESOS-3273
> Project: Mesos
> Issue Type: Bug
> Components: HTTP API
> Affects Versions: 0.24.0
> Environment: https://builds.apache.org/job/Mesos/705/COMPILER=clang,CONFIGURATION=--verbose,OS=ubuntu:14.04,label_exp=docker%7C%7CHadoop/consoleFull
> Reporter: Vinod Kone
> Labels: flaky-test, tech-debt, twitter
>
> Observed this on ASF CI. h/t [~haosdent@gmail.com]
> Looks like the HTTP scheduler never sent a SUBSCRIBE request to the master.
> {code}
> [ RUN ] ExamplesTest.EventCallFramework
> Using temporary directory '/tmp/ExamplesTest_EventCallFramework_k4vXkx'
> I0813 19:55:15.643579 26085 exec.cpp:443] Ignoring exited event because the driver is aborted!
> Shutting down
> Sending SIGTERM to process tree at pid 26061
> Killing the following process trees:
> [
> ]
> Shutting down
> Sending SIGTERM to process tree at pid 26062
> Shutting down
> Killing the following process trees:
> [
> ]
> Sending SIGTERM to process tree at pid 26063
> Killing the following process trees:
> [
> ]
> Shutting down
> Sending SIGTERM to process tree at pid 26098
> Killing the following process trees:
> [
> ]
> Shutting down
> Sending SIGTERM to process tree at pid 26099
> Killing the following process trees:
> [
> ]
> WARNING: Logging before InitGoogleLogging() is written to STDERR
> I0813 19:55:17.161726 26100 process.cpp:1012] libprocess is initialized on 172.17.2.10:60249 for 16 cpus
> I0813 19:55:17.161888 26100 logging.cpp:177] Logging to STDERR
> I0813 19:55:17.163625 26100 scheduler.cpp:157] Version: 0.24.0
> I0813 19:55:17.175302 26100 leveldb.cpp:176] Opened db in 3.167446ms
> I0813 19:55:17.176393 26100 leveldb.cpp:183] Compacted db in 1.047996ms
> I0813 19:55:17.176496 26100 leveldb.cpp:198] Created db iterator in 77155ns
> I0813 19:55:17.176518 26100 leveldb.cpp:204] Seeked to beginning of db in 8429ns
> I0813 19:55:17.176527 26100 leveldb.cpp:273] Iterated through 0 keys in the db in 4219ns
> I0813 19:55:17.176708 26100 replica.cpp:744] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> I0813 19:55:17.178951 26136 recover.cpp:449] Starting replica recovery
> I0813 19:55:17.179934 26136 recover.cpp:475] Replica is in EMPTY status
> I0813 19:55:17.181970 26126 master.cpp:378] Master 20150813-195517-167907756-60249-26100 (297daca2d01a) started on 172.17.2.10:60249
> I0813 19:55:17.182317 26126 master.cpp:380] 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" --credentials="/tmp/ExamplesTest_EventCallFramework_k4vXkx/credentials" --framework_sorter="drf" --help="false" --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.24.0/src/webui" --work_dir="/tmp/mesos-II8Gua" --zk_session_timeout="10secs"
> I0813 19:55:17.183475 26126 master.cpp:427] Master allowing unauthenticated frameworks to register
> I0813 19:55:17.183536 26126 master.cpp:432] Master allowing unauthenticated slaves to register
> I0813 19:55:17.183615 26126 credentials.hpp:37] Loading credentials for authentication from '/tmp/ExamplesTest_EventCallFramework_k4vXkx/credentials'
> W0813 19:55:17.183859 26126 credentials.hpp:52] Permissions on credentials file '/tmp/ExamplesTest_EventCallFramework_k4vXkx/credentials' are too open. It is recommended that your credentials file is NOT accessible by others.
> I0813 19:55:17.183969 26123 replica.cpp:641] Replica in EMPTY status received a broadcasted recover request
> I0813 19:55:17.184306 26126 master.cpp:469] Using default 'crammd5' authenticator
> I0813 19:55:17.184661 26126 authenticator.cpp:512] Initializing server SASL
> I0813 19:55:17.185104 26138 recover.cpp:195] Received a recover response from a replica in EMPTY status
> I0813 19:55:17.185972 26100 containerizer.cpp:143] Using isolation: posix/cpu,posix/mem,filesystem/posix
> I0813 19:55:17.186058 26135 recover.cpp:566] Updating replica status to STARTING
> I0813 19:55:17.187001 26138 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 654586ns
> I0813 19:55:17.187037 26138 replica.cpp:323] Persisted replica status to STARTING
> I0813 19:55:17.187499 26134 recover.cpp:475] Replica is in STARTING status
> I0813 19:55:17.187605 26126 auxprop.cpp:66] Initialized in-memory auxiliary property plugin
> I0813 19:55:17.187710 26126 master.cpp:506] Authorization enabled
> I0813 19:55:17.188657 26138 replica.cpp:641] Replica in STARTING status received a broadcasted recover request
> I0813 19:55:17.188853 26131 hierarchical.hpp:346] Initialized hierarchical allocator process
> I0813 19:55:17.189252 26132 whitelist_watcher.cpp:79] No whitelist given
> I0813 19:55:17.189321 26134 recover.cpp:195] Received a recover response from a replica in STARTING status
> I0813 19:55:17.190001 26125 recover.cpp:566] Updating replica status to VOTING
> I0813 19:55:17.190696 26124 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 357331ns
> I0813 19:55:17.190775 26124 replica.cpp:323] Persisted replica status to VOTING
> I0813 19:55:17.190970 26133 recover.cpp:580] Successfully joined the Paxos group
> I0813 19:55:17.192183 26129 recover.cpp:464] Recover process terminated
> I0813 19:55:17.192699 26123 slave.cpp:190] Slave started on 1)@172.17.2.10:60249
> I0813 19:55:17.192741 26123 slave.cpp:191] Flags at startup: --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_kill_orphans="true" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --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" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/mesos/mesos-0.24.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" --resource_monitoring_interval="1secs" --resources="cpus:2;mem:10240" --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --version="false" --work_dir="/tmp/mesos-II8Gua/0"
> I0813 19:55:17.194514 26100 containerizer.cpp:143] Using isolation: posix/cpu,posix/mem,filesystem/posix
> I0813 19:55:17.194658 26123 slave.cpp:354] Slave resources: cpus(*):2; mem(*):10240; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0813 19:55:17.194854 26123 slave.cpp:384] Slave hostname: 297daca2d01a
> I0813 19:55:17.194877 26123 slave.cpp:389] Slave checkpoint: true
> I0813 19:55:17.196751 26132 master.cpp:1524] The newly elected leader is master@172.17.2.10:60249 with id 20150813-195517-167907756-60249-26100
> I0813 19:55:17.196797 26132 master.cpp:1537] Elected as the leading master!
> I0813 19:55:17.196815 26132 master.cpp:1307] Recovering from registrar
> I0813 19:55:17.197032 26138 registrar.cpp:311] Recovering registrar
> I0813 19:55:17.197845 26132 slave.cpp:190] Slave started on 2)@172.17.2.10:60249
> I0813 19:55:17.198420 26125 log.cpp:661] Attempting to start the writer
> I0813 19:55:17.197948 26132 slave.cpp:191] Flags at startup: --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_kill_orphans="true" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --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" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/mesos/mesos-0.24.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" --resource_monitoring_interval="1secs" --resources="cpus:2;mem:10240" --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --version="false" --work_dir="/tmp/mesos-II8Gua/1"
> I0813 19:55:17.199121 26132 slave.cpp:354] Slave resources: cpus(*):2; mem(*):10240; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0813 19:55:17.199235 26138 state.cpp:54] Recovering state from '/tmp/mesos-II8Gua/0/meta'
> I0813 19:55:17.199322 26132 slave.cpp:384] Slave hostname: 297daca2d01a
> I0813 19:55:17.199345 26132 slave.cpp:389] Slave checkpoint: true
> I0813 19:55:17.199676 26100 containerizer.cpp:143] Using isolation: posix/cpu,posix/mem,filesystem/posix
> I0813 19:55:17.200085 26135 state.cpp:54] Recovering state from '/tmp/mesos-II8Gua/1/meta'
> I0813 19:55:17.200317 26132 status_update_manager.cpp:202] Recovering status update manager
> I0813 19:55:17.200371 26129 status_update_manager.cpp:202] Recovering status update manager
> I0813 19:55:17.202003 26129 replica.cpp:477] Replica received implicit promise request with proposal 1
> I0813 19:55:17.202585 26131 slave.cpp:190] Slave started on 3)@172.17.2.10:60249
> I0813 19:55:17.202596 26129 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 523191ns
> I0813 19:55:17.202756 26129 replica.cpp:345] Persisted promised to 1
> I0813 19:55:17.202770 26132 containerizer.cpp:379] Recovering containerizer
> I0813 19:55:17.203061 26135 containerizer.cpp:379] Recovering containerizer
> I0813 19:55:17.202663 26131 slave.cpp:191] Flags at startup: --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_kill_orphans="true" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --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" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/mesos/mesos-0.24.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" --resource_monitoring_interval="1secs" --resources="cpus:2;mem:10240" --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --version="false" --work_dir="/tmp/mesos-II8Gua/2"
> I0813 19:55:17.203819 26131 slave.cpp:354] Slave resources: cpus(*):2; mem(*):10240; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0813 19:55:17.203930 26131 slave.cpp:384] Slave hostname: 297daca2d01a
> I0813 19:55:17.203948 26131 slave.cpp:389] Slave checkpoint: true
> I0813 19:55:17.204674 26137 state.cpp:54] Recovering state from '/tmp/mesos-II8Gua/2/meta'
> I0813 19:55:17.205178 26135 status_update_manager.cpp:202] Recovering status update manager
> I0813 19:55:17.205323 26135 containerizer.cpp:379] Recovering containerizer
> I0813 19:55:17.205521 26136 slave.cpp:4069] Finished recovery
> I0813 19:55:17.206074 26136 slave.cpp:4226] Querying resource estimator for oversubscribable resources
> I0813 19:55:17.206424 26128 slave.cpp:4069] Finished recovery
> I0813 19:55:17.206722 26137 status_update_manager.cpp:176] Pausing sending status updates
> I0813 19:55:17.206858 26136 slave.cpp:684] New master detected at master@172.17.2.10:60249
> I0813 19:55:17.206902 26138 slave.cpp:4069] Finished recovery
> I0813 19:55:17.206962 26128 slave.cpp:4226] Querying resource estimator for oversubscribable resources
> I0813 19:55:17.208312 26134 scheduler.cpp:272] New master detected at master@172.17.2.10:60249
> I0813 19:55:17.208364 26136 slave.cpp:709] No credentials provided. Attempting to register without authentication
> I0813 19:55:17.208608 26136 slave.cpp:720] Detecting new master
> I0813 19:55:17.208839 26138 slave.cpp:4226] Querying resource estimator for oversubscribable resources
> I0813 19:55:17.209216 26123 coordinator.cpp:231] Coordinator attemping to fill missing position
> I0813 19:55:17.209247 26127 status_update_manager.cpp:176] Pausing sending status updates
> I0813 19:55:17.209259 26128 slave.cpp:684] New master detected at master@172.17.2.10:60249
> I0813 19:55:17.209322 26127 status_update_manager.cpp:176] Pausing sending status updates
> I0813 19:55:17.209364 26128 slave.cpp:709] No credentials provided. Attempting to register without authentication
> I0813 19:55:17.209344 26138 slave.cpp:684] New master detected at master@172.17.2.10:60249
> I0813 19:55:17.209455 26128 slave.cpp:720] Detecting new master
> I0813 19:55:17.209492 26138 slave.cpp:709] No credentials provided. Attempting to register without authentication
> I0813 19:55:17.209573 26128 slave.cpp:4240] Received oversubscribable resources from the resource estimator
> I0813 19:55:17.209601 26138 slave.cpp:720] Detecting new master
> I0813 19:55:17.209730 26138 slave.cpp:4240] Received oversubscribable resources from the resource estimator
> I0813 19:55:17.209883 26136 slave.cpp:4240] Received oversubscribable resources from the resource estimator
> I0813 19:55:17.211266 26136 replica.cpp:378] Replica received explicit promise request for position 0 with proposal 2
> I0813 19:55:17.211771 26136 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 462128ns
> I0813 19:55:17.211797 26136 replica.cpp:679] Persisted action at 0
> I0813 19:55:17.212980 26130 replica.cpp:511] Replica received write request for position 0
> I0813 19:55:17.213124 26130 leveldb.cpp:438] Reading position from leveldb took 67075ns
> I0813 19:55:17.213580 26130 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 301649ns
> I0813 19:55:17.213603 26130 replica.cpp:679] Persisted action at 0
> I0813 19:55:17.214284 26123 replica.cpp:658] Replica received learned notice for position 0
> I0813 19:55:17.214622 26123 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 284547ns
> I0813 19:55:17.214648 26123 replica.cpp:679] Persisted action at 0
> I0813 19:55:17.214675 26123 replica.cpp:664] Replica learned NOP action at position 0
> I0813 19:55:17.215420 26136 log.cpp:677] Writer started with ending position 0
> I0813 19:55:17.217463 26133 leveldb.cpp:438] Reading position from leveldb took 47943ns
> I0813 19:55:17.220762 26125 registrar.cpp:344] Successfully fetched the registry (0B) in 23.649024ms
> I0813 19:55:17.221081 26125 registrar.cpp:443] Applied 1 operations in 136902ns; attempting to update the 'registry'
> I0813 19:55:17.223667 26133 log.cpp:685] Attempting to append 174 bytes to the log
> I0813 19:55:17.223778 26125 coordinator.cpp:341] Coordinator attempting to write APPEND action at position 1
> I0813 19:55:17.224516 26127 replica.cpp:511] Replica received write request for position 1
> I0813 19:55:17.225009 26127 leveldb.cpp:343] Persisting action (193 bytes) to leveldb took 466230ns
> I0813 19:55:17.225042 26127 replica.cpp:679] Persisted action at 1
> I0813 19:55:17.225653 26126 replica.cpp:658] Replica received learned notice for position 1
> I0813 19:55:17.225953 26126 leveldb.cpp:343] Persisting action (195 bytes) to leveldb took 286966ns
> I0813 19:55:17.225975 26126 replica.cpp:679] Persisted action at 1
> I0813 19:55:17.226013 26126 replica.cpp:664] Replica learned APPEND action at position 1
> I0813 19:55:17.227545 26137 registrar.cpp:488] Successfully updated the 'registry' in 6.328064ms
> I0813 19:55:17.227722 26137 registrar.cpp:374] Successfully recovered registrar
> I0813 19:55:17.227918 26124 log.cpp:704] Attempting to truncate the log to 1
> I0813 19:55:17.228024 26133 coordinator.cpp:341] Coordinator attempting to write TRUNCATE action at position 2
> I0813 19:55:17.228193 26131 master.cpp:1334] Recovered 0 slaves from the Registry (135B) ; allowing 10mins for slaves to re-register
> I0813 19:55:17.228659 26127 replica.cpp:511] Replica received write request for position 2
> I0813 19:55:17.228972 26127 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 297903ns
> I0813 19:55:17.229004 26127 replica.cpp:679] Persisted action at 2
> I0813 19:55:17.229565 26127 replica.cpp:658] Replica received learned notice for position 2
> I0813 19:55:17.229837 26127 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 260326ns
> I0813 19:55:17.229899 26127 leveldb.cpp:401] Deleting ~1 keys from leveldb took 48697ns
> I0813 19:55:17.229923 26127 replica.cpp:679] Persisted action at 2
> I0813 19:55:17.229956 26127 replica.cpp:664] Replica learned TRUNCATE action at position 2
> I0813 19:55:17.325634 26138 slave.cpp:1209] Will retry registration in 445.955946ms if necessary
> I0813 19:55:17.326088 26124 master.cpp:3635] Registering slave at slave(2)@172.17.2.10:60249 (297daca2d01a) with id 20150813-195517-167907756-60249-26100-S0
> I0813 19:55:17.327446 26124 registrar.cpp:443] Applied 1 operations in 231072ns; attempting to update the 'registry'
> I0813 19:55:17.330252 26136 log.cpp:685] Attempting to append 344 bytes to the log
> I0813 19:55:17.330407 26132 coordinator.cpp:341] Coordinator attempting to write APPEND action at position 3
> I0813 19:55:17.331418 26128 replica.cpp:511] Replica received write request for position 3
> I0813 19:55:17.331753 26128 leveldb.cpp:343] Persisting action (363 bytes) to leveldb took 264140ns
> I0813 19:55:17.331778 26128 replica.cpp:679] Persisted action at 3
> I0813 19:55:17.332324 26133 replica.cpp:658] Replica received learned notice for position 3
> I0813 19:55:17.332809 26133 leveldb.cpp:343] Persisting action (365 bytes) to leveldb took 313064ns
> I0813 19:55:17.332834 26133 replica.cpp:679] Persisted action at 3
> I0813 19:55:17.332865 26133 replica.cpp:664] Replica learned APPEND action at position 3
> I0813 19:55:17.334211 26132 registrar.cpp:488] Successfully updated the 'registry' in 6.668032ms
> I0813 19:55:17.334430 26127 log.cpp:704] Attempting to truncate the log to 3
> I0813 19:55:17.334566 26132 coordinator.cpp:341] Coordinator attempting to write TRUNCATE action at position 4
> I0813 19:55:17.335283 26129 replica.cpp:511] Replica received write request for position 4
> I0813 19:55:17.335615 26127 slave.cpp:3058] Received ping from slave-observer(1)@172.17.2.10:60249
> I0813 19:55:17.335816 26129 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 458268ns
> I0813 19:55:17.335908 26137 master.cpp:3698] Registered slave 20150813-195517-167907756-60249-26100-S0 at slave(2)@172.17.2.10:60249 (297daca2d01a) with cpus(*):2; mem(*):10240; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0813 19:55:17.335983 26129 replica.cpp:679] Persisted action at 4
> I0813 19:55:17.336019 26136 slave.cpp:859] Registered with master master@172.17.2.10:60249; given slave ID 20150813-195517-167907756-60249-26100-S0
> I0813 19:55:17.336073 26136 fetcher.cpp:77] Clearing fetcher cache
> I0813 19:55:17.336220 26127 status_update_manager.cpp:183] Resuming sending status updates
> I0813 19:55:17.336328 26128 hierarchical.hpp:540] Added slave 20150813-195517-167907756-60249-26100-S0 (297daca2d01a) with cpus(*):2; mem(*):10240; disk(*):3.70122e+06; ports(*):[31000-32000] (allocated: )
> I0813 19:55:17.336599 26138 replica.cpp:658] Replica received learned notice for position 4
> I0813 19:55:17.336910 26128 hierarchical.hpp:1008] No resources available to allocate!
> I0813 19:55:17.336957 26128 hierarchical.hpp:926] Performed allocation for slave 20150813-195517-167907756-60249-26100-S0 in 580663ns
> I0813 19:55:17.337016 26136 slave.cpp:882] Checkpointing SlaveInfo to '/tmp/mesos-II8Gua/1/meta/slaves/20150813-195517-167907756-60249-26100-S0/slave.info'
> I0813 19:55:17.337035 26138 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 403607ns
> I0813 19:55:17.337138 26138 leveldb.cpp:401] Deleting ~2 keys from leveldb took 77040ns
> I0813 19:55:17.337167 26138 replica.cpp:679] Persisted action at 4
> I0813 19:55:17.337208 26138 replica.cpp:664] Replica learned TRUNCATE action at position 4
> I0813 19:55:17.337514 26136 slave.cpp:918] Forwarding total oversubscribed resources
> I0813 19:55:17.337745 26131 master.cpp:3997] Received update of slave 20150813-195517-167907756-60249-26100-S0 at slave(2)@172.17.2.10:60249 (297daca2d01a) with total oversubscribed resources
> I0813 19:55:17.338240 26131 hierarchical.hpp:600] Slave 20150813-195517-167907756-60249-26100-S0 (297daca2d01a) updated with oversubscribed resources (total: cpus(*):2; mem(*):10240; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: )
> I0813 19:55:17.338479 26131 hierarchical.hpp:1008] No resources available to allocate!
> I0813 19:55:17.338505 26131 hierarchical.hpp:926] Performed allocation for slave 20150813-195517-167907756-60249-26100-S0 in 216259ns
> I0813 19:55:17.504086 26124 slave.cpp:1209] Will retry registration in 1.92618421secs if necessary
> I0813 19:55:17.504408 26124 master.cpp:3635] Registering slave at slave(3)@172.17.2.10:60249 (297daca2d01a) with id 20150813-195517-167907756-60249-26100-S1
> I0813 19:55:17.505203 26124 registrar.cpp:443] Applied 1 operations in 144314ns; attempting to update the 'registry'
> I0813 19:55:17.507616 26124 log.cpp:685] Attempting to append 511 bytes to the log
> I0813 19:55:17.507796 26132 coordinator.cpp:341] Coordinator attempting to write APPEND action at position 5
> I0813 19:55:17.508735 26128 replica.cpp:511] Replica received write request for position 5
> I0813 19:55:17.509291 26128 leveldb.cpp:343] Persisting action (530 bytes) to leveldb took 527776ns
> I0813 19:55:17.509328 26128 replica.cpp:679] Persisted action at 5
> I0813 19:55:17.509945 26124 replica.cpp:658] Replica received learned notice for position 5
> I0813 19:55:17.510393 26124 leveldb.cpp:343] Persisting action (532 bytes) to leveldb took 438543ns
> I0813 19:55:17.510416 26124 replica.cpp:679] Persisted action at 5
> I0813 19:55:17.510437 26124 replica.cpp:664] Replica learned APPEND action at position 5
> I0813 19:55:17.511907 26125 registrar.cpp:488] Successfully updated the 'registry' in 6624us
> I0813 19:55:17.512225 26138 log.cpp:704] Attempting to truncate the log to 5
> I0813 19:55:17.512305 26136 coordinator.cpp:341] Coordinator attempting to write TRUNCATE action at position 6
> I0813 19:55:17.513066 26133 slave.cpp:3058] Received ping from slave-observer(2)@172.17.2.10:60249
> I0813 19:55:17.513242 26133 slave.cpp:859] Registered with master master@172.17.2.10:60249; given slave ID 20150813-195517-167907756-60249-26100-S1
> I0813 19:55:17.513221 26126 master.cpp:3698] Registered slave 20150813-195517-167907756-60249-26100-S1 at slave(3)@172.17.2.10:60249 (297daca2d01a) with cpus(*):2; mem(*):10240; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0813 19:55:17.513089 26129 replica.cpp:511] Replica received write request for position 6
> I0813 19:55:17.513393 26133 fetcher.cpp:77] Clearing fetcher cache
> I0813 19:55:17.513380 26138 hierarchical.hpp:540] Added slave 20150813-195517-167907756-60249-26100-S1 (297daca2d01a) with cpus(*):2; mem(*):10240; disk(*):3.70122e+06; ports(*):[31000-32000] (allocated: )
> I0813 19:55:17.513805 26132 status_update_manager.cpp:183] Resuming sending status updates
> I0813 19:55:17.513949 26129 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 340511ns
> I0813 19:55:17.514046 26138 hierarchical.hpp:1008] No resources available to allocate!
> I0813 19:55:17.514050 26129 replica.cpp:679] Persisted action at 6
> I0813 19:55:17.514195 26133 slave.cpp:882] Checkpointing SlaveInfo to '/tmp/mesos-II8Gua/2/meta/slaves/20150813-195517-167907756-60249-26100-S1/slave.info'
> I0813 19:55:17.514140 26138 hierarchical.hpp:926] Performed allocation for slave 20150813-195517-167907756-60249-26100-S1 in 417609ns
> I0813 19:55:17.514704 26133 slave.cpp:918] Forwarding total oversubscribed resources
> I0813 19:55:17.514708 26138 replica.cpp:658] Replica received learned notice for position 6
> I0813 19:55:17.514880 26133 master.cpp:3997] Received update of slave 20150813-195517-167907756-60249-26100-S1 at slave(3)@172.17.2.10:60249 (297daca2d01a) with total oversubscribed resources
> I0813 19:55:17.515244 26127 hierarchical.hpp:600] Slave 20150813-195517-167907756-60249-26100-S1 (297daca2d01a) updated with oversubscribed resources (total: cpus(*):2; mem(*):10240; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: )
> I0813 19:55:17.515454 26138 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 640882ns
> I0813 19:55:17.515522 26138 leveldb.cpp:401] Deleting ~2 keys from leveldb took 56550ns
> I0813 19:55:17.515547 26138 replica.cpp:679] Persisted action at 6
> I0813 19:55:17.515581 26138 replica.cpp:664] Replica learned TRUNCATE action at position 6
> I0813 19:55:17.515802 26127 hierarchical.hpp:1008] No resources available to allocate!
> I0813 19:55:17.515866 26127 hierarchical.hpp:926] Performed allocation for slave 20150813-195517-167907756-60249-26100-S1 in 591007ns
> I0813 19:55:17.984196 26135 slave.cpp:1209] Will retry registration in 1.542495291secs if necessary
> I0813 19:55:17.984391 26138 master.cpp:3635] Registering slave at slave(1)@172.17.2.10:60249 (297daca2d01a) with id 20150813-195517-167907756-60249-26100-S2
> I0813 19:55:17.985170 26133 registrar.cpp:443] Applied 1 operations in 202126ns; attempting to update the 'registry'
> I0813 19:55:17.987498 26133 log.cpp:685] Attempting to append 678 bytes to the log
> I0813 19:55:17.987656 26123 coordinator.cpp:341] Coordinator attempting to write APPEND action at position 7
> I0813 19:55:17.988704 26138 replica.cpp:511] Replica received write request for position 7
> I0813 19:55:17.989223 26138 leveldb.cpp:343] Persisting action (697 bytes) to leveldb took 490422ns
> I0813 19:55:17.989248 26138 replica.cpp:679] Persisted action at 7
> I0813 19:55:17.989972 26126 replica.cpp:658] Replica received learned notice for position 7
> I0813 19:55:17.990401 26126 leveldb.cpp:343] Persisting action (699 bytes) to leveldb took 404333ns
> I0813 19:55:17.990420 26126 replica.cpp:679] Persisted action at 7
> I0813 19:55:17.990440 26126 replica.cpp:664] Replica learned APPEND action at position 7
> I0813 19:55:17.994066 26123 registrar.cpp:488] Successfully updated the 'registry' in 8.788224ms
> I0813 19:55:17.994436 26134 log.cpp:704] Attempting to truncate the log to 7
> I0813 19:55:17.994575 26123 coordinator.cpp:341] Coordinator attempting to write TRUNCATE action at position 8
> I0813 19:55:17.995070 26134 slave.cpp:3058] Received ping from slave-observer(3)@172.17.2.10:60249
> I0813 19:55:17.995291 26134 slave.cpp:859] Registered with master master@172.17.2.10:60249; given slave ID 20150813-195517-167907756-60249-26100-S2
> I0813 19:55:17.995319 26134 fetcher.cpp:77] Clearing fetcher cache
> I0813 19:55:17.995246 26129 master.cpp:3698] Registered slave 20150813-195517-167907756-60249-26100-S2 at slave(1)@172.17.2.10:60249 (297daca2d01a) with cpus(*):2; mem(*):10240; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0813 19:55:17.995565 26123 status_update_manager.cpp:183] Resuming sending status updates
> I0813 19:55:17.995579 26129 replica.cpp:511] Replica received write request for position 8
> I0813 19:55:17.996016 26134 slave.cpp:882] Checkpointing SlaveInfo to '/tmp/mesos-II8Gua/0/meta/slaves/20150813-195517-167907756-60249-26100-S2/slave.info'
> I0813 19:55:17.996039 26129 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 440511ns
> I0813 19:55:17.996067 26129 replica.cpp:679] Persisted action at 8
> I0813 19:55:17.996294 26128 hierarchical.hpp:540] Added slave 20150813-195517-167907756-60249-26100-S2 (297daca2d01a) with cpus(*):2; mem(*):10240; disk(*):3.70122e+06; ports(*):[31000-32000] (allocated: )
> I0813 19:55:17.996556 26134 slave.cpp:918] Forwarding total oversubscribed resources
> I0813 19:55:17.996623 26133 replica.cpp:658] Replica received learned notice for position 8
> I0813 19:55:17.997095 26134 master.cpp:3997] Received update of slave 20150813-195517-167907756-60249-26100-S2 at slave(1)@172.17.2.10:60249 (297daca2d01a) with total oversubscribed resources
> I0813 19:55:17.997263 26133 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 442619ns
> I0813 19:55:17.997385 26133 leveldb.cpp:401] Deleting ~2 keys from leveldb took 95741ns
> I0813 19:55:17.997413 26133 replica.cpp:679] Persisted action at 8
> I0813 19:55:17.997465 26133 replica.cpp:664] Replica learned TRUNCATE action at position 8
> I0813 19:55:17.997756 26128 hierarchical.hpp:1008] No resources available to allocate!
> I0813 19:55:17.997925 26128 hierarchical.hpp:926] Performed allocation for slave 20150813-195517-167907756-60249-26100-S2 in 1.14489ms
> I0813 19:55:17.998159 26128 hierarchical.hpp:600] Slave 20150813-195517-167907756-60249-26100-S2 (297daca2d01a) updated with oversubscribed resources (total: cpus(*):2; mem(*):10240; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: )
> I0813 19:55:17.998445 26128 hierarchical.hpp:1008] No resources available to allocate!
> I0813 19:55:17.998471 26128 hierarchical.hpp:926] Performed allocation for slave 20150813-195517-167907756-60249-26100-S2 in 218856ns
> I0813 19:55:18.190146 26133 hierarchical.hpp:1008] No resources available to allocate!
> I0813 19:55:18.190217 26133 hierarchical.hpp:908] Performed allocation for 3 slaves in 637042ns
> I0813 19:55:19.191346 26131 hierarchical.hpp:1008] No resources available to allocate!
> I0813 19:55:19.191915 26131 hierarchical.hpp:908] Performed allocation for 3 slaves in 1.215355ms
> I0813 19:55:20.193631 26135 hierarchical.hpp:1008] No resources available to allocate!
> I0813 19:55:20.193709 26135 hierarchical.hpp:908] Performed allocation for 3 slaves in 834491ns
> I0813 19:55:21.194805 26134 hierarchical.hpp:1008] No resources available to allocate!
> I0813 19:55:21.194870 26134 hierarchical.hpp:908] Performed allocation for 3 slaves in 536547ns
> I0813 19:55:22.196143 26137 hierarchical.hpp:1008] No resources available to allocate!
> I0813 19:55:22.196216 26137 hierarchical.hpp:908] Performed allocation for 3 slaves in 755140ns
> I0813 19:55:23.197412 26132 hierarchical.hpp:1008] No resources available to allocate!
> I0813 19:55:23.197979 26132 hierarchical.hpp:908] Performed allocation for 3 slaves in 1.223984ms
> I0813 19:55:24.199429 26132 hierarchical.hpp:1008] No resources available to allocate!
> I0813 19:55:24.199735 26132 hierarchical.hpp:908] Performed allocation for 3 slaves in 904654ns
> I0813 19:55:25.200978 26127 hierarchical.hpp:1008] No resources available to allocate!
> I0813 19:55:25.201206 26127 hierarchical.hpp:908] Performed allocation for 3 slaves in 939979ns
> I0813 19:55:26.203023 26132 hierarchical.hpp:1008] No resources available to allocate!
> I0813 19:55:26.203101 26132 hierarchical.hpp:908] Performed allocation for 3 slaves in 721178ns
> I0813 19:55:27.204815 26126 hierarchical.hpp:1008] No resources available to allocate!
> I0813 19:55:27.204888 26126 hierarchical.hpp:908] Performed allocation for 3 slaves in 767983ns
> I0813 19:55:28.206374 26126 hierarchical.hpp:1008] No resources available to allocate!
> I0813 19:55:28.206444 26126 hierarchical.hpp:908] Performed allocation for 3 slaves in 745214ns
> I0813 19:55:29.207515 26124 hierarchical.hpp:1008] No resources available to allocate!
> I0813 19:55:29.207579 26124 hierarchical.hpp:908] Performed allocation for 3 slaves in 551217ns
> I0813 19:55:30.208966 26136 hierarchical.hpp:1008] No resources available to allocate!
> I0813 19:55:30.209053 26136 hierarchical.hpp:908] Performed allocation for 3 slaves in 649887ns
> I0813 19:55:31.210078 26123 hierarchical.hpp:1008] No resources available to allocate!
> I0813 19:55:31.210144 26123 hierarchical.hpp:908] Performed allocation for 3 slaves in 558919ns
> I0813 19:55:32.211027 26130 slave.cpp:4226] Querying resource estimator for oversubscribable resources
> I0813 19:55:32.211045 26129 slave.cpp:4226] Querying resource estimator for oversubscribable resources
> I0813 19:55:32.211084 26132 slave.cpp:4226] Querying resource estimator for oversubscribable resources
> I0813 19:55:32.211386 26129 slave.cpp:4240] Received oversubscribable resources from the resource estimator
> I0813 19:55:32.211688 26132 slave.cpp:4240] Received oversubscribable resources from the resource estimator
> I0813 19:55:32.211853 26133 hierarchical.hpp:1008] No resources available to allocate!
> I0813 19:55:32.212035 26133 hierarchical.hpp:908] Performed allocation for 3 slaves in 898985ns
> I0813 19:55:32.212169 26133 slave.cpp:4240] Received oversubscribable resources from the resource estimator
> I0813 19:55:32.336745 26135 slave.cpp:3058] Received ping from slave-observer(1)@172.17.2.10:60249
> I0813 19:55:32.514333 26129 slave.cpp:3058] Received ping from slave-observer(2)@172.17.2.10:60249
> I0813 19:55:32.996134 26128 slave.cpp:3058] Received ping from slave-observer(3)@172.17.2.10:60249
> I0813 19:55:33.213248 26128 hierarchical.hpp:1008] No resources available to allocate!
> I0813 19:55:33.213326 26128 hierarchical.hpp:908] Performed allocation for 3 slaves in 827511ns
> I0813 19:55:34.214326 26125 hierarchical.hpp:1008] No resources available to allocate!
> I0813 19:55:34.214391 26125 hierarchical.hpp:908] Performed allocation for 3 slaves in 546422ns
> I0813 19:55:35.215909 26123 hierarchical.hpp:1008] No resources available to allocate!
> I0813 19:55:35.215973 26123 hierarchical.hpp:908] Performed allocation for 3 slaves in 627190ns
> I0813 19:55:36.217156 26134 hierarchical.hpp:1008] No resources available to allocate!
> I0813 19:55:36.217339 26134 hierarchical.hpp:908] Performed allocation for 3 slaves in 906249ns
> I0813 19:55:37.218739 26132 hierarchical.hpp:1008] No resources available to allocate!
> I0813 19:55:37.219169 26132 hierarchical.hpp:908] Performed allocation for 3 slaves in 1.102465ms
> I0813 19:55:38.220641 26133 hierarchical.hpp:1008] No resources available to allocate!
> I0813 19:55:38.220711 26133 hierarchical.hpp:908] Performed allocation for 3 slaves in 643146ns
> I0813 19:55:39.221976 26133 hierarchical.hpp:1008] No resources available to allocate!
> I0813 19:55:39.222118 26133 hierarchical.hpp:908] Performed allocation for 3 slaves in 845334ns
> I0813 19:55:40.223338 26129 hierarchical.hpp:1008] No resources available to allocate!
> I0813 19:55:40.223546 26129 hierarchical.hpp:908] Performed allocation for 3 slaves in 849995ns
> I0813 19:55:41.225558 26138 hierarchical.hpp:1008] No resources available to allocate!
> I0813 19:55:41.225752 26138 hierarchical.hpp:908] Performed allocation for 3 slaves in 958480ns
> I0813 19:55:42.227176 26131 hierarchical.hpp:1008] No resources available to allocate!
> I0813 19:55:42.227378 26131 hierarchical.hpp:908] Performed allocation for 3 slaves in 927048ns
> I0813 19:55:43.228813 26137 hierarchical.hpp:1008] No resources available to allocate!
> I0813 19:55:43.229441 26137 hierarchical.hpp:908] Performed allocation for 3 slaves in 1.310118ms
> I0813 19:55:44.230828 26135 hierarchical.hpp:1008] No resources available to allocate!
> I0813 19:55:44.231142 26135 hierarchical.hpp:908] Performed allocation for 3 slaves in 896369ns
> I0813 19:55:45.232656 26135 hierarchical.hpp:1008] No resources available to allocate!
> I0813 19:55:45.232903 26135 hierarchical.hpp:908] Performed allocation for 3 slaves in 1.357693ms
> I0813 19:55:46.234973 26137 hierarchical.hpp:1008
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)