You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "Anand Mazumdar (JIRA)" <ji...@apache.org> on 2015/09/03 08:59:45 UTC
[jira] [Comment Edited] (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=14728577#comment-14728577 ]
Anand Mazumdar edited comment on MESOS-3273 at 9/3/15 6:59 AM:
---------------------------------------------------------------
Was able to reproduce this once on my machine. But the issue is not the same as the one seen on ASF build though as per logs. So we still need to dig around for what the issue on ASF test-run was.
In my test run, there is a race between the master successfully recovering its state from registry and the scheduler sending a call. In this case, we just log the error and leave it upon the framework to retry the call. This happened only because I was running in a debugger in a loop and there would have been state left in Master across various test invocations leading to the time in Registry Recovery. So , I won't worry too much about this occurrence.
{code}
I0902 23:29:28.815498 113774592 leveldb.cpp:438] Reading position from leveldb took 32us
I0902 23:29:28.826355 136355840 registrar.cpp:344] Successfully fetched the registry (0B) in 16.811008ms
I0902 23:29:28.826472 136355840 registrar.cpp:443] Applied 1 operations in 35us; attempting to update the 'registry'
I0902 23:29:28.826869 135819264 http.cpp:333] HTTP POST for /master/api/v1/scheduler from 192.168.29.132:56913
W0902 23:29:28.831881 135282688 scheduler.cpp:381] Received '503 Service Unavailable' () for SUBSCRIBE
{code}
[~ijimenez] [~vinodkone]
was (Author: anandmazumdar):
Was able to reproduce this once on my machine. But the issue is not the same as the one seen on ASF build though as per logs. So we still need to dig around for what the issue on ASF test-run was.
In my test run, there is a race between the master successfully recovering its state from registry and the scheduler sending a call. In this case, we just log the error and leave it upon the framework to retry the call.
{code}
I0902 23:29:28.815498 113774592 leveldb.cpp:438] Reading position from leveldb took 32us
I0902 23:29:28.826355 136355840 registrar.cpp:344] Successfully fetched the registry (0B) in 16.811008ms
I0902 23:29:28.826472 136355840 registrar.cpp:443] Applied 1 operations in 35us; attempting to update the 'registry'
I0902 23:29:28.826869 135819264 http.cpp:333] HTTP POST for /master/api/v1/scheduler from 192.168.29.132:56913
W0902 23:29:28.831881 135282688 scheduler.cpp:381] Received '503 Service Unavailable' () for SUBSCRIBE
{code}
[~ijimenez] [~vinodkone]
> 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)