Andrei Sekretenko created MESOS-10025:
-----------------------------------------
Summary: SlaveRecoveryTest/0.MasterFailover is flaky
Key: MESOS-10025
URL: https://issues.apache.org/jira/browse/MESOS-10025
Project: Mesos
Issue Type: Bug
Reporter: Andrei Sekretenko
Observed in internal CI on Mac in SSL build:
{code}
[ RUN ] SlaveRecoveryTest/0.MasterFailover
I1101 06:38:44.995235 331212224 cluster.cpp:177] Creating default 'local'
authorizer
I1101 06:38:44.997287 331212224 leveldb.cpp:174] Opened db in 1.89771ms
I1101 06:38:44.997844 331212224 leveldb.cpp:181] Compacted db in 528218ns
I1101 06:38:44.997884 331212224 leveldb.cpp:196] Created db iterator in 22023ns
I1101 06:38:44.997915 331212224 leveldb.cpp:202] Seeked to beginning of db in
15019ns
I1101 06:38:44.997946 331212224 leveldb.cpp:277] Iterated through 0 keys in the
db in 15493ns
I1101 06:38:44.997982 331212224 replica.cpp:795] Replica recovered with log
positions 0 -> 0 with 1 holes and 0 unlearned
I1101 06:38:44.998242 35291136 recover.cpp:437] Starting replica recovery
I1101 06:38:44.998492 34754560 recover.cpp:468] Replica is in EMPTY status
I1101 06:38:44.999156 36900864 replica.cpp:677] Replica in EMPTY status
received a broadcasted recover request from __req_res__(2262)@10.0.49.4:50652
I1101 06:38:44.999436 37974016 recover.cpp:197] Received a recover response
from a replica in EMPTY status
I1101 06:38:44.999634 36364288 recover.cpp:564] Updating replica status to
STARTING
I1101 06:38:45.000180 36900864 leveldb.cpp:310] Persisting metadata (8 bytes)
to leveldb took 335386ns
I1101 06:38:45.000216 36900864 replica.cpp:322] Persisted replica status to
STARTING
I1101 06:38:45.000524 35291136 recover.cpp:468] Replica is in STARTING status
I1101 06:38:45.000517 34217984 master.cpp:440] Master
dc415259-fb19-4aaf-b0fa-5c27ddcf33af (Jenkinss-Mac-mini.local) started on
10.0.49.4:50652
I1101 06:38:45.000583 34217984 master.cpp:443] Flags at startup: --acls=""
--agent_ping_timeout="15secs" --agent_reregister_timeout="10mins"
--allocation_interval="1secs" --allocator="hierarchical"
--authenticate_agents="true" --authenticate_frameworks="true"
--authenticate_http_frameworks="true" --authenticate_http_readonly="true"
--authenticate_http_readwrite="true" --authentication_v0_timeout="15secs"
--authenticators="crammd5" --authorizers="local"
--credentials="/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/rBzUi3/credentials"
--filter_gpu_resources="true" --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_agent_ping_timeouts="5" --max_completed_frameworks="50"
--max_completed_tasks_per_framework="1000"
--max_operator_event_stream_subscribers="1000"
--max_unreachable_tasks_per_framework="1000" --memory_profiling="false"
--min_allocatable_resources="cpus:0.01|mem:32" --port="5050"
--publish_per_framework_metrics="true" --quiet="false"
--recovery_agent_removal_limit="100%" --registry="replicated_log"
--registry_fetch_timeout="1mins" --registry_gc_interval="15mins"
--registry_max_agent_age="2weeks" --registry_max_agent_count="102400"
--registry_store_timeout="100secs" --registry_strict="false"
--require_agent_domain="false" --role_sorter="drf" --root_submissions="true"
--version="false" --webui_dir="/usr/local/share/mesos/webui"
--work_dir="/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/rBzUi3/master"
--zk_session_timeout="10secs"
I1101 06:38:45.000885 34217984 master.cpp:492] Master only allowing
authenticated frameworks to register
I1101 06:38:45.000897 34217984 master.cpp:498] Master only allowing
authenticated agents to register
I1101 06:38:45.000906 34217984 master.cpp:504] Master only allowing
authenticated HTTP frameworks to register
I1101 06:38:45.000938 34217984 credentials.hpp:37] Loading credentials for
authentication from
'/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/rBzUi3/credentials'
I1101 06:38:45.001150 34217984 master.cpp:548] Using default 'crammd5'
authenticator
I1101 06:38:45.001220 34217984 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-readonly'
I1101 06:38:45.001293 34217984 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-readwrite'
I1101 06:38:45.001339 34217984 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-scheduler'
I1101 06:38:45.001384 34217984 master.cpp:629] Authorization enabled
I1101 06:38:45.001549 36900864 replica.cpp:677] Replica in STARTING status
received a broadcasted recover request from __req_res__(2263)@10.0.49.4:50652
I1101 06:38:45.001629 35291136 hierarchical.cpp:567] Initialized hierarchical
allocator process
I1101 06:38:45.001816 34754560 whitelist_watcher.cpp:77] No whitelist given
I1101 06:38:45.002208 36900864 recover.cpp:197] Received a recover response
from a replica in STARTING status
I1101 06:38:45.002557 36364288 recover.cpp:564] Updating replica status to
VOTING
I1101 06:38:45.003129 37437440 leveldb.cpp:310] Persisting metadata (8 bytes)
to leveldb took 330664ns
I1101 06:38:45.003165 37437440 replica.cpp:322] Persisted replica status to
VOTING
I1101 06:38:45.003275 35291136 recover.cpp:578] Successfully joined the Paxos
group
I1101 06:38:45.003463 35291136 recover.cpp:447] Recover process terminated
I1101 06:38:45.004142 35291136 master.cpp:2169] Elected as the leading master!
I1101 06:38:45.004159 35291136 master.cpp:1665] Recovering from registrar
I1101 06:38:45.004223 34754560 registrar.cpp:339] Recovering registrar
I1101 06:38:45.004628 37437440 log.cpp:554] Attempting to start the writer
I1101 06:38:45.005187 36364288 replica.cpp:497] Replica received implicit
promise request from __req_res__(2264)@10.0.49.4:50652 with proposal 1
I1101 06:38:45.005503 36364288 leveldb.cpp:310] Persisting metadata (8 bytes)
to leveldb took 301157ns
I1101 06:38:45.005530 36364288 replica.cpp:344] Persisted promised to 1
I1101 06:38:45.005829 35827712 coordinator.cpp:238] Coordinator attempting to
fill missing positions
I1101 06:38:45.006225 37437440 replica.cpp:391] Replica received explicit
promise request from __req_res__(2265)@10.0.49.4:50652 for position 0 with
proposal 2
I1101 06:38:45.006481 37437440 leveldb.cpp:347] Persisting action (8 bytes) to
leveldb took 241451ns
I1101 06:38:45.006510 37437440 replica.cpp:712] Persisted action NOP at
position 0
I1101 06:38:45.006924 36364288 replica.cpp:541] Replica received write request
for position 0 from __req_res__(2266)@10.0.49.4:50652
I1101 06:38:45.006968 36364288 leveldb.cpp:460] Reading position from leveldb
took 31279ns
I1101 06:38:45.007233 36364288 leveldb.cpp:347] Persisting action (14 bytes) to
leveldb took 243498ns
I1101 06:38:45.007259 36364288 replica.cpp:712] Persisted action NOP at
position 0
I1101 06:38:45.007540 35291136 replica.cpp:695] Replica received learned notice
for position 0 from log-network(110)@10.0.49.4:50652
I1101 06:38:45.007786 35291136 leveldb.cpp:347] Persisting action (16 bytes) to
leveldb took 237077ns
I1101 06:38:45.007813 35291136 replica.cpp:712] Persisted action NOP at
position 0
I1101 06:38:45.008095 37974016 log.cpp:570] Writer started with ending position 0
I1101 06:38:45.008496 36364288 leveldb.cpp:460] Reading position from leveldb
took 26536ns
I1101 06:38:45.008867 34217984 registrar.cpp:383] Successfully fetched the
registry (0B) in 4.596992ms
I1101 06:38:45.008947 34217984 registrar.cpp:487] Applied 1 operations in
35015ns; attempting to update the registry
I1101 06:38:45.009217 36364288 log.cpp:578] Attempting to append 203 bytes to
the log
I1101 06:38:45.009261 36900864 coordinator.cpp:348] Coordinator attempting to
write APPEND action at position 1
I1101 06:38:45.009584 37437440 replica.cpp:541] Replica received write request
for position 1 from __req_res__(2267)@10.0.49.4:50652
I1101 06:38:45.009963 37437440 leveldb.cpp:347] Persisting action (222 bytes)
to leveldb took 363581ns
I1101 06:38:45.009990 37437440 replica.cpp:712] Persisted action APPEND at
position 1
I1101 06:38:45.010289 34754560 replica.cpp:695] Replica received learned notice
for position 1 from log-network(110)@10.0.49.4:50652
I1101 06:38:45.010577 34754560 leveldb.cpp:347] Persisting action (224 bytes)
to leveldb took 274162ns
I1101 06:38:45.010605 34754560 replica.cpp:712] Persisted action APPEND at
position 1
I1101 06:38:45.010949 35827712 registrar.cpp:544] Successfully updated the
registry in 1.965824ms
I1101 06:38:45.011042 35827712 registrar.cpp:416] Successfully recovered
registrar
I1101 06:38:45.011237 34217984 log.cpp:597] Attempting to truncate the log to 1
I1101 06:38:45.011296 36364288 master.cpp:1818] Recovered 0 agents from the
registry (164B); allowing 10mins for agents to reregister
I1101 06:38:45.011373 37974016 coordinator.cpp:348] Coordinator attempting to
write TRUNCATE action at position 2
I1101 06:38:45.011396 35291136 hierarchical.cpp:606] Skipping recovery of
hierarchical allocator: nothing to recover
I1101 06:38:45.011793 35291136 replica.cpp:541] Replica received write request
for position 2 from __req_res__(2268)@10.0.49.4:50652
I1101 06:38:45.012087 35291136 leveldb.cpp:347] Persisting action (16 bytes) to
leveldb took 274591ns
I1101 06:38:45.012120 35291136 replica.cpp:712] Persisted action TRUNCATE at
position 2
I1101 06:38:45.012516 36900864 replica.cpp:695] Replica received learned notice
for position 2 from log-network(110)@10.0.49.4:50652
I1101 06:38:45.012822 36900864 leveldb.cpp:347] Persisting action (18 bytes) to
leveldb took 269844ns
I1101 06:38:45.012902 36900864 leveldb.cpp:423] Deleting ~1 keys from leveldb
took 53888ns
I1101 06:38:45.012929 36900864 replica.cpp:712] Persisted action TRUNCATE at
position 2
I1101 06:38:45.016438 331212224 containerizer.cpp:318] Using isolation {
environment_secret, filesystem/posix, posix/mem, posix/cpu }
I1101 06:38:45.016708 331212224 provisioner.cpp:294] Using default backend
'copy'
W1101 06:38:45.018498 331212224 process.cpp:2877] Attempted to spawn already
running process files@10.0.49.4:50652
I1101 06:38:45.018898 331212224 cluster.cpp:524] Creating default 'local'
authorizer
I1101 06:38:45.019861 37974016 slave.cpp:267] Mesos agent started on
(584)@10.0.49.4:50652
I1101 06:38:45.019887 37974016 slave.cpp:268] Flags at startup: --acls=""
--appc_simple_discovery_uri_prefix="http://";
--appc_store_dir="/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/rBzUi3/thymz0/store/appc"
--authenticate_http_executors="true" --authenticate_http_readonly="true"
--authenticate_http_readwrite="true" --authenticatee="crammd5"
--authentication_backoff_factor="1secs" --authentication_timeout_max="1mins"
--authentication_timeout_min="5secs" --authorizer="local"
--container_disk_watch_interval="15secs" --containerizers="mesos"
--credential="/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/rBzUi3/thymz0/credential"
--default_role="*" --disk_watch_interval="1mins" --docker="docker"
--docker_ignore_runtime="false" --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="/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/rBzUi3/thymz0/store/docker"
--docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume"
--docker_volume_chown="false" --enforce_container_disk_quota="false"
--executor_registration_timeout="1mins"
--executor_reregistration_timeout="2secs"
--executor_shutdown_grace_period="5secs"
--fetcher_cache_dir="/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/rBzUi3/thymz0/fetch"
--fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins"
--frameworks_home="/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/rBzUi3/thymz0/frameworks"
--gc_delay="1weeks" --gc_disk_headroom="0.1"
--gc_non_executor_container_sandboxes="false" --help="false"
--hostname_lookup="true" --http_command_executor="false"
--http_credentials="/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/rBzUi3/thymz0/http_credentials"
--http_heartbeat_interval="30secs" --initialize_driver_logging="true"
--isolation="posix/cpu,posix/mem"
--jwt_secret_key="/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/rBzUi3/thymz0/jwt_secret_key"
--launcher="posix"
--launcher_dir="/Users/jenkins/workspace/workspace/mesos/Mesos_CI-build/FLAG/SSL/label/mac/mesos/build/src"
--logbufsecs="0" --logging_level="INFO"
--max_completed_executors_per_framework="150" --memory_profiling="false"
--network_cni_metrics="true" --network_cni_root_dir_persist="false"
--oversubscribed_resources_interval="15secs" --port="5051"
--qos_correction_interval_min="0ns" --quiet="false"
--reconfiguration_policy="equal" --recover="reconnect"
--recovery_timeout="15mins" --registration_backoff_factor="10ms"
--resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]"
--runtime_dir="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_MasterFailover_C19Enw"
--sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true"
--version="false"
--work_dir="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_MasterFailover_aukJ13"
--zk_session_timeout="10secs"
I1101 06:38:45.020129 37974016 credentials.hpp:86] Loading credential for
authentication from
'/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/rBzUi3/thymz0/credential'
I1101 06:38:45.020262 37974016 slave.cpp:300] Agent using credential for:
test-principal
I1101 06:38:45.020277 37974016 credentials.hpp:37] Loading credentials for
authentication from
'/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/rBzUi3/thymz0/http_credentials'
W1101 06:38:45.020457 331212224 process.cpp:2877] Attempted to spawn already
running process version@10.0.49.4:50652
I1101 06:38:45.020478 37974016 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-executor'
I1101 06:38:45.020540 37974016 http.cpp:996] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-executor'
I1101 06:38:45.020620 37974016 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-readonly'
I1101 06:38:45.020658 37974016 http.cpp:996] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-readonly'
I1101 06:38:45.020771 37974016 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-readwrite'
I1101 06:38:45.020817 37974016 http.cpp:996] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-readwrite'
I1101 06:38:45.020963 37974016 disk_profile_adaptor.cpp:78] Creating default
disk profile adaptor module
I1101 06:38:45.021327 37974016 slave.cpp:615] Agent resources:
[{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
I1101 06:38:45.021461 37974016 slave.cpp:623] Agent attributes: [ ]
I1101 06:38:45.021473 37974016 slave.cpp:632] Agent hostname:
Jenkinss-Mac-mini.local
I1101 06:38:45.021621 34217984 task_status_update_manager.cpp:181] Pausing
sending task status updates
I1101 06:38:45.021656 34754560 status_update_manager_process.hpp:379] Pausing
operation status update manager
I1101 06:38:45.022272 331212224 sched.cpp:239] Version: 1.10.0
I1101 06:38:45.022290 37437440 state.cpp:67] Recovering state from
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_MasterFailover_aukJ13/meta'
I1101 06:38:45.022477 34217984 slave.cpp:7492] Finished recovering checkpointed
state from
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_MasterFailover_aukJ13/meta',
beginning agent recovery
I1101 06:38:45.022589 36900864 sched.cpp:343] New master detected at
master@10.0.49.4:50652
I1101 06:38:45.022634 37974016 task_status_update_manager.cpp:207] Recovering
task status update manager
I1101 06:38:45.022688 36900864 sched.cpp:408] Authenticating with master
master@10.0.49.4:50652
I1101 06:38:45.022718 36900864 sched.cpp:415] Using default CRAM-MD5
authenticatee
I1101 06:38:45.022936 35827712 authenticatee.cpp:121] Creating new client SASL
connection
I1101 06:38:45.022965 37437440 containerizer.cpp:821] Recovering Mesos
containers
I1101 06:38:45.023097 37437440 containerizer.cpp:1161] Recovering isolators
I1101 06:38:45.023258 35291136 master.cpp:10594] Authenticating
scheduler-f3be4608-7102-4746-b118-24b725a298a8@10.0.49.4:50652
I1101 06:38:45.023468 34217984 authenticator.cpp:414] Starting authentication
session for crammd5-authenticatee(1164)@10.0.49.4:50652
I1101 06:38:45.023612 35827712 authenticator.cpp:98] Creating new server SASL
connection
I1101 06:38:45.023648 36900864 containerizer.cpp:1200] Recovering provisioner
I1101 06:38:45.023797 36364288 authenticatee.cpp:213] Received SASL
authentication mechanisms: CRAM-MD5
I1101 06:38:45.023823 36364288 authenticatee.cpp:239] Attempting to
authenticate with mechanism 'CRAM-MD5'
I1101 06:38:45.023902 37974016 authenticator.cpp:204] Received SASL
authentication start
I1101 06:38:45.024022 37974016 authenticator.cpp:326] Authentication requires
more steps
I1101 06:38:45.024086 34217984 provisioner.cpp:518] Provisioner recovery
complete
I1101 06:38:45.024113 37437440 authenticatee.cpp:259] Received SASL
authentication step
I1101 06:38:45.024237 35827712 authenticator.cpp:232] Received SASL
authentication step
I1101 06:38:45.024276 35827712 auxprop.cpp:109] Request to lookup properties
for user: 'test-principal' realm: 'Jenkinss-Mac-mini.local' server FQDN:
'Jenkinss-Mac-mini.local' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1101 06:38:45.024291 35827712 auxprop.cpp:181] Looking up auxiliary property
'*userPassword'
I1101 06:38:45.024318 35827712 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I1101 06:38:45.024334 35827712 auxprop.cpp:109] Request to lookup properties
for user: 'test-principal' realm: 'Jenkinss-Mac-mini.local' server FQDN:
'Jenkinss-Mac-mini.local' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1101 06:38:45.024346 35827712 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I1101 06:38:45.024354 35827712 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1101 06:38:45.024369 35827712 authenticator.cpp:318] Authentication success
I1101 06:38:45.024518 37437440 master.cpp:10626] Successfully authenticated
principal 'test-principal' at
scheduler-f3be4608-7102-4746-b118-24b725a298a8@10.0.49.4:50652
I1101 06:38:45.024592 37974016 authenticatee.cpp:299] Authentication success
I1101 06:38:45.024648 36900864 authenticator.cpp:432] Authentication session
cleanup for crammd5-authenticatee(1164)@10.0.49.4:50652
I1101 06:38:45.024997 35827712 sched.cpp:520] Successfully authenticated with
master master@10.0.49.4:50652
I1101 06:38:45.025017 35827712 sched.cpp:835] Sending SUBSCRIBE call to
master@10.0.49.4:50652
I1101 06:38:45.025115 35827712 sched.cpp:870] Will retry registration in
1.223096833secs if necessary
I1101 06:38:45.025137 34217984 composing.cpp:339] Finished recovering all
containerizers
I1101 06:38:45.025321 36364288 slave.cpp:7974] Recovering executors
I1101 06:38:45.025318 36900864 master.cpp:2909] Received SUBSCRIBE call for
framework 'default' at
scheduler-f3be4608-7102-4746-b118-24b725a298a8@10.0.49.4:50652
I1101 06:38:45.025347 36900864 master.cpp:2241] Authorizing framework principal
'test-principal' to receive offers for roles '{ * }'
I1101 06:38:45.025375 36364288 slave.cpp:8127] Finished recovery
I1101 06:38:45.025667 37974016 master.cpp:2996] Subscribing framework default
with checkpointing enabled and capabilities [ MULTI_ROLE,
RESERVATION_REFINEMENT ]
I1101 06:38:45.026289 37974016 master.cpp:10824] Adding framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000 (default) at
scheduler-f3be4608-7102-4746-b118-24b725a298a8@10.0.49.4:50652 with roles { }
suppressed
I1101 06:38:45.026594 34754560 slave.cpp:1351] New master detected at
master@10.0.49.4:50652
I1101 06:38:45.026638 34754560 slave.cpp:1416] Detecting new master
I1101 06:38:45.026721 36900864 hierarchical.cpp:700] Added framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000
I1101 06:38:45.026737 37974016 status_update_manager_process.hpp:379] Pausing
operation status update manager
I1101 06:38:45.026753 36364288 task_status_update_manager.cpp:181] Pausing
sending task status updates
I1101 06:38:45.026878 36900864 hierarchical.cpp:1853] Performed allocation for
0 agents in 64417ns
I1101 06:38:45.026947 35291136 sched.cpp:751] Framework registered with
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000
I1101 06:38:45.026994 35291136 sched.cpp:770] Scheduler::registered took 39285ns
I1101 06:38:45.037878 35291136 slave.cpp:1443] Authenticating with master
master@10.0.49.4:50652
I1101 06:38:45.037943 35291136 slave.cpp:1452] Using default CRAM-MD5
authenticatee
I1101 06:38:45.038182 34754560 authenticatee.cpp:121] Creating new client SASL
connection
I1101 06:38:45.038336 37974016 master.cpp:10594] Authenticating
slave(584)@10.0.49.4:50652
I1101 06:38:45.038388 36364288 authenticator.cpp:414] Starting authentication
session for crammd5-authenticatee(1165)@10.0.49.4:50652
I1101 06:38:45.038554 36900864 authenticator.cpp:98] Creating new server SASL
connection
I1101 06:38:45.038712 37437440 authenticatee.cpp:213] Received SASL
authentication mechanisms: CRAM-MD5
I1101 06:38:45.038739 37437440 authenticatee.cpp:239] Attempting to
authenticate with mechanism 'CRAM-MD5'
I1101 06:38:45.038834 35291136 authenticator.cpp:204] Received SASL
authentication start
I1101 06:38:45.038939 35291136 authenticator.cpp:326] Authentication requires
more steps
I1101 06:38:45.039103 34217984 authenticatee.cpp:259] Received SASL
authentication step
I1101 06:38:45.039191 34754560 authenticator.cpp:232] Received SASL
authentication step
I1101 06:38:45.039222 34754560 auxprop.cpp:109] Request to lookup properties
for user: 'test-principal' realm: 'Jenkinss-Mac-mini.local' server FQDN:
'Jenkinss-Mac-mini.local' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1101 06:38:45.039234 34754560 auxprop.cpp:181] Looking up auxiliary property
'*userPassword'
I1101 06:38:45.039273 34754560 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I1101 06:38:45.039288 34754560 auxprop.cpp:109] Request to lookup properties
for user: 'test-principal' realm: 'Jenkinss-Mac-mini.local' server FQDN:
'Jenkinss-Mac-mini.local' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1101 06:38:45.039335 34754560 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I1101 06:38:45.039363 34754560 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1101 06:38:45.039379 34754560 authenticator.cpp:318] Authentication success
I1101 06:38:45.039518 37974016 authenticatee.cpp:299] Authentication success
I1101 06:38:45.039559 35827712 master.cpp:10626] Successfully authenticated
principal 'test-principal' at slave(584)@10.0.49.4:50652
I1101 06:38:45.039636 36364288 authenticator.cpp:432] Authentication session
cleanup for crammd5-authenticatee(1165)@10.0.49.4:50652
I1101 06:38:45.039875 36900864 slave.cpp:1543] Successfully authenticated with
master master@10.0.49.4:50652
I1101 06:38:45.040375 36900864 slave.cpp:1993] Will retry registration in
2.665978ms if necessary
I1101 06:38:45.040597 35827712 master.cpp:7083] Received register agent message
from slave(584)@10.0.49.4:50652 (Jenkinss-Mac-mini.local)
I1101 06:38:45.040736 35827712 master.cpp:4189] Authorizing agent providing
resources 'cpus:2; mem:1024; disk:1024; ports:[31000-32000]' with principal
'test-principal'
I1101 06:38:45.041226 34217984 master.cpp:7150] Authorized registration of
agent at slave(584)@10.0.49.4:50652 (Jenkinss-Mac-mini.local)
I1101 06:38:45.041287 34217984 master.cpp:7262] Registering agent at
slave(584)@10.0.49.4:50652 (Jenkinss-Mac-mini.local) with id
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-S0
I1101 06:38:45.041661 36364288 registrar.cpp:487] Applied 1 operations in
173958ns; attempting to update the registry
I1101 06:38:44.907867 37437440 log.cpp:578] Attempting to append 383 bytes to
the log
I1101 06:38:44.908424 34754560 coordinator.cpp:348] Coordinator attempting to
write APPEND action at position 3
I1101 06:38:44.909652 34754560 replica.cpp:541] Replica received write request
for position 3 from __req_res__(2269)@10.0.49.4:50652
I1101 06:38:44.909955 34754560 leveldb.cpp:347] Persisting action (402 bytes)
to leveldb took 282118ns
I1101 06:38:44.910001 34754560 replica.cpp:712] Persisted action APPEND at
position 3
I1101 06:38:44.910552 36900864 replica.cpp:695] Replica received learned notice
for position 3 from log-network(110)@10.0.49.4:50652
I1101 06:38:44.910861 36900864 leveldb.cpp:347] Persisting action (404 bytes)
to leveldb took 299631ns
I1101 06:38:44.910895 36900864 replica.cpp:712] Persisted action APPEND at
position 3
I1101 06:38:44.911396 35827712 registrar.cpp:544] Successfully updated the
registry in -130.309888ms
I1101 06:38:44.911518 36364288 master.cpp:7310] Admitted agent
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-S0 at slave(584)@10.0.49.4:50652
(Jenkinss-Mac-mini.local)
I1101 06:38:44.911556 37437440 log.cpp:597] Attempting to truncate the log to 3
I1101 06:38:44.911628 36900864 coordinator.cpp:348] Coordinator attempting to
write TRUNCATE action at position 4
I1101 06:38:44.911875 36364288 master.cpp:7355] Registered agent
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-S0 at slave(584)@10.0.49.4:50652
(Jenkinss-Mac-mini.local) with cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I1101 06:38:44.912003 35291136 slave.cpp:1576] Registered with master
master@10.0.49.4:50652; given agent ID dc415259-fb19-4aaf-b0fa-5c27ddcf33af-S0
I1101 06:38:44.912015 35827712 hierarchical.cpp:959] Added agent
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-S0 (Jenkinss-Mac-mini.local) with cpus:2;
mem:1024; disk:1024; ports:[31000-32000] (offered or allocated: {})
I1101 06:38:44.912323 34217984 task_status_update_manager.cpp:188] Resuming
sending task status updates
I1101 06:38:44.912490 35291136 slave.cpp:1611] Checkpointing SlaveInfo to
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_MasterFailover_aukJ13/meta/slaves/dc415259-fb19-4aaf-b0fa-5c27ddcf33af-S0/slave.info'
I1101 06:38:44.912503 37437440 replica.cpp:541] Replica received write request
for position 4 from __req_res__(2270)@10.0.49.4:50652
I1101 06:38:44.912573 35827712 hierarchical.cpp:1853] Performed allocation for
1 agents in 373439ns
I1101 06:38:44.912700 36900864 status_update_manager_process.hpp:385] Resuming
operation status update manager
I1101 06:38:44.912900 37437440 leveldb.cpp:347] Persisting action (16 bytes) to
leveldb took 386753ns
I1101 06:38:44.912933 37437440 replica.cpp:712] Persisted action TRUNCATE at
position 4
I1101 06:38:44.912964 34754560 master.cpp:10409] Sending offers [
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-O0 ] to framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000 (default) at
scheduler-f3be4608-7102-4746-b118-24b725a298a8@10.0.49.4:50652
I1101 06:38:44.913416 36364288 sched.cpp:934] Scheduler::resourceOffers took
73013ns
I1101 06:38:44.913413 35291136 slave.cpp:1663] Forwarding agent update
{"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"IrX7OwYnRDuxvqQiXafUaA=="},"slave_id":{"value":"dc415259-fb19-4aaf-b0fa-5c27ddcf33af-S0"},"update_oversubscribed_resources":false}
I1101 06:38:44.913949 37437440 master.cpp:8474] Ignoring update on agent
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-S0 at slave(584)@10.0.49.4:50652
(Jenkinss-Mac-mini.local) as it reports no changes
I1101 06:38:44.914034 36900864 replica.cpp:695] Replica received learned notice
for position 4 from log-network(110)@10.0.49.4:50652
I1101 06:38:44.914439 36900864 leveldb.cpp:347] Persisting action (18 bytes) to
leveldb took 396603ns
I1101 06:38:44.914597 36900864 leveldb.cpp:423] Deleting ~2 keys from leveldb
took 119787ns
I1101 06:38:44.914635 36900864 replica.cpp:712] Persisted action TRUNCATE at
position 4
I1101 06:38:44.915402 36364288 master.cpp:4719] Processing ACCEPT call for
offers: [ dc415259-fb19-4aaf-b0fa-5c27ddcf33af-O0 ] on agent
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-S0 at slave(584)@10.0.49.4:50652
(Jenkinss-Mac-mini.local) for framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000 (default) at
scheduler-f3be4608-7102-4746-b118-24b725a298a8@10.0.49.4:50652
I1101 06:38:44.915474 36364288 master.cpp:3743] Authorizing framework principal
'test-principal' to launch task 65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0
I1101 06:38:44.916115 34754560 master.cpp:12706] Removing offer
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-O0
I1101 06:38:44.916790 34754560 master.cpp:4287] Adding task
65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0 with resources ports(allocated:
*):[31000-32000]; cpus(allocated: *):2; mem(allocated: *):1024; disk(allocated:
*):1024 of framework dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000 (default) at
scheduler-f3be4608-7102-4746-b118-24b725a298a8@10.0.49.4:50652 on agent
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-S0 at slave(584)@10.0.49.4:50652
(Jenkinss-Mac-mini.local)
I1101 06:38:44.917024 34754560 master.cpp:5714] Launching task
65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0 of framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000 (default) at
scheduler-f3be4608-7102-4746-b118-24b725a298a8@10.0.49.4:50652 with resources
[{"allocation_info":{"role":"*"},"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"},{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"}]
on agent dc415259-fb19-4aaf-b0fa-5c27ddcf33af-S0 at slave(584)@10.0.49.4:50652
(Jenkinss-Mac-mini.local) on new executor
I1101 06:38:44.917491 36364288 hierarchical.cpp:1777] Allocation paused
I1101 06:38:44.917838 36364288 hierarchical.cpp:1787] Allocation resumed
I1101 06:38:44.918128 35291136 slave.cpp:2130] Got assigned task
'65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0' for framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000
I1101 06:38:44.918252 35291136 slave.cpp:9918] Checkpointing FrameworkInfo to
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_MasterFailover_aukJ13/meta/slaves/dc415259-fb19-4aaf-b0fa-5c27ddcf33af-S0/frameworks/dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000/framework.info'
I1101 06:38:44.919081 35291136 slave.cpp:9929] Checkpointing framework pid
'scheduler-f3be4608-7102-4746-b118-24b725a298a8@10.0.49.4:50652' to
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_MasterFailover_aukJ13/meta/slaves/dc415259-fb19-4aaf-b0fa-5c27ddcf33af-S0/frameworks/dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000/framework.pid'
I1101 06:38:44.920230 35291136 slave.cpp:2504] Authorizing task
'65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0' for framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000
I1101 06:38:44.920276 35291136 slave.cpp:9466] Authorizing framework principal
'test-principal' to launch task 65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0
I1101 06:38:44.921336 35291136 slave.cpp:2977] Launching task
'65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0' for framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000
I1101 06:38:44.921406 35291136 paths.cpp:817] Creating sandbox
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_MasterFailover_aukJ13/slaves/dc415259-fb19-4aaf-b0fa-5c27ddcf33af-S0/frameworks/dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000/executors/65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0/runs/3f06cb00-7b15-4d42-8a04-d577df9f86cd'
for user 'jenkins'
I1101 06:38:44.922765 35291136 slave.cpp:10716] Checkpointing ExecutorInfo to
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_MasterFailover_aukJ13/meta/slaves/dc415259-fb19-4aaf-b0fa-5c27ddcf33af-S0/frameworks/dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000/executors/65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0/executor.info'
I1101 06:38:44.923818 35291136 paths.cpp:820] Creating sandbox
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_MasterFailover_aukJ13/meta/slaves/dc415259-fb19-4aaf-b0fa-5c27ddcf33af-S0/frameworks/dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000/executors/65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0/runs/3f06cb00-7b15-4d42-8a04-d577df9f86cd'
I1101 06:38:44.924314 35291136 slave.cpp:10004] Launching executor
'65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0' of framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000 with resources
[{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":32.0},"type":"SCALAR"}]
in work directory
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_MasterFailover_aukJ13/slaves/dc415259-fb19-4aaf-b0fa-5c27ddcf33af-S0/frameworks/dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000/executors/65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0/runs/3f06cb00-7b15-4d42-8a04-d577df9f86cd'
I1101 06:38:44.924942 35291136 slave.cpp:10747] Checkpointing TaskInfo to
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_MasterFailover_aukJ13/meta/slaves/dc415259-fb19-4aaf-b0fa-5c27ddcf33af-S0/frameworks/dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000/executors/65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0/runs/3f06cb00-7b15-4d42-8a04-d577df9f86cd/tasks/65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0/task.info'
I1101 06:38:44.925963 35291136 slave.cpp:3209] Queued task
'65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0' for executor
'65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0' of framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000
I1101 06:38:44.926425 35291136 slave.cpp:1084] Successfully attached
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_MasterFailover_aukJ13/slaves/dc415259-fb19-4aaf-b0fa-5c27ddcf33af-S0/frameworks/dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000/executors/65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0/runs/3f06cb00-7b15-4d42-8a04-d577df9f86cd'
to virtual path
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_MasterFailover_aukJ13/slaves/dc415259-fb19-4aaf-b0fa-5c27ddcf33af-S0/frameworks/dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000/executors/65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0/runs/latest'
I1101 06:38:44.926465 35291136 slave.cpp:1084] Successfully attached
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_MasterFailover_aukJ13/slaves/dc415259-fb19-4aaf-b0fa-5c27ddcf33af-S0/frameworks/dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000/executors/65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0/runs/3f06cb00-7b15-4d42-8a04-d577df9f86cd'
to virtual path
'/frameworks/dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000/executors/65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0/runs/latest'
I1101 06:38:44.926534 35291136 slave.cpp:1084] Successfully attached
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_MasterFailover_aukJ13/slaves/dc415259-fb19-4aaf-b0fa-5c27ddcf33af-S0/frameworks/dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000/executors/65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0/runs/3f06cb00-7b15-4d42-8a04-d577df9f86cd'
to virtual path
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_MasterFailover_aukJ13/slaves/dc415259-fb19-4aaf-b0fa-5c27ddcf33af-S0/frameworks/dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000/executors/65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0/runs/3f06cb00-7b15-4d42-8a04-d577df9f86cd'
I1101 06:38:44.926744 35291136 slave.cpp:3657] Launching container
3f06cb00-7b15-4d42-8a04-d577df9f86cd for executor
'65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0' of framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000
I1101 06:38:44.927006 34754560 containerizer.cpp:1396] Starting container
3f06cb00-7b15-4d42-8a04-d577df9f86cd
I1101 06:38:44.927376 34754560 containerizer.cpp:3318] Transitioning the state
of container 3f06cb00-7b15-4d42-8a04-d577df9f86cd from STARTING to PROVISIONING
after 94976ns
I1101 06:38:44.928032 34754560 containerizer.cpp:1574] Checkpointed
ContainerConfig at
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_MasterFailover_C19Enw/containers/3f06cb00-7b15-4d42-8a04-d577df9f86cd/config'
I1101 06:38:44.928056 34754560 containerizer.cpp:3318] Transitioning the state
of container 3f06cb00-7b15-4d42-8a04-d577df9f86cd from PROVISIONING to
PREPARING after 678912ns
I1101 06:38:44.930408 37437440 containerizer.cpp:2100] Launching
'mesos-containerizer' with flags '--help="false"
--launch_info="{"command":{"arguments":["mesos-executor","--launcher_dir=/Users/jenkins/workspace/workspace/mesos/Mesos_CI-build/FLAG/SSL/label/mac/mesos/build/src"],"shell":false,"value":"/Users/jenkins/workspace/workspace/mesos/Mesos_CI-build/FLAG/SSL/label/mac/mesos/build/src/mesos-executor"},"environment":{"variables":[{"name":"LIBPROCESS_PORT","type":"VALUE","value":"0"},{"name":"MESOS_AGENT_ENDPOINT","type":"VALUE","value":"10.0.49.4:50652"},{"name":"MESOS_CHECKPOINT","type":"VALUE","value":"1"},{"name":"MESOS_DIRECTORY","type":"VALUE","value":"/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_MasterFailover_aukJ13/slaves/dc415259-fb19-4aaf-b0fa-5c27ddcf33af-S0/frameworks/dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000/executors/65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0/runs/3f06cb00-7b15-4d42-8a04-d577df9f86cd"},{"name":"MESOS_EXECUTOR_AUTHENTICATION_TOKEN","type":"VALUE","value":"eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJjaWQiOiIzZjA2Y2IwMC03YjE1LTRkNDItOGEwNC1kNTc3ZGY5Zjg2Y2QiLCJlaWQiOiI2NTIwMWE3ZC1iOGZjLTQ4Y2QtOWNlMy1lMThjM2E4M2U0ZjAiLCJmaWQiOiJkYzQxNTI1OS1mYjE5LTRhYWYtYjBmYS01YzI3ZGRjZjMzYWYtMDAwMCJ9.kVhfg9GbbjUa_Lh9mmW7rkPaCfwH3hjKmzGxhNg7Hec"},{"name":"MESOS_EXECUTOR_ID","type":"VALUE","value":"65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0"},{"name":"MESOS_EXECUTOR_SHUTDOWN_GRACE_PERIOD","type":"VALUE","value":"5secs"},{"name":"MESOS_FRAMEWORK_ID","type":"VALUE","value":"dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000"},{"name":"MESOS_HTTP_COMMAND_EXECUTOR","type":"VALUE","value":"0"},{"name":"MESOS_RECOVERY_TIMEOUT","type":"VALUE","value":"15mins"},{"name":"MESOS_SLAVE_ID","type":"VALUE","value":"dc415259-fb19-4aaf-b0fa-5c27ddcf33af-S0"},{"name":"MESOS_SLAVE_PID","type":"VALUE","value":"slave(584)@10.0.49.4:50652"},{"name":"MESOS_SUBSCRIPTION_BACKOFF_MAX","type":"VALUE","value":"2secs"},{"name":"MESOS_SANDBOX","type":"VALUE","value":"/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_MasterFailover_aukJ13/slaves/dc415259-fb19-4aaf-b0fa-5c27ddcf33af-S0/frameworks/dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000/executors/65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0/runs/3f06cb00-7b15-4d42-8a04-d577df9f86cd"}]},"task_environment":{},"user":"jenkins","working_directory":"/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_MasterFailover_aukJ13/slaves/dc415259-fb19-4aaf-b0fa-5c27ddcf33af-S0/frameworks/dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000/executors/65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0/runs/3f06cb00-7b15-4d42-8a04-d577df9f86cd"}"
--pipe_read="28" --pipe_write="36"
--runtime_directory="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_MasterFailover_C19Enw/containers/3f06cb00-7b15-4d42-8a04-d577df9f86cd"'
I1101 06:38:44.932206 37437440 launcher.cpp:145] Forked child with pid '55357'
for container '3f06cb00-7b15-4d42-8a04-d577df9f86cd'
I1101 06:38:44.932386 37437440 containerizer.cpp:2209] Checkpointing
container's forked pid 55357 to
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_MasterFailover_aukJ13/meta/slaves/dc415259-fb19-4aaf-b0fa-5c27ddcf33af-S0/frameworks/dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000/executors/65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0/runs/3f06cb00-7b15-4d42-8a04-d577df9f86cd/pids/forked.pid'
I1101 06:38:44.934087 37437440 containerizer.cpp:3318] Transitioning the state
of container 3f06cb00-7b15-4d42-8a04-d577df9f86cd from PREPARING to ISOLATING
after 6.023936ms
I1101 06:38:44.935716 37437440 containerizer.cpp:3318] Transitioning the state
of container 3f06cb00-7b15-4d42-8a04-d577df9f86cd from ISOLATING to FETCHING
after 1.634048ms
I1101 06:38:44.936398 34754560 fetcher.cpp:369] Starting to fetch URIs for
container: 3f06cb00-7b15-4d42-8a04-d577df9f86cd, directory:
/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_MasterFailover_aukJ13/slaves/dc415259-fb19-4aaf-b0fa-5c27ddcf33af-S0/frameworks/dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000/executors/65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0/runs/3f06cb00-7b15-4d42-8a04-d577df9f86cd
I1101 06:38:44.937178 37974016 containerizer.cpp:3318] Transitioning the state
of container 3f06cb00-7b15-4d42-8a04-d577df9f86cd from FETCHING to RUNNING
after 1.443072ms
[warn] kq_init: detected broken kqueue; not using.: Undefined error: 0
I1101 06:38:45.967288 258213312 exec.cpp:164] Version: 1.10.0
I1101 06:38:45.970611 37974016 slave.cpp:5256] Got registration for executor
'65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0' of framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000 from executor(1)@10.0.49.4:52737
I1101 06:38:45.971005 37974016 slave.cpp:5342] Checkpointing executor pid
'executor(1)@10.0.49.4:52737' to
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_MasterFailover_aukJ13/meta/slaves/dc415259-fb19-4aaf-b0fa-5c27ddcf33af-S0/frameworks/dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000/executors/65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0/runs/3f06cb00-7b15-4d42-8a04-d577df9f86cd/pids/libprocess.pid'
I1101 06:38:45.972788 132202496 exec.cpp:237] Executor registered on agent
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-S0
I1101 06:38:45.972786 34217984 slave.cpp:3427] Sending queued task
'65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0' to executor
'65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0' of framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000 at executor(1)@10.0.49.4:52737
I1101 06:38:45.976541 132739072 executor.cpp:190] Received SUBSCRIBED event
I1101 06:38:45.977003 132739072 executor.cpp:194] Subscribed executor on
Jenkinss-Mac-mini.local
I1101 06:38:45.977129 132739072 executor.cpp:190] Received LAUNCH event
I1101 06:38:45.980144 132739072 executor.cpp:722] Starting task
65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0
I1101 06:38:45.983518 35827712 slave.cpp:5737] Handling status update
TASK_STARTING (Status UUID: c5df164e-d763-4592-9c46-22561c7d55f5) for task
65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0 of framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000 from executor(1)@10.0.49.4:52737
I1101 06:38:45.984509 37437440 task_status_update_manager.cpp:328] Received
task status update TASK_STARTING (Status UUID:
c5df164e-d763-4592-9c46-22561c7d55f5) for task
65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0 of framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000
I1101 06:38:45.984552 37437440 task_status_update_manager.cpp:507] Creating
StatusUpdate stream for task 65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0 of framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000
I1101 06:38:45.985193 37437440 task_status_update_manager.cpp:842]
Checkpointing UPDATE for task status update TASK_STARTING (Status UUID:
c5df164e-d763-4592-9c46-22561c7d55f5) for task
65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0 of framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000
I1101 06:38:45.985380 37437440 task_status_update_manager.cpp:383] Forwarding
task status update TASK_STARTING (Status UUID:
c5df164e-d763-4592-9c46-22561c7d55f5) for task
65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0 of framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000 to the agent
I1101 06:38:45.985460 34217984 slave.cpp:6277] Forwarding the update
TASK_STARTING (Status UUID: c5df164e-d763-4592-9c46-22561c7d55f5) for task
65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0 of framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000 to master@10.0.49.4:50652
I1101 06:38:45.985617 34217984 slave.cpp:6161] Task status update manager
successfully handled status update TASK_STARTING (Status UUID:
c5df164e-d763-4592-9c46-22561c7d55f5) for task
65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0 of framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000
I1101 06:38:45.985648 35827712 master.cpp:8956] Status update TASK_STARTING
(Status UUID: c5df164e-d763-4592-9c46-22561c7d55f5) for task
65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0 of framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000 from agent
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-S0 at slave(584)@10.0.49.4:50652
(Jenkinss-Mac-mini.local)
I1101 06:38:45.985687 35827712 master.cpp:9013] Forwarding status update
TASK_STARTING (Status UUID: c5df164e-d763-4592-9c46-22561c7d55f5) for task
65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0 of framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000
I1101 06:38:45.985683 34217984 slave.cpp:6188] Sending acknowledgement for
status update TASK_STARTING (Status UUID: c5df164e-d763-4592-9c46-22561c7d55f5)
for task 65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0 of framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000 to executor(1)@10.0.49.4:52737
I1101 06:38:45.985810 35827712 master.cpp:12023] Updating the state of task
65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0 of framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000 (latest state: TASK_STARTING, status
update state: TASK_STARTING)
I1101 06:38:45.986008 36900864 sched.cpp:1042] Scheduler::statusUpdate took
42788ns
I1101 06:38:45.986207 36364288 master.cpp:6690] Processing ACKNOWLEDGE call for
status c5df164e-d763-4592-9c46-22561c7d55f5 for task
65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0 of framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000 (default) at
scheduler-f3be4608-7102-4746-b118-24b725a298a8@10.0.49.4:50652 on agent
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-S0
I1101 06:38:45.986419 37974016 task_status_update_manager.cpp:401] Received
task status update acknowledgement (UUID: c5df164e-d763-4592-9c46-22561c7d55f5)
for task 65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0 of framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000
I1101 06:38:45.986467 37974016 task_status_update_manager.cpp:842]
Checkpointing ACK for task status update TASK_STARTING (Status UUID:
c5df164e-d763-4592-9c46-22561c7d55f5) for task
65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0 of framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000
I1101 06:38:45.986778 35291136 slave.cpp:4866] Task status update manager
successfully handled status update acknowledgement (UUID:
c5df164e-d763-4592-9c46-22561c7d55f5) for task
65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0 of framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000
I1101 06:38:45.989995 132739072 executor.cpp:740] Forked command at 55385
I1101 06:38:45.994843 37437440 slave.cpp:5737] Handling status update
TASK_RUNNING (Status UUID: ff8638ce-5c18-4c5e-be68-98473d2ad4e1) for task
65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0 of framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000 from executor(1)@10.0.49.4:52737
I1101 06:38:45.995831 34754560 task_status_update_manager.cpp:328] Received
task status update TASK_RUNNING (Status UUID:
ff8638ce-5c18-4c5e-be68-98473d2ad4e1) for task
65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0 of framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000
I1101 06:38:45.995877 34754560 task_status_update_manager.cpp:842]
Checkpointing UPDATE for task status update TASK_RUNNING (Status UUID:
ff8638ce-5c18-4c5e-be68-98473d2ad4e1) for task
65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0 of framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000
I1101 06:38:45.996107 34754560 task_status_update_manager.cpp:383] Forwarding
task status update TASK_RUNNING (Status UUID:
ff8638ce-5c18-4c5e-be68-98473d2ad4e1) for task
65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0 of framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000 to the agent
I1101 06:38:45.996217 37974016 slave.cpp:6277] Forwarding the update
TASK_RUNNING (Status UUID: ff8638ce-5c18-4c5e-be68-98473d2ad4e1) for task
65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0 of framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000 to master@10.0.49.4:50652
I1101 06:38:45.996327 37974016 slave.cpp:6161] Task status update manager
successfully handled status update TASK_RUNNING (Status UUID:
ff8638ce-5c18-4c5e-be68-98473d2ad4e1) for task
65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0 of framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000
I1101 06:38:45.996381 37974016 slave.cpp:6188] Sending acknowledgement for
status update TASK_RUNNING (Status UUID: ff8638ce-5c18-4c5e-be68-98473d2ad4e1)
for task 65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0 of framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000 to executor(1)@10.0.49.4:52737
I1101 06:38:45.996484 35291136 master.cpp:8956] Status update TASK_RUNNING
(Status UUID: ff8638ce-5c18-4c5e-be68-98473d2ad4e1) for task
65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0 of framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000 from agent
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-S0 at slave(584)@10.0.49.4:50652
(Jenkinss-Mac-mini.local)
I1101 06:38:45.996534 35291136 master.cpp:9013] Forwarding status update
TASK_RUNNING (Status UUID: ff8638ce-5c18-4c5e-be68-98473d2ad4e1) for task
65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0 of framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000
I1101 06:38:45.996709 35291136 master.cpp:12023] Updating the state of task
65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0 of framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000 (latest state: TASK_RUNNING, status
update state: TASK_RUNNING)
I1101 06:38:45.996888 37437440 sched.cpp:1042] Scheduler::statusUpdate took
35192ns
I1101 06:38:45.997120 35827712 master.cpp:6690] Processing ACKNOWLEDGE call for
status ff8638ce-5c18-4c5e-be68-98473d2ad4e1 for task
65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0 of framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000 (default) at
scheduler-f3be4608-7102-4746-b118-24b725a298a8@10.0.49.4:50652 on agent
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-S0
I1101 06:38:45.997395 36364288 task_status_update_manager.cpp:401] Received
task status update acknowledgement (UUID: ff8638ce-5c18-4c5e-be68-98473d2ad4e1)
for task 65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0 of framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000
I1101 06:38:45.997447 36364288 task_status_update_manager.cpp:842]
Checkpointing ACK for task status update TASK_RUNNING (Status UUID:
ff8638ce-5c18-4c5e-be68-98473d2ad4e1) for task
65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0 of framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000
I1101 06:38:45.997689 34217984 slave.cpp:4866] Task status update manager
successfully handled status update acknowledgement (UUID:
ff8638ce-5c18-4c5e-be68-98473d2ad4e1) for task
65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0 of framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000
I1101 06:38:45.997920 36364288 slave.cpp:924] Agent terminating
I1101 06:38:45.998342 35291136 master.cpp:1296] Agent
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-S0 at slave(584)@10.0.49.4:50652
(Jenkinss-Mac-mini.local) disconnected
I1101 06:38:45.998358 35291136 master.cpp:3391] Disconnecting agent
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-S0 at slave(584)@10.0.49.4:50652
(Jenkinss-Mac-mini.local)
I1101 06:38:45.998419 35291136 master.cpp:3410] Deactivating agent
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-S0 at slave(584)@10.0.49.4:50652
(Jenkinss-Mac-mini.local)
I1101 06:38:45.998600 34217984 hierarchical.cpp:1156] Agent
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-S0 deactivated
I1101 06:38:45.998603 35291136 master.cpp:1137] Master terminating
W1101 06:38:45.998786 35291136 master.cpp:12108] Removing task
65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0 with resources ports(allocated:
*):[31000-32000]; cpus(allocated: *):2; mem(allocated: *):1024; disk(allocated:
*):1024 of framework dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000 on agent
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-S0 at slave(584)@10.0.49.4:50652
(Jenkinss-Mac-mini.local) in non-terminal state TASK_RUNNING
I1101 06:38:45.999450 37974016 hierarchical.cpp:1132] Removed all filters for
agent dc415259-fb19-4aaf-b0fa-5c27ddcf33af-S0
I1101 06:38:45.999467 37974016 hierarchical.cpp:1008] Removed agent
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-S0
I1101 06:38:45.999693 37974016 hierarchical.cpp:757] Removed framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000
I1101 06:38:46.001935 37974016 hierarchical.cpp:1853] Performed allocation for
0 agents in 55874ns
I1101 06:38:46.004272 331212224 cluster.cpp:177] Creating default 'local'
authorizer
I1101 06:38:46.007431 331212224 leveldb.cpp:174] Opened db in 3.015938ms
I1101 06:38:46.009451 331212224 leveldb.cpp:181] Compacted db in 1.975536ms
I1101 06:38:46.009505 331212224 leveldb.cpp:196] Created db iterator in 25312ns
I1101 06:38:46.009546 331212224 leveldb.cpp:202] Seeked to beginning of db in
25236ns
I1101 06:38:46.009626 331212224 leveldb.cpp:277] Iterated through 3 keys in the
db in 80013ns
I1101 06:38:46.009685 331212224 replica.cpp:795] Replica recovered with log
positions 3 -> 4 with 0 holes and 0 unlearned
I1101 06:38:46.009996 37437440 recover.cpp:437] Starting replica recovery
I1101 06:38:46.010381 35291136 recover.cpp:468] Replica is in VOTING status
I1101 06:38:46.010543 35291136 recover.cpp:447] Recover process terminated
I1101 06:38:46.012109 36364288 master.cpp:440] Master
11ceefb6-cec0-4eb1-b166-8cb28152b2bb (Jenkinss-Mac-mini.local) started on
10.0.49.4:50652
I1101 06:38:46.012135 36364288 master.cpp:443] Flags at startup: --acls=""
--agent_ping_timeout="15secs" --agent_reregister_timeout="10mins"
--allocation_interval="1secs" --allocator="hierarchical"
--authenticate_agents="true" --authenticate_frameworks="true"
--authenticate_http_frameworks="true" --authenticate_http_readonly="true"
--authenticate_http_readwrite="true" --authentication_v0_timeout="15secs"
--authenticators="crammd5" --authorizers="local"
--credentials="/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/rBzUi3/credentials"
--filter_gpu_resources="true" --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_agent_ping_timeouts="5" --max_completed_frameworks="50"
--max_completed_tasks_per_framework="1000"
--max_operator_event_stream_subscribers="1000"
--max_unreachable_tasks_per_framework="1000" --memory_profiling="false"
--min_allocatable_resources="cpus:0.01|mem:32" --port="5050"
--publish_per_framework_metrics="true" --quiet="false"
--recovery_agent_removal_limit="100%" --registry="replicated_log"
--registry_fetch_timeout="1mins" --registry_gc_interval="15mins"
--registry_max_agent_age="2weeks" --registry_max_agent_count="102400"
--registry_store_timeout="100secs" --registry_strict="false"
--require_agent_domain="false" --role_sorter="drf" --root_submissions="true"
--version="false" --webui_dir="/usr/local/share/mesos/webui"
--work_dir="/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/rBzUi3/master"
--zk_session_timeout="10secs"
I1101 06:38:46.012367 36364288 master.cpp:492] Master only allowing
authenticated frameworks to register
I1101 06:38:46.012378 36364288 master.cpp:498] Master only allowing
authenticated agents to register
I1101 06:38:46.012387 36364288 master.cpp:504] Master only allowing
authenticated HTTP frameworks to register
I1101 06:38:46.012394 36364288 credentials.hpp:37] Loading credentials for
authentication from
'/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/rBzUi3/credentials'
I1101 06:38:46.012598 36364288 master.cpp:548] Using default 'crammd5'
authenticator
I1101 06:38:46.012692 36364288 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-readonly'
I1101 06:38:46.012781 36364288 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-readwrite'
I1101 06:38:46.012830 36364288 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-scheduler'
I1101 06:38:46.012873 36364288 master.cpp:629] Authorization enabled
I1101 06:38:46.013073 36900864 whitelist_watcher.cpp:77] No whitelist given
I1101 06:38:46.013113 37974016 hierarchical.cpp:567] Initialized hierarchical
allocator process
I1101 06:38:46.015974 36900864 master.cpp:2169] Elected as the leading master!
I1101 06:38:46.016073 36900864 master.cpp:1665] Recovering from registrar
I1101 06:38:46.016207 34754560 registrar.cpp:339] Recovering registrar
I1101 06:38:46.016444 34217984 log.cpp:554] Attempting to start the writer
I1101 06:38:46.017000 35827712 replica.cpp:497] Replica received implicit
promise request from __req_res__(2271)@10.0.49.4:50652 with proposal 2
I1101 06:38:46.021705 35827712 leveldb.cpp:310] Persisting metadata (8 bytes)
to leveldb took 4.691321ms
I1101 06:38:46.021760 35827712 replica.cpp:344] Persisted promised to 2
I1101 06:38:46.022136 34217984 coordinator.cpp:238] Coordinator attempting to
fill missing positions
I1101 06:38:46.022275 35827712 log.cpp:570] Writer started with ending position
4
I1101 06:38:46.022707 34754560 leveldb.cpp:460] Reading position from leveldb
took 47888ns
I1101 06:38:46.022795 34754560 leveldb.cpp:460] Reading position from leveldb
took 50122ns
I1101 06:38:46.023236 37974016 registrar.cpp:383] Successfully fetched the
registry (344B) in 7008us
I1101 06:38:46.023361 37974016 registrar.cpp:487] Applied 1 operations in
50272ns; attempting to update the registry
I1101 06:38:46.023623 34754560 log.cpp:578] Attempting to append 383 bytes to
the log
I1101 06:38:46.023669 34217984 coordinator.cpp:348] Coordinator attempting to
write APPEND action at position 5
I1101 06:38:46.023988 34217984 replica.cpp:541] Replica received write request
for position 5 from __req_res__(2272)@10.0.49.4:50652
I1101 06:38:46.024312 34217984 leveldb.cpp:347] Persisting action (402 bytes)
to leveldb took 329855ns
I1101 06:38:46.024359 34217984 replica.cpp:712] Persisted action APPEND at
position 5
I1101 06:38:46.024683 37437440 replica.cpp:695] Replica received learned notice
for position 5 from log-network(111)@10.0.49.4:50652
I1101 06:38:46.024927 37437440 leveldb.cpp:347] Persisting action (404 bytes)
to leveldb took 231082ns
I1101 06:38:46.024955 37437440 replica.cpp:712] Persisted action APPEND at
position 5
I1101 06:38:46.025300 37974016 registrar.cpp:544] Successfully updated the
registry in 1.907968ms
I1101 06:38:46.025444 37974016 registrar.cpp:416] Successfully recovered
registrar
I1101 06:38:46.025470 34754560 log.cpp:597] Attempting to truncate the log to 5
I1101 06:38:46.025575 34217984 coordinator.cpp:348] Coordinator attempting to
write TRUNCATE action at position 6
I1101 06:38:46.025954 37437440 master.cpp:1818] Recovered 1 agents from the
registry (344B); allowing 10mins for agents to reregister
I1101 06:38:46.025972 35291136 hierarchical.cpp:606] Skipping recovery of
hierarchical allocator: nothing to recover
I1101 06:38:46.026253 37974016 replica.cpp:541] Replica received write request
for position 6 from __req_res__(2273)@10.0.49.4:50652
I1101 06:38:46.026588 37974016 leveldb.cpp:347] Persisting action (16 bytes) to
leveldb took 305763ns
I1101 06:38:46.026623 37974016 replica.cpp:712] Persisted action TRUNCATE at
position 6
I1101 06:38:46.027000 36900864 replica.cpp:695] Replica received learned notice
for position 6 from log-network(111)@10.0.49.4:50652
I1101 06:38:46.027225 36900864 leveldb.cpp:347] Persisting action (18 bytes) to
leveldb took 212843ns
I1101 06:38:46.027290 36900864 leveldb.cpp:423] Deleting ~2 keys from leveldb
took 47782ns
I1101 06:38:46.027319 36900864 replica.cpp:712] Persisted action TRUNCATE at
position 6
I1101 06:38:46.027933 35827712 sched.cpp:337] Scheduler::disconnected took
24661ns
I1101 06:38:46.027954 35827712 sched.cpp:343] New master detected at
master@10.0.49.4:50652
I1101 06:38:46.028053 35827712 sched.cpp:408] Authenticating with master
master@10.0.49.4:50652
I1101 06:38:46.028067 35827712 sched.cpp:415] Using default CRAM-MD5
authenticatee
I1101 06:38:46.028173 37974016 authenticatee.cpp:121] Creating new client SASL
connection
I1101 06:38:46.028318 37437440 master.cpp:10594] Authenticating
scheduler-f3be4608-7102-4746-b118-24b725a298a8@10.0.49.4:50652
I1101 06:38:46.028368 34754560 authenticator.cpp:414] Starting authentication
session for crammd5-authenticatee(1166)@10.0.49.4:50652
I1101 06:38:46.028525 34217984 authenticator.cpp:98] Creating new server SASL
connection
I1101 06:38:46.028615 35291136 authenticatee.cpp:213] Received SASL
authentication mechanisms: CRAM-MD5
I1101 06:38:46.028640 35291136 authenticatee.cpp:239] Attempting to
authenticate with mechanism 'CRAM-MD5'
I1101 06:38:46.028702 36900864 authenticator.cpp:204] Received SASL
authentication start
I1101 06:38:46.028784 36900864 authenticator.cpp:326] Authentication requires
more steps
I1101 06:38:46.028832 37974016 authenticatee.cpp:259] Received SASL
authentication step
I1101 06:38:46.028930 35827712 authenticator.cpp:232] Received SASL
authentication step
I1101 06:38:46.028949 35827712 auxprop.cpp:109] Request to lookup properties
for user: 'test-principal' realm: 'Jenkinss-Mac-mini.local' server FQDN:
'Jenkinss-Mac-mini.local' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1101 06:38:46.028959 35827712 auxprop.cpp:181] Looking up auxiliary property
'*userPassword'
I1101 06:38:46.028980 35827712 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I1101 06:38:46.028993 35827712 auxprop.cpp:109] Request to lookup properties
for user: 'test-principal' realm: 'Jenkinss-Mac-mini.local' server FQDN:
'Jenkinss-Mac-mini.local' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1101 06:38:46.029004 35827712 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I1101 06:38:46.029013 35827712 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1101 06:38:46.029026 35827712 authenticator.cpp:318] Authentication success
I1101 06:38:46.029080 36364288 authenticatee.cpp:299] Authentication success
I1101 06:38:46.029153 37437440 master.cpp:10626] Successfully authenticated
principal 'test-principal' at
scheduler-f3be4608-7102-4746-b118-24b725a298a8@10.0.49.4:50652
I1101 06:38:46.029204 34754560 authenticator.cpp:432] Authentication session
cleanup for crammd5-authenticatee(1166)@10.0.49.4:50652
I1101 06:38:46.029295 34217984 sched.cpp:520] Successfully authenticated with
master master@10.0.49.4:50652
I1101 06:38:46.029448 34217984 sched.cpp:835] Sending SUBSCRIBE call to
master@10.0.49.4:50652
I1101 06:38:46.029551 34217984 sched.cpp:870] Will retry registration in
201.216675ms if necessary
I1101 06:38:46.029644 35827712 master.cpp:2909] Received SUBSCRIBE call for
framework 'default' at
scheduler-f3be4608-7102-4746-b118-24b725a298a8@10.0.49.4:50652
I1101 06:38:46.029662 35827712 master.cpp:2241] Authorizing framework principal
'test-principal' to receive offers for roles '{ * }'
I1101 06:38:46.029938 34754560 master.cpp:2996] Subscribing framework default
with checkpointing enabled and capabilities [ MULTI_ROLE,
RESERVATION_REFINEMENT ]
I1101 06:38:46.030375 34754560 master.cpp:10824] Adding framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000 (default) with roles { } suppressed
I1101 06:38:46.030455 34754560 master.cpp:8295] Updating framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000 (default) with roles { } suppressed
I1101 06:38:46.030732 35291136 sched.cpp:751] Framework registered with
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000
I1101 06:38:46.030750 36364288 hierarchical.cpp:700] Added framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000
I1101 06:38:46.030766 36364288 hierarchical.cpp:813] Deactivated framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000
I1101 06:38:46.030836 35291136 sched.cpp:770] Scheduler::registered took 86490ns
I1101 06:38:46.030876 36364288 hierarchical.cpp:1681] Suppressed offers for
roles { } of framework dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000
I1101 06:38:46.030895 36364288 hierarchical.cpp:1721] Unsuppressed offers and
cleared filters for roles { } of framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000
I1101 06:38:46.030936 36364288 hierarchical.cpp:783] Activated framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000
I1101 06:38:46.031067 36364288 hierarchical.cpp:1853] Performed allocation for
0 agents in 50507ns
I1101 06:38:46.031359 331212224 containerizer.cpp:318] Using isolation {
environment_secret, filesystem/posix, posix/mem, posix/cpu }
I1101 06:38:46.031585 331212224 provisioner.cpp:294] Using default backend
'copy'
W1101 06:38:46.034698 331212224 process.cpp:2877] Attempted to spawn already
running process files@10.0.49.4:50652
I1101 06:38:46.035065 331212224 cluster.cpp:524] Creating default 'local'
authorizer
I1101 06:38:46.035914 36364288 slave.cpp:267] Mesos agent started on
(585)@10.0.49.4:50652
I1101 06:38:46.035939 36364288 slave.cpp:268] Flags at startup: --acls=""
--appc_simple_discovery_uri_prefix="http://";
--appc_store_dir="/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/rBzUi3/thymz0/store/appc"
--authenticate_http_executors="true" --authenticate_http_readonly="true"
--authenticate_http_readwrite="true" --authenticatee="crammd5"
--authentication_backoff_factor="1secs" --authentication_timeout_max="1mins"
--authentication_timeout_min="5secs" --authorizer="local"
--container_disk_watch_interval="15secs" --containerizers="mesos"
--credential="/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/rBzUi3/thymz0/credential"
--default_role="*" --disk_watch_interval="1mins" --docker="docker"
--docker_ignore_runtime="false" --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="/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/rBzUi3/thymz0/store/docker"
--docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume"
--docker_volume_chown="false" --enforce_container_disk_quota="false"
--executor_registration_timeout="1mins"
--executor_reregistration_timeout="2secs"
--executor_shutdown_grace_period="5secs"
--fetcher_cache_dir="/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/rBzUi3/thymz0/fetch"
--fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins"
--frameworks_home="/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/rBzUi3/thymz0/frameworks"
--gc_delay="1weeks" --gc_disk_headroom="0.1"
--gc_non_executor_container_sandboxes="false" --help="false"
--hostname_lookup="true" --http_command_executor="false"
--http_credentials="/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/rBzUi3/thymz0/http_credentials"
--http_heartbeat_interval="30secs" --initialize_driver_logging="true"
--isolation="posix/cpu,posix/mem"
--jwt_secret_key="/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/rBzUi3/thymz0/jwt_secret_key"
--launcher="posix"
--launcher_dir="/Users/jenkins/workspace/workspace/mesos/Mesos_CI-build/FLAG/SSL/label/mac/mesos/build/src"
--logbufsecs="0" --logging_level="INFO"
--max_completed_executors_per_framework="150" --memory_profiling="false"
--network_cni_metrics="true" --network_cni_root_dir_persist="false"
--oversubscribed_resources_interval="15secs" --port="5051"
--qos_correction_interval_min="0ns" --quiet="false"
--reconfiguration_policy="equal" --recover="reconnect"
--recovery_timeout="15mins" --registration_backoff_factor="10ms"
--resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]"
--runtime_dir="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_MasterFailover_C19Enw"
--sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true"
--version="false"
--work_dir="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_MasterFailover_aukJ13"
--zk_session_timeout="10secs"
I1101 06:38:46.036170 36364288 credentials.hpp:86] Loading credential for
authentication from
'/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/rBzUi3/thymz0/credential'
I1101 06:38:46.036295 36364288 slave.cpp:300] Agent using credential for:
test-principal
I1101 06:38:46.036310 36364288 credentials.hpp:37] Loading credentials for
authentication from
'/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/rBzUi3/thymz0/http_credentials'
I1101 06:38:46.036648 36364288 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-executor'
I1101 06:38:46.036742 36364288 http.cpp:996] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-executor'
I1101 06:38:46.036846 36364288 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-readonly'
I1101 06:38:46.036891 36364288 http.cpp:996] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-readonly'
I1101 06:38:46.036963 36364288 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-readwrite'
I1101 06:38:46.037003 36364288 http.cpp:996] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-readwrite'
I1101 06:38:46.037163 36364288 disk_profile_adaptor.cpp:78] Creating default
disk profile adaptor module
I1101 06:38:46.037955 36364288 slave.cpp:615] Agent resources:
[{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
I1101 06:38:46.038264 36364288 slave.cpp:623] Agent attributes: [ ]
I1101 06:38:46.038321 36364288 slave.cpp:632] Agent hostname:
Jenkinss-Mac-mini.local
I1101 06:38:46.038518 37437440 status_update_manager_process.hpp:379] Pausing
operation status update manager
I1101 06:38:46.038610 37974016 task_status_update_manager.cpp:181] Pausing
sending task status updates
I1101 06:38:46.038987 36900864 state.cpp:67] Recovering state from
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_MasterFailover_aukJ13/meta'
I1101 06:38:46.039058 36900864 state.cpp:874] No committed checkpointed
resources and operations found at
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_MasterFailover_aukJ13/meta/resources/resources_and_operations.state'
I1101 06:38:46.039088 36900864 state.cpp:880] No committed checkpointed
resources found at
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_MasterFailover_aukJ13/meta/resources/resources.info'
I1101 06:38:46.039463 36900864 state.cpp:99] Agent host rebooted
I1101 06:38:46.042847 37974016 slave.cpp:7492] Finished recovering checkpointed
state from
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_MasterFailover_aukJ13/meta',
beginning agent recovery
I1101 06:38:46.043287 37974016 slave.cpp:8224] Recovering framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000
I1101 06:38:46.043334 37974016 slave.cpp:10122] Recovering executor
'65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0' of framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000
I1101 06:38:46.044322 36900864 task_status_update_manager.cpp:207] Recovering
task status update manager
I1101 06:38:46.044339 36900864 task_status_update_manager.cpp:215] Recovering
executor '65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0' of framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000
I1101 06:38:46.044389 36900864 task_status_update_manager.cpp:507] Creating
StatusUpdate stream for task 65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0 of framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000
I1101 06:38:46.044878 36900864 task_status_update_manager.cpp:818] Replaying
task status update stream for task 65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0
I1101 06:38:46.045785 36364288 containerizer.cpp:821] Recovering Mesos
containers
I1101 06:38:46.046846 36364288 containerizer.cpp:1161] Recovering isolators
I1101 06:38:46.047188 34217984 containerizer.cpp:1200] Recovering provisioner
I1101 06:38:46.047475 34754560 provisioner.cpp:518] Provisioner recovery
complete
I1101 06:38:46.047574 35827712 containerizer.cpp:1272] Cleaning up orphan
container 3f06cb00-7b15-4d42-8a04-d577df9f86cd
I1101 06:38:46.047602 35827712 containerizer.cpp:2620] Destroying container
3f06cb00-7b15-4d42-8a04-d577df9f86cd in RUNNING state
I1101 06:38:46.047621 35827712 containerizer.cpp:3318] Transitioning the state
of container 3f06cb00-7b15-4d42-8a04-d577df9f86cd from RUNNING to DESTROYING
after 0ns
I1101 06:38:46.047773 35827712 launcher.cpp:161] Asked to destroy container
3f06cb00-7b15-4d42-8a04-d577df9f86cd
W1101 06:38:46.047789 35827712 launcher.cpp:164] Ignored destroy for unknown
container 3f06cb00-7b15-4d42-8a04-d577df9f86cd
I1101 06:38:46.048101 34754560 composing.cpp:339] Finished recovering all
containerizers
I1101 06:38:46.048416 35827712 status_update_manager_process.hpp:314]
Recovering operation status update manager
I1101 06:38:46.048571 37437440 slave.cpp:7974] Recovering executors
I1101 06:38:46.048616 37437440 slave.cpp:8064] Unable to reconnect to executor
'65201a7d-b8fc-48cd-9ce3-e18c3a83e4f0' of framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000 because no pid or http checkpoint
file was found
../../src/tests/slave_recovery_tests.cpp:4360: Failure
Failed to wait 15secs for reregisterExecutorMessage
I1101 06:39:01.040810 34754560 master.cpp:1411] Framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000 (default) at
scheduler-f3be4608-7102-4746-b118-24b725a298a8@10.0.49.4:50652 disconnected
I1101 06:39:01.040843 34754560 master.cpp:3356] Deactivating framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000 (default) at
scheduler-f3be4608-7102-4746-b118-24b725a298a8@10.0.49.4:50652
I1101 06:39:01.040910 34754560 master.cpp:3333] Disconnecting framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000 (default) at
scheduler-f3be4608-7102-4746-b118-24b725a298a8@10.0.49.4:50652
I1101 06:39:01.040937 34754560 master.cpp:1426] Giving framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000 (default) at
scheduler-f3be4608-7102-4746-b118-24b725a298a8@10.0.49.4:50652 0ns to failover
I1101 06:39:01.041164 37437440 hierarchical.cpp:813] Deactivated framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000
I1101 06:39:01.041239 36364288 slave.cpp:924] Agent terminating
I1101 06:39:01.041247 35291136 master.cpp:10195] Framework failover timeout,
removing framework dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000 (default) at
scheduler-f3be4608-7102-4746-b118-24b725a298a8@10.0.49.4:50652
I1101 06:39:01.041280 35291136 master.cpp:11197] Removing framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000 (default) at
scheduler-f3be4608-7102-4746-b118-24b725a298a8@10.0.49.4:50652
I1101 06:39:01.041469 37437440 hierarchical.cpp:1777] Allocation paused
I1101 06:39:01.041613 37437440 hierarchical.cpp:757] Removed framework
dc415259-fb19-4aaf-b0fa-5c27ddcf33af-0000
I1101 06:39:01.041646 37437440 hierarchical.cpp:1787] Allocation resumed
I1101 06:39:01.042497 37974016 hierarchical.cpp:1853] Performed allocation for
0 agents in 47903ns
I1101 06:39:02.053269 37437440 hierarchical.cpp:1853] Performed allocation for
0 agents in 49859ns
I1101 06:39:03.064496 35291136 hierarchical.cpp:1853] Performed allocation for
0 agents in 59722ns
I1101 06:39:04.075709 34217984 hierarchical.cpp:1853] Performed allocation for
0 agents in 52806ns
I1101 06:39:05.086405 35827712 hierarchical.cpp:1853] Performed allocation for
0 agents in 50570ns
I1101 06:39:06.097071 36900864 hierarchical.cpp:1853] Performed allocation for
0 agents in 51359ns
I1101 06:39:07.102789 34217984 hierarchical.cpp:1853] Performed allocation for
0 agents in 48543ns
I1101 06:39:08.113611 35827712 hierarchical.cpp:1853] Performed allocation for
0 agents in 50749ns
I1101 06:39:09.119666 36900864 hierarchical.cpp:1853] Performed allocation for
0 agents in 52174ns
I1101 06:39:10.130461 34754560 hierarchical.cpp:1853] Performed allocation for
0 agents in 51393ns
I1101 06:39:11.134860 35827712 hierarchical.cpp:1853] Performed allocation for
0 agents in 51386ns
I1101 06:39:12.143784 36364288 hierarchical.cpp:1853] Performed allocation for
0 agents in 50388ns
I1101 06:39:13.147156 35291136 hierarchical.cpp:1853] Performed allocation for
0 agents in 51735ns
I1101 06:39:14.158150 37974016 hierarchical.cpp:1853] Performed allocation for
0 agents in 51363ns
I1101 06:39:15.169366 37437440 hierarchical.cpp:1853] Performed allocation for
0 agents in 51440ns
../../src/tests/cluster.cpp:723: Failure
Failed to wait 15secs for termination
I1101 06:39:16.051592 331212224 master.cpp:1137] Master terminating
../../3rdparty/libprocess/include/process/gmock.hpp:504: Failure
Actual function call count doesn't match EXPECT_CALL(filter->mock, filter(to,
testing::A<const MessageEvent&>()))...
Expected args: message matcher (24-byte object <31-00 00-00 00-00 00-00
28-00 00-00 00-00 00-00 10-84 B9-58 DF-7F 00-00>, 1-byte object <31>)
Expected: to be called once
Actual: never called - unsatisfied and active
../../3rdparty/libprocess/include/process/gmock.hpp:504: Failure
Actual function call count doesn't match EXPECT_CALL(filter->mock, filter(to,
testing::A<const MessageEvent&>()))...
Expected args: message matcher (24-byte object <31-00 00-00 00-00 00-00
27-00 00-00 00-00 00-00 10-84 B9-58 DF-7F 00-00>, 1-byte object <31>)
Expected: to be called once
Actual: never called - unsatisfied and active
[ FAILED ] SlaveRecoveryTest/0.MasterFailover, where TypeParam =
mesos::internal::slave::MesosContainerizer (31062 ms)
{code}
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
