[
https://issues.apache.org/jira/browse/MESOS-1802?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15115532#comment-15115532
]
Greg Mann commented on MESOS-1802:
----------------------------------
Looks like this is still an issue. Just saw this on the ASF CI, Ubuntu 14.04
with gcc:
{code}
[ RUN ] HealthCheckTest.HealthStatusChange
I0125 15:22:26.282974 31962 leveldb.cpp:174] Opened db in 83.974532ms
I0125 15:22:26.329022 31962 leveldb.cpp:181] Compacted db in 45.96014ms
I0125 15:22:26.329654 31962 leveldb.cpp:196] Created db iterator in 28398ns
I0125 15:22:26.330154 31962 leveldb.cpp:202] Seeked to beginning of db in 4095ns
I0125 15:22:26.330663 31962 leveldb.cpp:271] Iterated through 0 keys in the db
in 468ns
I0125 15:22:26.331181 31962 replica.cpp:779] Replica recovered with log
positions 0 -> 0 with 1 holes and 0 unlearned
I0125 15:22:26.332582 31988 recover.cpp:447] Starting replica recovery
I0125 15:22:26.333237 31991 recover.cpp:473] Replica is in EMPTY status
I0125 15:22:26.336228 31993 replica.cpp:673] Replica in EMPTY status received a
broadcasted recover request from (2239)@172.17.0.2:52355
I0125 15:22:26.336789 31992 recover.cpp:193] Received a recover response from a
replica in EMPTY status
I0125 15:22:26.338047 31992 recover.cpp:564] Updating replica status to STARTING
I0125 15:22:26.350210 31982 master.cpp:374] Master
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be (6a3fa6c4588a) started on 172.17.0.2:52355
I0125 15:22:26.350651 31982 master.cpp:376] Flags at startup: --acls=""
--allocation_interval="1secs" --allocator="HierarchicalDRF"
--authenticate="true" --authenticate_http="true" --authenticate_slaves="true"
--authenticators="crammd5" --authorizers="local"
--credentials="/tmp/inJ0ZL/credentials" --framework_sorter="drf" --help="false"
--hostname_lookup="true" --http_authenticators="basic"
--initialize_driver_logging="true" --log_auto_initialize="true"
--logbufsecs="0" --logging_level="INFO" --max_completed_frameworks="50"
--max_completed_tasks_per_framework="1000" --max_slave_ping_timeouts="5"
--quiet="false" --recovery_slave_removal_limit="100%"
--registry="replicated_log" --registry_fetch_timeout="1mins"
--registry_store_timeout="25secs" --registry_strict="true"
--root_submissions="true" --slave_ping_timeout="15secs"
--slave_reregister_timeout="10mins" --user_sorter="drf" --version="false"
--webui_dir="/mesos/mesos-0.27.0/_inst/share/mesos/webui"
--work_dir="/tmp/inJ0ZL/master" --zk_session_timeout="10secs"
I0125 15:22:26.352558 31982 master.cpp:421] Master only allowing authenticated
frameworks to register
I0125 15:22:26.352833 31982 master.cpp:426] Master only allowing authenticated
slaves to register
I0125 15:22:26.353160 31982 credentials.hpp:35] Loading credentials for
authentication from '/tmp/inJ0ZL/credentials'
I0125 15:22:26.356725 31982 master.cpp:466] Using default 'crammd5'
authenticator
I0125 15:22:26.357357 31982 master.cpp:535] Using default 'basic' HTTP
authenticator
I0125 15:22:26.357851 31982 master.cpp:569] Authorization enabled
I0125 15:22:26.359246 31986 hierarchical.cpp:144] Initialized hierarchical
allocator process
I0125 15:22:26.359474 31992 whitelist_watcher.cpp:77] No whitelist given
I0125 15:22:26.364750 31991 leveldb.cpp:304] Persisting metadata (8 bytes) to
leveldb took 25.971673ms
I0125 15:22:26.365209 31991 replica.cpp:320] Persisted replica status to
STARTING
I0125 15:22:26.365898 31991 recover.cpp:473] Replica is in STARTING status
I0125 15:22:26.369220 31993 replica.cpp:673] Replica in STARTING status
received a broadcasted recover request from (2241)@172.17.0.2:52355
I0125 15:22:26.370393 31991 recover.cpp:193] Received a recover response from a
replica in STARTING status
I0125 15:22:26.371255 31993 recover.cpp:564] Updating replica status to VOTING
I0125 15:22:26.372786 31982 master.cpp:1710] The newly elected leader is
[email protected]:52355 with id 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be
I0125 15:22:26.373251 31982 master.cpp:1723] Elected as the leading master!
I0125 15:22:26.373553 31982 master.cpp:1468] Recovering from registrar
I0125 15:22:26.374184 31991 registrar.cpp:307] Recovering registrar
I0125 15:22:26.398006 31993 leveldb.cpp:304] Persisting metadata (8 bytes) to
leveldb took 26.052513ms
I0125 15:22:26.398576 31993 replica.cpp:320] Persisted replica status to VOTING
I0125 15:22:26.399235 31982 recover.cpp:578] Successfully joined the Paxos group
I0125 15:22:26.399518 31982 recover.cpp:462] Recover process terminated
I0125 15:22:26.400599 31993 log.cpp:659] Attempting to start the writer
I0125 15:22:26.402815 31992 replica.cpp:493] Replica received implicit promise
request from (2242)@172.17.0.2:52355 with proposal 1
I0125 15:22:26.423198 31992 leveldb.cpp:304] Persisting metadata (8 bytes) to
leveldb took 19.954945ms
I0125 15:22:26.423651 31992 replica.cpp:342] Persisted promised to 1
I0125 15:22:26.425547 31992 coordinator.cpp:238] Coordinator attempting to fill
missing positions
I0125 15:22:26.427817 31993 replica.cpp:388] Replica received explicit promise
request from (2243)@172.17.0.2:52355 for position 0 with proposal 2
I0125 15:22:26.448343 31993 leveldb.cpp:341] Persisting action (8 bytes) to
leveldb took 20.029847ms
I0125 15:22:26.448870 31993 replica.cpp:712] Persisted action at 0
I0125 15:22:26.450934 31995 replica.cpp:537] Replica received write request for
position 0 from (2244)@172.17.0.2:52355
I0125 15:22:26.451378 31995 leveldb.cpp:436] Reading position from leveldb took
118656ns
I0125 15:22:26.473486 31995 leveldb.cpp:341] Persisting action (14 bytes) to
leveldb took 21.791896ms
I0125 15:22:26.473932 31995 replica.cpp:712] Persisted action at 0
I0125 15:22:26.475330 31995 replica.cpp:691] Replica received learned notice
for position 0 from @0.0.0.0:0
I0125 15:22:26.498622 31995 leveldb.cpp:341] Persisting action (16 bytes) to
leveldb took 22.966725ms
I0125 15:22:26.499091 31995 replica.cpp:712] Persisted action at 0
I0125 15:22:26.499519 31995 replica.cpp:697] Replica learned NOP action at
position 0
I0125 15:22:26.501288 31994 log.cpp:675] Writer started with ending position 0
I0125 15:22:26.503401 31994 leveldb.cpp:436] Reading position from leveldb took
64755ns
I0125 15:22:26.505323 31986 registrar.cpp:340] Successfully fetched the
registry (0B) in 130.733056ms
I0125 15:22:26.505962 31986 registrar.cpp:439] Applied 1 operations in 57111ns;
attempting to update the 'registry'
I0125 15:22:26.507951 31994 log.cpp:683] Attempting to append 170 bytes to the
log
I0125 15:22:26.508689 31981 coordinator.cpp:348] Coordinator attempting to
write APPEND action at position 1
I0125 15:22:26.510378 31994 replica.cpp:537] Replica received write request for
position 1 from (2245)@172.17.0.2:52355
I0125 15:22:26.532110 31994 leveldb.cpp:341] Persisting action (189 bytes) to
leveldb took 21.385759ms
I0125 15:22:26.532683 31994 replica.cpp:712] Persisted action at 1
I0125 15:22:26.534441 31987 replica.cpp:691] Replica received learned notice
for position 1 from @0.0.0.0:0
I0125 15:22:26.557276 31987 leveldb.cpp:341] Persisting action (191 bytes) to
leveldb took 22.49124ms
I0125 15:22:26.557835 31987 replica.cpp:712] Persisted action at 1
I0125 15:22:26.558156 31987 replica.cpp:697] Replica learned APPEND action at
position 1
I0125 15:22:26.560673 31987 registrar.cpp:484] Successfully updated the
'registry' in 54.236928ms
I0125 15:22:26.561043 31984 log.cpp:702] Attempting to truncate the log to 1
I0125 15:22:26.561795 31984 coordinator.cpp:348] Coordinator attempting to
write TRUNCATE action at position 2
I0125 15:22:26.563083 31984 replica.cpp:537] Replica received write request for
position 2 from (2246)@172.17.0.2:52355
I0125 15:22:26.563714 31987 registrar.cpp:370] Successfully recovered registrar
I0125 15:22:26.564749 31987 master.cpp:1520] Recovered 0 slaves from the
Registry (131B) ; allowing 10mins for slaves to re-register
I0125 15:22:26.565105 31990 hierarchical.cpp:171] Skipping recovery of
hierarchical allocator: nothing to recover
I0125 15:22:26.588583 31984 leveldb.cpp:341] Persisting action (16 bytes) to
leveldb took 25.162931ms
I0125 15:22:26.589154 31984 replica.cpp:712] Persisted action at 2
I0125 15:22:26.590899 31984 replica.cpp:691] Replica received learned notice
for position 2 from @0.0.0.0:0
I0125 15:22:26.615885 31984 leveldb.cpp:341] Persisting action (18 bytes) to
leveldb took 24.588268ms
I0125 15:22:26.616564 31984 leveldb.cpp:399] Deleting ~1 keys from leveldb took
197510ns
I0125 15:22:26.616847 31984 replica.cpp:712] Persisted action at 2
I0125 15:22:26.617198 31984 replica.cpp:697] Replica learned TRUNCATE action at
position 2
I0125 15:22:26.623775 31962 containerizer.cpp:143] Using isolation:
posix/cpu,posix/mem,filesystem/posix
W0125 15:22:26.625557 31962 backend.cpp:48] Failed to create 'bind' backend:
BindBackend requires root privileges
I0125 15:22:26.646574 31985 slave.cpp:192] Slave started on 62)@172.17.0.2:52355
I0125 15:22:26.647231 31985 slave.cpp:193] 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"
--credential="/tmp/HealthCheckTest_HealthStatusChange_uxXuR2/credential"
--default_role="*" --disk_watch_interval="1mins" --docker="docker"
--docker_auth_server="https://auth.docker.io"; --docker_kill_orphans="true"
--docker_puller_timeout="60" --docker_registry="https://registry-1.docker.io";
--docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock"
--docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker"
--enforce_container_disk_quota="false" --executor_registration_timeout="1mins"
--executor_shutdown_grace_period="5secs"
--fetcher_cache_dir="/tmp/HealthCheckTest_HealthStatusChange_uxXuR2/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="posix/cpu,posix/mem"
--launcher_dir="/mesos/mesos-0.27.0/_build/src" --logbufsecs="0"
--logging_level="INFO" --oversubscribed_resources_interval="15secs"
--perf_duration="10secs" --perf_interval="1mins"
--qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect"
--recovery_timeout="15mins" --registration_backoff_factor="10ms"
--resources="cpus:2;mem:1024;disk:1024;ports:[31000-32000]"
--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/HealthCheckTest_HealthStatusChange_uxXuR2"
I0125 15:22:26.648396 31985 credentials.hpp:83] Loading credential for
authentication from '/tmp/HealthCheckTest_HealthStatusChange_uxXuR2/credential'
I0125 15:22:26.649049 31985 slave.cpp:323] Slave using credential for:
test-principal
I0125 15:22:26.649721 31985 resources.cpp:564] Parsing resources as JSON
failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000]
Trying semicolon-delimited string format instead
I0125 15:22:26.650990 31985 slave.cpp:463] Slave resources: cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0125 15:22:26.651430 31985 slave.cpp:471] Slave attributes: [ ]
I0125 15:22:26.651746 31985 slave.cpp:476] Slave hostname: 6a3fa6c4588a
I0125 15:22:26.654419 31996 state.cpp:58] Recovering state from
'/tmp/HealthCheckTest_HealthStatusChange_uxXuR2/meta'
I0125 15:22:26.655592 31996 status_update_manager.cpp:200] Recovering status
update manager
I0125 15:22:26.656435 31988 containerizer.cpp:390] Recovering containerizer
I0125 15:22:26.659112 31988 provisioner.cpp:245] Provisioner recovery complete
I0125 15:22:26.660279 31986 slave.cpp:4495] Finished recovery
I0125 15:22:26.661286 31986 slave.cpp:4667] Querying resource estimator for
oversubscribable resources
I0125 15:22:26.662472 31986 slave.cpp:795] New master detected at
[email protected]:52355
I0125 15:22:26.662765 31993 status_update_manager.cpp:174] Pausing sending
status updates
I0125 15:22:26.663326 31986 slave.cpp:858] Authenticating with master
[email protected]:52355
I0125 15:22:26.663650 31986 slave.cpp:863] Using default CRAM-MD5 authenticatee
I0125 15:22:26.664311 31992 authenticatee.cpp:121] Creating new client SASL
connection
I0125 15:22:26.665274 31987 master.cpp:5521] Authenticating
slave(62)@172.17.0.2:52355
I0125 15:22:26.665814 31987 authenticator.cpp:413] Starting authentication
session for crammd5_authenticatee(171)@172.17.0.2:52355
I0125 15:22:26.666512 31987 authenticator.cpp:98] Creating new server SASL
connection
I0125 15:22:26.668195 31986 slave.cpp:831] Detecting new master
I0125 15:22:26.668895 31992 authenticatee.cpp:212] Received SASL authentication
mechanisms: CRAM-MD5
I0125 15:22:26.669280 31992 authenticatee.cpp:238] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0125 15:22:26.669106 31986 slave.cpp:4681] Received oversubscribable resources
from the resource estimator
I0125 15:22:26.670027 31992 authenticator.cpp:203] Received SASL authentication
start
I0125 15:22:26.670344 31992 authenticator.cpp:325] Authentication requires more
steps
I0125 15:22:26.670738 31992 authenticatee.cpp:258] Received SASL authentication
step
I0125 15:22:26.671170 31992 authenticator.cpp:231] Received SASL authentication
step
I0125 15:22:26.671408 31992 auxprop.cpp:107] Request to lookup properties for
user: 'test-principal' realm: '6a3fa6c4588a' server FQDN: '6a3fa6c4588a'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
I0125 15:22:26.671649 31992 auxprop.cpp:179] Looking up auxiliary property
'*userPassword'
I0125 15:22:26.671952 31992 auxprop.cpp:179] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0125 15:22:26.672349 31992 auxprop.cpp:107] Request to lookup properties for
user: 'test-principal' realm: '6a3fa6c4588a' server FQDN: '6a3fa6c4588a'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
I0125 15:22:26.672575 31992 auxprop.cpp:129] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0125 15:22:26.672735 31992 auxprop.cpp:129] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0125 15:22:26.673010 31992 authenticator.cpp:317] Authentication success
I0125 15:22:26.673619 31992 authenticatee.cpp:298] Authentication success
I0125 15:22:26.673836 31991 master.cpp:5551] Successfully authenticated
principal 'test-principal' at slave(62)@172.17.0.2:52355
I0125 15:22:26.673940 31982 authenticator.cpp:431] Authentication session
cleanup for crammd5_authenticatee(171)@172.17.0.2:52355
I0125 15:22:26.675019 31992 slave.cpp:926] Successfully authenticated with
master [email protected]:52355
I0125 15:22:26.675532 31992 slave.cpp:1320] Will retry registration in
17.342244ms if necessary
I0125 15:22:26.675969 31984 master.cpp:4235] Registering slave at
slave(62)@172.17.0.2:52355 (6a3fa6c4588a) with id
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-S0
I0125 15:22:26.676969 31984 registrar.cpp:439] Applied 1 operations in 85189ns;
attempting to update the 'registry'
I0125 15:22:26.678900 31984 log.cpp:683] Attempting to append 339 bytes to the
log
I0125 15:22:26.679414 31990 coordinator.cpp:348] Coordinator attempting to
write APPEND action at position 3
I0125 15:22:26.680824 31990 replica.cpp:537] Replica received write request for
position 3 from (2260)@172.17.0.2:52355
I0125 15:22:26.685106 31962 sched.cpp:164] Version: 0.27.0
I0125 15:22:26.686100 31982 sched.cpp:268] New master detected at
[email protected]:52355
I0125 15:22:26.686529 31982 sched.cpp:324] Authenticating with master
[email protected]:52355
I0125 15:22:26.686744 31982 sched.cpp:331] Using default CRAM-MD5 authenticatee
I0125 15:22:26.687468 31982 authenticatee.cpp:121] Creating new client SASL
connection
I0125 15:22:26.688256 31987 master.cpp:5521] Authenticating
[email protected]:52355
I0125 15:22:26.688662 31984 authenticator.cpp:413] Starting authentication
session for crammd5_authenticatee(172)@172.17.0.2:52355
I0125 15:22:26.689288 31988 authenticator.cpp:98] Creating new server SASL
connection
I0125 15:22:26.690136 31982 authenticatee.cpp:212] Received SASL authentication
mechanisms: CRAM-MD5
I0125 15:22:26.690374 31982 authenticatee.cpp:238] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0125 15:22:26.690583 31982 authenticator.cpp:203] Received SASL authentication
start
I0125 15:22:26.690655 31982 authenticator.cpp:325] Authentication requires more
steps
I0125 15:22:26.690773 31996 authenticatee.cpp:258] Received SASL authentication
step
I0125 15:22:26.690978 31982 authenticator.cpp:231] Received SASL authentication
step
I0125 15:22:26.691009 31982 auxprop.cpp:107] Request to lookup properties for
user: 'test-principal' realm: '6a3fa6c4588a' server FQDN: '6a3fa6c4588a'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
I0125 15:22:26.691040 31982 auxprop.cpp:179] Looking up auxiliary property
'*userPassword'
I0125 15:22:26.691094 31982 auxprop.cpp:179] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0125 15:22:26.691155 31982 auxprop.cpp:107] Request to lookup properties for
user: 'test-principal' realm: '6a3fa6c4588a' server FQDN: '6a3fa6c4588a'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
I0125 15:22:26.691174 31982 auxprop.cpp:129] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0125 15:22:26.691201 31982 auxprop.cpp:129] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0125 15:22:26.691220 31982 authenticator.cpp:317] Authentication success
I0125 15:22:26.691395 31991 authenticatee.cpp:298] Authentication success
I0125 15:22:26.691468 31986 master.cpp:5551] Successfully authenticated
principal 'test-principal' at
[email protected]:52355
I0125 15:22:26.691907 31981 sched.cpp:413] Successfully authenticated with
master [email protected]:52355
I0125 15:22:26.691933 31981 sched.cpp:722] Sending SUBSCRIBE call to
[email protected]:52355
I0125 15:22:26.692033 31981 sched.cpp:755] Will retry registration in
49.26057ms if necessary
I0125 15:22:26.692239 31981 master.cpp:2278] Received SUBSCRIBE call for
framework 'default' at
[email protected]:52355
I0125 15:22:26.692302 31981 master.cpp:1749] Authorizing framework principal
'test-principal' to receive offers for role '*'
I0125 15:22:26.692577 31981 master.cpp:2349] Subscribing framework default with
checkpointing disabled and capabilities [ ]
I0125 15:22:26.693334 31986 sched.cpp:649] Framework registered with
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:26.693387 31986 sched.cpp:663] Scheduler::registered took 26089ns
I0125 15:22:26.693548 31981 hierarchical.cpp:265] Added framework
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:26.693622 31981 hierarchical.cpp:1355] No resources available to
allocate!
I0125 15:22:26.693662 31981 hierarchical.cpp:1450] No inverse offers to send
out!
I0125 15:22:26.693691 31981 hierarchical.cpp:1090] Performed allocation for 0
slaves in 123384ns
I0125 15:22:26.693852 31982 authenticator.cpp:431] Authentication session
cleanup for crammd5_authenticatee(172)@172.17.0.2:52355
I0125 15:22:26.700639 31989 slave.cpp:1320] Will retry registration in 839715ns
if necessary
I0125 15:22:26.701162 31989 master.cpp:4223] Ignoring register slave message
from slave(62)@172.17.0.2:52355 (6a3fa6c4588a) as admission is already in
progress
I0125 15:22:26.703377 31993 slave.cpp:1320] Will retry registration in
50.877167ms if necessary
I0125 15:22:26.703589 31993 master.cpp:4223] Ignoring register slave message
from slave(62)@172.17.0.2:52355 (6a3fa6c4588a) as admission is already in
progress
I0125 15:22:26.709228 31990 leveldb.cpp:341] Persisting action (358 bytes) to
leveldb took 28.107677ms
I0125 15:22:26.709779 31990 replica.cpp:712] Persisted action at 3
I0125 15:22:26.711303 31994 replica.cpp:691] Replica received learned notice
for position 3 from @0.0.0.0:0
I0125 15:22:26.741838 31994 leveldb.cpp:341] Persisting action (360 bytes) to
leveldb took 30.474075ms
I0125 15:22:26.742066 31994 replica.cpp:712] Persisted action at 3
I0125 15:22:26.742287 31994 replica.cpp:697] Replica learned APPEND action at
position 3
I0125 15:22:26.746264 31983 registrar.cpp:484] Successfully updated the
'registry' in 68.914944ms
I0125 15:22:26.746861 31983 log.cpp:702] Attempting to truncate the log to 3
I0125 15:22:26.748200 31981 coordinator.cpp:348] Coordinator attempting to
write TRUNCATE action at position 4
I0125 15:22:26.748806 31986 hierarchical.cpp:471] Added slave
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-S0 (6a3fa6c4588a) with cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
I0125 15:22:26.748986 31984 slave.cpp:970] Registered with master
[email protected]:52355; given slave ID 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-S0
I0125 15:22:26.750226 31984 fetcher.cpp:81] Clearing fetcher cache
I0125 15:22:26.750797 31984 slave.cpp:993] Checkpointing SlaveInfo to
'/tmp/HealthCheckTest_HealthStatusChange_uxXuR2/meta/slaves/8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-S0/slave.info'
I0125 15:22:26.750919 31995 status_update_manager.cpp:181] Resuming sending
status updates
I0125 15:22:26.751628 31984 slave.cpp:1029] Forwarding total oversubscribed
resources
I0125 15:22:26.751771 31984 slave.cpp:3435] Received ping from
slave-observer(59)@172.17.0.2:52355
I0125 15:22:26.753825 31986 hierarchical.cpp:1450] No inverse offers to send
out!
I0125 15:22:26.753902 31986 hierarchical.cpp:1110] Performed allocation for
slave 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-S0 in 4.623741ms
I0125 15:22:26.748070 31983 master.cpp:4303] Registered slave
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-S0 at slave(62)@172.17.0.2:52355
(6a3fa6c4588a) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0125 15:22:26.754299 31984 replica.cpp:537] Replica received write request for
position 4 from (2261)@172.17.0.2:52355
I0125 15:22:26.754783 31983 master.cpp:4644] Received update of slave
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-S0 at slave(62)@172.17.0.2:52355
(6a3fa6c4588a) with total oversubscribed resources
I0125 15:22:26.755764 31996 hierarchical.cpp:527] Slave
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-S0 (6a3fa6c4588a) updated with
oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000])
I0125 15:22:26.756073 31996 hierarchical.cpp:1355] No resources available to
allocate!
I0125 15:22:26.756146 31996 hierarchical.cpp:1450] No inverse offers to send
out!
I0125 15:22:26.756183 31996 hierarchical.cpp:1110] Performed allocation for
slave 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-S0 in 353455ns
I0125 15:22:26.756825 31983 master.cpp:5350] Sending 1 offers to framework
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 (default) at
[email protected]:52355
I0125 15:22:26.757510 31983 sched.cpp:819] Scheduler::resourceOffers took
172909ns
I0125 15:22:26.760304 31993 master.cpp:3136] Processing ACCEPT call for offers:
[ 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-O0 ] on slave
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-S0 at slave(62)@172.17.0.2:52355
(6a3fa6c4588a) for framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
(default) at [email protected]:52355
I0125 15:22:26.760391 31993 master.cpp:2823] Authorizing framework principal
'test-principal' to launch task 1 as user 'mesos'
I0125 15:22:26.763656 31993 master.hpp:176] Adding task 1 with resources
cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-S0 (6a3fa6c4588a)
I0125 15:22:26.764000 31993 master.cpp:3621] Launching task 1 of framework
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 (default) at
[email protected]:52355 with resources
cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-S0 at slave(62)@172.17.0.2:52355
(6a3fa6c4588a)
I0125 15:22:26.764678 31993 slave.cpp:1360] Got assigned task 1 for framework
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:26.765007 31993 resources.cpp:564] Parsing resources as JSON
failed: cpus:0.1;mem:32
Trying semicolon-delimited string format instead
I0125 15:22:26.766017 31993 slave.cpp:1479] Launching task 1 for framework
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:26.766172 31993 resources.cpp:564] Parsing resources as JSON
failed: cpus:0.1;mem:32
Trying semicolon-delimited string format instead
I0125 15:22:26.776538 31993 paths.cpp:472] Trying to chown
'/tmp/HealthCheckTest_HealthStatusChange_uxXuR2/slaves/8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-S0/frameworks/8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000/executors/1/runs/0e4ce8de-c0bb-4498-810e-b154badfc094'
to user 'mesos'
I0125 15:22:26.784256 31984 leveldb.cpp:341] Persisting action (16 bytes) to
leveldb took 29.869861ms
I0125 15:22:26.784363 31984 replica.cpp:712] Persisted action at 4
I0125 15:22:26.786635 31989 replica.cpp:691] Replica received learned notice
for position 4 from @0.0.0.0:0
I0125 15:22:26.789561 31993 slave.cpp:5281] Launching executor 1 of framework
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 with resources cpus(*):0.1; mem(*):32
in work directory
'/tmp/HealthCheckTest_HealthStatusChange_uxXuR2/slaves/8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-S0/frameworks/8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000/executors/1/runs/0e4ce8de-c0bb-4498-810e-b154badfc094'
I0125 15:22:26.790385 31985 containerizer.cpp:649] Starting container
'0e4ce8de-c0bb-4498-810e-b154badfc094' for executor '1' of framework
'8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000'
I0125 15:22:26.790431 31993 slave.cpp:1697] Queuing task '1' for executor '1'
of framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:26.791306 31993 slave.cpp:748] Successfully attached file
'/tmp/HealthCheckTest_HealthStatusChange_uxXuR2/slaves/8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-S0/frameworks/8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000/executors/1/runs/0e4ce8de-c0bb-4498-810e-b154badfc094'
I0125 15:22:26.797827 31985 launcher.cpp:132] Forked child with pid '4766' for
container '0e4ce8de-c0bb-4498-810e-b154badfc094'
I0125 15:22:26.818343 31989 leveldb.cpp:341] Persisting action (18 bytes) to
leveldb took 31.617937ms
I0125 15:22:26.819110 31989 leveldb.cpp:399] Deleting ~2 keys from leveldb took
169424ns
I0125 15:22:26.819483 31989 replica.cpp:712] Persisted action at 4
I0125 15:22:26.819918 31989 replica.cpp:697] Replica learned TRUNCATE action at
position 4
I0125 15:22:27.212316 31988 slave.cpp:2642] Got registration for executor '1'
of framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 from
executor(1)@172.17.0.2:56551
I0125 15:22:27.217492 31996 slave.cpp:1862] Sending queued task '1' to executor
'1' of framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 at
executor(1)@172.17.0.2:56551
I0125 15:22:27.254505 31982 slave.cpp:3001] Handling status update TASK_RUNNING
(UUID: c14708bc-7cdb-47be-ae75-0d1bd8bd1561) for task 1 of framework
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 from executor(1)@172.17.0.2:56551
I0125 15:22:27.255272 31982 status_update_manager.cpp:320] Received status
update TASK_RUNNING (UUID: c14708bc-7cdb-47be-ae75-0d1bd8bd1561) for task 1 of
framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:27.255687 31982 status_update_manager.cpp:497] Creating
StatusUpdate stream for task 1 of framework
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:27.256330 31982 status_update_manager.cpp:374] Forwarding update
TASK_RUNNING (UUID: c14708bc-7cdb-47be-ae75-0d1bd8bd1561) for task 1 of
framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 to the slave
I0125 15:22:27.257153 31982 slave.cpp:3353] Forwarding the update TASK_RUNNING
(UUID: c14708bc-7cdb-47be-ae75-0d1bd8bd1561) for task 1 of framework
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 to [email protected]:52355
I0125 15:22:27.258007 31994 master.cpp:4789] Status update TASK_RUNNING (UUID:
c14708bc-7cdb-47be-ae75-0d1bd8bd1561) for task 1 of framework
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 from slave
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-S0 at slave(62)@172.17.0.2:52355
(6a3fa6c4588a)
I0125 15:22:27.258328 31994 master.cpp:4837] Forwarding status update
TASK_RUNNING (UUID: c14708bc-7cdb-47be-ae75-0d1bd8bd1561) for task 1 of
framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:27.258908 31990 sched.cpp:927] Scheduler::statusUpdate took 131399ns
I0125 15:22:27.259495 31994 master.cpp:6445] Updating the state of task 1 of
framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 (latest state:
TASK_RUNNING, status update state: TASK_RUNNING)
I0125 15:22:27.260234 31994 master.cpp:3947] Processing ACKNOWLEDGE call
c14708bc-7cdb-47be-ae75-0d1bd8bd1561 for task 1 of framework
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 (default) at
[email protected]:52355 on slave
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-S0
I0125 15:22:27.260895 31982 slave.cpp:3247] Status update manager successfully
handled status update TASK_RUNNING (UUID: c14708bc-7cdb-47be-ae75-0d1bd8bd1561)
for task 1 of framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:27.261179 31982 slave.cpp:3263] Sending acknowledgement for status
update TASK_RUNNING (UUID: c14708bc-7cdb-47be-ae75-0d1bd8bd1561) for task 1 of
framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 to
executor(1)@172.17.0.2:56551
I0125 15:22:27.261868 31982 status_update_manager.cpp:392] Received status
update acknowledgement (UUID: c14708bc-7cdb-47be-ae75-0d1bd8bd1561) for task 1
of framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:27.262595 31982 slave.cpp:2411] Status update manager successfully
handled status update acknowledgement (UUID:
c14708bc-7cdb-47be-ae75-0d1bd8bd1561) for task 1 of framework
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:27.361070 31986 hierarchical.cpp:1355] No resources available to
allocate!
I0125 15:22:27.361371 31986 hierarchical.cpp:1450] No inverse offers to send
out!
I0125 15:22:27.361552 31986 hierarchical.cpp:1090] Performed allocation for 1
slaves in 826625ns
I0125 15:22:27.604053 31986 slave.cpp:3001] Handling status update TASK_RUNNING
(UUID: 0d1cba72-f04b-4623-bd93-49fd10d02e18) for task 1 in health state healthy
of framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 from
executor(1)@172.17.0.2:56551
I0125 15:22:27.605211 31981 status_update_manager.cpp:320] Received status
update TASK_RUNNING (UUID: 0d1cba72-f04b-4623-bd93-49fd10d02e18) for task 1 in
health state healthy of framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:27.605792 31981 status_update_manager.cpp:374] Forwarding update
TASK_RUNNING (UUID: 0d1cba72-f04b-4623-bd93-49fd10d02e18) for task 1 in health
state healthy of framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 to the
slave
I0125 15:22:27.606716 31981 slave.cpp:3353] Forwarding the update TASK_RUNNING
(UUID: 0d1cba72-f04b-4623-bd93-49fd10d02e18) for task 1 in health state healthy
of framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 to
[email protected]:52355
I0125 15:22:27.607311 31981 slave.cpp:3247] Status update manager successfully
handled status update TASK_RUNNING (UUID: 0d1cba72-f04b-4623-bd93-49fd10d02e18)
for task 1 in health state healthy of framework
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:27.608062 31981 slave.cpp:3263] Sending acknowledgement for status
update TASK_RUNNING (UUID: 0d1cba72-f04b-4623-bd93-49fd10d02e18) for task 1 in
health state healthy of framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 to
executor(1)@172.17.0.2:56551
I0125 15:22:27.607839 31983 master.cpp:4789] Status update TASK_RUNNING (UUID:
0d1cba72-f04b-4623-bd93-49fd10d02e18) for task 1 in health state healthy of
framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 from slave
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-S0 at slave(62)@172.17.0.2:52355
(6a3fa6c4588a)
I0125 15:22:27.608814 31983 master.cpp:4837] Forwarding status update
TASK_RUNNING (UUID: 0d1cba72-f04b-4623-bd93-49fd10d02e18) for task 1 in health
state healthy of framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:27.609424 31983 master.cpp:6445] Updating the state of task 1 of
framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 (latest state:
TASK_RUNNING, status update state: TASK_RUNNING)
I0125 15:22:27.610005 31990 sched.cpp:927] Scheduler::statusUpdate took 136834ns
I0125 15:22:27.611498 31990 master.cpp:3947] Processing ACKNOWLEDGE call
0d1cba72-f04b-4623-bd93-49fd10d02e18 for task 1 of framework
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 (default) at
[email protected]:52355 on slave
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-S0
I0125 15:22:27.612169 31990 status_update_manager.cpp:392] Received status
update acknowledgement (UUID: 0d1cba72-f04b-4623-bd93-49fd10d02e18) for task 1
of framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:27.612839 31990 slave.cpp:2411] Status update manager successfully
handled status update acknowledgement (UUID:
0d1cba72-f04b-4623-bd93-49fd10d02e18) for task 1 of framework
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:27.621296 31987 process.cpp:3141] Handling HTTP event for process
'master' with path: '/master/state'
I0125 15:22:27.622369 31987 http.cpp:503] HTTP GET for /master/state from
172.17.0.2:35405
I0125 15:22:27.635979 31993 process.cpp:3141] Handling HTTP event for process
'slave(62)' with path: '/slave(62)/state'
I0125 15:22:27.636605 31993 http.cpp:190] HTTP GET for /slave(62)/state from
172.17.0.2:35406
I0125 15:22:27.723979 31985 slave.cpp:3001] Handling status update TASK_RUNNING
(UUID: 652cd5e4-98fb-4050-8778-b8fb47bee8c1) for task 1 in health state
unhealthy of framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 from
executor(1)@172.17.0.2:56551
I0125 15:22:27.725005 31982 status_update_manager.cpp:320] Received status
update TASK_RUNNING (UUID: 652cd5e4-98fb-4050-8778-b8fb47bee8c1) for task 1 in
health state unhealthy of framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:27.725406 31982 status_update_manager.cpp:374] Forwarding update
TASK_RUNNING (UUID: 652cd5e4-98fb-4050-8778-b8fb47bee8c1) for task 1 in health
state unhealthy of framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 to the
slave
I0125 15:22:27.726119 31985 slave.cpp:3353] Forwarding the update TASK_RUNNING
(UUID: 652cd5e4-98fb-4050-8778-b8fb47bee8c1) for task 1 in health state
unhealthy of framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 to
[email protected]:52355
I0125 15:22:27.726804 31991 master.cpp:4789] Status update TASK_RUNNING (UUID:
652cd5e4-98fb-4050-8778-b8fb47bee8c1) for task 1 in health state unhealthy of
framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 from slave
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-S0 at slave(62)@172.17.0.2:52355
(6a3fa6c4588a)
I0125 15:22:27.726954 31991 master.cpp:4837] Forwarding status update
TASK_RUNNING (UUID: 652cd5e4-98fb-4050-8778-b8fb47bee8c1) for task 1 in health
state unhealthy of framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:27.727339 31991 master.cpp:6445] Updating the state of task 1 of
framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 (latest state:
TASK_RUNNING, status update state: TASK_RUNNING)
I0125 15:22:27.727805 31986 sched.cpp:927] Scheduler::statusUpdate took 133105ns
I0125 15:22:27.728729 31991 master.cpp:3947] Processing ACKNOWLEDGE call
652cd5e4-98fb-4050-8778-b8fb47bee8c1 for task 1 of framework
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 (default) at
[email protected]:52355 on slave
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-S0
I0125 15:22:27.729161 31985 slave.cpp:3247] Status update manager successfully
handled status update TASK_RUNNING (UUID: 652cd5e4-98fb-4050-8778-b8fb47bee8c1)
for task 1 in health state unhealthy of framework
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:27.729310 31985 slave.cpp:3263] Sending acknowledgement for status
update TASK_RUNNING (UUID: 652cd5e4-98fb-4050-8778-b8fb47bee8c1) for task 1 in
health state unhealthy of framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
to executor(1)@172.17.0.2:56551
I0125 15:22:27.730073 31986 status_update_manager.cpp:392] Received status
update acknowledgement (UUID: 652cd5e4-98fb-4050-8778-b8fb47bee8c1) for task 1
of framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:27.730661 31985 slave.cpp:2411] Status update manager successfully
handled status update acknowledgement (UUID:
652cd5e4-98fb-4050-8778-b8fb47bee8c1) for task 1 of framework
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:27.736881 31991 process.cpp:3141] Handling HTTP event for process
'master' with path: '/master/state'
I0125 15:22:27.737740 31991 http.cpp:503] HTTP GET for /master/state from
172.17.0.2:35410
I0125 15:22:27.798907 31987 process.cpp:3141] Handling HTTP event for process
'slave(62)' with path: '/slave(62)/state'
I0125 15:22:27.800882 31987 http.cpp:190] HTTP GET for /slave(62)/state from
172.17.0.2:35411
I0125 15:22:27.860637 31995 slave.cpp:3001] Handling status update TASK_RUNNING
(UUID: 43e96c29-fc0f-4eb0-9e49-5c8c36c146d4) for task 1 in health state healthy
of framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 from
executor(1)@172.17.0.2:56551
I0125 15:22:27.861495 31995 status_update_manager.cpp:320] Received status
update TASK_RUNNING (UUID: 43e96c29-fc0f-4eb0-9e49-5c8c36c146d4) for task 1 in
health state healthy of framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:27.861948 31995 status_update_manager.cpp:374] Forwarding update
TASK_RUNNING (UUID: 43e96c29-fc0f-4eb0-9e49-5c8c36c146d4) for task 1 in health
state healthy of framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 to the
slave
I0125 15:22:27.862629 31995 slave.cpp:3353] Forwarding the update TASK_RUNNING
(UUID: 43e96c29-fc0f-4eb0-9e49-5c8c36c146d4) for task 1 in health state healthy
of framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 to
[email protected]:52355
I0125 15:22:27.863328 31995 slave.cpp:3247] Status update manager successfully
handled status update TASK_RUNNING (UUID: 43e96c29-fc0f-4eb0-9e49-5c8c36c146d4)
for task 1 in health state healthy of framework
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:27.863790 31989 master.cpp:4789] Status update TASK_RUNNING (UUID:
43e96c29-fc0f-4eb0-9e49-5c8c36c146d4) for task 1 in health state healthy of
framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 from slave
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-S0 at slave(62)@172.17.0.2:52355
(6a3fa6c4588a)
I0125 15:22:27.864204 31989 master.cpp:4837] Forwarding status update
TASK_RUNNING (UUID: 43e96c29-fc0f-4eb0-9e49-5c8c36c146d4) for task 1 in health
state healthy of framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:27.864610 31989 master.cpp:6445] Updating the state of task 1 of
framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 (latest state:
TASK_RUNNING, status update state: TASK_RUNNING)
I0125 15:22:27.866212 31989 sched.cpp:927] Scheduler::statusUpdate took
1.126092ms
I0125 15:22:27.866664 31989 master.cpp:3947] Processing ACKNOWLEDGE call
43e96c29-fc0f-4eb0-9e49-5c8c36c146d4 for task 1 of framework
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 (default) at
[email protected]:52355 on slave
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-S0
I0125 15:22:27.864078 31995 slave.cpp:3263] Sending acknowledgement for status
update TASK_RUNNING (UUID: 43e96c29-fc0f-4eb0-9e49-5c8c36c146d4) for task 1 in
health state healthy of framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 to
executor(1)@172.17.0.2:56551
I0125 15:22:27.867688 31995 status_update_manager.cpp:392] Received status
update acknowledgement (UUID: 43e96c29-fc0f-4eb0-9e49-5c8c36c146d4) for task 1
of framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:27.868309 31995 slave.cpp:2411] Status update manager successfully
handled status update acknowledgement (UUID:
43e96c29-fc0f-4eb0-9e49-5c8c36c146d4) for task 1 of framework
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:27.900404 31987 process.cpp:3141] Handling HTTP event for process
'master' with path: '/master/state'
I0125 15:22:27.900969 31987 http.cpp:503] HTTP GET for /master/state from
172.17.0.2:35413
I0125 15:22:27.979339 31989 slave.cpp:3001] Handling status update TASK_RUNNING
(UUID: 80d4fae5-4d58-4441-9bab-7fc118d66c6b) for task 1 in health state
unhealthy of framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 from
executor(1)@172.17.0.2:56551
I0125 15:22:27.979832 31989 status_update_manager.cpp:320] Received status
update TASK_RUNNING (UUID: 80d4fae5-4d58-4441-9bab-7fc118d66c6b) for task 1 in
health state unhealthy of framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:27.980032 31989 status_update_manager.cpp:374] Forwarding update
TASK_RUNNING (UUID: 80d4fae5-4d58-4441-9bab-7fc118d66c6b) for task 1 in health
state unhealthy of framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 to the
slave
I0125 15:22:27.982230 31996 slave.cpp:3353] Forwarding the update TASK_RUNNING
(UUID: 80d4fae5-4d58-4441-9bab-7fc118d66c6b) for task 1 in health state
unhealthy of framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 to
[email protected]:52355
I0125 15:22:27.982642 31996 slave.cpp:3247] Status update manager successfully
handled status update TASK_RUNNING (UUID: 80d4fae5-4d58-4441-9bab-7fc118d66c6b)
for task 1 in health state unhealthy of framework
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:27.982692 31996 slave.cpp:3263] Sending acknowledgement for status
update TASK_RUNNING (UUID: 80d4fae5-4d58-4441-9bab-7fc118d66c6b) for task 1 in
health state unhealthy of framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
to executor(1)@172.17.0.2:56551
I0125 15:22:27.983098 31996 master.cpp:4789] Status update TASK_RUNNING (UUID:
80d4fae5-4d58-4441-9bab-7fc118d66c6b) for task 1 in health state unhealthy of
framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 from slave
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-S0 at slave(62)@172.17.0.2:52355
(6a3fa6c4588a)
I0125 15:22:27.983160 31996 master.cpp:4837] Forwarding status update
TASK_RUNNING (UUID: 80d4fae5-4d58-4441-9bab-7fc118d66c6b) for task 1 in health
state unhealthy of framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:27.983333 31996 master.cpp:6445] Updating the state of task 1 of
framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 (latest state:
TASK_RUNNING, status update state: TASK_RUNNING)
../../src/tests/health_check_tests.cpp:529: Failure
Mock function called more times than expected - returning directly.
Function call: statusUpdate(0x7fffa28454b0, @0x2abda2aab650 112-byte object
<70-5E E8-97 BD-2A 00-00 00-00 00-00 00-00 00-00 80-A5 00-E4 BD-2A 00-00 70-5E
0D-02 00-00 00-00 01-00 00-00 02-00 00-00 70-5E 0D-02 00-00 00-00 50-A5 00-E4
BD-2A 00-00 00-37 00-E4 BD-2A 00-00 00-00 00-00 00-2A 00-00 C4-0A FA-6C 8F-A9
D5-41 30-37 00-E4 BD-2A 00-00 00-00 00-00 00-00 00-00 C0-3C 00-E4 BD-2A 00-00
00-00 00-00 CB-17 00-00>)
Expected: to be called 4 times
Actual: called 5 times - over-saturated and active
I0125 15:22:27.983691 31996 sched.cpp:927] Scheduler::statusUpdate took 187029ns
I0125 15:22:27.983927 31996 master.cpp:3947] Processing ACKNOWLEDGE call
80d4fae5-4d58-4441-9bab-7fc118d66c6b for task 1 of framework
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 (default) at
[email protected]:52355 on slave
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-S0
I0125 15:22:27.984235 31996 status_update_manager.cpp:392] Received status
update acknowledgement (UUID: 80d4fae5-4d58-4441-9bab-7fc118d66c6b) for task 1
of framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:27.984541 31996 slave.cpp:2411] Status update manager successfully
handled status update acknowledgement (UUID:
80d4fae5-4d58-4441-9bab-7fc118d66c6b) for task 1 of framework
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:27.985502 31993 process.cpp:3141] Handling HTTP event for process
'slave(62)' with path: '/slave(62)/state'
I0125 15:22:27.986088 31993 http.cpp:190] HTTP GET for /slave(62)/state from
172.17.0.2:35416
I0125 15:22:28.028769 31985 slave.cpp:3001] Handling status update TASK_RUNNING
(UUID: dce2e149-f1fd-40db-8def-f9d8627d71ee) for task 1 in health state healthy
of framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 from
executor(1)@172.17.0.2:56551
I0125 15:22:28.031385 31985 status_update_manager.cpp:320] Received status
update TASK_RUNNING (UUID: dce2e149-f1fd-40db-8def-f9d8627d71ee) for task 1 in
health state healthy of framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:28.031640 31985 status_update_manager.cpp:374] Forwarding update
TASK_RUNNING (UUID: dce2e149-f1fd-40db-8def-f9d8627d71ee) for task 1 in health
state healthy of framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 to the
slave
I0125 15:22:28.033169 31985 slave.cpp:3353] Forwarding the update TASK_RUNNING
(UUID: dce2e149-f1fd-40db-8def-f9d8627d71ee) for task 1 in health state healthy
of framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 to
[email protected]:52355
I0125 15:22:28.033386 31985 slave.cpp:3247] Status update manager successfully
handled status update TASK_RUNNING (UUID: dce2e149-f1fd-40db-8def-f9d8627d71ee)
for task 1 in health state healthy of framework
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:28.033438 31985 slave.cpp:3263] Sending acknowledgement for status
update TASK_RUNNING (UUID: dce2e149-f1fd-40db-8def-f9d8627d71ee) for task 1 in
health state healthy of framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 to
executor(1)@172.17.0.2:56551
I0125 15:22:28.033969 31985 master.cpp:4789] Status update TASK_RUNNING (UUID:
dce2e149-f1fd-40db-8def-f9d8627d71ee) for task 1 in health state healthy of
framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 from slave
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-S0 at slave(62)@172.17.0.2:52355
(6a3fa6c4588a)
I0125 15:22:28.034020 31985 master.cpp:4837] Forwarding status update
TASK_RUNNING (UUID: dce2e149-f1fd-40db-8def-f9d8627d71ee) for task 1 in health
state healthy of framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:28.035220 31985 master.cpp:6445] Updating the state of task 1 of
framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 (latest state:
TASK_RUNNING, status update state: TASK_RUNNING)
../../src/tests/health_check_tests.cpp:529: Failure
Mock function called more times than expected - returning directly.
Function call: statusUpdate(0x7fffa28454b0, @0x2abda14a0650 112-byte object
<70-5E E8-97 BD-2A 00-00 00-00 00-00 00-00 00-00 C0-30 00-C8 BD-2A 00-00 70-5E
0D-02 00-00 00-00 01-00 00-00 02-00 00-00 70-5E 0D-02 00-00 00-00 B0-36 02-C8
BD-2A 00-00 20-31 00-C8 BD-2A 00-00 00-00 00-00 01-2A 00-00 87-A2 00-6D 8F-A9
D5-41 70-53 00-C8 BD-2A 00-00 00-00 00-00 00-00 00-00 D0-FE 01-C8 BD-2A 00-00
00-00 00-00 CB-17 00-00>)
Expected: to be called 4 times
Actual: called 6 times - over-saturated and active
I0125 15:22:28.035569 31985 sched.cpp:927] Scheduler::statusUpdate took 158172ns
I0125 15:22:28.035837 31985 master.cpp:3947] Processing ACKNOWLEDGE call
dce2e149-f1fd-40db-8def-f9d8627d71ee for task 1 of framework
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 (default) at
[email protected]:52355 on slave
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-S0
I0125 15:22:28.037189 31985 status_update_manager.cpp:392] Received status
update acknowledgement (UUID: dce2e149-f1fd-40db-8def-f9d8627d71ee) for task 1
of framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:28.037554 31985 slave.cpp:2411] Status update manager successfully
handled status update acknowledgement (UUID:
dce2e149-f1fd-40db-8def-f9d8627d71ee) for task 1 of framework
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
../../src/tests/health_check_tests.cpp:631: Failure
Value of: (find).get()
Actual: 16-byte object <05-00 00-00 01-7F 00-00 90-05 82-03 00-00 00-00>
Expected: true
Which is: true
I0125 15:22:28.052209 31962 sched.cpp:1851] Asked to stop the driver
I0125 15:22:28.061291 31993 sched.cpp:1089] Stopping framework
'8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000'
I0125 15:22:28.061614 31986 master.cpp:5921] Processing TEARDOWN call for
framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 (default) at
[email protected]:52355
I0125 15:22:28.061651 31986 master.cpp:5933] Removing framework
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 (default) at
[email protected]:52355
I0125 15:22:28.061858 31986 master.cpp:6445] Updating the state of task 1 of
framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 (latest state: TASK_KILLED,
status update state: TASK_KILLED)
I0125 15:22:28.062573 31986 master.cpp:6511] Removing task 1 with resources
cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 on slave
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-S0 at slave(62)@172.17.0.2:52355
(6a3fa6c4588a)
I0125 15:22:28.063097 31986 hierarchical.cpp:375] Deactivated framework
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:28.063694 31986 hierarchical.cpp:886] Recovered cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on slave
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-S0 from framework
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:28.063850 31986 hierarchical.cpp:326] Removed framework
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:28.063923 31986 slave.cpp:2078] Asked to shut down framework
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 by [email protected]:52355
I0125 15:22:28.063966 31986 slave.cpp:2103] Shutting down framework
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:28.064034 31986 slave.cpp:4128] Shutting down executor '1' of
framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 at
executor(1)@172.17.0.2:56551
I0125 15:22:28.065841 31984 master.cpp:1025] Master terminating
I0125 15:22:28.066727 31985 hierarchical.cpp:502] Removed slave
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-S0
I0125 15:22:28.074441 31984 slave.cpp:3481] [email protected]:52355 exited
W0125 15:22:28.074491 31984 slave.cpp:3484] Master disconnected! Waiting for a
new master to be elected
I0125 15:22:28.087342 31989 containerizer.cpp:1227] Destroying container
'0e4ce8de-c0bb-4498-810e-b154badfc094'
I0125 15:22:28.089411 31987 slave.cpp:3001] Handling status update TASK_KILLED
(UUID: 2b7bb0b4-b336-4a4b-8d86-aafb7a564442) for task 1 of framework
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 from executor(1)@172.17.0.2:56551
W0125 15:22:28.089488 31987 slave.cpp:3054] Ignoring status update TASK_KILLED
(UUID: 2b7bb0b4-b336-4a4b-8d86-aafb7a564442) for task 1 of framework
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 for terminating framework
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:28.120442 31991 slave.cpp:3481] executor(1)@172.17.0.2:56551 exited
I0125 15:22:28.184353 31996 containerizer.cpp:1443] Executor for container
'0e4ce8de-c0bb-4498-810e-b154badfc094' has exited
I0125 15:22:28.188390 31996 provisioner.cpp:306] Ignoring destroy request for
unknown container 0e4ce8de-c0bb-4498-810e-b154badfc094
I0125 15:22:28.188851 31996 slave.cpp:3816] Executor '1' of framework
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 terminated with signal Killed
I0125 15:22:28.188913 31996 slave.cpp:3920] Cleaning up executor '1' of
framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000 at
executor(1)@172.17.0.2:56551
I0125 15:22:28.189599 31996 slave.cpp:4008] Cleaning up framework
8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:28.189793 31996 gc.cpp:54] Scheduling
'/tmp/HealthCheckTest_HealthStatusChange_uxXuR2/slaves/8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-S0/frameworks/8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000/executors/1/runs/0e4ce8de-c0bb-4498-810e-b154badfc094'
for gc 6.99999781114667days in the future
I0125 15:22:28.189967 31996 gc.cpp:54] Scheduling
'/tmp/HealthCheckTest_HealthStatusChange_uxXuR2/slaves/8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-S0/frameworks/8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000/executors/1'
for gc 6.99999780626074days in the future
I0125 15:22:28.190261 31982 status_update_manager.cpp:282] Closing status
update streams for framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:28.190332 31982 status_update_manager.cpp:528] Cleaning up status
update stream for task 1 of framework 8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000
I0125 15:22:28.190115 31996 gc.cpp:54] Scheduling
'/tmp/HealthCheckTest_HealthStatusChange_uxXuR2/slaves/8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-S0/frameworks/8bd61c8a-63c9-4f67-99a4-d6ce2e3f77be-0000'
for gc 6.99999780428444days in the future
I0125 15:22:28.191551 31962 slave.cpp:667] Slave terminating
[ FAILED ] HealthCheckTest.HealthStatusChange (2002 ms)
{code}
> HealthCheckTest.HealthStatusChange is flaky on jenkins.
> -------------------------------------------------------
>
> Key: MESOS-1802
> URL: https://issues.apache.org/jira/browse/MESOS-1802
> Project: Mesos
> Issue Type: Bug
> Components: test
> Reporter: Benjamin Mahler
> Assignee: Timothy Chen
> Labels: flaky, mesosphere
>
> https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/2374/consoleFull
> {noformat}
> [ RUN ] HealthCheckTest.HealthStatusChange
> Using temporary directory '/tmp/HealthCheckTest_HealthStatusChange_IYnlu2'
> I0916 22:56:14.034612 21026 leveldb.cpp:176] Opened db in 2.155713ms
> I0916 22:56:14.034965 21026 leveldb.cpp:183] Compacted db in 332489ns
> I0916 22:56:14.034984 21026 leveldb.cpp:198] Created db iterator in 3710ns
> I0916 22:56:14.034996 21026 leveldb.cpp:204] Seeked to beginning of db in
> 642ns
> I0916 22:56:14.035006 21026 leveldb.cpp:273] Iterated through 0 keys in the
> db in 343ns
> I0916 22:56:14.035023 21026 replica.cpp:741] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0916 22:56:14.035200 21054 recover.cpp:425] Starting replica recovery
> I0916 22:56:14.035403 21041 recover.cpp:451] Replica is in EMPTY status
> I0916 22:56:14.035888 21045 replica.cpp:638] Replica in EMPTY status received
> a broadcasted recover request
> I0916 22:56:14.035969 21052 recover.cpp:188] Received a recover response from
> a replica in EMPTY status
> I0916 22:56:14.036118 21042 recover.cpp:542] Updating replica status to
> STARTING
> I0916 22:56:14.036603 21046 master.cpp:286] Master
> 20140916-225614-3125920579-47865-21026 (penates.apache.org) started on
> 67.195.81.186:47865
> I0916 22:56:14.036634 21046 master.cpp:332] Master only allowing
> authenticated frameworks to register
> I0916 22:56:14.036648 21046 master.cpp:337] Master only allowing
> authenticated slaves to register
> I0916 22:56:14.036659 21046 credentials.hpp:36] Loading credentials for
> authentication from
> '/tmp/HealthCheckTest_HealthStatusChange_IYnlu2/credentials'
> I0916 22:56:14.036686 21045 leveldb.cpp:306] Persisting metadata (8 bytes) to
> leveldb took 480322ns
> I0916 22:56:14.036700 21045 replica.cpp:320] Persisted replica status to
> STARTING
> I0916 22:56:14.036769 21046 master.cpp:366] Authorization enabled
> I0916 22:56:14.036826 21045 recover.cpp:451] Replica is in STARTING status
> I0916 22:56:14.036944 21052 master.cpp:120] No whitelist given. Advertising
> offers for all slaves
> I0916 22:56:14.036968 21049 hierarchical_allocator_process.hpp:299]
> Initializing hierarchical allocator process with master :
> [email protected]:47865
> I0916 22:56:14.037284 21054 replica.cpp:638] Replica in STARTING status
> received a broadcasted recover request
> I0916 22:56:14.037312 21046 master.cpp:1212] The newly elected leader is
> [email protected]:47865 with id 20140916-225614-3125920579-47865-21026
> I0916 22:56:14.037333 21046 master.cpp:1225] Elected as the leading master!
> I0916 22:56:14.037345 21046 master.cpp:1043] Recovering from registrar
> I0916 22:56:14.037504 21040 registrar.cpp:313] Recovering registrar
> I0916 22:56:14.037505 21053 recover.cpp:188] Received a recover response from
> a replica in STARTING status
> I0916 22:56:14.037681 21047 recover.cpp:542] Updating replica status to VOTING
> I0916 22:56:14.038072 21052 leveldb.cpp:306] Persisting metadata (8 bytes) to
> leveldb took 330251ns
> I0916 22:56:14.038087 21052 replica.cpp:320] Persisted replica status to
> VOTING
> I0916 22:56:14.038127 21053 recover.cpp:556] Successfully joined the Paxos
> group
> I0916 22:56:14.038202 21053 recover.cpp:440] Recover process terminated
> I0916 22:56:14.038364 21048 log.cpp:656] Attempting to start the writer
> I0916 22:56:14.038812 21053 replica.cpp:474] Replica received implicit
> promise request with proposal 1
> I0916 22:56:14.038925 21053 leveldb.cpp:306] Persisting metadata (8 bytes) to
> leveldb took 92623ns
> I0916 22:56:14.038944 21053 replica.cpp:342] Persisted promised to 1
> I0916 22:56:14.039201 21052 coordinator.cpp:230] Coordinator attemping to
> fill missing position
> I0916 22:56:14.039676 21047 replica.cpp:375] Replica received explicit
> promise request for position 0 with proposal 2
> I0916 22:56:14.039836 21047 leveldb.cpp:343] Persisting action (8 bytes) to
> leveldb took 144215ns
> I0916 22:56:14.039850 21047 replica.cpp:676] Persisted action at 0
> I0916 22:56:14.040243 21047 replica.cpp:508] Replica received write request
> for position 0
> I0916 22:56:14.040267 21047 leveldb.cpp:438] Reading position from leveldb
> took 10323ns
> I0916 22:56:14.040362 21047 leveldb.cpp:343] Persisting action (14 bytes) to
> leveldb took 79471ns
> I0916 22:56:14.040375 21047 replica.cpp:676] Persisted action at 0
> I0916 22:56:14.040556 21054 replica.cpp:655] Replica received learned notice
> for position 0
> I0916 22:56:14.040658 21054 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 83975ns
> I0916 22:56:14.040676 21054 replica.cpp:676] Persisted action at 0
> I0916 22:56:14.040689 21054 replica.cpp:661] Replica learned NOP action at
> position 0
> I0916 22:56:14.041023 21043 log.cpp:672] Writer started with ending position 0
> I0916 22:56:14.041342 21052 leveldb.cpp:438] Reading position from leveldb
> took 10642ns
> I0916 22:56:14.042325 21050 registrar.cpp:346] Successfully fetched the
> registry (0B)
> I0916 22:56:14.042346 21050 registrar.cpp:422] Attempting to update the
> 'registry'
> I0916 22:56:14.043306 21054 log.cpp:680] Attempting to append 140 bytes to
> the log
> I0916 22:56:14.043354 21050 coordinator.cpp:340] Coordinator attempting to
> write APPEND action at position 1
> I0916 22:56:14.043637 21047 replica.cpp:508] Replica received write request
> for position 1
> I0916 22:56:14.044042 21047 leveldb.cpp:343] Persisting action (159 bytes) to
> leveldb took 386690ns
> I0916 22:56:14.044057 21047 replica.cpp:676] Persisted action at 1
> I0916 22:56:14.044271 21040 replica.cpp:655] Replica received learned notice
> for position 1
> I0916 22:56:14.044435 21040 leveldb.cpp:343] Persisting action (161 bytes) to
> leveldb took 145186ns
> I0916 22:56:14.044448 21040 replica.cpp:676] Persisted action at 1
> I0916 22:56:14.044456 21040 replica.cpp:661] Replica learned APPEND action at
> position 1
> I0916 22:56:14.044729 21055 registrar.cpp:479] Successfully updated 'registry'
> I0916 22:56:14.044776 21047 log.cpp:699] Attempting to truncate the log to 1
> I0916 22:56:14.044795 21055 registrar.cpp:372] Successfully recovered
> registrar
> I0916 22:56:14.044831 21051 coordinator.cpp:340] Coordinator attempting to
> write TRUNCATE action at position 2
> I0916 22:56:14.044899 21053 master.cpp:1070] Recovered 0 slaves from the
> Registry (102B) ; allowing 10mins for slaves to re-register
> I0916 22:56:14.045133 21055 replica.cpp:508] Replica received write request
> for position 2
> I0916 22:56:14.045450 21055 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 300867ns
> I0916 22:56:14.045465 21055 replica.cpp:676] Persisted action at 2
> I0916 22:56:14.045725 21052 replica.cpp:655] Replica received learned notice
> for position 2
> I0916 22:56:14.045925 21052 leveldb.cpp:343] Persisting action (18 bytes) to
> leveldb took 182657ns
> I0916 22:56:14.045948 21052 leveldb.cpp:401] Deleting ~1 keys from leveldb
> took 10733ns
> I0916 22:56:14.045958 21052 replica.cpp:676] Persisted action at 2
> I0916 22:56:14.045964 21052 replica.cpp:661] Replica learned TRUNCATE action
> at position 2
> I0916 22:56:14.055306 21026 containerizer.cpp:89] Using isolation:
> posix/cpu,posix/mem
> I0916 22:56:14.057139 21048 slave.cpp:169] Slave started on
> 102)@67.195.81.186:47865
> I0916 22:56:14.057178 21048 credentials.hpp:84] Loading credential for
> authentication from
> '/tmp/HealthCheckTest_HealthStatusChange_cGKTiG/credential'
> I0916 22:56:14.057283 21048 slave.cpp:276] Slave using credential for:
> test-principal
> I0916 22:56:14.057354 21048 slave.cpp:289] Slave resources: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0916 22:56:14.057457 21048 slave.cpp:317] Slave hostname: penates.apache.org
> I0916 22:56:14.057468 21048 slave.cpp:318] Slave checkpoint: false
> I0916 22:56:14.057754 21043 state.cpp:33] Recovering state from
> '/tmp/HealthCheckTest_HealthStatusChange_cGKTiG/meta'
> I0916 22:56:14.057864 21042 status_update_manager.cpp:193] Recovering status
> update manager
> I0916 22:56:14.057958 21042 containerizer.cpp:252] Recovering containerizer
> I0916 22:56:14.058226 21042 slave.cpp:3219] Finished recovery
> I0916 22:56:14.058452 21047 slave.cpp:600] New master detected at
> [email protected]:47865
> I0916 22:56:14.058485 21047 slave.cpp:674] Authenticating with master
> [email protected]:47865
> I0916 22:56:14.058506 21042 status_update_manager.cpp:167] New master
> detected at [email protected]:47865
> I0916 22:56:14.058539 21047 slave.cpp:647] Detecting new master
> I0916 22:56:14.058555 21042 authenticatee.hpp:128] Creating new client SASL
> connection
> I0916 22:56:14.058656 21043 master.cpp:3653] Authenticating
> slave(102)@67.195.81.186:47865
> I0916 22:56:14.058737 21040 authenticator.hpp:156] Creating new server SASL
> connection
> I0916 22:56:14.058830 21047 authenticatee.hpp:219] Received SASL
> authentication mechanisms: CRAM-MD5
> I0916 22:56:14.058852 21047 authenticatee.hpp:245] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0916 22:56:14.058884 21047 authenticator.hpp:262] Received SASL
> authentication start
> I0916 22:56:14.058936 21047 authenticator.hpp:384] Authentication requires
> more steps
> I0916 22:56:14.058981 21047 authenticatee.hpp:265] Received SASL
> authentication step
> I0916 22:56:14.059052 21040 authenticator.hpp:290] Received SASL
> authentication step
> I0916 22:56:14.059074 21040 auxprop.cpp:81] Request to lookup properties for
> user: 'test-principal' realm: 'penates.apache.org' server FQDN:
> 'penates.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0916 22:56:14.059087 21040 auxprop.cpp:153] Looking up auxiliary property
> '*userPassword'
> I0916 22:56:14.059101 21040 auxprop.cpp:153] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0916 22:56:14.059111 21040 auxprop.cpp:81] Request to lookup properties for
> user: 'test-principal' realm: 'penates.apache.org' server FQDN:
> 'penates.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0916 22:56:14.059118 21040 auxprop.cpp:103] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0916 22:56:14.059123 21040 auxprop.cpp:103] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0916 22:56:14.059135 21040 authenticator.hpp:376] Authentication success
> I0916 22:56:14.059182 21047 authenticatee.hpp:305] Authentication success
> I0916 22:56:14.059192 21040 master.cpp:3693] Successfully authenticated
> principal 'test-principal' at slave(102)@67.195.81.186:47865
> I0916 22:56:14.059309 21047 slave.cpp:731] Successfully authenticated with
> master [email protected]:47865
> I0916 22:56:14.059348 21047 slave.cpp:994] Will retry registration in
> 12.6149ms if necessary
> I0916 22:56:14.059396 21040 master.cpp:2843] Registering slave at
> slave(102)@67.195.81.186:47865 (penates.apache.org) with id
> 20140916-225614-3125920579-47865-21026-0
> I0916 22:56:14.059495 21054 registrar.cpp:422] Attempting to update the
> 'registry'
> I0916 22:56:14.059558 21026 sched.cpp:137] Version: 0.21.0
> I0916 22:56:14.059710 21041 sched.cpp:233] New master detected at
> [email protected]:47865
> I0916 22:56:14.059730 21041 sched.cpp:283] Authenticating with master
> [email protected]:47865
> I0916 22:56:14.059788 21052 authenticatee.hpp:128] Creating new client SASL
> connection
> I0916 22:56:14.059890 21043 master.cpp:3653] Authenticating
> [email protected]:47865
> I0916 22:56:14.059960 21055 authenticator.hpp:156] Creating new server SASL
> connection
> I0916 22:56:14.060039 21040 authenticatee.hpp:219] Received SASL
> authentication mechanisms: CRAM-MD5
> I0916 22:56:14.060061 21040 authenticatee.hpp:245] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0916 22:56:14.060107 21055 authenticator.hpp:262] Received SASL
> authentication start
> I0916 22:56:14.060158 21055 authenticator.hpp:384] Authentication requires
> more steps
> I0916 22:56:14.060189 21055 authenticatee.hpp:265] Received SASL
> authentication step
> I0916 22:56:14.060220 21055 authenticator.hpp:290] Received SASL
> authentication step
> I0916 22:56:14.060236 21055 auxprop.cpp:81] Request to lookup properties for
> user: 'test-principal' realm: 'penates.apache.org' server FQDN:
> 'penates.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0916 22:56:14.060250 21055 auxprop.cpp:153] Looking up auxiliary property
> '*userPassword'
> I0916 22:56:14.060277 21055 auxprop.cpp:153] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0916 22:56:14.060288 21055 auxprop.cpp:81] Request to lookup properties for
> user: 'test-principal' realm: 'penates.apache.org' server FQDN:
> 'penates.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0916 22:56:14.060295 21055 auxprop.cpp:103] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0916 22:56:14.060300 21055 auxprop.cpp:103] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0916 22:56:14.060312 21055 authenticator.hpp:376] Authentication success
> I0916 22:56:14.060349 21040 authenticatee.hpp:305] Authentication success
> I0916 22:56:14.060364 21055 master.cpp:3693] Successfully authenticated
> principal 'test-principal' at
> [email protected]:47865
> I0916 22:56:14.060480 21046 sched.cpp:357] Successfully authenticated with
> master [email protected]:47865
> I0916 22:56:14.060499 21046 sched.cpp:476] Sending registration request to
> [email protected]:47865
> I0916 22:56:14.060564 21050 master.cpp:1331] Received registration request
> from [email protected]:47865
> I0916 22:56:14.060593 21050 master.cpp:1291] Authorizing framework principal
> 'test-principal' to receive offers for role '*'
> I0916 22:56:14.060767 21053 master.cpp:1390] Registering framework
> 20140916-225614-3125920579-47865-21026-0000 at
> [email protected]:47865
> I0916 22:56:14.060797 21049 log.cpp:680] Attempting to append 337 bytes to
> the log
> I0916 22:56:14.060873 21042 hierarchical_allocator_process.hpp:329] Added
> framework 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:14.060873 21040 coordinator.cpp:340] Coordinator attempting to
> write APPEND action at position 3
> I0916 22:56:14.060899 21042 hierarchical_allocator_process.hpp:697] No
> resources available to allocate!
> I0916 22:56:14.060909 21042 hierarchical_allocator_process.hpp:659] Performed
> allocation for 0 slaves in 11862ns
> I0916 22:56:14.061061 21044 sched.cpp:407] Framework registered with
> 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:14.061115 21044 sched.cpp:421] Scheduler::registered took 34395ns
> I0916 22:56:14.061173 21047 replica.cpp:508] Replica received write request
> for position 3
> I0916 22:56:14.061298 21047 leveldb.cpp:343] Persisting action (356 bytes) to
> leveldb took 108843ns
> I0916 22:56:14.061311 21047 replica.cpp:676] Persisted action at 3
> I0916 22:56:14.061553 21049 replica.cpp:655] Replica received learned notice
> for position 3
> I0916 22:56:14.061965 21049 leveldb.cpp:343] Persisting action (358 bytes) to
> leveldb took 392670ns
> I0916 22:56:14.061985 21049 replica.cpp:676] Persisted action at 3
> I0916 22:56:14.061996 21049 replica.cpp:661] Replica learned APPEND action at
> position 3
> I0916 22:56:14.062268 21050 registrar.cpp:479] Successfully updated 'registry'
> I0916 22:56:14.062331 21051 log.cpp:699] Attempting to truncate the log to 3
> I0916 22:56:14.062355 21040 master.cpp:2883] Registered slave
> 20140916-225614-3125920579-47865-21026-0 at slave(102)@67.195.81.186:47865
> (penates.apache.org)
> I0916 22:56:14.062386 21043 coordinator.cpp:340] Coordinator attempting to
> write TRUNCATE action at position 4
> I0916 22:56:14.062376 21040 master.cpp:4126] Adding slave
> 20140916-225614-3125920579-47865-21026-0 at slave(102)@67.195.81.186:47865
> (penates.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000]
> I0916 22:56:14.062510 21045 slave.cpp:765] Registered with master
> [email protected]:47865; given slave ID
> 20140916-225614-3125920579-47865-21026-0
> I0916 22:56:14.062573 21045 slave.cpp:2346] Received ping from
> slave-observer(98)@67.195.81.186:47865
> I0916 22:56:14.062599 21049 hierarchical_allocator_process.hpp:442] Added
> slave 20140916-225614-3125920579-47865-21026-0 (penates.apache.org) with
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
> I0916 22:56:14.062669 21049 hierarchical_allocator_process.hpp:734] Offering
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
> 20140916-225614-3125920579-47865-21026-0 to framework
> 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:14.062764 21041 replica.cpp:508] Replica received write request
> for position 4
> I0916 22:56:14.062788 21049 hierarchical_allocator_process.hpp:679] Performed
> allocation for slave 20140916-225614-3125920579-47865-21026-0 in 145691ns
> I0916 22:56:14.062839 21050 master.hpp:861] Adding offer
> 20140916-225614-3125920579-47865-21026-0 with resources cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
> 20140916-225614-3125920579-47865-21026-0 (penates.apache.org)
> I0916 22:56:14.062891 21041 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 110169ns
> I0916 22:56:14.062907 21041 replica.cpp:676] Persisted action at 4
> I0916 22:56:14.062911 21050 master.cpp:3600] Sending 1 offers to framework
> 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:14.063065 21043 sched.cpp:544] Scheduler::resourceOffers took
> 39808ns
> I0916 22:56:14.063163 21046 replica.cpp:655] Replica received learned notice
> for position 4
> I0916 22:56:14.063272 21046 leveldb.cpp:343] Persisting action (18 bytes) to
> leveldb took 89981ns
> I0916 22:56:14.063308 21046 leveldb.cpp:401] Deleting ~2 keys from leveldb
> took 18542ns
> I0916 22:56:14.063323 21046 replica.cpp:676] Persisted action at 4
> I0916 22:56:14.063333 21046 replica.cpp:661] Replica learned TRUNCATE action
> at position 4
> I0916 22:56:14.063482 21044 master.hpp:871] Removing offer
> 20140916-225614-3125920579-47865-21026-0 with resources cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
> 20140916-225614-3125920579-47865-21026-0 (penates.apache.org)
> I0916 22:56:14.063535 21044 master.cpp:2201] Processing reply for offers: [
> 20140916-225614-3125920579-47865-21026-0 ] on slave
> 20140916-225614-3125920579-47865-21026-0 at slave(102)@67.195.81.186:47865
> (penates.apache.org) for framework 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:14.063561 21044 master.cpp:2284] Authorizing framework principal
> 'test-principal' to launch task 1 as user 'jenkins'
> I0916 22:56:14.063824 21040 master.hpp:833] Adding task 1 with resources
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
> 20140916-225614-3125920579-47865-21026-0 (penates.apache.org)
> I0916 22:56:14.063860 21040 master.cpp:2350] Launching task 1 of framework
> 20140916-225614-3125920579-47865-21026-0000 with resources cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
> 20140916-225614-3125920579-47865-21026-0 at slave(102)@67.195.81.186:47865
> (penates.apache.org)
> I0916 22:56:14.063943 21050 slave.cpp:1025] Got assigned task 1 for framework
> 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:14.064158 21050 slave.cpp:1135] Launching task 1 for framework
> 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:14.065439 21050 slave.cpp:1248] Queuing task '1' for executor 1
> of framework '20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:14.065460 21041 containerizer.cpp:394] Starting container
> 'd383a013-89cf-47c6-ad8e-39e2f3e971fd' for executor '1' of framework
> '20140916-225614-3125920579-47865-21026-0000'
> I0916 22:56:14.065477 21050 slave.cpp:554] Successfully attached file
> '/tmp/HealthCheckTest_HealthStatusChange_cGKTiG/slaves/20140916-225614-3125920579-47865-21026-0/frameworks/20140916-225614-3125920579-47865-21026-0000/executors/1/runs/d383a013-89cf-47c6-ad8e-39e2f3e971fd'
> I0916 22:56:14.066735 21055 launcher.cpp:137] Forked child with pid '21858'
> for container 'd383a013-89cf-47c6-ad8e-39e2f3e971fd'
> I0916 22:56:14.067486 21044 containerizer.cpp:510] Fetching URIs for
> container 'd383a013-89cf-47c6-ad8e-39e2f3e971fd' using command
> '/home/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/build/src/mesos-fetcher'
> I0916 22:56:15.037449 21050 hierarchical_allocator_process.hpp:659] Performed
> allocation for 1 slaves in 43708ns
> I0916 22:56:15.038743 21054 slave.cpp:2559] Monitoring executor '1' of
> framework '20140916-225614-3125920579-47865-21026-0000' in container
> 'd383a013-89cf-47c6-ad8e-39e2f3e971fd'
> I0916 22:56:15.078441 21053 slave.cpp:1758] Got registration for executor '1'
> of framework 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:15.078866 21053 slave.cpp:1876] Flushing queued task 1 for
> executor '1' of framework 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:15.084800 21043 slave.cpp:2110] Handling status update
> TASK_RUNNING (UUID: a16d2819-e9f4-4119-bde6-f00ad33033e5) for task 1 of
> framework 20140916-225614-3125920579-47865-21026-0000 from
> executor(1)@67.195.81.186:35510
> I0916 22:56:15.084969 21041 status_update_manager.cpp:320] Received status
> update TASK_RUNNING (UUID: a16d2819-e9f4-4119-bde6-f00ad33033e5) for task 1
> of framework 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:15.084995 21041 status_update_manager.cpp:499] Creating
> StatusUpdate stream for task 1 of framework
> 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:15.085160 21041 status_update_manager.cpp:373] Forwarding status
> update TASK_RUNNING (UUID: a16d2819-e9f4-4119-bde6-f00ad33033e5) for task 1
> of framework 20140916-225614-3125920579-47865-21026-0000 to
> [email protected]:47865
> I0916 22:56:15.085314 21043 slave.cpp:2267] Status update manager
> successfully handled status update TASK_RUNNING (UUID:
> a16d2819-e9f4-4119-bde6-f00ad33033e5) for task 1 of framework
> 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:15.085332 21041 master.cpp:3212] Forwarding status update
> TASK_RUNNING (UUID: a16d2819-e9f4-4119-bde6-f00ad33033e5) for task 1 of
> framework 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:15.085335 21043 slave.cpp:2273] Sending acknowledgement for
> status update TASK_RUNNING (UUID: a16d2819-e9f4-4119-bde6-f00ad33033e5) for
> task 1 of framework 20140916-225614-3125920579-47865-21026-0000 to
> executor(1)@67.195.81.186:35510
> I0916 22:56:15.085435 21041 master.cpp:3178] Status update TASK_RUNNING
> (UUID: a16d2819-e9f4-4119-bde6-f00ad33033e5) for task 1 of framework
> 20140916-225614-3125920579-47865-21026-0000 from slave
> 20140916-225614-3125920579-47865-21026-0 at slave(102)@67.195.81.186:47865
> (penates.apache.org)
> I0916 22:56:15.085675 21044 sched.cpp:635] Scheduler::statusUpdate took
> 113998ns
> I0916 22:56:15.085888 21052 master.cpp:2693] Forwarding status update
> acknowledgement a16d2819-e9f4-4119-bde6-f00ad33033e5 for task 1 of framework
> 20140916-225614-3125920579-47865-21026-0000 to slave
> 20140916-225614-3125920579-47865-21026-0 at slave(102)@67.195.81.186:47865
> (penates.apache.org)
> I0916 22:56:15.086109 21051 status_update_manager.cpp:398] Received status
> update acknowledgement (UUID: a16d2819-e9f4-4119-bde6-f00ad33033e5) for task
> 1 of framework 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:15.086205 21051 slave.cpp:1698] Status update manager
> successfully handled status update acknowledgement (UUID:
> a16d2819-e9f4-4119-bde6-f00ad33033e5) for task 1 of framework
> 20140916-225614-3125920579-47865-21026-0000
> I../../src/tests/health_check_tests.cpp:330: Failure
> Failed to wait 10secs for statusHealth1
> 0916 22:56:16.038705 21049 hierarchical_allocator_process.hpp:659] Performed
> allocation for 1 slaves in 40061ns
> I0916 22:56:16.126260 21052 slave.cpp:2110] Handling status update
> TASK_RUNNING (UUID: 792b8e42-0d72-451b-978a-7d1f29a15751) for task 1 in
> health state healthy of framework 20140916-225614-3125920579-47865-21026-0000
> from executor(1)@67.195.81.186:35510
> I0916 22:56:28.190274 21045 master.cpp:741] Framework
> 20140916-225614-3125920579-47865-21026-0000 disconnected
> I0916 22:56:28.190304 21045 master.cpp:1687] Deactivating framework
> 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:19.037235 21050 master.cpp:120] No whitelist given. Advertising
> offers for all slaves
> I0916 22:56:28.190394 21045 master.cpp:763] Giving framework
> 20140916-225614-3125920579-47865-21026-0000 0ns to failover
> ../../src/tests/health_check_tests.cpp:319: Failure
> Actual function call count doesn't match EXPECT_CALL(sched,
> statusUpdate(&driver, _))...
> Expected: to be called 4 times
> Actual: called once - unsatisfied and active
> I0916 22:56:28.190624 21052 slave.cpp:2110] Handling status update
> TASK_RUNNING (UUID: 5783bb6f-112f-4434-a160-a336e890398a) for task 1 in
> health state unhealthy of framework
> 20140916-225614-3125920579-47865-21026-0000 from
> executor(1)@67.195.81.186:35510
> I0916 22:56:28.190757 21052 slave.cpp:2110] Handling status update
> TASK_RUNNING (UUID: b4a9f647-3894-47f3-b55e-49d0355b20f9) for task 1 in
> health state healthy of framework 20140916-225614-3125920579-47865-21026-0000
> from executor(1)@67.195.81.186:35510
> I0916 22:56:28.190773 21046 status_update_manager.cpp:320] Received status
> update TASK_RUNNING (UUID: 792b8e42-0d72-451b-978a-7d1f29a15751) for task 1
> in health state healthy of framework
> 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:28.190831 21040 hierarchical_allocator_process.hpp:405]
> Deactivated framework 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:28.190856 21054 master.cpp:3471] Framework failover timeout,
> removing framework 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:28.190846 21046 status_update_manager.cpp:373] Forwarding status
> update TASK_RUNNING (UUID: 792b8e42-0d72-451b-978a-7d1f29a15751) for task 1
> in health state healthy of framework
> 20140916-225614-3125920579-47865-21026-0000 to [email protected]:47865
> I0916 22:56:28.190887 21054 master.cpp:3976] Removing framework
> 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:28.190887 21052 slave.cpp:2110] Handling status update
> TASK_RUNNING (UUID: b5d5d6c7-e92c-4ca0-ab72-656542c14ade) for task 1 in
> health state unhealthy of framework
> 20140916-225614-3125920579-47865-21026-0000 from
> executor(1)@67.195.81.186:35510
> I0916 22:56:28.190994 21052 slave.cpp:2110] Handling status update
> TASK_RUNNING (UUID: c0225c5c-b15e-4b5e-a063-07a29703ea12) for task 1 in
> health state healthy of framework 20140916-225614-3125920579-47865-21026-0000
> from executor(1)@67.195.81.186:35510
> I0916 22:56:28.190996 21046 status_update_manager.cpp:320] Received status
> update TASK_RUNNING (UUID: 5783bb6f-112f-4434-a160-a336e890398a) for task 1
> in health state unhealthy of framework
> 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:28.190999 21054 master.hpp:851] Removing task 1 with resources
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
> 20140916-225614-3125920579-47865-21026-0 (penates.apache.org)
> I0916 22:56:28.191090 21046 status_update_manager.cpp:320] Received status
> update TASK_RUNNING (UUID: b4a9f647-3894-47f3-b55e-49d0355b20f9) for task 1
> in health state healthy of framework
> 20140916-225614-3125920579-47865-21026-0000
> W0916 22:56:28.191141 21054 master.cpp:4419] Removing task 1 of framework
> 20140916-225614-3125920579-47865-21026-0000 and slave
> 20140916-225614-3125920579-47865-21026-0 in non-terminal state TASK_RUNNING
> I0916 22:56:28.191093 21052 slave.cpp:2110] Handling status update
> TASK_RUNNING (UUID: e9e3fdb1-d8e0-4bfc-970b-fcd098cace13) for task 1 in
> health state unhealthy of framework
> 20140916-225614-3125920579-47865-21026-0000 from
> executor(1)@67.195.81.186:35510
> I0916 22:56:28.191181 21046 status_update_manager.cpp:320] Received status
> update TASK_RUNNING (UUID: b5d5d6c7-e92c-4ca0-ab72-656542c14ade) for task 1
> in health state unhealthy of framework
> 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:28.191256 21054 master.cpp:650] Master terminating
> I0916 22:56:28.191258 21043 hierarchical_allocator_process.hpp:563] Recovered
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total
> allocatable: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on
> slave 20140916-225614-3125920579-47865-21026-0 from framework
> 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:28.369088 21046 status_update_manager.cpp:320] Received status
> update TASK_RUNNING (UUID: c0225c5c-b15e-4b5e-a063-07a29703ea12) for task 1
> in health state healthy of framework
> 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:28.191319 21052 slave.cpp:2110] Handling status update
> TASK_RUNNING (UUID: 780d211b-6ecc-478d-93e9-6744ed0a2d33) for task 1 in
> health state healthy of framework 20140916-225614-3125920579-47865-21026-0000
> from executor(1)@67.195.81.186:35510
> I0916 22:56:28.369132 21043 hierarchical_allocator_process.hpp:360] Removed
> framework 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:28.369225 21046 status_update_manager.cpp:320] Received status
> update TASK_RUNNING (UUID: e9e3fdb1-d8e0-4bfc-970b-fcd098cace13) for task 1
> in health state unhealthy of framework
> 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:28.369283 21052 slave.cpp:2110] Handling status update
> TASK_RUNNING (UUID: f41475b5-9b45-478e-8cd9-2cf7854627dd) for task 1 in
> health state unhealthy of framework
> 20140916-225614-3125920579-47865-21026-0000 from
> executor(1)@67.195.81.186:35510
> I0916 22:56:28.369323 21046 status_update_manager.cpp:320] Received status
> update TASK_RUNNING (UUID: 780d211b-6ecc-478d-93e9-6744ed0a2d33) for task 1
> in health state healthy of framework
> 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:28.369415 21046 status_update_manager.cpp:320] Received status
> update TASK_RUNNING (UUID: f41475b5-9b45-478e-8cd9-2cf7854627dd) for task 1
> in health state unhealthy of framework
> 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:28.369420 21052 slave.cpp:2110] Handling status update
> TASK_RUNNING (UUID: 5f3a1b44-51f0-4deb-ba4c-e7238f63f856) for task 1 in
> health state healthy of framework 20140916-225614-3125920579-47865-21026-0000
> from executor(1)@67.195.81.186:35510
> I0916 22:56:28.369536 21052 slave.cpp:2110] Handling status update
> TASK_RUNNING (UUID: 4663a09b-147f-455c-a577-3d967ddf5256) for task 1 in
> health state unhealthy of framework
> 20140916-225614-3125920579-47865-21026-0000 from
> executor(1)@67.195.81.186:35510
> I0916 22:56:28.369642 21052 slave.cpp:2110] Handling status update
> TASK_RUNNING (UUID: 89cbabd7-0169-4b58-8df7-d8fd4bc4a287) for task 1 in
> health state healthy of framework 20140916-225614-3125920579-47865-21026-0000
> from executor(1)@67.195.81.186:35510
> I0916 22:56:28.369685 21055 status_update_manager.cpp:320] Received status
> update TASK_RUNNING (UUID: 5f3a1b44-51f0-4deb-ba4c-e7238f63f856) for task 1
> in health state healthy of framework
> 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:28.369753 21052 slave.cpp:2110] Handling status update
> TASK_RUNNING (UUID: 3c491f72-95f1-4c52-b7ca-c6470f748eb5) for task 1 in
> health state unhealthy of framework
> 20140916-225614-3125920579-47865-21026-0000 from
> executor(1)@67.195.81.186:35510
> I0916 22:56:28.369802 21055 status_update_manager.cpp:320] Received status
> update TASK_RUNNING (UUID: 4663a09b-147f-455c-a577-3d967ddf5256) for task 1
> in health state unhealthy of framework
> 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:28.369884 21055 status_update_manager.cpp:320] Received status
> update TASK_RUNNING (UUID: 89cbabd7-0169-4b58-8df7-d8fd4bc4a287) for task 1
> in health state healthy of framework
> 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:28.369889 21052 slave.cpp:2110] Handling status update
> TASK_RUNNING (UUID: 218be9bd-a229-4808-8fb6-1e507830cdaf) for task 1 in
> health state healthy of framework 20140916-225614-3125920579-47865-21026-0000
> from executor(1)@67.195.81.186:35510
> I0916 22:56:28.369943 21055 status_update_manager.cpp:320] Received status
> update TASK_RUNNING (UUID: 3c491f72-95f1-4c52-b7ca-c6470f748eb5) for task 1
> in health state unhealthy of framework
> 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:28.369978 21052 slave.cpp:1431] Asked to shut down framework
> 20140916-225614-3125920579-47865-21026-0000 by [email protected]:47865
> I0916 22:56:28.369998 21052 slave.cpp:1456] Shutting down framework
> 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:28.370009 21055 status_update_manager.cpp:320] Received status
> update TASK_RUNNING (UUID: 218be9bd-a229-4808-8fb6-1e507830cdaf) for task 1
> in health state healthy of framework
> 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:28.370018 21052 slave.cpp:2899] Shutting down executor '1' of
> framework 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:28.370183 21052 slave.cpp:2267] Status update manager
> successfully handled status update TASK_RUNNING (UUID:
> 792b8e42-0d72-451b-978a-7d1f29a15751) for task 1 in health state healthy of
> framework 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:28.370206 21052 slave.cpp:2273] Sending acknowledgement for
> status update TASK_RUNNING (UUID: 792b8e42-0d72-451b-978a-7d1f29a15751) for
> task 1 in health state healthy of framework
> 20140916-225614-3125920579-47865-21026-0000 to executor(1)@67.195.81.186:35510
> I0916 22:56:28.370426 21052 slave.cpp:2267] Status update manager
> successfully handled status update TASK_RUNNING (UUID:
> 5783bb6f-112f-4434-a160-a336e890398a) for task 1 in health state unhealthy of
> framework 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:28.370447 21052 slave.cpp:2273] Sending acknowledgement for
> status update TASK_RUNNING (UUID: 5783bb6f-112f-4434-a160-a336e890398a) for
> task 1 in health state unhealthy of framework
> 20140916-225614-3125920579-47865-21026-0000 to executor(1)@67.195.81.186:35510
> I0916 22:56:28.370635 21052 slave.cpp:2267] Status update manager
> successfully handled status update TASK_RUNNING (UUID:
> b4a9f647-3894-47f3-b55e-49d0355b20f9) for task 1 in health state healthy of
> framework 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:28.370657 21052 slave.cpp:2273] Sending acknowledgement for
> status update TASK_RUNNING (UUID: b4a9f647-3894-47f3-b55e-49d0355b20f9) for
> task 1 in health state healthy of framework
> 20140916-225614-3125920579-47865-21026-0000 to executor(1)@67.195.81.186:35510
> I0916 22:56:28.370815 21052 slave.cpp:2267] Status update manager
> successfully handled status update TASK_RUNNING (UUID:
> b5d5d6c7-e92c-4ca0-ab72-656542c14ade) for task 1 in health state unhealthy of
> framework 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:28.370837 21052 slave.cpp:2273] Sending acknowledgement for
> status update TASK_RUNNING (UUID: b5d5d6c7-e92c-4ca0-ab72-656542c14ade) for
> task 1 in health state unhealthy of framework
> 20140916-225614-3125920579-47865-21026-0000 to executor(1)@67.195.81.186:35510
> I0916 22:56:28.370972 21052 slave.cpp:2267] Status update manager
> successfully handled status update TASK_RUNNING (UUID:
> c0225c5c-b15e-4b5e-a063-07a29703ea12) for task 1 in health state healthy of
> framework 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:28.371000 21052 slave.cpp:2273] Sending acknowledgement for
> status update TASK_RUNNING (UUID: c0225c5c-b15e-4b5e-a063-07a29703ea12) for
> task 1 in health state healthy of framework
> 20140916-225614-3125920579-47865-21026-0000 to executor(1)@67.195.81.186:35510
> I0916 22:56:28.371155 21052 slave.cpp:2378] [email protected]:47865 exited
> W0916 22:56:28.371177 21052 slave.cpp:2381] Master disconnected! Waiting for
> a new master to be elected
> I0916 22:56:28.371202 21052 slave.cpp:2267] Status update manager
> successfully handled status update TASK_RUNNING (UUID:
> e9e3fdb1-d8e0-4bfc-970b-fcd098cace13) for task 1 in health state unhealthy of
> framework 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:28.540035 21052 slave.cpp:2273] Sending acknowledgement for
> status update TASK_RUNNING (UUID: e9e3fdb1-d8e0-4bfc-970b-fcd098cace13) for
> task 1 in health state unhealthy of framework
> 20140916-225614-3125920579-47865-21026-0000 to executor(1)@67.195.81.186:35510
> I0916 22:56:28.371701 21053 containerizer.cpp:882] Destroying container
> 'd383a013-89cf-47c6-ad8e-39e2f3e971fd'
> I0916 22:56:28.540177 21052 slave.cpp:2267] Status update manager
> successfully handled status update TASK_RUNNING (UUID:
> 780d211b-6ecc-478d-93e9-6744ed0a2d33) for task 1 in health state healthy of
> framework 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:28.540196 21052 slave.cpp:2273] Sending acknowledgement for
> status update TASK_RUNNING (UUID: 780d211b-6ecc-478d-93e9-6744ed0a2d33) for
> task 1 in health state healthy of framework
> 20140916-225614-3125920579-47865-21026-0000 to executor(1)@67.195.81.186:35510
> I0916 22:56:28.540324 21052 slave.cpp:2267] Status update manager
> successfully handled status update TASK_RUNNING (UUID:
> f41475b5-9b45-478e-8cd9-2cf7854627dd) for task 1 in health state unhealthy of
> framework 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:28.540350 21052 slave.cpp:2273] Sending acknowledgement for
> status update TASK_RUNNING (UUID: f41475b5-9b45-478e-8cd9-2cf7854627dd) for
> task 1 in health state unhealthy of framework
> 20140916-225614-3125920579-47865-21026-0000 to executor(1)@67.195.81.186:35510
> I0916 22:56:28.540403 21052 slave.cpp:2267] Status update manager
> successfully handled status update TASK_RUNNING (UUID:
> 5f3a1b44-51f0-4deb-ba4c-e7238f63f856) for task 1 in health state healthy of
> framework 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:28.540421 21052 slave.cpp:2273] Sending acknowledgement for
> status update TASK_RUNNING (UUID: 5f3a1b44-51f0-4deb-ba4c-e7238f63f856) for
> task 1 in health state healthy of framework
> 20140916-225614-3125920579-47865-21026-0000 to executor(1)@67.195.81.186:35510
> I0916 22:56:28.540530 21052 slave.cpp:2267] Status update manager
> successfully handled status update TASK_RUNNING (UUID:
> 4663a09b-147f-455c-a577-3d967ddf5256) for task 1 in health state unhealthy of
> framework 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:28.540556 21052 slave.cpp:2273] Sending acknowledgement for
> status update TASK_RUNNING (UUID: 4663a09b-147f-455c-a577-3d967ddf5256) for
> task 1 in health state unhealthy of framework
> 20140916-225614-3125920579-47865-21026-0000 to executor(1)@67.195.81.186:35510
> I0916 22:56:28.540664 21052 slave.cpp:2267] Status update manager
> successfully handled status update TASK_RUNNING (UUID:
> 89cbabd7-0169-4b58-8df7-d8fd4bc4a287) for task 1 in health state healthy of
> framework 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:28.540681 21052 slave.cpp:2273] Sending acknowledgement for
> status update TASK_RUNNING (UUID: 89cbabd7-0169-4b58-8df7-d8fd4bc4a287) for
> task 1 in health state healthy of framework
> 20140916-225614-3125920579-47865-21026-0000 to executor(1)@67.195.81.186:35510
> I0916 22:56:28.540889 21052 slave.cpp:2267] Status update manager
> successfully handled status update TASK_RUNNING (UUID:
> 3c491f72-95f1-4c52-b7ca-c6470f748eb5) for task 1 in health state unhealthy of
> framework 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:28.540918 21052 slave.cpp:2273] Sending acknowledgement for
> status update TASK_RUNNING (UUID: 3c491f72-95f1-4c52-b7ca-c6470f748eb5) for
> task 1 in health state unhealthy of framework
> 20140916-225614-3125920579-47865-21026-0000 to executor(1)@67.195.81.186:35510
> I0916 22:56:28.541082 21052 slave.cpp:2267] Status update manager
> successfully handled status update TASK_RUNNING (UUID:
> 218be9bd-a229-4808-8fb6-1e507830cdaf) for task 1 in health state healthy of
> framework 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:28.541111 21052 slave.cpp:2273] Sending acknowledgement for
> status update TASK_RUNNING (UUID: 218be9bd-a229-4808-8fb6-1e507830cdaf) for
> task 1 in health state healthy of framework
> 20140916-225614-3125920579-47865-21026-0000 to executor(1)@67.195.81.186:35510
> I0916 22:56:29.047708 21053 containerizer.cpp:997] Executor for container
> 'd383a013-89cf-47c6-ad8e-39e2f3e971fd' has exited
> I0916 22:56:29.048037 21050 slave.cpp:2617] Executor '1' of framework
> 20140916-225614-3125920579-47865-21026-0000 terminated with signal Killed
> I0916 22:56:29.048197 21050 slave.cpp:2753] Cleaning up executor '1' of
> framework 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:29.048373 21050 slave.cpp:2828] Cleaning up framework
> 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:29.048444 21043 status_update_manager.cpp:282] Closing status
> update streams for framework 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:29.048457 21050 slave.cpp:477] Slave terminating
> I0916 22:56:29.048476 21043 status_update_manager.cpp:530] Cleaning up status
> update stream for task 1 of framework
> 20140916-225614-3125920579-47865-21026-0000
> I0916 22:56:29.048462 21041 gc.cpp:56] Scheduling
> '/tmp/HealthCheckTest_HealthStatusChange_cGKTiG/slaves/20140916-225614-3125920579-47865-21026-0/frameworks/20140916-225614-3125920579-47865-21026-0000/executors/1/runs/d383a013-89cf-47c6-ad8e-39e2f3e971fd'
> for gc 6.99999944121481days in the future
> I0916 22:56:29.048568 21041 gc.cpp:56] Scheduling
> '/tmp/HealthCheckTest_HealthStatusChange_cGKTiG/slaves/20140916-225614-3125920579-47865-21026-0/frameworks/20140916-225614-3125920579-47865-21026-0000/executors/1'
> for gc 6.99999944031111days in the future
> I0916 22:56:29.048607 21041 gc.cpp:56] Scheduling
> '/tmp/HealthCheckTest_HealthStatusChange_cGKTiG/slaves/20140916-225614-3125920579-47865-21026-0/frameworks/20140916-225614-3125920579-47865-21026-0000'
> for gc 6.99999943939852days in the future
> [ FAILED ] HealthCheckTest.HealthStatusChange (15019 ms)
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
