You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "Anand Mazumdar (JIRA)" <ji...@apache.org> on 2015/10/16 22:16:05 UTC
[jira] [Commented] (MESOS-3750)
ContentType/SchedulerTest.ShutdownExecutor/0 is flaky
[ https://issues.apache.org/jira/browse/MESOS-3750?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14961305#comment-14961305 ]
Anand Mazumdar commented on MESOS-3750:
---------------------------------------
The root cause for the flakiness is due to the following race condition:
Bad Run
- The master sends 1 offer to the framework.
- The framework accepts the offer and launches a task.
- The executor , when the task completes, sends a {{TASK_FINISHED}} status update to the master.
- The master upon noticing the terminal status update , marks the resources as available. Note, there that these resources can now be offered back to the framework.
- The master sends an {{Event::Offer}} to the framework.
- This fails the test as the framework was expecting an {{Event::Failure}}.
Good Run
- The master sends 1 offer to the framework.
- The framework accepts the offer and launches a task.
- The executor , when the task completes, sends a {{TASK_FINISHED}} status update to the master.
- The framework on getting the status update, sends a {{Event::SHUTDOWN}} to the master leading to the master destroying the executor.
- No subsequent offers are sent to the framework in this case. An {{Event::FAILURE}} is sent by the master to the framework letting it know that an active executor has finished.
This seems easily fixable but I wonder if we should wait for a resolution on MESOS-3339 before fixing this as that enables us to filter subsequent offers quite easily and set expectations based on that.
> ContentType/SchedulerTest.ShutdownExecutor/0 is flaky
> -----------------------------------------------------
>
> Key: MESOS-3750
> URL: https://issues.apache.org/jira/browse/MESOS-3750
> Project: Mesos
> Issue Type: Bug
> Reporter: Anand Mazumdar
> Labels: flaky-test
>
> Showed up on ASF CI:
> https://builds.apache.org/job/Mesos/942/COMPILER=gcc,CONFIGURATION=--verbose,OS=centos:7,label_exp=docker%7C%7CHadoop/consoleFull
> {code}
> [ RUN ] ContentType/SchedulerTest.ShutdownExecutor/0
> Using temporary directory '/tmp/ContentType_SchedulerTest_ShutdownExecutor_0_AEwZqa'
> I1016 12:51:41.421211 30336 leveldb.cpp:176] Opened db in 131.548926ms
> I1016 12:51:41.480257 30336 leveldb.cpp:183] Compacted db in 58.993935ms
> I1016 12:51:41.480355 30336 leveldb.cpp:198] Created db iterator in 28351ns
> I1016 12:51:41.480376 30336 leveldb.cpp:204] Seeked to beginning of db in 2740ns
> I1016 12:51:41.480388 30336 leveldb.cpp:273] Iterated through 0 keys in the db in 493ns
> I1016 12:51:41.480445 30336 replica.cpp:746] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> I1016 12:51:41.481050 30359 recover.cpp:449] Starting replica recovery
> I1016 12:51:41.481324 30359 recover.cpp:475] Replica is in EMPTY status
> I1016 12:51:41.482493 30360 replica.cpp:642] Replica in EMPTY status received a broadcasted recover request from (9945)@172.17.7.238:34368
> I1016 12:51:41.482924 30363 recover.cpp:195] Received a recover response from a replica in EMPTY status
> I1016 12:51:41.483568 30361 recover.cpp:566] Updating replica status to STARTING
> I1016 12:51:41.485028 30365 master.cpp:376] Master 3684704c-615f-4f62-b45c-b7ae0cb8176f (635f798fc895) started on 172.17.7.238:34368
> I1016 12:51:41.485051 30365 master.cpp:378] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="false" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/ContentType_SchedulerTest_ShutdownExecutor_0_AEwZqa/credentials" --framework_sorter="drf" --help="false" --hostname_lookup="true" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_slave_ping_timeouts="5" --quiet="false" --recovery_slave_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_store_timeout="25secs" --registry_strict="true" --root_submissions="true" --slave_ping_timeout="15secs" --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false" --webui_dir="/mesos/mesos-0.26.0/_inst/share/mesos/webui" --work_dir="/tmp/ContentType_SchedulerTest_ShutdownExecutor_0_AEwZqa/master" --zk_session_timeout="10secs"
> I1016 12:51:41.485404 30365 master.cpp:425] Master allowing unauthenticated frameworks to register
> I1016 12:51:41.485419 30365 master.cpp:428] Master only allowing authenticated slaves to register
> I1016 12:51:41.485429 30365 credentials.hpp:37] Loading credentials for authentication from '/tmp/ContentType_SchedulerTest_ShutdownExecutor_0_AEwZqa/credentials'
> I1016 12:51:41.485692 30365 master.cpp:467] Using default 'crammd5' authenticator
> I1016 12:51:41.485827 30365 master.cpp:504] Authorization enabled
> I1016 12:51:41.486111 30360 whitelist_watcher.cpp:79] No whitelist given
> I1016 12:51:41.486193 30358 hierarchical.cpp:140] Initialized hierarchical allocator process
> I1016 12:51:41.487990 30356 master.cpp:1609] The newly elected leader is master@172.17.7.238:34368 with id 3684704c-615f-4f62-b45c-b7ae0cb8176f
> I1016 12:51:41.488039 30356 master.cpp:1622] Elected as the leading master!
> I1016 12:51:41.488068 30356 master.cpp:1382] Recovering from registrar
> I1016 12:51:41.488278 30359 registrar.cpp:309] Recovering registrar
> I1016 12:51:41.524139 30368 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 40.300862ms
> I1016 12:51:41.524193 30368 replica.cpp:323] Persisted replica status to STARTING
> I1016 12:51:41.524440 30368 recover.cpp:475] Replica is in STARTING status
> I1016 12:51:41.525777 30364 replica.cpp:642] Replica in STARTING status received a broadcasted recover request from (9946)@172.17.7.238:34368
> I1016 12:51:41.526093 30357 recover.cpp:195] Received a recover response from a replica in STARTING status
> I1016 12:51:41.526592 30365 recover.cpp:566] Updating replica status to VOTING
> I1016 12:51:41.582528 30361 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 55.827311ms
> I1016 12:51:41.582567 30361 replica.cpp:323] Persisted replica status to VOTING
> I1016 12:51:41.582695 30361 recover.cpp:580] Successfully joined the Paxos group
> I1016 12:51:41.582998 30361 recover.cpp:464] Recover process terminated
> I1016 12:51:41.583570 30364 log.cpp:661] Attempting to start the writer
> I1016 12:51:41.585400 30356 replica.cpp:478] Replica received implicit promise request from (9947)@172.17.7.238:34368 with proposal 1
> I1016 12:51:41.648470 30356 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 63.025985ms
> I1016 12:51:41.648515 30356 replica.cpp:345] Persisted promised to 1
> I1016 12:51:41.649210 30360 coordinator.cpp:231] Coordinator attemping to fill missing position
> I1016 12:51:41.650701 30370 replica.cpp:378] Replica received explicit promise request from (9948)@172.17.7.238:34368 for position 0 with proposal 2
> I1016 12:51:41.691156 30370 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 40.399776ms
> I1016 12:51:41.691206 30370 replica.cpp:681] Persisted action at 0
> I1016 12:51:41.692914 30358 replica.cpp:512] Replica received write request for position 0 from (9949)@172.17.7.238:34368
> I1016 12:51:41.693019 30358 leveldb.cpp:438] Reading position from leveldb took 61262ns
> I1016 12:51:41.757253 30358 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 64.171831ms
> I1016 12:51:41.757299 30358 replica.cpp:681] Persisted action at 0
> I1016 12:51:41.758080 30356 replica.cpp:660] Replica received learned notice for position 0 from @0.0.0.0:0
> I1016 12:51:41.808841 30356 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 50.722214ms
> I1016 12:51:41.808888 30356 replica.cpp:681] Persisted action at 0
> I1016 12:51:41.808917 30356 replica.cpp:666] Replica learned NOP action at position 0
> I1016 12:51:41.809870 30368 log.cpp:677] Writer started with ending position 0
> I1016 12:51:41.810999 30366 leveldb.cpp:438] Reading position from leveldb took 52492ns
> I1016 12:51:41.812075 30368 registrar.cpp:342] Successfully fetched the registry (0B) in 323.719936ms
> I1016 12:51:41.812197 30368 registrar.cpp:441] Applied 1 operations in 27586ns; attempting to update the 'registry'
> I1016 12:51:41.812932 30363 log.cpp:685] Attempting to append 176 bytes to the log
> I1016 12:51:41.813082 30365 coordinator.cpp:341] Coordinator attempting to write APPEND action at position 1
> I1016 12:51:41.813837 30363 replica.cpp:512] Replica received write request for position 1 from (9950)@172.17.7.238:34368
> I1016 12:51:41.900899 30363 leveldb.cpp:343] Persisting action (195 bytes) to leveldb took 87.022378ms
> I1016 12:51:41.900946 30363 replica.cpp:681] Persisted action at 1
> I1016 12:51:41.901654 30362 replica.cpp:660] Replica received learned notice for position 1 from @0.0.0.0:0
> I1016 12:51:42.259953 30362 leveldb.cpp:343] Persisting action (197 bytes) to leveldb took 358.253025ms
> I1016 12:51:42.260071 30362 replica.cpp:681] Persisted action at 1
> I1016 12:51:42.260102 30362 replica.cpp:666] Replica learned APPEND action at position 1
> I1016 12:51:42.261531 30366 registrar.cpp:486] Successfully updated the 'registry' in 449.252096ms
> I1016 12:51:42.261721 30366 registrar.cpp:372] Successfully recovered registrar
> I1016 12:51:42.261880 30364 log.cpp:704] Attempting to truncate the log to 1
> I1016 12:51:42.262276 30356 coordinator.cpp:341] Coordinator attempting to write TRUNCATE action at position 2
> I1016 12:51:42.262337 30359 master.cpp:1419] Recovered 0 slaves from the Registry (137B) ; allowing 10mins for slaves to re-register
> I1016 12:51:42.263034 30355 replica.cpp:512] Replica received write request for position 2 from (9951)@172.17.7.238:34368
> I1016 12:51:42.318370 30355 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 55.296079ms
> I1016 12:51:42.318405 30355 replica.cpp:681] Persisted action at 2
> I1016 12:51:42.319141 30356 replica.cpp:660] Replica received learned notice for position 2 from @0.0.0.0:0
> I1016 12:51:42.351897 30356 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 32.717505ms
> I1016 12:51:42.352010 30356 leveldb.cpp:401] Deleting ~1 keys from leveldb took 66624ns
> I1016 12:51:42.352035 30356 replica.cpp:681] Persisted action at 2
> I1016 12:51:42.352058 30356 replica.cpp:666] Replica learned TRUNCATE action at position 2
> I1016 12:51:42.357023 30356 slave.cpp:191] Slave started on 345)@172.17.7.238:34368
> I1016 12:51:42.357046 30356 slave.cpp:192] Flags at startup: --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/ContentType_SchedulerTest_ShutdownExecutor_0_mDrIUE/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_local_archives_dir="/tmp/mesos/images/docker" --docker_puller="local" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/ContentType_SchedulerTest_ShutdownExecutor_0_mDrIUE/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/mesos/mesos-0.26.0/_build/src" --logbufsecs="0" --logging_level="INFO" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:2;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/ContentType_SchedulerTest_ShutdownExecutor_0_mDrIUE"
> I1016 12:51:42.357542 30356 credentials.hpp:85] Loading credential for authentication from '/tmp/ContentType_SchedulerTest_ShutdownExecutor_0_mDrIUE/credential'
> I1016 12:51:42.357730 30356 slave.cpp:322] Slave using credential for: test-principal
> I1016 12:51:42.358242 30336 scheduler.cpp:157] Version: 0.26.0
> I1016 12:51:42.358233 30356 slave.cpp:392] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I1016 12:51:42.358288 30356 slave.cpp:400] Slave attributes: [ ]
> I1016 12:51:42.358299 30356 slave.cpp:405] Slave hostname: 635f798fc895
> I1016 12:51:42.358305 30356 slave.cpp:410] Slave checkpoint: true
> I1016 12:51:42.358772 30370 scheduler.cpp:240] New master detected at master@172.17.7.238:34368
> I1016 12:51:42.359359 30362 state.cpp:54] Recovering state from '/tmp/ContentType_SchedulerTest_ShutdownExecutor_0_mDrIUE/meta'
> I1016 12:51:42.359761 30367 status_update_manager.cpp:202] Recovering status update manager
> I1016 12:51:42.360070 30359 slave.cpp:4222] Finished recovery
> I1016 12:51:42.360110 30365 scheduler.cpp:302] Sending SUBSCRIBE call to master@172.17.7.238:34368
> I1016 12:51:42.360476 30359 slave.cpp:4379] Querying resource estimator for oversubscribable resources
> I1016 12:51:42.360682 30359 slave.cpp:726] New master detected at master@172.17.7.238:34368
> I1016 12:51:42.360716 30368 status_update_manager.cpp:176] Pausing sending status updates
> I1016 12:51:42.360790 30359 slave.cpp:789] Authenticating with master master@172.17.7.238:34368
> I1016 12:51:42.360816 30359 slave.cpp:794] Using default CRAM-MD5 authenticatee
> I1016 12:51:42.360987 30359 slave.cpp:762] Detecting new master
> I1016 12:51:42.361032 30355 authenticatee.cpp:115] Creating new client SASL connection
> I1016 12:51:42.361140 30359 slave.cpp:4393] Received oversubscribable resources from the resource estimator
> I1016 12:51:42.361348 30369 master.cpp:5144] Authenticating slave(345)@172.17.7.238:34368
> I1016 12:51:42.361456 30359 authenticator.cpp:407] Starting authentication session for crammd5_authenticatee(750)@172.17.7.238:34368
> I1016 12:51:42.361644 30370 authenticator.cpp:92] Creating new server SASL connection
> I1016 12:51:42.361709 30366 process.cpp:3078] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
> I1016 12:51:42.361842 30369 authenticatee.cpp:206] Received SASL authentication mechanisms: CRAM-MD5
> I1016 12:51:42.361873 30369 authenticatee.cpp:232] Attempting to authenticate with mechanism 'CRAM-MD5'
> I1016 12:51:42.361943 30366 http.cpp:338] HTTP POST for /master/api/v1/scheduler from 172.17.7.238:53273
> I1016 12:51:42.361994 30363 authenticator.cpp:197] Received SASL authentication start
> I1016 12:51:42.362054 30363 authenticator.cpp:319] Authentication requires more steps
> I1016 12:51:42.362133 30363 authenticatee.cpp:252] Received SASL authentication step
> I1016 12:51:42.362133 30366 master.cpp:1871] Received subscription request for HTTP framework 'default'
> I1016 12:51:42.362223 30366 master.cpp:1648] Authorizing framework principal 'test-principal' to receive offers for role '*'
> I1016 12:51:42.362252 30364 authenticator.cpp:225] Received SASL authentication step
> I1016 12:51:42.362342 30364 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: '635f798fc895' server FQDN: '635f798fc895' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I1016 12:51:42.362465 30364 auxprop.cpp:174] Looking up auxiliary property '*userPassword'
> I1016 12:51:42.362583 30364 auxprop.cpp:174] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I1016 12:51:42.362581 30367 master.cpp:1963] Subscribing framework 'default' with checkpointing disabled and capabilities [ ]
> I1016 12:51:42.362633 30364 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: '635f798fc895' server FQDN: '635f798fc895' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I1016 12:51:42.362653 30364 auxprop.cpp:124] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I1016 12:51:42.362665 30364 auxprop.cpp:124] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I1016 12:51:42.362687 30364 authenticator.cpp:311] Authentication success
> I1016 12:51:42.362826 30356 authenticatee.cpp:292] Authentication success
> I1016 12:51:42.362867 30359 authenticator.cpp:425] Authentication session cleanup for crammd5_authenticatee(750)@172.17.7.238:34368
> I1016 12:51:42.362939 30370 hierarchical.cpp:185] Added framework 3684704c-615f-4f62-b45c-b7ae0cb8176f-0000
> I1016 12:51:42.363005 30370 hierarchical.cpp:952] No resources available to allocate!
> I1016 12:51:42.363045 30370 hierarchical.cpp:1045] No inverse offers to send out!
> I1016 12:51:42.363075 30370 hierarchical.cpp:851] Performed allocation for 0 slaves in 111429ns
> I1016 12:51:42.363111 30359 master.hpp:1436] Sending heartbeat to 3684704c-615f-4f62-b45c-b7ae0cb8176f-0000
> I1016 12:51:42.363149 30367 master.cpp:5174] Successfully authenticated principal 'test-principal' at slave(345)@172.17.7.238:34368
> I1016 12:51:42.363399 30369 slave.cpp:857] Successfully authenticated with master master@172.17.7.238:34368
> I1016 12:51:42.363612 30369 slave.cpp:1251] Will retry registration in 14.145118ms if necessary
> I1016 12:51:42.363760 30356 scheduler.cpp:461] Enqueuing event SUBSCRIBED received from master@172.17.7.238:34368
> I1016 12:51:42.363770 30359 master.cpp:3868] Registering slave at slave(345)@172.17.7.238:34368 (635f798fc895) with id 3684704c-615f-4f62-b45c-b7ae0cb8176f-S0
> I1016 12:51:42.364214 30364 registrar.cpp:441] Applied 1 operations in 52145ns; attempting to update the 'registry'
> I1016 12:51:42.364259 30356 scheduler.cpp:461] Enqueuing event HEARTBEAT received from master@172.17.7.238:34368
> I1016 12:51:42.364908 30361 master_maintenance_tests.cpp:179] Ignoring HEARTBEAT event
> I1016 12:51:42.365020 30365 log.cpp:685] Attempting to append 345 bytes to the log
> I1016 12:51:42.365187 30356 coordinator.cpp:341] Coordinator attempting to write APPEND action at position 3
> I1016 12:51:42.365792 30365 replica.cpp:512] Replica received write request for position 3 from (9957)@172.17.7.238:34368
> I1016 12:51:42.378258 30357 slave.cpp:1251] Will retry registration in 18.54045ms if necessary
> I1016 12:51:42.378425 30355 master.cpp:3856] Ignoring register slave message from slave(345)@172.17.7.238:34368 (635f798fc895) as admission is already in progress
> I1016 12:51:42.397873 30361 slave.cpp:1251] Will retry registration in 69.385416ms if necessary
> I1016 12:51:42.398053 30360 master.cpp:3856] Ignoring register slave message from slave(345)@172.17.7.238:34368 (635f798fc895) as admission is already in progress
> I1016 12:51:42.405876 30365 leveldb.cpp:343] Persisting action (364 bytes) to leveldb took 40.04942ms
> I1016 12:51:42.405925 30365 replica.cpp:681] Persisted action at 3
> I1016 12:51:42.406626 30369 replica.cpp:660] Replica received learned notice for position 3 from @0.0.0.0:0
> I1016 12:51:42.439296 30369 leveldb.cpp:343] Persisting action (366 bytes) to leveldb took 32.573783ms
> I1016 12:51:42.439337 30369 replica.cpp:681] Persisted action at 3
> I1016 12:51:42.439359 30369 replica.cpp:666] Replica learned APPEND action at position 3
> I1016 12:51:42.440899 30364 registrar.cpp:486] Successfully updated the 'registry' in 76.599296ms
> I1016 12:51:42.441118 30363 log.cpp:704] Attempting to truncate the log to 3
> I1016 12:51:42.441231 30366 coordinator.cpp:341] Coordinator attempting to write TRUNCATE action at position 4
> I1016 12:51:42.441730 30368 slave.cpp:3212] Received ping from slave-observer(319)@172.17.7.238:34368
> I1016 12:51:42.441865 30368 replica.cpp:512] Replica received write request for position 4 from (9958)@172.17.7.238:34368
> I1016 12:51:42.442004 30365 hierarchical.cpp:335] Added slave 3684704c-615f-4f62-b45c-b7ae0cb8176f-S0 (635f798fc895) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
> I1016 12:51:42.441920 30360 master.cpp:3936] Registered slave 3684704c-615f-4f62-b45c-b7ae0cb8176f-S0 at slave(345)@172.17.7.238:34368 (635f798fc895) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I1016 12:51:42.442039 30355 slave.cpp:901] Registered with master master@172.17.7.238:34368; given slave ID 3684704c-615f-4f62-b45c-b7ae0cb8176f-S0
> I1016 12:51:42.442060 30355 fetcher.cpp:79] Clearing fetcher cache
> I1016 12:51:42.442179 30356 status_update_manager.cpp:183] Resuming sending status updates
> I1016 12:51:42.442345 30355 slave.cpp:924] Checkpointing SlaveInfo to '/tmp/ContentType_SchedulerTest_ShutdownExecutor_0_mDrIUE/meta/slaves/3684704c-615f-4f62-b45c-b7ae0cb8176f-S0/slave.info'
> I1016 12:51:42.442595 30365 hierarchical.cpp:1045] No inverse offers to send out!
> I1016 12:51:42.442616 30355 slave.cpp:960] Forwarding total oversubscribed resources
> I1016 12:51:42.442632 30365 hierarchical.cpp:867] Performed allocation for slave 3684704c-615f-4f62-b45c-b7ae0cb8176f-S0 in 587770ns
> I1016 12:51:42.442854 30357 master.cpp:4973] Sending 1 offers to framework 3684704c-615f-4f62-b45c-b7ae0cb8176f-0000 (default)
> I1016 12:51:42.443344 30357 master.cpp:4278] Received update of slave 3684704c-615f-4f62-b45c-b7ae0cb8176f-S0 at slave(345)@172.17.7.238:34368 (635f798fc895) with total oversubscribed resources
> I1016 12:51:42.443666 30366 hierarchical.cpp:391] Slave 3684704c-615f-4f62-b45c-b7ae0cb8176f-S0 (635f798fc895) updated with oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000])
> I1016 12:51:42.444103 30366 hierarchical.cpp:952] No resources available to allocate!
> I1016 12:51:42.444139 30366 hierarchical.cpp:1045] No inverse offers to send out!
> I1016 12:51:42.444154 30366 hierarchical.cpp:867] Performed allocation for slave 3684704c-615f-4f62-b45c-b7ae0cb8176f-S0 in 442588ns
> I1016 12:51:42.444330 30369 scheduler.cpp:461] Enqueuing event OFFERS received from master@172.17.7.238:34368
> I1016 12:51:42.445899 30356 scheduler.cpp:302] Sending ACCEPT call to master@172.17.7.238:34368
> I1016 12:51:42.447247 30359 process.cpp:3078] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
> I1016 12:51:42.447536 30359 http.cpp:338] HTTP POST for /master/api/v1/scheduler from 172.17.7.238:53274
> I1016 12:51:42.448107 30359 master.cpp:2924] Processing ACCEPT call for offers: [ 3684704c-615f-4f62-b45c-b7ae0cb8176f-O0 ] on slave 3684704c-615f-4f62-b45c-b7ae0cb8176f-S0 at slave(345)@172.17.7.238:34368 (635f798fc895) for framework 3684704c-615f-4f62-b45c-b7ae0cb8176f-0000 (default)
> I1016 12:51:42.448149 30359 master.cpp:2720] Authorizing framework principal 'test-principal' to launch task fc95ca51-b4bb-4ec3-983a-aec0a7d80058 as user 'mesos'
> W1016 12:51:42.449432 30369 validation.cpp:422] Executor default for task fc95ca51-b4bb-4ec3-983a-aec0a7d80058 uses less CPUs (None) than the minimum required (0.01). Please update your executor, as this will be mandatory in future releases.
> W1016 12:51:42.449468 30369 validation.cpp:434] Executor default for task fc95ca51-b4bb-4ec3-983a-aec0a7d80058 uses less memory (None) than the minimum required (32MB). Please update your executor, as this will be mandatory in future releases.
> I1016 12:51:42.449833 30369 master.hpp:176] Adding task fc95ca51-b4bb-4ec3-983a-aec0a7d80058 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 3684704c-615f-4f62-b45c-b7ae0cb8176f-S0 (635f798fc895)
> I1016 12:51:42.450060 30369 master.cpp:3254] Launching task fc95ca51-b4bb-4ec3-983a-aec0a7d80058 of framework 3684704c-615f-4f62-b45c-b7ae0cb8176f-0000 (default) with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 3684704c-615f-4f62-b45c-b7ae0cb8176f-S0 at slave(345)@172.17.7.238:34368 (635f798fc895)
> I1016 12:51:42.450455 30362 slave.cpp:1291] Got assigned task fc95ca51-b4bb-4ec3-983a-aec0a7d80058 for framework 3684704c-615f-4f62-b45c-b7ae0cb8176f-0000
> I1016 12:51:42.450906 30362 slave.cpp:1407] Launching task fc95ca51-b4bb-4ec3-983a-aec0a7d80058 for framework 3684704c-615f-4f62-b45c-b7ae0cb8176f-0000
> I1016 12:51:42.476635 30362 slave.cpp:4994] Launching executor default of framework 3684704c-615f-4f62-b45c-b7ae0cb8176f-0000 with resources in work directory '/tmp/ContentType_SchedulerTest_ShutdownExecutor_0_mDrIUE/slaves/3684704c-615f-4f62-b45c-b7ae0cb8176f-S0/frameworks/3684704c-615f-4f62-b45c-b7ae0cb8176f-0000/executors/default/runs/8ce67241-0a3b-4506-a89c-2c6112278868'
> I1016 12:51:42.479178 30362 exec.cpp:136] Version: 0.26.0
> I1016 12:51:42.479632 30360 exec.cpp:186] Executor started at: executor(122)@172.17.7.238:34368 with pid 30336
> I1016 12:51:42.479944 30362 slave.cpp:1625] Queuing task 'fc95ca51-b4bb-4ec3-983a-aec0a7d80058' for executor default of framework '3684704c-615f-4f62-b45c-b7ae0cb8176f-0000
> I1016 12:51:42.480279 30362 slave.cpp:679] Successfully attached file '/tmp/ContentType_SchedulerTest_ShutdownExecutor_0_mDrIUE/slaves/3684704c-615f-4f62-b45c-b7ae0cb8176f-S0/frameworks/3684704c-615f-4f62-b45c-b7ae0cb8176f-0000/executors/default/runs/8ce67241-0a3b-4506-a89c-2c6112278868'
> I1016 12:51:42.480547 30362 slave.cpp:2415] Got registration for executor 'default' of framework 3684704c-615f-4f62-b45c-b7ae0cb8176f-0000 from executor(122)@172.17.7.238:34368
> I1016 12:51:42.480983 30355 exec.cpp:210] Executor registered on slave 3684704c-615f-4f62-b45c-b7ae0cb8176f-S0
> I1016 12:51:42.481040 30355 exec.cpp:222] Executor::registered took 25648ns
> I1016 12:51:42.481523 30362 slave.cpp:1796] Sending queued task 'fc95ca51-b4bb-4ec3-983a-aec0a7d80058' to executor 'default' of framework 3684704c-615f-4f62-b45c-b7ae0cb8176f-0000
> I1016 12:51:42.481988 30369 exec.cpp:297] Executor asked to run task 'fc95ca51-b4bb-4ec3-983a-aec0a7d80058'
> I1016 12:51:42.482092 30369 exec.cpp:306] Executor::launchTask took 70285ns
> I1016 12:51:42.482202 30369 exec.cpp:519] Executor sending status update TASK_FINISHED (UUID: b7a94e2c-dc5e-4b05-843b-59596cc91843) for task fc95ca51-b4bb-4ec3-983a-aec0a7d80058 of framework 3684704c-615f-4f62-b45c-b7ae0cb8176f-0000
> I1016 12:51:42.482555 30367 slave.cpp:2778] Handling status update TASK_FINISHED (UUID: b7a94e2c-dc5e-4b05-843b-59596cc91843) for task fc95ca51-b4bb-4ec3-983a-aec0a7d80058 of framework 3684704c-615f-4f62-b45c-b7ae0cb8176f-0000 from executor(122)@172.17.7.238:34368
> I1016 12:51:42.482702 30367 slave.cpp:5289] Terminating task fc95ca51-b4bb-4ec3-983a-aec0a7d80058
> I1016 12:51:42.483239 30369 status_update_manager.cpp:322] Received status update TASK_FINISHED (UUID: b7a94e2c-dc5e-4b05-843b-59596cc91843) for task fc95ca51-b4bb-4ec3-983a-aec0a7d80058 of framework 3684704c-615f-4f62-b45c-b7ae0cb8176f-0000
> I1016 12:51:42.483286 30369 status_update_manager.cpp:499] Creating StatusUpdate stream for task fc95ca51-b4bb-4ec3-983a-aec0a7d80058 of framework 3684704c-615f-4f62-b45c-b7ae0cb8176f-0000
> I1016 12:51:42.483651 30369 status_update_manager.cpp:376] Forwarding update TASK_FINISHED (UUID: b7a94e2c-dc5e-4b05-843b-59596cc91843) for task fc95ca51-b4bb-4ec3-983a-aec0a7d80058 of framework 3684704c-615f-4f62-b45c-b7ae0cb8176f-0000 to the slave
> I1016 12:51:42.483916 30357 slave.cpp:3090] Forwarding the update TASK_FINISHED (UUID: b7a94e2c-dc5e-4b05-843b-59596cc91843) for task fc95ca51-b4bb-4ec3-983a-aec0a7d80058 of framework 3684704c-615f-4f62-b45c-b7ae0cb8176f-0000 to master@172.17.7.238:34368
> I1016 12:51:42.484067 30357 slave.cpp:3014] Status update manager successfully handled status update TASK_FINISHED (UUID: b7a94e2c-dc5e-4b05-843b-59596cc91843) for task fc95ca51-b4bb-4ec3-983a-aec0a7d80058 of framework 3684704c-615f-4f62-b45c-b7ae0cb8176f-0000
> I1016 12:51:42.484099 30357 slave.cpp:3020] Sending acknowledgement for status update TASK_FINISHED (UUID: b7a94e2c-dc5e-4b05-843b-59596cc91843) for task fc95ca51-b4bb-4ec3-983a-aec0a7d80058 of framework 3684704c-615f-4f62-b45c-b7ae0cb8176f-0000 to executor(122)@172.17.7.238:34368
> I1016 12:51:42.484262 30356 exec.cpp:343] Executor received status update acknowledgement b7a94e2c-dc5e-4b05-843b-59596cc91843 for task fc95ca51-b4bb-4ec3-983a-aec0a7d80058 of framework 3684704c-615f-4f62-b45c-b7ae0cb8176f-0000
> I1016 12:51:42.484309 30362 master.cpp:4421] Status update TASK_FINISHED (UUID: b7a94e2c-dc5e-4b05-843b-59596cc91843) for task fc95ca51-b4bb-4ec3-983a-aec0a7d80058 of framework 3684704c-615f-4f62-b45c-b7ae0cb8176f-0000 from slave 3684704c-615f-4f62-b45c-b7ae0cb8176f-S0 at slave(345)@172.17.7.238:34368 (635f798fc895)
> I1016 12:51:42.484400 30362 master.cpp:4460] Forwarding status update TASK_FINISHED (UUID: b7a94e2c-dc5e-4b05-843b-59596cc91843) for task fc95ca51-b4bb-4ec3-983a-aec0a7d80058 of framework 3684704c-615f-4f62-b45c-b7ae0cb8176f-0000
> I1016 12:51:42.484753 30362 master.cpp:6087] Updating the latest state of task fc95ca51-b4bb-4ec3-983a-aec0a7d80058 of framework 3684704c-615f-4f62-b45c-b7ae0cb8176f-0000 to TASK_FINISHED
> I1016 12:51:42.485245 30365 hierarchical.cpp:739] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on slave 3684704c-615f-4f62-b45c-b7ae0cb8176f-S0 from framework 3684704c-615f-4f62-b45c-b7ae0cb8176f-0000
> I1016 12:51:42.485787 30357 scheduler.cpp:461] Enqueuing event UPDATE received from master@172.17.7.238:34368
> I1016 12:51:42.487072 30367 scheduler.cpp:302] Sending SHUTDOWN call to master@172.17.7.238:34368
> I1016 12:51:42.487414 30355 hierarchical.cpp:1045] No inverse offers to send out!
> I1016 12:51:42.487514 30355 hierarchical.cpp:851] Performed allocation for 1 slaves in 726395ns
> I1016 12:51:42.487743 30361 master.cpp:4973] Sending 1 offers to framework 3684704c-615f-4f62-b45c-b7ae0cb8176f-0000 (default)
> I1016 12:51:42.488414 30358 process.cpp:3078] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
> I1016 12:51:42.488601 30358 http.cpp:338] HTTP POST for /master/api/v1/scheduler from 172.17.7.238:53275
> I1016 12:51:42.488936 30363 slave.cpp:3793] Asked to shut down executor 'default' of framework 3684704c-615f-4f62-b45c-b7ae0cb8176f-0000 by master@172.17.7.238:34368
> I1016 12:51:42.488999 30363 slave.cpp:3853] Shutting down executor 'default' of framework 3684704c-615f-4f62-b45c-b7ae0cb8176f-0000
> I1016 12:51:42.489112 30357 exec.cpp:383] Executor asked to shutdown
> I1016 12:51:42.489181 30357 exec.cpp:398] Executor::shutdown took 45904ns
> I1016 12:51:42.489564 30361 scheduler.cpp:461] Enqueuing event OFFERS received from master@172.17.7.238:34368
> I1016 12:51:42.489858 30359 slave.cpp:3542] Executor 'default' of framework 3684704c-615f-4f62-b45c-b7ae0cb8176f-0000 exited with status 0
> I1016 12:51:42.490288 30357 master.cpp:4514] Executor default of framework 3684704c-615f-4f62-b45c-b7ae0cb8176f-0000 on slave 3684704c-615f-4f62-b45c-b7ae0cb8176f-S0 at slave(345)@172.17.7.238:34368 (635f798fc895): exited with status 0
> I1016 12:51:42.490350 30357 master.cpp:6184] Removing executor 'default' with resources of framework 3684704c-615f-4f62-b45c-b7ae0cb8176f-0000 on slave 3684704c-615f-4f62-b45c-b7ae0cb8176f-S0 at slave(345)@172.17.7.238:34368 (635f798fc895)
> ../../src/tests/scheduler_tests.cpp:653: Failure
> Value of: event.get().type()
> Actual: OFFERS
> Expected: Event::FAILURE
> Which is: FAILURE
> ../../src/tests/scheduler_tests.cpp:655: Failure
> Value of: event.get().failure().executor_id()
> Actual:
> Expected: executorId
> Which is: default
> I1016 12:51:42.491024 30362 master.cpp:925] Master terminating
> I1016 12:51:42.491152 30362 master.cpp:6155] Removing task fc95ca51-b4bb-4ec3-983a-aec0a7d80058 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework 3684704c-615f-4f62-b45c-b7ae0cb8176f-0000 on slave 3684704c-615f-4f62-b45c-b7ae0cb8176f-S0 at slave(345)@172.17.7.238:34368 (635f798fc895)
> I1016 12:51:42.491262 30370 hierarchical.cpp:364] Removed slave 3684704c-615f-4f62-b45c-b7ae0cb8176f-S0
> I1016 12:51:42.491336 30368 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 49.419324ms
> I1016 12:51:42.491379 30368 replica.cpp:681] Persisted action at 4
> I1016 12:51:42.491508 30366 scheduler.cpp:461] Enqueuing event FAILURE received from master@172.17.7.238:34368
> I1016 12:51:42.492032 30359 replica.cpp:660] Replica received learned notice for position 4 from @0.0.0.0:0
> I1016 12:51:42.492316 30365 hierarchical.cpp:220] Removed framework 3684704c-615f-4f62-b45c-b7ae0cb8176f-0000
> E1016 12:51:42.492740 30364 scheduler.cpp:435] End-Of-File received from master. The master closed the event stream
> I1016 12:51:42.492856 30370 slave.cpp:3258] master@172.17.7.238:34368 exited
> W1016 12:51:42.492884 30370 slave.cpp:3261] Master disconnected! Waiting for a new master to be elected
> I1016 12:51:42.541610 30359 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 49.537394ms
> I1016 12:51:42.541702 30359 leveldb.cpp:401] Deleting ~2 keys from leveldb took 47319ns
> I1016 12:51:42.541721 30359 replica.cpp:681] Persisted action at 4
> I1016 12:51:42.541743 30359 replica.cpp:666] Replica learned TRUNCATE action at position 4
> I1016 12:51:42.542917 30368 slave.cpp:606] Slave terminating
> I1016 12:51:42.543138 30368 slave.cpp:2016] Asked to shut down framework 3684704c-615f-4f62-b45c-b7ae0cb8176f-0000 by @0.0.0.0:0
> I1016 12:51:42.543169 30368 slave.cpp:2041] Shutting down framework 3684704c-615f-4f62-b45c-b7ae0cb8176f-0000
> I1016 12:51:42.543236 30368 slave.cpp:3646] Cleaning up executor 'default' of framework 3684704c-615f-4f62-b45c-b7ae0cb8176f-0000
> I1016 12:51:42.543460 30370 gc.cpp:56] Scheduling '/tmp/ContentType_SchedulerTest_ShutdownExecutor_0_mDrIUE/slaves/3684704c-615f-4f62-b45c-b7ae0cb8176f-S0/frameworks/3684704c-615f-4f62-b45c-b7ae0cb8176f-0000/executors/default/runs/8ce67241-0a3b-4506-a89c-2c6112278868' for gc 6.99999371081185days in the future
> I1016 12:51:42.543596 30368 slave.cpp:3735] Cleaning up framework 3684704c-615f-4f62-b45c-b7ae0cb8176f-0000
> I1016 12:51:42.543617 30370 gc.cpp:56] Scheduling '/tmp/ContentType_SchedulerTest_ShutdownExecutor_0_mDrIUE/slaves/3684704c-615f-4f62-b45c-b7ae0cb8176f-S0/frameworks/3684704c-615f-4f62-b45c-b7ae0cb8176f-0000/executors/default' for gc 6.99999370904days in the future
> I1016 12:51:42.543704 30358 status_update_manager.cpp:284] Closing status update streams for framework 3684704c-615f-4f62-b45c-b7ae0cb8176f-0000
> I1016 12:51:42.543766 30358 status_update_manager.cpp:530] Cleaning up status update stream for task fc95ca51-b4bb-4ec3-983a-aec0a7d80058 of framework 3684704c-615f-4f62-b45c-b7ae0cb8176f-0000
> I1016 12:51:42.543787 30360 gc.cpp:56] Scheduling '/tmp/ContentType_SchedulerTest_ShutdownExecutor_0_mDrIUE/slaves/3684704c-615f-4f62-b45c-b7ae0cb8176f-S0/frameworks/3684704c-615f-4f62-b45c-b7ae0cb8176f-0000' for gc 6.99999370702518days in the future
> [ FAILED ] ContentType/SchedulerTest.ShutdownExecutor/0, where GetParam() = application/x-protobuf (1258 ms)
> {code}
> Logs from a good run:
> {code}
> [ RUN ] ContentType/SchedulerTest.ShutdownExecutor/0
> Using temporary directory '/tmp/ContentType_SchedulerTest_ShutdownExecutor_0_aMZZtp'
> I1015 22:22:50.799415 30281 leveldb.cpp:176] Opened db in 2.911403ms
> I1015 22:22:50.800370 30281 leveldb.cpp:183] Compacted db in 915053ns
> I1015 22:22:50.800421 30281 leveldb.cpp:198] Created db iterator in 19635ns
> I1015 22:22:50.800439 30281 leveldb.cpp:204] Seeked to beginning of db in 2175ns
> I1015 22:22:50.800451 30281 leveldb.cpp:273] Iterated through 0 keys in the db in 278ns
> I1015 22:22:50.800531 30281 replica.cpp:746] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> I1015 22:22:50.801086 30310 recover.cpp:449] Starting replica recovery
> I1015 22:22:50.801580 30310 recover.cpp:475] Replica is in EMPTY status
> I1015 22:22:50.802747 30305 replica.cpp:642] Replica in EMPTY status received a broadcasted recover request from (9928)@172.17.2.230:38254
> I1015 22:22:50.803688 30305 recover.cpp:195] Received a recover response from a replica in EMPTY status
> I1015 22:22:50.804288 30309 recover.cpp:566] Updating replica status to STARTING
> I1015 22:22:50.805028 30314 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 482895ns
> I1015 22:22:50.805124 30314 replica.cpp:323] Persisted replica status to STARTING
> I1015 22:22:50.805341 30314 recover.cpp:475] Replica is in STARTING status
> I1015 22:22:50.805743 30302 master.cpp:376] Master c52a727f-6d79-4640-ae17-57a9c52b995e (b31269e7cfe6) started on 172.17.2.230:38254
> I1015 22:22:50.805775 30302 master.cpp:378] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="false" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/ContentType_SchedulerTest_ShutdownExecutor_0_aMZZtp/credentials" --framework_sorter="drf" --help="false" --hostname_lookup="true" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_slave_ping_timeouts="5" --quiet="false" --recovery_slave_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_store_timeout="25secs" --registry_strict="true" --root_submissions="true" --slave_ping_timeout="15secs" --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false" --webui_dir="/mesos/mesos-0.26.0/_inst/share/mesos/webui" --work_dir="/tmp/ContentType_SchedulerTest_ShutdownExecutor_0_aMZZtp/master" --zk_session_timeout="10secs"
> I1015 22:22:50.806251 30302 master.cpp:425] Master allowing unauthenticated frameworks to register
> I1015 22:22:50.806264 30302 master.cpp:428] Master only allowing authenticated slaves to register
> I1015 22:22:50.806273 30302 credentials.hpp:37] Loading credentials for authentication from '/tmp/ContentType_SchedulerTest_ShutdownExecutor_0_aMZZtp/credentials'
> I1015 22:22:50.806463 30309 replica.cpp:642] Replica in STARTING status received a broadcasted recover request from (9929)@172.17.2.230:38254
> I1015 22:22:50.806568 30302 master.cpp:467] Using default 'crammd5' authenticator
> I1015 22:22:50.806718 30302 master.cpp:504] Authorization enabled
> I1015 22:22:50.806970 30301 whitelist_watcher.cpp:79] No whitelist given
> I1015 22:22:50.807018 30310 hierarchical.cpp:140] Initialized hierarchical allocator process
> I1015 22:22:50.807018 30307 recover.cpp:195] Received a recover response from a replica in STARTING status
> I1015 22:22:50.807610 30306 recover.cpp:566] Updating replica status to VOTING
> I1015 22:22:50.808182 30308 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 384675ns
> I1015 22:22:50.808212 30308 replica.cpp:323] Persisted replica status to VOTING
> I1015 22:22:50.808357 30312 recover.cpp:580] Successfully joined the Paxos group
> I1015 22:22:50.808948 30312 recover.cpp:464] Recover process terminated
> I1015 22:22:50.809029 30306 master.cpp:1609] The newly elected leader is master@172.17.2.230:38254 with id c52a727f-6d79-4640-ae17-57a9c52b995e
> I1015 22:22:50.809160 30306 master.cpp:1622] Elected as the leading master!
> I1015 22:22:50.809200 30306 master.cpp:1382] Recovering from registrar
> I1015 22:22:50.809373 30301 registrar.cpp:309] Recovering registrar
> I1015 22:22:50.810107 30300 log.cpp:661] Attempting to start the writer
> I1015 22:22:50.811528 30305 replica.cpp:478] Replica received implicit promise request from (9930)@172.17.2.230:38254 with proposal 1
> I1015 22:22:50.811923 30305 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 346538ns
> I1015 22:22:50.811961 30305 replica.cpp:345] Persisted promised to 1
> I1015 22:22:50.812690 30313 coordinator.cpp:231] Coordinator attemping to fill missing position
> I1015 22:22:50.813896 30301 replica.cpp:378] Replica received explicit promise request from (9931)@172.17.2.230:38254 for position 0 with proposal 2
> I1015 22:22:50.814374 30301 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 438837ns
> I1015 22:22:50.814399 30301 replica.cpp:681] Persisted action at 0
> I1015 22:22:50.815384 30301 replica.cpp:512] Replica received write request for position 0 from (9932)@172.17.2.230:38254
> I1015 22:22:50.815441 30301 leveldb.cpp:438] Reading position from leveldb took 29133ns
> I1015 22:22:50.815865 30301 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 359376ns
> I1015 22:22:50.815888 30301 replica.cpp:681] Persisted action at 0
> I1015 22:22:50.816560 30303 replica.cpp:660] Replica received learned notice for position 0 from @0.0.0.0:0
> I1015 22:22:50.817040 30303 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 449173ns
> I1015 22:22:50.817065 30303 replica.cpp:681] Persisted action at 0
> I1015 22:22:50.817090 30303 replica.cpp:666] Replica learned NOP action at position 0
> I1015 22:22:50.817705 30304 log.cpp:677] Writer started with ending position 0
> I1015 22:22:50.818671 30307 leveldb.cpp:438] Reading position from leveldb took 24224ns
> I1015 22:22:50.819533 30309 registrar.cpp:342] Successfully fetched the registry (0B) in 10.105856ms
> I1015 22:22:50.819664 30309 registrar.cpp:441] Applied 1 operations in 35659ns; attempting to update the 'registry'
> I1015 22:22:50.820317 30301 log.cpp:685] Attempting to append 176 bytes to the log
> I1015 22:22:50.820425 30313 coordinator.cpp:341] Coordinator attempting to write APPEND action at position 1
> I1015 22:22:50.821069 30300 replica.cpp:512] Replica received write request for position 1 from (9933)@172.17.2.230:38254
> I1015 22:22:50.821519 30300 leveldb.cpp:343] Persisting action (195 bytes) to leveldb took 413989ns
> I1015 22:22:50.821542 30300 replica.cpp:681] Persisted action at 1
> I1015 22:22:50.822101 30301 replica.cpp:660] Replica received learned notice for position 1 from @0.0.0.0:0
> I1015 22:22:50.822540 30301 leveldb.cpp:343] Persisting action (197 bytes) to leveldb took 407310ns
> I1015 22:22:50.822563 30301 replica.cpp:681] Persisted action at 1
> I1015 22:22:50.822578 30301 replica.cpp:666] Replica learned APPEND action at position 1
> I1015 22:22:50.823621 30300 registrar.cpp:486] Successfully updated the 'registry' in 3.88608ms
> I1015 22:22:50.823781 30300 registrar.cpp:372] Successfully recovered registrar
> I1015 22:22:50.823889 30307 log.cpp:704] Attempting to truncate the log to 1
> I1015 22:22:50.824056 30304 coordinator.cpp:341] Coordinator attempting to write TRUNCATE action at position 2
> I1015 22:22:50.824311 30303 master.cpp:1419] Recovered 0 slaves from the Registry (137B) ; allowing 10mins for slaves to re-register
> I1015 22:22:50.825393 30308 replica.cpp:512] Replica received write request for position 2 from (9934)@172.17.2.230:38254
> I1015 22:22:50.825804 30308 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 366396ns
> I1015 22:22:50.825832 30308 replica.cpp:681] Persisted action at 2
> I1015 22:22:50.826583 30305 replica.cpp:660] Replica received learned notice for position 2 from @0.0.0.0:0
> I1015 22:22:50.827003 30305 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 388393ns
> I1015 22:22:50.827059 30305 leveldb.cpp:401] Deleting ~1 keys from leveldb took 29929ns
> I1015 22:22:50.827076 30305 replica.cpp:681] Persisted action at 2
> I1015 22:22:50.827093 30305 replica.cpp:666] Replica learned TRUNCATE action at position 2
> I1015 22:22:50.839429 30313 slave.cpp:191] Slave started on 345)@172.17.2.230:38254
> I1015 22:22:50.839455 30313 slave.cpp:192] Flags at startup: --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/ContentType_SchedulerTest_ShutdownExecutor_0_BMRugf/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_local_archives_dir="/tmp/mesos/images/docker" --docker_puller="local" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/ContentType_SchedulerTest_ShutdownExecutor_0_BMRugf/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/mesos/mesos-0.26.0/_build/src" --logbufsecs="0" --logging_level="INFO" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:2;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/ContentType_SchedulerTest_ShutdownExecutor_0_BMRugf"
> I1015 22:22:50.840006 30313 credentials.hpp:85] Loading credential for authentication from '/tmp/ContentType_SchedulerTest_ShutdownExecutor_0_BMRugf/credential'
> I1015 22:22:50.840245 30313 slave.cpp:322] Slave using credential for: test-principal
> I1015 22:22:50.840921 30313 slave.cpp:392] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I1015 22:22:50.840999 30313 slave.cpp:400] Slave attributes: [ ]
> I1015 22:22:50.841014 30313 slave.cpp:405] Slave hostname: b31269e7cfe6
> I1015 22:22:50.841030 30313 slave.cpp:410] Slave checkpoint: true
> I1015 22:22:50.841539 30281 scheduler.cpp:157] Version: 0.26.0
> I1015 22:22:50.842082 30302 state.cpp:54] Recovering state from '/tmp/ContentType_SchedulerTest_ShutdownExecutor_0_BMRugf/meta'
> I1015 22:22:50.842296 30313 scheduler.cpp:240] New master detected at master@172.17.2.230:38254
> I1015 22:22:50.842697 30306 status_update_manager.cpp:202] Recovering status update manager
> I1015 22:22:50.843349 30305 slave.cpp:4222] Finished recovery
> I1015 22:22:50.843703 30309 scheduler.cpp:302] Sending SUBSCRIBE call to master@172.17.2.230:38254
> I1015 22:22:50.843989 30305 slave.cpp:4379] Querying resource estimator for oversubscribable resources
> I1015 22:22:50.844280 30302 status_update_manager.cpp:176] Pausing sending status updates
> I1015 22:22:50.844285 30306 slave.cpp:726] New master detected at master@172.17.2.230:38254
> I1015 22:22:50.844386 30306 slave.cpp:789] Authenticating with master master@172.17.2.230:38254
> I1015 22:22:50.844414 30306 slave.cpp:794] Using default CRAM-MD5 authenticatee
> I1015 22:22:50.844595 30306 slave.cpp:762] Detecting new master
> I1015 22:22:50.844687 30301 authenticatee.cpp:115] Creating new client SASL connection
> I1015 22:22:50.844772 30306 slave.cpp:4393] Received oversubscribable resources from the resource estimator
> I1015 22:22:50.844986 30310 master.cpp:5144] Authenticating slave(345)@172.17.2.230:38254
> I1015 22:22:50.845108 30306 authenticator.cpp:407] Starting authentication session for crammd5_authenticatee(754)@172.17.2.230:38254
> I1015 22:22:50.845362 30310 authenticator.cpp:92] Creating new server SASL connection
> I1015 22:22:50.845661 30311 authenticatee.cpp:206] Received SASL authentication mechanisms: CRAM-MD5
> I1015 22:22:50.845700 30311 authenticatee.cpp:232] Attempting to authenticate with mechanism 'CRAM-MD5'
> I1015 22:22:50.845824 30311 authenticator.cpp:197] Received SASL authentication start
> I1015 22:22:50.845849 30314 process.cpp:3078] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
> I1015 22:22:50.845892 30311 authenticator.cpp:319] Authentication requires more steps
> I1015 22:22:50.846035 30315 authenticatee.cpp:252] Received SASL authentication step
> I1015 22:22:50.846083 30314 http.cpp:338] HTTP POST for /master/api/v1/scheduler from 172.17.2.230:35366
> I1015 22:22:50.846189 30300 authenticator.cpp:225] Received SASL authentication step
> I1015 22:22:50.846232 30300 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: 'b31269e7cfe6' server FQDN: 'b31269e7cfe6' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I1015 22:22:50.846246 30300 auxprop.cpp:174] Looking up auxiliary property '*userPassword'
> I1015 22:22:50.846268 30314 master.cpp:1871] Received subscription request for HTTP framework 'default'
> I1015 22:22:50.846294 30300 auxprop.cpp:174] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I1015 22:22:50.846329 30314 master.cpp:1648] Authorizing framework principal 'test-principal' to receive offers for role '*'
> I1015 22:22:50.846334 30300 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: 'b31269e7cfe6' server FQDN: 'b31269e7cfe6' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I1015 22:22:50.846354 30300 auxprop.cpp:124] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I1015 22:22:50.846364 30300 auxprop.cpp:124] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I1015 22:22:50.846387 30300 authenticator.cpp:311] Authentication success
> I1015 22:22:50.846571 30312 authenticatee.cpp:292] Authentication success
> I1015 22:22:50.846745 30303 master.cpp:1963] Subscribing framework 'default' with checkpointing disabled and capabilities [ ]
> I1015 22:22:50.846781 30306 authenticator.cpp:425] Authentication session cleanup for crammd5_authenticatee(754)@172.17.2.230:38254
> I1015 22:22:50.847108 30306 hierarchical.cpp:185] Added framework c52a727f-6d79-4640-ae17-57a9c52b995e-0000
> I1015 22:22:50.847460 30306 hierarchical.cpp:952] No resources available to allocate!
> I1015 22:22:50.847223 30303 master.cpp:5174] Successfully authenticated principal 'test-principal' at slave(345)@172.17.2.230:38254
> I1015 22:22:50.847686 30306 hierarchical.cpp:1045] No inverse offers to send out!
> I1015 22:22:50.847718 30306 hierarchical.cpp:851] Performed allocation for 0 slaves in 292735ns
> I1015 22:22:50.847174 30314 master.hpp:1436] Sending heartbeat to c52a727f-6d79-4640-ae17-57a9c52b995e-0000
> I1015 22:22:50.847878 30304 slave.cpp:857] Successfully authenticated with master master@172.17.2.230:38254
> I1015 22:22:50.847986 30303 scheduler.cpp:461] Enqueuing event SUBSCRIBED received from master@172.17.2.230:38254
> I1015 22:22:50.848106 30304 slave.cpp:1251] Will retry registration in 16.896427ms if necessary
> I1015 22:22:50.848325 30314 master.cpp:3868] Registering slave at slave(345)@172.17.2.230:38254 (b31269e7cfe6) with id c52a727f-6d79-4640-ae17-57a9c52b995e-S0
> I1015 22:22:50.848847 30305 registrar.cpp:441] Applied 1 operations in 61971ns; attempting to update the 'registry'
> I1015 22:22:50.848857 30303 scheduler.cpp:461] Enqueuing event HEARTBEAT received from master@172.17.2.230:38254
> I1015 22:22:50.849489 30314 master_maintenance_tests.cpp:179] Ignoring HEARTBEAT event
> I1015 22:22:50.849702 30304 log.cpp:685] Attempting to append 345 bytes to the log
> I1015 22:22:50.849843 30305 coordinator.cpp:341] Coordinator attempting to write APPEND action at position 3
> I1015 22:22:50.850528 30303 replica.cpp:512] Replica received write request for position 3 from (9940)@172.17.2.230:38254
> I1015 22:22:50.850721 30303 leveldb.cpp:343] Persisting action (364 bytes) to leveldb took 157222ns
> I1015 22:22:50.850754 30303 replica.cpp:681] Persisted action at 3
> I1015 22:22:50.851595 30303 replica.cpp:660] Replica received learned notice for position 3 from @0.0.0.0:0
> I1015 22:22:50.852017 30303 leveldb.cpp:343] Persisting action (366 bytes) to leveldb took 393469ns
> I1015 22:22:50.852043 30303 replica.cpp:681] Persisted action at 3
> I1015 22:22:50.852071 30303 replica.cpp:666] Replica learned APPEND action at position 3
> I1015 22:22:50.853358 30306 registrar.cpp:486] Successfully updated the 'registry' in 4.443136ms
> I1015 22:22:50.853571 30308 log.cpp:704] Attempting to truncate the log to 3
> I1015 22:22:50.853754 30306 coordinator.cpp:341] Coordinator attempting to write TRUNCATE action at position 4
> I1015 22:22:50.854337 30312 replica.cpp:512] Replica received write request for position 4 from (9941)@172.17.2.230:38254
> I1015 22:22:50.854393 30307 slave.cpp:3212] Received ping from slave-observer(331)@172.17.2.230:38254
> I1015 22:22:50.854492 30304 master.cpp:3936] Registered slave c52a727f-6d79-4640-ae17-57a9c52b995e-S0 at slave(345)@172.17.2.230:38254 (b31269e7cfe6) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I1015 22:22:50.854621 30310 hierarchical.cpp:335] Added slave c52a727f-6d79-4640-ae17-57a9c52b995e-S0 (b31269e7cfe6) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
> I1015 22:22:50.854748 30312 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 371546ns
> I1015 22:22:50.854780 30312 replica.cpp:681] Persisted action at 4
> I1015 22:22:50.854707 30307 slave.cpp:901] Registered with master master@172.17.2.230:38254; given slave ID c52a727f-6d79-4640-ae17-57a9c52b995e-S0
> I1015 22:22:50.854897 30307 fetcher.cpp:77] Clearing fetcher cache
> I1015 22:22:50.855139 30300 status_update_manager.cpp:183] Resuming sending status updates
> I1015 22:22:50.855150 30310 hierarchical.cpp:1045] No inverse offers to send out!
> I1015 22:22:50.855180 30310 hierarchical.cpp:867] Performed allocation for slave c52a727f-6d79-4640-ae17-57a9c52b995e-S0 in 523344ns
> I1015 22:22:50.855365 30307 slave.cpp:924] Checkpointing SlaveInfo to '/tmp/ContentType_SchedulerTest_ShutdownExecutor_0_BMRugf/meta/slaves/c52a727f-6d79-4640-ae17-57a9c52b995e-S0/slave.info'
> I1015 22:22:50.855670 30309 replica.cpp:660] Replica received learned notice for position 4 from @0.0.0.0:0
> I1015 22:22:50.855921 30307 slave.cpp:960] Forwarding total oversubscribed resources
> I1015 22:22:50.855944 30300 master.cpp:4973] Sending 1 offers to framework c52a727f-6d79-4640-ae17-57a9c52b995e-0000 (default)
> I1015 22:22:50.856119 30309 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 410485ns
> I1015 22:22:50.856199 30309 leveldb.cpp:401] Deleting ~2 keys from leveldb took 46981ns
> I1015 22:22:50.856343 30309 replica.cpp:681] Persisted action at 4
> I1015 22:22:50.856379 30309 replica.cpp:666] Replica learned TRUNCATE action at position 4
> I1015 22:22:50.856626 30300 master.cpp:4278] Received update of slave c52a727f-6d79-4640-ae17-57a9c52b995e-S0 at slave(345)@172.17.2.230:38254 (b31269e7cfe6) with total oversubscribed resources
> I1015 22:22:50.856971 30315 hierarchical.cpp:391] Slave c52a727f-6d79-4640-ae17-57a9c52b995e-S0 (b31269e7cfe6) updated with oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000])
> I1015 22:22:50.857396 30315 hierarchical.cpp:952] No resources available to allocate!
> I1015 22:22:50.857450 30315 hierarchical.cpp:1045] No inverse offers to send out!
> I1015 22:22:50.857556 30315 hierarchical.cpp:867] Performed allocation for slave c52a727f-6d79-4640-ae17-57a9c52b995e-S0 in 532081ns
> I1015 22:22:50.857771 30312 scheduler.cpp:461] Enqueuing event OFFERS received from master@172.17.2.230:38254
> I1015 22:22:50.860173 30309 scheduler.cpp:302] Sending ACCEPT call to master@172.17.2.230:38254
> I1015 22:22:50.861713 30301 process.cpp:3078] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
> I1015 22:22:50.861915 30301 http.cpp:338] HTTP POST for /master/api/v1/scheduler from 172.17.2.230:35367
> I1015 22:22:50.862594 30301 master.cpp:2924] Processing ACCEPT call for offers: [ c52a727f-6d79-4640-ae17-57a9c52b995e-O0 ] on slave c52a727f-6d79-4640-ae17-57a9c52b995e-S0 at slave(345)@172.17.2.230:38254 (b31269e7cfe6) for framework c52a727f-6d79-4640-ae17-57a9c52b995e-0000 (default)
> I1015 22:22:50.862648 30301 master.cpp:2720] Authorizing framework principal 'test-principal' to launch task 1d75b310-1f63-454d-ac9a-294c3655cf8a as user 'mesos'
> W1015 22:22:50.864137 30301 validation.cpp:422] Executor default for task 1d75b310-1f63-454d-ac9a-294c3655cf8a uses less CPUs (None) than the minimum required (0.01). Please update your executor, as this will be mandatory in future releases.
> W1015 22:22:50.864192 30301 validation.cpp:434] Executor default for task 1d75b310-1f63-454d-ac9a-294c3655cf8a uses less memory (None) than the minimum required (32MB). Please update your executor, as this will be mandatory in future releases.
> I1015 22:22:50.864575 30301 master.hpp:176] Adding task 1d75b310-1f63-454d-ac9a-294c3655cf8a with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave c52a727f-6d79-4640-ae17-57a9c52b995e-S0 (b31269e7cfe6)
> I1015 22:22:50.864787 30301 master.cpp:3254] Launching task 1d75b310-1f63-454d-ac9a-294c3655cf8a of framework c52a727f-6d79-4640-ae17-57a9c52b995e-0000 (default) with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave c52a727f-6d79-4640-ae17-57a9c52b995e-S0 at slave(345)@172.17.2.230:38254 (b31269e7cfe6)
> I1015 22:22:50.865196 30313 slave.cpp:1291] Got assigned task 1d75b310-1f63-454d-ac9a-294c3655cf8a for framework c52a727f-6d79-4640-ae17-57a9c52b995e-0000
> I1015 22:22:50.865854 30313 slave.cpp:1407] Launching task 1d75b310-1f63-454d-ac9a-294c3655cf8a for framework c52a727f-6d79-4640-ae17-57a9c52b995e-0000
> I1015 22:22:50.873836 30313 slave.cpp:4994] Launching executor default of framework c52a727f-6d79-4640-ae17-57a9c52b995e-0000 with resources in work directory '/tmp/ContentType_SchedulerTest_ShutdownExecutor_0_BMRugf/slaves/c52a727f-6d79-4640-ae17-57a9c52b995e-S0/frameworks/c52a727f-6d79-4640-ae17-57a9c52b995e-0000/executors/default/runs/f70c9537-3b05-4d1c-b84c-dba972f97dd6'
> I1015 22:22:50.876085 30313 exec.cpp:136] Version: 0.26.0
> I1015 22:22:50.876468 30311 exec.cpp:186] Executor started at: executor(122)@172.17.2.230:38254 with pid 30281
> I1015 22:22:50.876775 30313 slave.cpp:1625] Queuing task '1d75b310-1f63-454d-ac9a-294c3655cf8a' for executor default of framework 'c52a727f-6d79-4640-ae17-57a9c52b995e-0000
> I1015 22:22:50.876971 30313 slave.cpp:679] Successfully attached file '/tmp/ContentType_SchedulerTest_ShutdownExecutor_0_BMRugf/slaves/c52a727f-6d79-4640-ae17-57a9c52b995e-S0/frameworks/c52a727f-6d79-4640-ae17-57a9c52b995e-0000/executors/default/runs/f70c9537-3b05-4d1c-b84c-dba972f97dd6'
> I1015 22:22:50.877079 30313 slave.cpp:2415] Got registration for executor 'default' of framework c52a727f-6d79-4640-ae17-57a9c52b995e-0000 from executor(122)@172.17.2.230:38254
> I1015 22:22:50.877540 30302 exec.cpp:210] Executor registered on slave c52a727f-6d79-4640-ae17-57a9c52b995e-S0
> I1015 22:22:50.877645 30302 exec.cpp:222] Executor::registered took 65220ns
> I1015 22:22:50.878059 30313 slave.cpp:1796] Sending queued task '1d75b310-1f63-454d-ac9a-294c3655cf8a' to executor 'default' of framework c52a727f-6d79-4640-ae17-57a9c52b995e-0000
> I1015 22:22:50.878404 30313 exec.cpp:297] Executor asked to run task '1d75b310-1f63-454d-ac9a-294c3655cf8a'
> I1015 22:22:50.878517 30313 exec.cpp:306] Executor::launchTask took 83073ns
> I1015 22:22:50.878618 30313 exec.cpp:519] Executor sending status update TASK_FINISHED (UUID: dd3760ad-7d44-4490-99e2-82da50558316) for task 1d75b310-1f63-454d-ac9a-294c3655cf8a of framework c52a727f-6d79-4640-ae17-57a9c52b995e-0000
> I1015 22:22:50.878887 30313 slave.cpp:2778] Handling status update TASK_FINISHED (UUID: dd3760ad-7d44-4490-99e2-82da50558316) for task 1d75b310-1f63-454d-ac9a-294c3655cf8a of framework c52a727f-6d79-4640-ae17-57a9c52b995e-0000 from executor(122)@172.17.2.230:38254
> I1015 22:22:50.879058 30313 slave.cpp:5289] Terminating task 1d75b310-1f63-454d-ac9a-294c3655cf8a
> I1015 22:22:50.879830 30308 status_update_manager.cpp:322] Received status update TASK_FINISHED (UUID: dd3760ad-7d44-4490-99e2-82da50558316) for task 1d75b310-1f63-454d-ac9a-294c3655cf8a of framework c52a727f-6d79-4640-ae17-57a9c52b995e-0000
> I1015 22:22:50.879895 30308 status_update_manager.cpp:499] Creating StatusUpdate stream for task 1d75b310-1f63-454d-ac9a-294c3655cf8a of framework c52a727f-6d79-4640-ae17-57a9c52b995e-0000
> I1015 22:22:50.880333 30308 status_update_manager.cpp:376] Forwarding update TASK_FINISHED (UUID: dd3760ad-7d44-4490-99e2-82da50558316) for task 1d75b310-1f63-454d-ac9a-294c3655cf8a of framework c52a727f-6d79-4640-ae17-57a9c52b995e-0000 to the slave
> I1015 22:22:50.880632 30303 slave.cpp:3090] Forwarding the update TASK_FINISHED (UUID: dd3760ad-7d44-4490-99e2-82da50558316) for task 1d75b310-1f63-454d-ac9a-294c3655cf8a of framework c52a727f-6d79-4640-ae17-57a9c52b995e-0000 to master@172.17.2.230:38254
> I1015 22:22:50.880812 30303 slave.cpp:3014] Status update manager successfully handled status update TASK_FINISHED (UUID: dd3760ad-7d44-4490-99e2-82da50558316) for task 1d75b310-1f63-454d-ac9a-294c3655cf8a of framework c52a727f-6d79-4640-ae17-57a9c52b995e-0000
> I1015 22:22:50.880844 30303 slave.cpp:3020] Sending acknowledgement for status update TASK_FINISHED (UUID: dd3760ad-7d44-4490-99e2-82da50558316) for task 1d75b310-1f63-454d-ac9a-294c3655cf8a of framework c52a727f-6d79-4640-ae17-57a9c52b995e-0000 to executor(122)@172.17.2.230:38254
> I1015 22:22:50.881001 30313 master.cpp:4421] Status update TASK_FINISHED (UUID: dd3760ad-7d44-4490-99e2-82da50558316) for task 1d75b310-1f63-454d-ac9a-294c3655cf8a of framework c52a727f-6d79-4640-ae17-57a9c52b995e-0000 from slave c52a727f-6d79-4640-ae17-57a9c52b995e-S0 at slave(345)@172.17.2.230:38254 (b31269e7cfe6)
> I1015 22:22:50.881023 30310 exec.cpp:343] Executor received status update acknowledgement dd3760ad-7d44-4490-99e2-82da50558316 for task 1d75b310-1f63-454d-ac9a-294c3655cf8a of framework c52a727f-6d79-4640-ae17-57a9c52b995e-0000
> I1015 22:22:50.881057 30313 master.cpp:4460] Forwarding status update TASK_FINISHED (UUID: dd3760ad-7d44-4490-99e2-82da50558316) for task 1d75b310-1f63-454d-ac9a-294c3655cf8a of framework c52a727f-6d79-4640-ae17-57a9c52b995e-0000
> I1015 22:22:50.881463 30313 master.cpp:6087] Updating the latest state of task 1d75b310-1f63-454d-ac9a-294c3655cf8a of framework c52a727f-6d79-4640-ae17-57a9c52b995e-0000 to TASK_FINISHED
> I1015 22:22:50.882067 30307 hierarchical.cpp:739] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on slave c52a727f-6d79-4640-ae17-57a9c52b995e-S0 from framework c52a727f-6d79-4640-ae17-57a9c52b995e-0000
> I1015 22:22:50.883672 30305 scheduler.cpp:461] Enqueuing event UPDATE received from master@172.17.2.230:38254
> I1015 22:22:50.885498 30305 scheduler.cpp:302] Sending SHUTDOWN call to master@172.17.2.230:38254
> I1015 22:22:50.887410 30302 process.cpp:3078] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
> I1015 22:22:50.887694 30302 http.cpp:338] HTTP POST for /master/api/v1/scheduler from 172.17.2.230:35368
> I1015 22:22:50.888064 30307 slave.cpp:3793] Asked to shut down executor 'default' of framework c52a727f-6d79-4640-ae17-57a9c52b995e-0000 by master@172.17.2.230:38254
> I1015 22:22:50.888185 30307 slave.cpp:3853] Shutting down executor 'default' of framework c52a727f-6d79-4640-ae17-57a9c52b995e-0000
> I1015 22:22:50.888346 30310 exec.cpp:383] Executor asked to shutdown
> I1015 22:22:50.888509 30310 exec.cpp:398] Executor::shutdown took 104195ns
> I1015 22:22:50.889508 30315 slave.cpp:3542] Executor 'default' of framework c52a727f-6d79-4640-ae17-57a9c52b995e-0000 exited with status 0
> I1015 22:22:50.889881 30309 master.cpp:4514] Executor default of framework c52a727f-6d79-4640-ae17-57a9c52b995e-0000 on slave c52a727f-6d79-4640-ae17-57a9c52b995e-S0 at slave(345)@172.17.2.230:38254 (b31269e7cfe6): exited with status 0
> I1015 22:22:50.890055 30309 master.cpp:6184] Removing executor 'default' with resources of framework c52a727f-6d79-4640-ae17-57a9c52b995e-0000 on slave c52a727f-6d79-4640-ae17-57a9c52b995e-S0 at slave(345)@172.17.2.230:38254 (b31269e7cfe6)
> I1015 22:22:50.891549 30314 scheduler.cpp:461] Enqueuing event FAILURE received from master@172.17.2.230:38254
> I1015 22:22:50.892606 30309 master.cpp:925] Master terminating
> I1015 22:22:50.892747 30309 master.cpp:6155] Removing task 1d75b310-1f63-454d-ac9a-294c3655cf8a with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework c52a727f-6d79-4640-ae17-57a9c52b995e-0000 on slave c52a727f-6d79-4640-ae17-57a9c52b995e-S0 at slave(345)@172.17.2.230:38254 (b31269e7cfe6)
> I1015 22:22:50.892918 30311 hierarchical.cpp:364] Removed slave c52a727f-6d79-4640-ae17-57a9c52b995e-S0
> I1015 22:22:50.893426 30312 hierarchical.cpp:220] Removed framework c52a727f-6d79-4640-ae17-57a9c52b995e-0000
> I1015 22:22:50.894060 30310 slave.cpp:3258] master@172.17.2.230:38254 exited
> W1015 22:22:50.894085 30310 slave.cpp:3261] Master disconnected! Waiting for a new master to be elected
> E1015 22:22:50.894281 30308 scheduler.cpp:435] End-Of-File received from master. The master closed the event stream
> I1015 22:22:50.898538 30302 slave.cpp:606] Slave terminating
> I1015 22:22:50.898612 30302 slave.cpp:2016] Asked to shut down framework c52a727f-6d79-4640-ae17-57a9c52b995e-0000 by @0.0.0.0:0
> I1015 22:22:50.898640 30302 slave.cpp:2041] Shutting down framework c52a727f-6d79-4640-ae17-57a9c52b995e-0000
> I1015 22:22:50.898692 30302 slave.cpp:3646] Cleaning up executor 'default' of framework c52a727f-6d79-4640-ae17-57a9c52b995e-0000
> I1015 22:22:50.898881 30307 gc.cpp:56] Scheduling '/tmp/ContentType_SchedulerTest_ShutdownExecutor_0_BMRugf/slaves/c52a727f-6d79-4640-ae17-57a9c52b995e-S0/frameworks/c52a727f-6d79-4640-ae17-57a9c52b995e-0000/executors/default/runs/f70c9537-3b05-4d1c-b84c-dba972f97dd6' for gc 6.99998959708148days in the future
> I1015 22:22:50.899006 30302 slave.cpp:3735] Cleaning up framework c52a727f-6d79-4640-ae17-57a9c52b995e-0000
> I1015 22:22:50.899022 30307 gc.cpp:56] Scheduling '/tmp/ContentType_SchedulerTest_ShutdownExecutor_0_BMRugf/slaves/c52a727f-6d79-4640-ae17-57a9c52b995e-S0/frameworks/c52a727f-6d79-4640-ae17-57a9c52b995e-0000/executors/default' for gc 6.99998959547259days in the future
> I1015 22:22:50.899114 30314 status_update_manager.cpp:284] Closing status update streams for framework c52a727f-6d79-4640-ae17-57a9c52b995e-0000
> I1015 22:22:50.899178 30314 status_update_manager.cpp:530] Cleaning up status update stream for task 1d75b310-1f63-454d-ac9a-294c3655cf8a of framework c52a727f-6d79-4640-ae17-57a9c52b995e-0000
> I1015 22:22:50.899174 30311 gc.cpp:56] Scheduling '/tmp/ContentType_SchedulerTest_ShutdownExecutor_0_BMRugf/slaves/c52a727f-6d79-4640-ae17-57a9c52b995e-S0/frameworks/c52a727f-6d79-4640-ae17-57a9c52b995e-0000' for gc 6.99998959353185days in the future
> [ OK ] ContentType/SchedulerTest.ShutdownExecutor/0 (107 ms)
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)