SlaveRecoveryTest/0.MasterFailover is flaky

[ 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)