You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "haosdent (JIRA)" <ji...@apache.org> on 2016/04/19 19:21:25 UTC
[jira] [Commented] (MESOS-1802) HealthCheckTest.HealthStatusChange
is flaky on jenkins.
[ https://issues.apache.org/jira/browse/MESOS-1802?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15248222#comment-15248222 ]
haosdent commented on MESOS-1802:
---------------------------------
According to another flaky log provided by [~neilc] (Thanks a lot!)
{code}
[ RUN ] HealthCheckTest.HealthStatusChange
I0420 00:33:12.691145 15381 cluster.cpp:149] Creating default 'local' authorizer
I0420 00:33:12.691897 15381 leveldb.cpp:174] Opened db in 620608ns
I0420 00:33:12.692211 15381 leveldb.cpp:181] Compacted db in 283038ns
I0420 00:33:12.692265 15381 leveldb.cpp:196] Created db iterator in 15184ns
I0420 00:33:12.692273 15381 leveldb.cpp:202] Seeked to beginning of db in 2161ns
I0420 00:33:12.692281 15381 leveldb.cpp:271] Iterated through 0 keys in the db in 1084ns
I0420 00:33:12.692312 15381 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0420 00:33:12.693172 15398 recover.cpp:447] Starting replica recovery
I0420 00:33:12.693435 15400 recover.cpp:473] Replica is in EMPTY status
I0420 00:33:12.695106 15400 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from (3755)@10.0.2.15:41408
I0420 00:33:12.695829 15400 recover.cpp:193] Received a recover response from a replica in EMPTY status
I0420 00:33:12.696321 15398 recover.cpp:564] Updating replica status to STARTING
I0420 00:33:12.696807 15402 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 101090ns
I0420 00:33:12.696836 15402 replica.cpp:320] Persisted replica status to STARTING
I0420 00:33:12.696964 15402 recover.cpp:473] Replica is in STARTING status
I0420 00:33:12.697968 15400 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from (3756)@10.0.2.15:41408
I0420 00:33:12.698274 15400 recover.cpp:193] Received a recover response from a replica in STARTING status
I0420 00:33:12.698691 15400 recover.cpp:564] Updating replica status to VOTING
I0420 00:33:12.698882 15400 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 62549ns
I0420 00:33:12.698938 15400 replica.cpp:320] Persisted replica status to VOTING
I0420 00:33:12.699002 15400 recover.cpp:578] Successfully joined the Paxos group
I0420 00:33:12.699128 15400 recover.cpp:462] Recover process terminated
I0420 00:33:12.721339 15401 master.cpp:382] Master 7cf5923c-3d03-4ed6-826a-efa97f54e765 (archlinux.vagrant.vm) started on 10.0.2.15:41408
I0420 00:33:12.721387 15401 master.cpp:384] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="true" --authenticate_http="true" --authenticate_http_frameworks="true" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/9zoT36/credentials" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_framework_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="100secs" --registry_strict="true" --root_submissions="true" --slave_ping_timeout="15secs" --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false" --webui_dir="/usr/local/share/mesos/webui" --work_dir="/tmp/9zoT36/master" --zk_session_timeout="10secs"
I0420 00:33:12.721667 15401 master.cpp:433] Master only allowing authenticated frameworks to register
I0420 00:33:12.721736 15401 master.cpp:439] Master only allowing authenticated agents to register
I0420 00:33:12.721745 15401 master.cpp:445] Master only allowing authenticated HTTP frameworks to register
I0420 00:33:12.721750 15401 credentials.hpp:37] Loading credentials for authentication from '/tmp/9zoT36/credentials'
I0420 00:33:12.722005 15401 master.cpp:489] Using default 'crammd5' authenticator
I0420 00:33:12.723206 15401 master.cpp:560] Using default 'basic' HTTP authenticator
I0420 00:33:12.723458 15401 master.cpp:640] Using default 'basic' HTTP framework authenticator
I0420 00:33:12.723574 15401 master.cpp:687] Authorization enabled
I0420 00:33:12.725332 15399 master.cpp:1932] The newly elected leader is master@10.0.2.15:41408 with id 7cf5923c-3d03-4ed6-826a-efa97f54e765
I0420 00:33:12.725376 15399 master.cpp:1945] Elected as the leading master!
I0420 00:33:12.725389 15399 master.cpp:1632] Recovering from registrar
I0420 00:33:12.725544 15399 registrar.cpp:331] Recovering registrar
I0420 00:33:12.726506 15399 log.cpp:524] Attempting to start the writer
I0420 00:33:12.727424 15399 replica.cpp:493] Replica received implicit promise request from (3759)@10.0.2.15:41408 with proposal 1
I0420 00:33:12.727517 15399 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 50404ns
I0420 00:33:12.727541 15399 replica.cpp:342] Persisted promised to 1
I0420 00:33:12.728299 15395 coordinator.cpp:238] Coordinator attempting to fill missing positions
I0420 00:33:12.735360 15402 replica.cpp:388] Replica received explicit promise request from (3760)@10.0.2.15:41408 for position 0 with proposal 2
I0420 00:33:12.735448 15402 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 51677ns
I0420 00:33:12.735525 15402 replica.cpp:712] Persisted action at 0
I0420 00:33:12.736783 15399 replica.cpp:537] Replica received write request for position 0 from (3761)@10.0.2.15:41408
I0420 00:33:12.736955 15399 leveldb.cpp:436] Reading position from leveldb took 27734ns
I0420 00:33:12.737108 15399 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 40858ns
I0420 00:33:12.737249 15399 replica.cpp:712] Persisted action at 0
I0420 00:33:12.738021 15398 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0
I0420 00:33:12.738092 15398 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 35952ns
I0420 00:33:12.738131 15398 replica.cpp:712] Persisted action at 0
I0420 00:33:12.738145 15398 replica.cpp:697] Replica learned NOP action at position 0
I0420 00:33:12.739038 15395 log.cpp:540] Writer started with ending position 0
I0420 00:33:12.740397 15400 leveldb.cpp:436] Reading position from leveldb took 43374ns
I0420 00:33:12.741741 15397 registrar.cpp:364] Successfully fetched the registry (0B) in 16.1408ms
I0420 00:33:12.741844 15397 registrar.cpp:463] Applied 1 operations in 22449ns; attempting to update the 'registry'
I0420 00:33:12.742624 15397 log.cpp:548] Attempting to append 185 bytes to the log
I0420 00:33:12.742825 15399 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
I0420 00:33:12.743827 15399 replica.cpp:537] Replica received write request for position 1 from (3762)@10.0.2.15:41408
I0420 00:33:12.744009 15399 leveldb.cpp:341] Persisting action (204 bytes) to leveldb took 59247ns
I0420 00:33:12.744189 15399 replica.cpp:712] Persisted action at 1
I0420 00:33:12.745023 15397 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
I0420 00:33:12.745139 15397 leveldb.cpp:341] Persisting action (206 bytes) to leveldb took 65024ns
I0420 00:33:12.745167 15397 replica.cpp:712] Persisted action at 1
I0420 00:33:12.745183 15397 replica.cpp:697] Replica learned APPEND action at position 1
I0420 00:33:12.746696 15395 registrar.cpp:508] Successfully updated the 'registry' in 4.788992ms
I0420 00:33:12.746841 15395 registrar.cpp:394] Successfully recovered registrar
I0420 00:33:12.746913 15401 log.cpp:567] Attempting to truncate the log to 1
I0420 00:33:12.747383 15399 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
I0420 00:33:12.747747 15395 master.cpp:1740] Recovered 0 agents from the Registry (146B) ; allowing 10mins for agents to re-register
I0420 00:33:12.749722 15397 replica.cpp:537] Replica received write request for position 2 from (3763)@10.0.2.15:41408
I0420 00:33:12.749837 15397 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 51623ns
I0420 00:33:12.749862 15397 replica.cpp:712] Persisted action at 2
I0420 00:33:12.750529 15400 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
I0420 00:33:12.750602 15400 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 34873ns
I0420 00:33:12.750695 15400 leveldb.cpp:399] Deleting ~1 keys from leveldb took 23637ns
I0420 00:33:12.750730 15400 replica.cpp:712] Persisted action at 2
I0420 00:33:12.750746 15400 replica.cpp:697] Replica learned TRUNCATE action at position 2
I0420 00:33:12.761435 15381 containerizer.cpp:174] Using isolation: posix/cpu,posix/mem,filesystem/posix,network/cni
W0420 00:33:12.762092 15381 backend.cpp:66] Failed to create 'bind' backend: BindBackend requires root privileges
I0420 00:33:12.810016 15400 slave.cpp:201] Agent started on 76)@10.0.2.15:41408
I0420 00:33:12.810070 15400 slave.cpp:202] Flags at startup: --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http="true" --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_T3YdIF/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/HealthCheckTest_HealthStatusChange_T3YdIF/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="true" --hostname_lookup="true" --http_authenticators="basic" --http_command_executor="false" --http_credentials="/tmp/HealthCheckTest_HealthStatusChange_T3YdIF/http_credentials" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/home/vagrant/build-mesos-default-opts/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_enable_support="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/HealthCheckTest_HealthStatusChange_T3YdIF"
I0420 00:33:12.810362 15400 credentials.hpp:86] Loading credential for authentication from '/tmp/HealthCheckTest_HealthStatusChange_T3YdIF/credential'
I0420 00:33:12.810511 15400 slave.cpp:339] Agent using credential for: test-principal
I0420 00:33:12.810564 15400 credentials.hpp:37] Loading credentials for authentication from '/tmp/HealthCheckTest_HealthStatusChange_T3YdIF/http_credentials'
I0420 00:33:12.810765 15400 slave.cpp:391] Using default 'basic' HTTP authenticator
I0420 00:33:12.839030 15400 slave.cpp:590] Agent resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0420 00:33:12.839357 15400 slave.cpp:598] Agent attributes: [ ]
I0420 00:33:12.839551 15400 slave.cpp:603] Agent hostname: archlinux.vagrant.vm
I0420 00:33:12.841415 15400 state.cpp:57] Recovering state from '/tmp/HealthCheckTest_HealthStatusChange_T3YdIF/meta'
I0420 00:33:12.841830 15400 status_update_manager.cpp:200] Recovering status update manager
I0420 00:33:12.842087 15397 containerizer.cpp:439] Recovering containerizer
I0420 00:33:12.843364 15395 provisioner.cpp:245] Provisioner recovery complete
I0420 00:33:12.843719 15395 slave.cpp:4800] Finished recovery
I0420 00:33:12.844300 15395 slave.cpp:945] New master detected at master@10.0.2.15:41408
I0420 00:33:12.844360 15401 status_update_manager.cpp:174] Pausing sending status updates
I0420 00:33:12.844458 15395 slave.cpp:1008] Authenticating with master master@10.0.2.15:41408
I0420 00:33:12.844509 15395 slave.cpp:1013] Using default CRAM-MD5 authenticatee
I0420 00:33:12.844620 15395 slave.cpp:981] Detecting new master
I0420 00:33:12.844779 15395 authenticatee.cpp:121] Creating new client SASL connection
I0420 00:33:12.845008 15395 master.cpp:5801] Authenticating slave(76)@10.0.2.15:41408
I0420 00:33:12.845345 15395 authenticator.cpp:98] Creating new server SASL connection
I0420 00:33:12.845471 15395 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
I0420 00:33:12.845504 15395 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
I0420 00:33:12.845552 15395 authenticator.cpp:203] Received SASL authentication start
I0420 00:33:12.845609 15395 authenticator.cpp:325] Authentication requires more steps
I0420 00:33:12.845657 15395 authenticatee.cpp:258] Received SASL authentication step
I0420 00:33:12.845787 15395 authenticator.cpp:231] Received SASL authentication step
I0420 00:33:12.845851 15395 authenticator.cpp:317] Authentication success
I0420 00:33:12.846011 15400 authenticatee.cpp:298] Authentication success
I0420 00:33:12.846009 15396 master.cpp:5831] Successfully authenticated principal 'test-principal' at slave(76)@10.0.2.15:41408
I0420 00:33:12.846340 15400 slave.cpp:1078] Successfully authenticated with master master@10.0.2.15:41408
I0420 00:33:12.846705 15396 master.cpp:4512] Registering agent at slave(76)@10.0.2.15:41408 (archlinux.vagrant.vm) with id 7cf5923c-3d03-4ed6-826a-efa97f54e765-S0
I0420 00:33:12.847108 15396 registrar.cpp:463] Applied 1 operations in 45782ns; attempting to update the 'registry'
I0420 00:33:12.847733 15400 log.cpp:548] Attempting to append 362 bytes to the log
I0420 00:33:12.848198 15401 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3
I0420 00:33:12.848323 15400 master.cpp:4500] Ignoring register agent message from slave(76)@10.0.2.15:41408 (archlinux.vagrant.vm) as admission is already in progress
I0420 00:33:12.849373 15402 replica.cpp:537] Replica received write request for position 3 from (3779)@10.0.2.15:41408
I0420 00:33:12.849591 15402 leveldb.cpp:341] Persisting action (381 bytes) to leveldb took 56531ns
I0420 00:33:12.849700 15402 replica.cpp:712] Persisted action at 3
I0420 00:33:12.850530 15402 replica.cpp:691] Replica received learned notice for position 3 from @0.0.0.0:0
I0420 00:33:12.850774 15402 leveldb.cpp:341] Persisting action (383 bytes) to leveldb took 37554ns
I0420 00:33:12.850862 15402 replica.cpp:712] Persisted action at 3
I0420 00:33:12.850985 15402 replica.cpp:697] Replica learned APPEND action at position 3
I0420 00:33:12.852195 15402 registrar.cpp:508] Successfully updated the 'registry' in 4.989952ms
I0420 00:33:12.852668 15395 log.cpp:567] Attempting to truncate the log to 3
I0420 00:33:12.852953 15401 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 4
I0420 00:33:12.853283 15397 master.cpp:4580] Registered agent 7cf5923c-3d03-4ed6-826a-efa97f54e765-S0 at slave(76)@10.0.2.15:41408 (archlinux.vagrant.vm) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0420 00:33:12.853458 15397 hierarchical.cpp:473] Added agent 7cf5923c-3d03-4ed6-826a-efa97f54e765-S0 (archlinux.vagrant.vm) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
I0420 00:33:12.853458 15396 slave.cpp:1122] Registered with master master@10.0.2.15:41408; given agent ID 7cf5923c-3d03-4ed6-826a-efa97f54e765-S0
I0420 00:33:12.854084 15396 slave.cpp:1182] Forwarding total oversubscribed resources
I0420 00:33:12.854123 15398 status_update_manager.cpp:181] Resuming sending status updates
I0420 00:33:12.854295 15402 master.cpp:4924] Received update of agent 7cf5923c-3d03-4ed6-826a-efa97f54e765-S0 at slave(76)@10.0.2.15:41408 (archlinux.vagrant.vm) with total oversubscribed resources
I0420 00:33:12.854722 15402 hierarchical.cpp:531] Agent 7cf5923c-3d03-4ed6-826a-efa97f54e765-S0 (archlinux.vagrant.vm) updated with oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: )
I0420 00:33:12.855062 15396 replica.cpp:537] Replica received write request for position 4 from (3780)@10.0.2.15:41408
I0420 00:33:12.855365 15396 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 130625ns
I0420 00:33:12.855507 15396 replica.cpp:712] Persisted action at 4
I0420 00:33:12.856474 15398 replica.cpp:691] Replica received learned notice for position 4 from @0.0.0.0:0
I0420 00:33:12.856557 15398 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 37939ns
I0420 00:33:12.856595 15398 leveldb.cpp:399] Deleting ~2 keys from leveldb took 15093ns
I0420 00:33:12.856617 15398 replica.cpp:712] Persisted action at 4
I0420 00:33:12.856632 15398 replica.cpp:697] Replica learned TRUNCATE action at position 4
I0420 00:33:12.895501 15381 sched.cpp:224] Version: 0.29.0
I0420 00:33:12.896266 15397 sched.cpp:328] New master detected at master@10.0.2.15:41408
I0420 00:33:12.896371 15397 sched.cpp:384] Authenticating with master master@10.0.2.15:41408
I0420 00:33:12.896396 15397 sched.cpp:391] Using default CRAM-MD5 authenticatee
I0420 00:33:12.896672 15399 authenticatee.cpp:121] Creating new client SASL connection
I0420 00:33:12.896965 15399 master.cpp:5801] Authenticating scheduler-5bd5e446-a017-45d9-8193-be7d23002487@10.0.2.15:41408
I0420 00:33:12.897411 15399 authenticator.cpp:98] Creating new server SASL connection
I0420 00:33:12.897600 15399 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
I0420 00:33:12.897644 15399 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
I0420 00:33:12.897754 15399 authenticator.cpp:203] Received SASL authentication start
I0420 00:33:12.897883 15399 authenticator.cpp:325] Authentication requires more steps
I0420 00:33:12.898066 15399 authenticatee.cpp:258] Received SASL authentication step
I0420 00:33:12.898208 15399 authenticator.cpp:231] Received SASL authentication step
I0420 00:33:12.898401 15399 authenticator.cpp:317] Authentication success
I0420 00:33:12.898542 15399 master.cpp:5831] Successfully authenticated principal 'test-principal' at scheduler-5bd5e446-a017-45d9-8193-be7d23002487@10.0.2.15:41408
I0420 00:33:12.898576 15400 authenticatee.cpp:298] Authentication success
I0420 00:33:12.898938 15400 sched.cpp:474] Successfully authenticated with master master@10.0.2.15:41408
I0420 00:33:12.899281 15400 master.cpp:2463] Received SUBSCRIBE call for framework 'default' at scheduler-5bd5e446-a017-45d9-8193-be7d23002487@10.0.2.15:41408
I0420 00:33:12.899384 15400 master.cpp:1971] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0420 00:33:12.899658 15395 master.cpp:2539] Subscribing framework default with checkpointing disabled and capabilities [ ]
I0420 00:33:12.900406 15395 sched.cpp:706] Framework registered with 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000
I0420 00:33:12.900682 15400 hierarchical.cpp:264] Added framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000
I0420 00:33:12.901666 15399 master.cpp:5630] Sending 1 offers to framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000 (default) at scheduler-5bd5e446-a017-45d9-8193-be7d23002487@10.0.2.15:41408
I0420 00:33:12.903337 15401 master.cpp:3410] Processing ACCEPT call for offers: [ 7cf5923c-3d03-4ed6-826a-efa97f54e765-O0 ] on agent 7cf5923c-3d03-4ed6-826a-efa97f54e765-S0 at slave(76)@10.0.2.15:41408 (archlinux.vagrant.vm) for framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000 (default) at scheduler-5bd5e446-a017-45d9-8193-be7d23002487@10.0.2.15:41408
I0420 00:33:12.903411 15401 master.cpp:3013] Authorizing framework principal 'test-principal' to launch task 1 as user 'vagrant'
I0420 00:33:12.904501 15399 master.hpp:177] Adding task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on agent 7cf5923c-3d03-4ed6-826a-efa97f54e765-S0 (archlinux.vagrant.vm)
I0420 00:33:12.904616 15399 master.cpp:3895] Launching task 1 of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000 (default) at scheduler-5bd5e446-a017-45d9-8193-be7d23002487@10.0.2.15:41408 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on agent 7cf5923c-3d03-4ed6-826a-efa97f54e765-S0 at slave(76)@10.0.2.15:41408 (archlinux.vagrant.vm)
I0420 00:33:12.904985 15401 slave.cpp:1514] Got assigned task 1 for framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000
I0420 00:33:12.905398 15401 slave.cpp:1633] Launching task 1 for framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000
I0420 00:33:12.905660 15401 paths.cpp:528] Trying to chown '/tmp/HealthCheckTest_HealthStatusChange_T3YdIF/slaves/7cf5923c-3d03-4ed6-826a-efa97f54e765-S0/frameworks/7cf5923c-3d03-4ed6-826a-efa97f54e765-0000/executors/1/runs/8e9198d4-5a23-40f2-b372-8130ec375783' to user 'vagrant'
I0420 00:33:12.909620 15401 slave.cpp:5620] Launching executor 1 of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/HealthCheckTest_HealthStatusChange_T3YdIF/slaves/7cf5923c-3d03-4ed6-826a-efa97f54e765-S0/frameworks/7cf5923c-3d03-4ed6-826a-efa97f54e765-0000/executors/1/runs/8e9198d4-5a23-40f2-b372-8130ec375783'
I0420 00:33:12.910140 15401 slave.cpp:1851] Queuing task '1' for executor '1' of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000
I0420 00:33:12.910404 15395 containerizer.cpp:698] Starting container '8e9198d4-5a23-40f2-b372-8130ec375783' for executor '1' of framework '7cf5923c-3d03-4ed6-826a-efa97f54e765-0000'
I0420 00:33:12.914448 15395 launcher.cpp:123] Forked child with pid '20895' for container '8e9198d4-5a23-40f2-b372-8130ec375783'
I0420 00:33:13.059639 20895 exec.cpp:150] Version: 0.29.0
I0420 00:33:13.065830 15399 slave.cpp:2842] Got registration for executor '1' of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000 from executor(1)@10.0.2.15:37107
I0420 00:33:13.067417 15402 slave.cpp:2016] Sending queued task '1' to executor '1' of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000 at executor(1)@10.0.2.15:37107
I0420 00:33:13.068193 20923 exec.cpp:225] Executor registered on agent 7cf5923c-3d03-4ed6-826a-efa97f54e765-S0
Registered executor on archlinux.vagrant.vm
Starting task 1
sh -c 'sleep 120'
Forked command at 20931
Launching health check process: /home/vagrant/build-mesos-default-opts/src/mesos-health-check --executor=(1)@10.0.2.15:37107 --health_check_json={"command":{"shell":true,"value":"rm \/tmp\/1NKfr1 || (touch \/tmp\/1NKfr1 && exit 1)"},"consecutive_failures":3,"delay_seconds":0.0,"grace_period_seconds":0.0,"interval_seconds":0.0,"timeout_seconds":20.0} --task_id=1
Health check process launched at pid: 20932
I0420 00:33:13.075927 15396 slave.cpp:3201] Handling status update TASK_RUNNING (UUID: 02c2030b-ec12-485c-83e8-5ae201178bea) for task 1 of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000 from executor(1)@10.0.2.15:37107
I0420 00:33:13.077280 15396 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 02c2030b-ec12-485c-83e8-5ae201178bea) for task 1 of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000
I0420 00:33:13.077841 15396 slave.cpp:3599] Forwarding the update TASK_RUNNING (UUID: 02c2030b-ec12-485c-83e8-5ae201178bea) for task 1 of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000 to master@10.0.2.15:41408
I0420 00:33:13.077960 15396 slave.cpp:3509] Sending acknowledgement for status update TASK_RUNNING (UUID: 02c2030b-ec12-485c-83e8-5ae201178bea) for task 1 of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000 to executor(1)@10.0.2.15:37107
I0420 00:33:13.078277 15397 master.cpp:5069] Status update TASK_RUNNING (UUID: 02c2030b-ec12-485c-83e8-5ae201178bea) for task 1 of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000 from agent 7cf5923c-3d03-4ed6-826a-efa97f54e765-S0 at slave(76)@10.0.2.15:41408 (archlinux.vagrant.vm)
I0420 00:33:13.078330 15397 master.cpp:5117] Forwarding status update TASK_RUNNING (UUID: 02c2030b-ec12-485c-83e8-5ae201178bea) for task 1 of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000
I0420 00:33:13.078431 15397 master.cpp:6725] Updating the state of task 1 of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
I0420 00:33:13.079056 15397 master.cpp:4224] Processing ACKNOWLEDGE call 02c2030b-ec12-485c-83e8-5ae201178bea for task 1 of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000 (default) at scheduler-5bd5e446-a017-45d9-8193-be7d23002487@10.0.2.15:41408 on agent 7cf5923c-3d03-4ed6-826a-efa97f54e765-S0
I0420 00:33:13.079445 15396 status_update_manager.cpp:392] Received status update acknowledgement (UUID: 02c2030b-ec12-485c-83e8-5ae201178bea) for task 1 of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000
Received task health update, healthy: true
I0420 00:33:13.302896 15396 slave.cpp:3201] Handling status update TASK_RUNNING (UUID: 8506a0b4-03cd-435c-bdfa-b88fffe1d977) for task 1 in health state healthy of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000 from executor(1)@10.0.2.15:37107
I0420 00:33:13.304239 15396 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 8506a0b4-03cd-435c-bdfa-b88fffe1d977) for task 1 in health state healthy of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000
I0420 00:33:13.304553 15396 slave.cpp:3599] Forwarding the update TASK_RUNNING (UUID: 8506a0b4-03cd-435c-bdfa-b88fffe1d977) for task 1 in health state healthy of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000 to master@10.0.2.15:41408
I0420 00:33:13.304700 15396 slave.cpp:3509] Sending acknowledgement for status update TASK_RUNNING (UUID: 8506a0b4-03cd-435c-bdfa-b88fffe1d977) for task 1 in health state healthy of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000 to executor(1)@10.0.2.15:37107
I0420 00:33:13.305068 15396 master.cpp:5069] Status update TASK_RUNNING (UUID: 8506a0b4-03cd-435c-bdfa-b88fffe1d977) for task 1 in health state healthy of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000 from agent 7cf5923c-3d03-4ed6-826a-efa97f54e765-S0 at slave(76)@10.0.2.15:41408 (archlinux.vagrant.vm)
I0420 00:33:13.305097 15396 master.cpp:5117] Forwarding status update TASK_RUNNING (UUID: 8506a0b4-03cd-435c-bdfa-b88fffe1d977) for task 1 in health state healthy of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000
I0420 00:33:13.305197 15396 master.cpp:6725] Updating the state of task 1 of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
I0420 00:33:13.306653 15396 master.cpp:4224] Processing ACKNOWLEDGE call 8506a0b4-03cd-435c-bdfa-b88fffe1d977 for task 1 of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000 (default) at scheduler-5bd5e446-a017-45d9-8193-be7d23002487@10.0.2.15:41408 on agent 7cf5923c-3d03-4ed6-826a-efa97f54e765-S0
I0420 00:33:13.307194 15395 status_update_manager.cpp:392] Received status update acknowledgement (UUID: 8506a0b4-03cd-435c-bdfa-b88fffe1d977) for task 1 of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000
rm: cannot remove '/tmp/1NKfr1': No such file or directory
I0420 00:33:13.308562 15401 http.cpp:313] HTTP GET for /master/state from 10.0.2.15:44472
I0420 00:33:13.314609 15396 http.cpp:178] HTTP GET for /slave(76)/state from 10.0.2.15:44474
Received task health update, healthy: false
I0420 00:33:13.489945 15396 slave.cpp:3201] Handling status update TASK_RUNNING (UUID: 34c9cab0-3f63-4ee6-b2a0-5db4e406afbd) for task 1 in health state unhealthy of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000 from executor(1)@10.0.2.15:37107
I0420 00:33:13.492075 15399 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 34c9cab0-3f63-4ee6-b2a0-5db4e406afbd) for task 1 in health state unhealthy of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000
I0420 00:33:13.492472 15400 slave.cpp:3599] Forwarding the update TASK_RUNNING (UUID: 34c9cab0-3f63-4ee6-b2a0-5db4e406afbd) for task 1 in health state unhealthy of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000 to master@10.0.2.15:41408
I0420 00:33:13.492743 15400 slave.cpp:3509] Sending acknowledgement for status update TASK_RUNNING (UUID: 34c9cab0-3f63-4ee6-b2a0-5db4e406afbd) for task 1 in health state unhealthy of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000 to executor(1)@10.0.2.15:37107
I0420 00:33:13.492822 15397 master.cpp:5069] Status update TASK_RUNNING (UUID: 34c9cab0-3f63-4ee6-b2a0-5db4e406afbd) for task 1 in health state unhealthy of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000 from agent 7cf5923c-3d03-4ed6-826a-efa97f54e765-S0 at slave(76)@10.0.2.15:41408 (archlinux.vagrant.vm)
I0420 00:33:13.492871 15397 master.cpp:5117] Forwarding status update TASK_RUNNING (UUID: 34c9cab0-3f63-4ee6-b2a0-5db4e406afbd) for task 1 in health state unhealthy of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000
I0420 00:33:13.493135 15397 master.cpp:6725] Updating the state of task 1 of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
I0420 00:33:13.493801 15398 master.cpp:4224] Processing ACKNOWLEDGE call 34c9cab0-3f63-4ee6-b2a0-5db4e406afbd for task 1 of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000 (default) at scheduler-5bd5e446-a017-45d9-8193-be7d23002487@10.0.2.15:41408 on agent 7cf5923c-3d03-4ed6-826a-efa97f54e765-S0
I0420 00:33:13.494067 15399 status_update_manager.cpp:392] Received status update acknowledgement (UUID: 34c9cab0-3f63-4ee6-b2a0-5db4e406afbd) for task 1 of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000
I0420 00:33:13.497138 15400 http.cpp:313] HTTP GET for /master/state from 10.0.2.15:44478
Received task health update, healthy: true
I0420 00:33:13.502598 15400 slave.cpp:3201] Handling status update TASK_RUNNING (UUID: e19c76cc-096a-4398-b616-afb628b8e5b8) for task 1 in health state healthy of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000 from executor(1)@10.0.2.15:37107
I0420 00:33:13.504456 15400 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: e19c76cc-096a-4398-b616-afb628b8e5b8) for task 1 in health state healthy of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000
I0420 00:33:13.505009 15400 slave.cpp:3599] Forwarding the update TASK_RUNNING (UUID: e19c76cc-096a-4398-b616-afb628b8e5b8) for task 1 in health state healthy of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000 to master@10.0.2.15:41408
I0420 00:33:13.505167 15400 slave.cpp:3509] Sending acknowledgement for status update TASK_RUNNING (UUID: e19c76cc-096a-4398-b616-afb628b8e5b8) for task 1 in health state healthy of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000 to executor(1)@10.0.2.15:37107
I0420 00:33:13.505524 15400 master.cpp:5069] Status update TASK_RUNNING (UUID: e19c76cc-096a-4398-b616-afb628b8e5b8) for task 1 in health state healthy of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000 from agent 7cf5923c-3d03-4ed6-826a-efa97f54e765-S0 at slave(76)@10.0.2.15:41408 (archlinux.vagrant.vm)
I0420 00:33:13.505602 15400 master.cpp:5117] Forwarding status update TASK_RUNNING (UUID: e19c76cc-096a-4398-b616-afb628b8e5b8) for task 1 in health state healthy of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000
I0420 00:33:13.505738 15400 master.cpp:6725] Updating the state of task 1 of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
I0420 00:33:13.505985 15400 master.cpp:4224] Processing ACKNOWLEDGE call e19c76cc-096a-4398-b616-afb628b8e5b8 for task 1 of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000 (default) at scheduler-5bd5e446-a017-45d9-8193-be7d23002487@10.0.2.15:41408 on agent 7cf5923c-3d03-4ed6-826a-efa97f54e765-S0
I0420 00:33:13.506142 15400 status_update_manager.cpp:392] Received status update acknowledgement (UUID: e19c76cc-096a-4398-b616-afb628b8e5b8) for task 1 of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000
rm: cannot remove '/tmp/1NKfr1': No such file or directory
I0420 00:33:13.508203 15400 http.cpp:178] HTTP GET for /slave(76)/state from 10.0.2.15:44482
../../mesos/src/tests/health_check_tests.cpp:647: Failure
Value of: (find).get()
Actual: 16-byte object <05-00 00-00 00-00 00-00 90-C4 2D-03 00-00 00-00>
Expected: false
Which is: false
*** Aborted at 1461076393 (unix time) try "date -d @1461076393" if you are using GNU date ***
PC: @ 0x1899ba0 testing::UnitTest::AddTestPartResult()
*** SIGSEGV (@0x0) received by PID 15381 (TID 0x7f0aa958a7c0) from PID 0; stack trace: ***
@ 0x7f0aa3259e80 (unknown)
@ 0x1899ba0 testing::UnitTest::AddTestPartResult()
@ 0x188e319 testing::internal::AssertHelper::operator=()
@ 0xdfa79a mesos::internal::tests::HealthCheckTest_HealthStatusChange_Test::TestBody()
@ 0x18b7e16 testing::internal::HandleSehExceptionsInMethodIfSupported<>()
@ 0x18b2e52 testing::internal::HandleExceptionsInMethodIfSupported<>()
@ 0x189379e testing::Test::Run()
@ 0x1893f56 testing::TestInfo::Run()
@ 0x18945a7 testing::TestCase::Run()
@ 0x189b0e5 testing::internal::UnitTestImpl::RunAllTests()
@ 0x18b8add testing::internal::HandleSehExceptionsInMethodIfSupported<>()
@ 0x18b3992 testing::internal::HandleExceptionsInMethodIfSupported<>()
@ 0x1899dc1 testing::UnitTest::Run()
Received task health update, healthy: false
@ 0xf9375c RUN_ALL_TESTS()
I0420 00:33:13.603853 15399 slave.cpp:3201] Handling status update TASK_RUNNING (UUID: 1b2154a8-6f83-4b4a-a811-1db971288986) for task 1 in health state unhealthy of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000 from executor(1)@10.0.2.15:37107
@ 0xf93378 main
@ 0x7f0aa27b7710 __libc_start_main
I0420 00:33:13.605831 15399 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 1b2154a8-6f83-4b4a-a811-1db971288986) for task 1 in health state unhealthy of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000
I0420 00:33:13.606142 15399 slave.cpp:3599] Forwarding the update TASK_RUNNING (UUID: 1b2154a8-6f83-4b4a-a811-1db971288986) for task 1 in health state unhealthy of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000 to master@10.0.2.15:41408
I0420 00:33:13.606263 15399 slave.cpp:3509] Sending acknowledgement for status update TASK_RUNNING (UUID: 1b2154a8-6f83-4b4a-a811-1db971288986) for task 1 in health state unhealthy of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000 to executor(1)@10.0.2.15:37107
I0420 00:33:13.606644 15399 master.cpp:5069] Status update TASK_RUNNING (UUID: 1b2154a8-6f83-4b4a-a811-1db971288986) for task 1 in health state unhealthy of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000 from agent 7cf5923c-3d03-4ed6-826a-efa97f54e765-S0 at slave(76)@10.0.2.15:41408 (archlinux.vagrant.vm)
I0420 00:33:13.606685 15399 master.cpp:5117] Forwarding status update TASK_RUNNING (UUID: 1b2154a8-6f83-4b4a-a811-1db971288986) for task 1 in health state unhealthy of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000
I0420 00:33:13.606780 15399 master.cpp:6725] Updating the state of task 1 of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
I0420 00:33:13.607326 15399 master.cpp:4224] Processing ACKNOWLEDGE call 1b2154a8-6f83-4b4a-a811-1db971288986 for task 1 of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000 (default) at scheduler-5bd5e446-a017-45d9-8193-be7d23002487@10.0.2.15:41408 on agent 7cf5923c-3d03-4ed6-826a-efa97f54e765-S0
I0420 00:33:13.607579 15399 status_update_manager.cpp:392] Received status update acknowledgement (UUID: 1b2154a8-6f83-4b4a-a811-1db971288986) for task 1 of framework 7cf5923c-3d03-4ed6-826a-efa97f54e765-0000
@ 0xa644d9 _start
@ 0x0 (unknown)
I0420 00:33:13.701517 20926 exec.cpp:481] Agent exited ... shutting down
Segmentation fault (core dumped)
vagrant@archlinux:~/build-mesos-default-opts$ Received task health update, healthy: true
Shutting down
Sending SIGTERM to process tree at pid 20931
E0420 00:33:13.705188 20930 process.cpp:1963] Failed to shutdown socket with fd 11: Transport endpoint is not connected
rm: cannot remove '/tmp/1NKfr1': No such file or directory
Sent SIGTERM to the following process trees:
[
--- 20931 sleep 120
]
Command terminated with signal Terminated (pid: 20931)
E0420 00:33:13.786746 20930 process.cpp:1963] Failed to shutdown socket with fd 8: Transport endpoint is not connected
{code}
This test case have another tricky part. We could not guarantee the http queries order match the statusUpdate order. When we send http queries, master have already received the statusUpdate multiple times.
And because {{mesos-health-check}} is launched by {{subprocess}}, could not controlled by {{Clock::pause()}}. Seems not way to ensure http queries are match expected behaviour in this test case.
> 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, tests
> Affects Versions: 0.26.0
> Reporter: Benjamin Mahler
> Assignee: haosdent
> Labels: flaky, health-check, mesosphere
> Attachments: health_check_flaky_test_log.txt
>
>
> 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 : master@67.195.81.186: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 master@67.195.81.186: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 master@67.195.81.186:47865
> I0916 22:56:14.058485 21047 slave.cpp:674] Authenticating with master master@67.195.81.186:47865
> I0916 22:56:14.058506 21042 status_update_manager.cpp:167] New master detected at master@67.195.81.186: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 master@67.195.81.186: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 master@67.195.81.186:47865
> I0916 22:56:14.059730 21041 sched.cpp:283] Authenticating with master master@67.195.81.186: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 scheduler-59427aee-c9d1-45c7-96fc-12d0d48529a4@67.195.81.186: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 scheduler-59427aee-c9d1-45c7-96fc-12d0d48529a4@67.195.81.186:47865
> I0916 22:56:14.060480 21046 sched.cpp:357] Successfully authenticated with master master@67.195.81.186:47865
> I0916 22:56:14.060499 21046 sched.cpp:476] Sending registration request to master@67.195.81.186:47865
> I0916 22:56:14.060564 21050 master.cpp:1331] Received registration request from scheduler-59427aee-c9d1-45c7-96fc-12d0d48529a4@67.195.81.186: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 scheduler-59427aee-c9d1-45c7-96fc-12d0d48529a4@67.195.81.186: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 master@67.195.81.186: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 master@67.195.81.186: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 master@67.195.81.186: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 master@67.195.81.186: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] master@67.195.81.186: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)