SchedulerTask.KillTest fails for JSON Requests

[ RUN      ] ContentType/SchedulerTest.KillTask/1
Using temporary directory '/tmp/ContentType_SchedulerTest_KillTask_1_pw8Bxz'
I0814 18:06:08.107872 26867 leveldb.cpp:176] Opened db in 157.425874ms
I0814 18:06:08.120825 26867 leveldb.cpp:183] Compacted db in 12.852495ms
I0814 18:06:08.120947 26867 leveldb.cpp:198] Created db iterator in 7943ns
I0814 18:06:08.120971 26867 leveldb.cpp:204] Seeked to beginning of db in 1223ns
I0814 18:06:08.120990 26867 leveldb.cpp:273] Iterated through 0 keys in the db in 497ns
I0814 18:06:08.121021 26867 replica.cpp:744] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0814 18:06:08.121356 26904 recover.cpp:449] Starting replica recovery
I0814 18:06:08.121534 26904 recover.cpp:475] Replica is in EMPTY status
I0814 18:06:08.123564 26896 replica.cpp:641] Replica in EMPTY status received a broadcasted recover request
I0814 18:06:08.124219 26897 recover.cpp:195] Received a recover response from a replica in EMPTY status
I0814 18:06:08.124769 26902 recover.cpp:566] Updating replica status to STARTING
I0814 18:06:08.125264 26892 master.cpp:378] Master 20150814-180608-1828659978-44896-26867 (smfd-atr-11-sr1.devel.twitter.com) started on 10.35.255.108:44896
I0814 18:06:08.125349 26892 master.cpp:380] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="false" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/ContentType_SchedulerTest_KillTask_1_pw8Bxz/credentials" --framework_sorter="drf" --help="false" --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="/usr/local/share/mesos/webui" --work_dir="/tmp/ContentType_SchedulerTest_KillTask_1_pw8Bxz/master" --zk_session_timeout="10secs"
I0814 18:06:08.125602 26892 master.cpp:427] Master allowing unauthenticated frameworks to register
I0814 18:06:08.125622 26892 master.cpp:430] Master only allowing authenticated slaves to register
I0814 18:06:08.125638 26892 credentials.hpp:37] Loading credentials for authentication from '/tmp/ContentType_SchedulerTest_KillTask_1_pw8Bxz/credentials'
I0814 18:06:08.125919 26892 master.cpp:469] Using default 'crammd5' authenticator
I0814 18:06:08.126086 26892 master.cpp:506] Authorization enabled
I0814 18:06:08.126198 26904 whitelist_watcher.cpp:79] No whitelist given
I0814 18:06:08.126225 26885 hierarchical.hpp:346] Initialized hierarchical allocator process
I0814 18:06:08.126955 26892 master.cpp:1524] The newly elected leader is master@10.35.255.108:44896 with id 20150814-180608-1828659978-44896-26867
I0814 18:06:08.127017 26892 master.cpp:1537] Elected as the leading master!
I0814 18:06:08.127039 26892 master.cpp:1307] Recovering from registrar
I0814 18:06:08.127137 26891 registrar.cpp:311] Recovering registrar
I0814 18:06:08.166405 26882 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 40.915176ms
I0814 18:06:08.166468 26882 replica.cpp:323] Persisted replica status to STARTING
I0814 18:06:08.166705 26882 recover.cpp:475] Replica is in STARTING status
I0814 18:06:08.168915 26891 replica.cpp:641] Replica in STARTING status received a broadcasted recover request
I0814 18:06:08.169270 26887 recover.cpp:195] Received a recover response from a replica in STARTING status
I0814 18:06:08.170073 26890 recover.cpp:566] Updating replica status to VOTING
I0814 18:06:08.181941 26883 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 11.758255ms
I0814 18:06:08.182054 26883 replica.cpp:323] Persisted replica status to VOTING
I0814 18:06:08.182149 26883 recover.cpp:580] Successfully joined the Paxos group
I0814 18:06:08.182520 26883 recover.cpp:464] Recover process terminated
I0814 18:06:08.183352 26898 log.cpp:661] Attempting to start the writer
I0814 18:06:08.185245 26900 replica.cpp:477] Replica received implicit promise request with proposal 1
I0814 18:06:08.198587 26900 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 13.274753ms
I0814 18:06:08.198681 26900 replica.cpp:345] Persisted promised to 1
I0814 18:06:08.199422 26900 coordinator.cpp:231] Coordinator attemping to fill missing position
I0814 18:06:08.201781 26898 replica.cpp:378] Replica received explicit promise request for position 0 with proposal 2
I0814 18:06:08.215220 26898 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 13.344936ms
I0814 18:06:08.215302 26898 replica.cpp:679] Persisted action at 0
I0814 18:06:08.218333 26890 replica.cpp:511] Replica received write request for position 0
I0814 18:06:08.218410 26890 leveldb.cpp:438] Reading position from leveldb took 23739ns
I0814 18:06:08.231933 26890 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 13.469254ms
I0814 18:06:08.232023 26890 replica.cpp:679] Persisted action at 0
I0814 18:06:08.232573 26888 replica.cpp:658] Replica received learned notice for position 0
I0814 18:06:08.248574 26888 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 15.915847ms
I0814 18:06:08.248666 26888 replica.cpp:679] Persisted action at 0
I0814 18:06:08.248698 26888 replica.cpp:664] Replica learned NOP action at position 0
I0814 18:06:08.249105 26892 log.cpp:677] Writer started with ending position 0
I0814 18:06:08.250542 26902 leveldb.cpp:438] Reading position from leveldb took 18186ns
I0814 18:06:08.252938 26883 registrar.cpp:344] Successfully fetched the registry (0B) in 125.679104ms
I0814 18:06:08.253058 26883 registrar.cpp:443] Applied 1 operations in 10065ns; attempting to update the 'registry'
I0814 18:06:08.255141 26898 log.cpp:685] Attempting to append 222 bytes to the log
I0814 18:06:08.255290 26893 coordinator.cpp:341] Coordinator attempting to write APPEND action at position 1
I0814 18:06:08.256623 26884 replica.cpp:511] Replica received write request for position 1
I0814 18:06:08.265223 26884 leveldb.cpp:343] Persisting action (241 bytes) to leveldb took 8.46042ms
I0814 18:06:08.265311 26884 replica.cpp:679] Persisted action at 1
I0814 18:06:08.266747 26901 replica.cpp:658] Replica received learned notice for position 1
I0814 18:06:08.281903 26901 leveldb.cpp:343] Persisting action (243 bytes) to leveldb took 15.103006ms
I0814 18:06:08.281996 26901 replica.cpp:679] Persisted action at 1
I0814 18:06:08.282022 26901 replica.cpp:664] Replica learned APPEND action at position 1
I0814 18:06:08.283289 26889 registrar.cpp:488] Successfully updated the 'registry' in 30.16576ms
I0814 18:06:08.283385 26903 log.cpp:704] Attempting to truncate the log to 1
I0814 18:06:08.283634 26889 registrar.cpp:374] Successfully recovered registrar
I0814 18:06:08.283742 26888 coordinator.cpp:341] Coordinator attempting to write TRUNCATE action at position 2
I0814 18:06:08.284013 26899 master.cpp:1334] Recovered 0 slaves from the Registry (183B) ; allowing 10mins for slaves to re-register
I0814 18:06:08.285148 26891 replica.cpp:511] Replica received write request for position 2
I0814 18:06:08.298528 26891 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 13.3213ms
I0814 18:06:08.298614 26891 replica.cpp:679] Persisted action at 2
I0814 18:06:08.299363 26892 replica.cpp:658] Replica received learned notice for position 2
I0814 18:06:08.306901 26892 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 7.488727ms
I0814 18:06:08.307013 26892 leveldb.cpp:401] Deleting ~1 keys from leveldb took 20136ns
I0814 18:06:08.307037 26892 replica.cpp:679] Persisted action at 2
I0814 18:06:08.307063 26892 replica.cpp:664] Replica learned TRUNCATE action at position 2
I0814 18:06:08.319324 26902 slave.cpp:190] Slave started on 6)@10.35.255.108:44896
I0814 18:06:08.319471 26902 slave.cpp:191] 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_KillTask_1_gxVuMf/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/ContentType_SchedulerTest_KillTask_1_gxVuMf/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/home/vinod/mesos/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" --resource_monitoring_interval="1secs" --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" --version="false" --work_dir="/tmp/ContentType_SchedulerTest_KillTask_1_gxVuMf"
I0814 18:06:08.319911 26902 credentials.hpp:85] Loading credential for authentication from '/tmp/ContentType_SchedulerTest_KillTask_1_gxVuMf/credential'
I0814 18:06:08.320065 26902 slave.cpp:321] Slave using credential for: test-principal
I0814 18:06:08.320480 26902 slave.cpp:354] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0814 18:06:08.320809 26867 scheduler.cpp:157] Version: 0.24.0
I0814 18:06:08.321018 26902 slave.cpp:384] Slave hostname: smfd-atr-11-sr1.devel.twitter.com
I0814 18:06:08.321068 26902 slave.cpp:389] Slave checkpoint: true
I0814 18:06:08.321774 26899 state.cpp:54] Recovering state from '/tmp/ContentType_SchedulerTest_KillTask_1_gxVuMf/meta'
I0814 18:06:08.322042 26899 status_update_manager.cpp:202] Recovering status update manager
I0814 18:06:08.322505 26905 slave.cpp:4069] Finished recovery
I0814 18:06:08.322849 26905 slave.cpp:4226] Querying resource estimator for oversubscribable resources
I0814 18:06:08.323031 26899 slave.cpp:4240] Received oversubscribable resources  from the resource estimator
I0814 18:06:08.323333 26886 status_update_manager.cpp:176] Pausing sending status updates
I0814 18:06:08.323379 26899 slave.cpp:684] New master detected at master@10.35.255.108:44896
I0814 18:06:08.323604 26899 slave.cpp:747] Authenticating with master master@10.35.255.108:44896
I0814 18:06:08.323822 26899 slave.cpp:752] Using default CRAM-MD5 authenticatee
I0814 18:06:08.324046 26899 slave.cpp:720] Detecting new master
I0814 18:06:08.324086 26882 authenticatee.cpp:115] Creating new client SASL connection
I0814 18:06:08.324157 26895 scheduler.cpp:241] New master detected at master@10.35.255.108:44896
I0814 18:06:08.324573 26891 master.cpp:4693] Authenticating slave(6)@10.35.255.108:44896
I0814 18:06:08.324862 26901 authenticator.cpp:407] Starting authentication session for crammd5_authenticatee(6)@10.35.255.108:44896
I0814 18:06:08.325374 26894 authenticator.cpp:92] Creating new server SASL connection
I0814 18:06:08.325521 26893 authenticatee.cpp:206] Received SASL authentication mechanisms: CRAM-MD5
I0814 18:06:08.325593 26893 authenticatee.cpp:232] Attempting to authenticate with mechanism 'CRAM-MD5'
I0814 18:06:08.325707 26890 authenticator.cpp:197] Received SASL authentication start
I0814 18:06:08.325805 26890 authenticator.cpp:319] Authentication requires more steps
I0814 18:06:08.326082 26903 authenticatee.cpp:252] Received SASL authentication step
I0814 18:06:08.326830 26885 authenticator.cpp:225] Received SASL authentication step
I0814 18:06:08.327126 26885 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: 'smfd-atr-11-sr1.devel.twitter.com' server FQDN: 'smfd-atr-11-sr1.devel.twitter.com' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
I0814 18:06:08.327206 26885 auxprop.cpp:174] Looking up auxiliary property '*userPassword'
I0814 18:06:08.327237 26885 auxprop.cpp:174] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0814 18:06:08.327265 26885 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: 'smfd-atr-11-sr1.devel.twitter.com' server FQDN: 'smfd-atr-11-sr1.devel.twitter.com' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
I0814 18:06:08.327368 26885 auxprop.cpp:124] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0814 18:06:08.327385 26885 auxprop.cpp:124] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0814 18:06:08.327411 26885 authenticator.cpp:311] Authentication success
I0814 18:06:08.327590 26896 authenticatee.cpp:292] Authentication success
I0814 18:06:08.327668 26888 process.cpp:3043] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I0814 18:06:08.328444 26886 slave.cpp:815] Successfully authenticated with master master@10.35.255.108:44896
I0814 18:06:08.328479 26891 authenticator.cpp:425] Authentication session cleanup for crammd5_authenticatee(6)@10.35.255.108:44896
I0814 18:06:08.328626 26886 slave.cpp:1209] Will retry registration in 1.765808ms if necessary
I0814 18:06:08.328640 26888 master.cpp:1782] Received subscription request for HTTP framework 'default'
I0814 18:06:08.328961 26888 master.cpp:1563] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0814 18:06:08.329412 26888 master.cpp:4723] Successfully authenticated principal 'test-principal' at slave(6)@10.35.255.108:44896
I0814 18:06:08.329716 26888 master.cpp:3635] Registering slave at slave(6)@10.35.255.108:44896 (smfd-atr-11-sr1.devel.twitter.com) with id 20150814-180608-1828659978-44896-26867-S0
I0814 18:06:08.329916 26888 master.cpp:1874] Subscribing framework 'default' with checkpointing disabled and capabilities [  ]
I0814 18:06:08.330065 26895 registrar.cpp:443] Applied 1 operations in 39640ns; attempting to update the 'registry'
I0814 18:06:08.330225 26892 hierarchical.hpp:391] Added framework 20150814-180608-1828659978-44896-26867-0000
I0814 18:06:08.330302 26892 hierarchical.hpp:1008] No resources available to allocate!
I0814 18:06:08.330330 26889 master.hpp:1308] Sending heartbeat to 20150814-180608-1828659978-44896-26867-0000
I0814 18:06:08.330334 26892 hierarchical.hpp:908] Performed allocation for 0 slaves in 39462ns
I0814 18:06:08.330940 26888 slave.cpp:1209] Will retry registration in 9.971013ms if necessary
I0814 18:06:08.331006 26890 master.cpp:3623] Ignoring register slave message from slave(6)@10.35.255.108:44896 (smfd-atr-11-sr1.devel.twitter.com) as admission is already in progress
I0814 18:06:08.333257 26886 scheduler_tests.cpp:113] Ignoring HEARTBEAT event
I0814 18:06:08.333463 26892 log.cpp:685] Attempting to append 414 bytes to the log
I0814 18:06:08.333560 26890 coordinator.cpp:341] Coordinator attempting to write APPEND action at position 3
I0814 18:06:08.335301 26882 replica.cpp:511] Replica received write request for position 3
I0814 18:06:08.341595 26893 slave.cpp:1209] Will retry registration in 79.616244ms if necessary
I0814 18:06:08.341733 26886 master.cpp:3623] Ignoring register slave message from slave(6)@10.35.255.108:44896 (smfd-atr-11-sr1.devel.twitter.com) as admission is already in progress
I0814 18:06:08.348547 26882 leveldb.cpp:343] Persisting action (433 bytes) to leveldb took 13.177202ms
I0814 18:06:08.348640 26882 replica.cpp:679] Persisted action at 3
I0814 18:06:08.349150 26897 replica.cpp:658] Replica received learned notice for position 3
I0814 18:06:08.356866 26897 leveldb.cpp:343] Persisting action (435 bytes) to leveldb took 7.621235ms
I0814 18:06:08.356958 26897 replica.cpp:679] Persisted action at 3
I0814 18:06:08.356984 26897 replica.cpp:664] Replica learned APPEND action at position 3
I0814 18:06:08.357990 26904 registrar.cpp:488] Successfully updated the 'registry' in 27.864832ms
I0814 18:06:08.358191 26884 log.cpp:704] Attempting to truncate the log to 3
I0814 18:06:08.358443 26893 coordinator.cpp:341] Coordinator attempting to write TRUNCATE action at position 4
I0814 18:06:08.358674 26897 slave.cpp:3058] Received ping from slave-observer(6)@10.35.255.108:44896
I0814 18:06:08.358712 26900 master.cpp:3698] Registered slave 20150814-180608-1828659978-44896-26867-S0 at slave(6)@10.35.255.108:44896 (smfd-atr-11-sr1.devel.twitter.com) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0814 18:06:08.358816 26892 hierarchical.hpp:540] Added slave 20150814-180608-1828659978-44896-26867-S0 (smfd-atr-11-sr1.devel.twitter.com) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
I0814 18:06:08.358815 26897 slave.cpp:859] Registered with master master@10.35.255.108:44896; given slave ID 20150814-180608-1828659978-44896-26867-S0
I0814 18:06:08.358889 26897 fetcher.cpp:77] Clearing fetcher cache
I0814 18:06:08.359159 26889 status_update_manager.cpp:183] Resuming sending status updates
I0814 18:06:08.359282 26892 hierarchical.hpp:926] Performed allocation for slave 20150814-180608-1828659978-44896-26867-S0 in 405998ns
I0814 18:06:08.359316 26897 slave.cpp:882] Checkpointing SlaveInfo to '/tmp/ContentType_SchedulerTest_KillTask_1_gxVuMf/meta/slaves/20150814-180608-1828659978-44896-26867-S0/slave.info'
I0814 18:06:08.359184 26891 replica.cpp:511] Replica received write request for position 4
I0814 18:06:08.359529 26897 slave.cpp:918] Forwarding total oversubscribed resources 
I0814 18:06:08.359549 26904 master.cpp:4612] Sending 1 offers to framework 20150814-180608-1828659978-44896-26867-0000 (default)
I0814 18:06:08.360407 26904 master.cpp:3997] Received update of slave 20150814-180608-1828659978-44896-26867-S0 at slave(6)@10.35.255.108:44896 (smfd-atr-11-sr1.devel.twitter.com) with total oversubscribed resources 
I0814 18:06:08.360611 26904 hierarchical.hpp:600] Slave 20150814-180608-1828659978-44896-26867-S0 (smfd-atr-11-sr1.devel.twitter.com) updated with oversubscribed resources  (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000])
I0814 18:06:08.360893 26904 hierarchical.hpp:1008] No resources available to allocate!
I0814 18:06:08.360949 26904 hierarchical.hpp:926] Performed allocation for slave 20150814-180608-1828659978-44896-26867-S0 in 288627ns
I0814 18:06:08.366634 26897 process.cpp:3043] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I0814 18:06:08.368067 26897 master.cpp:2738] Processing ACCEPT call for offers: [ 20150814-180608-1828659978-44896-26867-O0 ] on slave 20150814-180608-1828659978-44896-26867-S0 at slave(6)@10.35.255.108:44896 (smfd-atr-11-sr1.devel.twitter.com) for framework 20150814-180608-1828659978-44896-26867-0000 (default)
I0814 18:06:08.368147 26897 master.cpp:2569] Authorizing framework principal 'test-principal' to launch task a17705ba-09db-4a7c-a3ae-80588afbef81 as user 'root'
W0814 18:06:08.369264 26892 validation.cpp:419] Executor default for task a17705ba-09db-4a7c-a3ae-80588afbef81 uses less CPUs (None) than the minimum required (0.01). Please update your executor, as this will be mandatory in future releases.
W0814 18:06:08.369433 26892 validation.cpp:431] Executor default for task a17705ba-09db-4a7c-a3ae-80588afbef81 uses less memory (None) than the minimum required (32MB). Please update your executor, as this will be mandatory in future releases.
I0814 18:06:08.369674 26892 master.hpp:170] Adding task a17705ba-09db-4a7c-a3ae-80588afbef81 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20150814-180608-1828659978-44896-26867-S0 (smfd-atr-11-sr1.devel.twitter.com)
I0814 18:06:08.369935 26892 master.cpp:3068] Launching task a17705ba-09db-4a7c-a3ae-80588afbef81 of framework 20150814-180608-1828659978-44896-26867-0000 (default) with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20150814-180608-1828659978-44896-26867-S0 at slave(6)@10.35.255.108:44896 (smfd-atr-11-sr1.devel.twitter.com)
I0814 18:06:08.370240 26892 slave.cpp:1249] Got assigned task a17705ba-09db-4a7c-a3ae-80588afbef81 for framework 20150814-180608-1828659978-44896-26867-0000
I0814 18:06:08.370573 26892 slave.cpp:1365] Launching task a17705ba-09db-4a7c-a3ae-80588afbef81 for framework 20150814-180608-1828659978-44896-26867-0000
I0814 18:06:08.373613 26891 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 14.157947ms
I0814 18:06:08.373705 26891 replica.cpp:679] Persisted action at 4
I0814 18:06:08.374198 26897 replica.cpp:658] Replica received learned notice for position 4
I0814 18:06:08.382215 26892 slave.cpp:4799] Launching executor default of framework 20150814-180608-1828659978-44896-26867-0000 with resources  in work directory '/tmp/ContentType_SchedulerTest_KillTask_1_gxVuMf/slaves/20150814-180608-1828659978-44896-26867-S0/frameworks/20150814-180608-1828659978-44896-26867-0000/executors/default/runs/c5935633-2c84-4455-b8d8-cb929848cd61'
I0814 18:06:08.384953 26892 exec.cpp:133] Version: 0.24.0
I0814 18:06:08.385145 26904 exec.cpp:183] Executor started at: executor(6)@10.35.255.108:44896 with pid 26867
I0814 18:06:08.385282 26892 slave.cpp:1583] Queuing task 'a17705ba-09db-4a7c-a3ae-80588afbef81' for executor default of framework '20150814-180608-1828659978-44896-26867-0000
I0814 18:06:08.385376 26892 slave.cpp:637] Successfully attached file '/tmp/ContentType_SchedulerTest_KillTask_1_gxVuMf/slaves/20150814-180608-1828659978-44896-26867-S0/frameworks/20150814-180608-1828659978-44896-26867-0000/executors/default/runs/c5935633-2c84-4455-b8d8-cb929848cd61'
I0814 18:06:08.385500 26892 slave.cpp:2358] Got registration for executor 'default' of framework 20150814-180608-1828659978-44896-26867-0000 from executor(6)@10.35.255.108:44896
I0814 18:06:08.385905 26889 exec.cpp:207] Executor registered on slave 20150814-180608-1828659978-44896-26867-S0
I0814 18:06:08.386072 26892 slave.cpp:1739] Sending queued task 'a17705ba-09db-4a7c-a3ae-80588afbef81' to executor 'default' of framework 20150814-180608-1828659978-44896-26867-0000
I0814 18:06:08.387698 26889 exec.cpp:219] Executor::registered took 32815ns
I0814 18:06:08.387855 26889 exec.cpp:294] Executor asked to run task 'a17705ba-09db-4a7c-a3ae-80588afbef81'
I0814 18:06:08.387997 26889 exec.cpp:303] Executor::launchTask took 36307ns
I0814 18:06:08.389662 26889 exec.cpp:516] Executor sending status update TASK_RUNNING (UUID: 3c287ef4-ee95-45ca-a5d0-97b73a3d9825) for task a17705ba-09db-4a7c-a3ae-80588afbef81 of framework 20150814-180608-1828659978-44896-26867-0000
I0814 18:06:08.389889 26889 slave.cpp:2696] Handling status update TASK_RUNNING (UUID: 3c287ef4-ee95-45ca-a5d0-97b73a3d9825) for task a17705ba-09db-4a7c-a3ae-80588afbef81 of framework 20150814-180608-1828659978-44896-26867-0000 from executor(6)@10.35.255.108:44896
I0814 18:06:08.390125 26897 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 15.735159ms
I0814 18:06:08.390142 26891 status_update_manager.cpp:322] Received status update TASK_RUNNING (UUID: 3c287ef4-ee95-45ca-a5d0-97b73a3d9825) for task a17705ba-09db-4a7c-a3ae-80588afbef81 of framework 20150814-180608-1828659978-44896-26867-0000
I0814 18:06:08.390213 26891 status_update_manager.cpp:499] Creating StatusUpdate stream for task a17705ba-09db-4a7c-a3ae-80588afbef81 of framework 20150814-180608-1828659978-44896-26867-0000
I0814 18:06:08.390213 26897 leveldb.cpp:401] Deleting ~2 keys from leveldb took 32613ns
I0814 18:06:08.390278 26897 replica.cpp:679] Persisted action at 4
I0814 18:06:08.390321 26897 replica.cpp:664] Replica learned TRUNCATE action at position 4
I0814 18:06:08.390494 26891 status_update_manager.cpp:376] Forwarding update TASK_RUNNING (UUID: 3c287ef4-ee95-45ca-a5d0-97b73a3d9825) for task a17705ba-09db-4a7c-a3ae-80588afbef81 of framework 20150814-180608-1828659978-44896-26867-0000 to the slave
I0814 18:06:08.390842 26896 slave.cpp:2975] Forwarding the update TASK_RUNNING (UUID: 3c287ef4-ee95-45ca-a5d0-97b73a3d9825) for task a17705ba-09db-4a7c-a3ae-80588afbef81 of framework 20150814-180608-1828659978-44896-26867-0000 to master@10.35.255.108:44896
I0814 18:06:08.391197 26896 slave.cpp:2899] Status update manager successfully handled status update TASK_RUNNING (UUID: 3c287ef4-ee95-45ca-a5d0-97b73a3d9825) for task a17705ba-09db-4a7c-a3ae-80588afbef81 of framework 20150814-180608-1828659978-44896-26867-0000
I0814 18:06:08.391263 26896 slave.cpp:2905] Sending acknowledgement for status update TASK_RUNNING (UUID: 3c287ef4-ee95-45ca-a5d0-97b73a3d9825) for task a17705ba-09db-4a7c-a3ae-80588afbef81 of framework 20150814-180608-1828659978-44896-26867-0000 to executor(6)@10.35.255.108:44896
I0814 18:06:08.391311 26892 master.cpp:4068] Status update TASK_RUNNING (UUID: 3c287ef4-ee95-45ca-a5d0-97b73a3d9825) for task a17705ba-09db-4a7c-a3ae-80588afbef81 of framework 20150814-180608-1828659978-44896-26867-0000 from slave 20150814-180608-1828659978-44896-26867-S0 at slave(6)@10.35.255.108:44896 (smfd-atr-11-sr1.devel.twitter.com)
I0814 18:06:08.391361 26892 master.cpp:4107] Forwarding status update TASK_RUNNING (UUID: 3c287ef4-ee95-45ca-a5d0-97b73a3d9825) for task a17705ba-09db-4a7c-a3ae-80588afbef81 of framework 20150814-180608-1828659978-44896-26867-0000
I0814 18:06:08.391423 26898 exec.cpp:340] Executor received status update acknowledgement 3c287ef4-ee95-45ca-a5d0-97b73a3d9825 for task a17705ba-09db-4a7c-a3ae-80588afbef81 of framework 20150814-180608-1828659978-44896-26867-0000
I0814 18:06:08.391723 26892 master.cpp:5575] Updating the latest state of task a17705ba-09db-4a7c-a3ae-80588afbef81 of framework 20150814-180608-1828659978-44896-26867-0000 to TASK_RUNNING
I0814 18:06:08.395661 26891 process.cpp:3043] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I0814 18:06:08.396078 26891 master.cpp:3397] Processing ACKNOWLEDGE call 3c287ec3-83c2-b4c3-83c2-aec382c29545 for task a17705ba-09db-4a7c-a3ae-80588afbef81 of framework 20150814-180608-1828659978-44896-26867-0000 (default) on slave 20150814-180608-1828659978-44896-26867-S0
I0814 18:06:08.396860 26891 status_update_manager.cpp:394] Received status update acknowledgement (UUID: 3c287ec3-83c2-b4c3-83c2-aec382c29545) for task a17705ba-09db-4a7c-a3ae-80588afbef81 of framework 20150814-180608-1828659978-44896-26867-0000
W0814 18:06:08.396981 26891 status_update_manager.cpp:764] Unexpected status update acknowledgement (received 3c287ec3-83c2-b4c3-83c2-aec382c29545, expecting 3c287ef4-ee95-45ca-a5d0-97b73a3d9825) for update TASK_RUNNING (UUID: 3c287ef4-ee95-45ca-a5d0-97b73a3d9825) for task a17705ba-09db-4a7c-a3ae-80588afbef81 of framework 20150814-180608-1828659978-44896-26867-0000
E0814 18:06:08.397202 26893 slave.cpp:2291] Failed to handle status update acknowledgement (UUID: 3c287ec3-83c2-b4c3-83c2-aec382c29545) for task a17705ba-09db-4a7c-a3ae-80588afbef81 of framework 20150814-180608-1828659978-44896-26867-0000: Duplicate acknowledgement
I0814 18:06:08.398042 26891 process.cpp:3043] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I0814 18:06:08.398434 26891 master.cpp:3273] Telling slave 20150814-180608-1828659978-44896-26867-S0 at slave(6)@10.35.255.108:44896 (smfd-atr-11-sr1.devel.twitter.com) to kill task a17705ba-09db-4a7c-a3ae-80588afbef81 of framework 20150814-180608-1828659978-44896-26867-0000 (default)
I0814 18:06:08.398596 26902 slave.cpp:1768] Asked to kill task a17705ba-09db-4a7c-a3ae-80588afbef81 of framework 20150814-180608-1828659978-44896-26867-0000
I0814 18:06:08.398895 26896 exec.cpp:314] Executor asked to kill task 'a17705ba-09db-4a7c-a3ae-80588afbef81'
I0814 18:06:08.398983 26896 exec.cpp:323] Executor::killTask took 34869ns
I0814 18:06:08.400749 26896 exec.cpp:516] Executor sending status update TASK_KILLED (UUID: a323ad7c-bd18-4c0d-a49d-60766fddf3b0) for task a17705ba-09db-4a7c-a3ae-80588afbef81 of framework 20150814-180608-1828659978-44896-26867-0000
I0814 18:06:08.400900 26896 slave.cpp:2696] Handling status update TASK_KILLED (UUID: a323ad7c-bd18-4c0d-a49d-60766fddf3b0) for task a17705ba-09db-4a7c-a3ae-80588afbef81 of framework 20150814-180608-1828659978-44896-26867-0000 from executor(6)@10.35.255.108:44896
I0814 18:06:08.400976 26896 slave.cpp:5094] Terminating task a17705ba-09db-4a7c-a3ae-80588afbef81
I0814 18:06:08.401257 26895 status_update_manager.cpp:322] Received status update TASK_KILLED (UUID: a323ad7c-bd18-4c0d-a49d-60766fddf3b0) for task a17705ba-09db-4a7c-a3ae-80588afbef81 of framework 20150814-180608-1828659978-44896-26867-0000
I0814 18:06:08.401425 26904 slave.cpp:2899] Status update manager successfully handled status update TASK_KILLED (UUID: a323ad7c-bd18-4c0d-a49d-60766fddf3b0) for task a17705ba-09db-4a7c-a3ae-80588afbef81 of framework 20150814-180608-1828659978-44896-26867-0000
I0814 18:06:08.401505 26904 slave.cpp:2905] Sending acknowledgement for status update TASK_KILLED (UUID: a323ad7c-bd18-4c0d-a49d-60766fddf3b0) for task a17705ba-09db-4a7c-a3ae-80588afbef81 of framework 20150814-180608-1828659978-44896-26867-0000 to executor(6)@10.35.255.108:44896
I0814 18:06:08.401633 26904 exec.cpp:340] Executor received status update acknowledgement a323ad7c-bd18-4c0d-a49d-60766fddf3b0 for task a17705ba-09db-4a7c-a3ae-80588afbef81 of framework 20150814-180608-1828659978-44896-26867-0000
I0814 18:06:09.127125 26883 hierarchical.hpp:1008] No resources available to allocate!
I0814 18:06:09.127177 26883 hierarchical.hpp:908] Performed allocation for 1 slaves in 280830ns
I0814 18:06:10.127856 26895 hierarchical.hpp:1008] No resources available to allocate!
I0814 18:06:10.127892 26895 hierarchical.hpp:908] Performed allocation for 1 slaves in 240007ns
I0814 18:06:11.129323 26888 hierarchical.hpp:1008] No resources available to allocate!
I0814 18:06:11.129369 26888 hierarchical.hpp:908] Performed allocation for 1 slaves in 312825ns
I0814 18:06:12.130945 26885 hierarchical.hpp:1008] No resources available to allocate!
I0814 18:06:12.130985 26885 hierarchical.hpp:908] Performed allocation for 1 slaves in 254811ns
I0814 18:06:13.131691 26884 hierarchical.hpp:1008] No resources available to allocate!
I0814 18:06:13.131724 26884 hierarchical.hpp:908] Performed allocation for 1 slaves in 245484ns
I0814 18:06:14.132834 26885 hierarchical.hpp:1008] No resources available to allocate!
I0814 18:06:14.132881 26885 hierarchical.hpp:908] Performed allocation for 1 slaves in 335293ns
I0814 18:06:15.133868 26896 hierarchical.hpp:1008] No resources available to allocate!
I0814 18:06:15.133899 26896 hierarchical.hpp:908] Performed allocation for 1 slaves in 264043ns
I0814 18:06:16.134724 26895 hierarchical.hpp:1008] No resources available to allocate!
I0814 18:06:16.134755 26895 hierarchical.hpp:908] Performed allocation for 1 slaves in 263112ns
I0814 18:06:17.135427 26905 hierarchical.hpp:1008] No resources available to allocate!
I0814 18:06:17.135470 26905 hierarchical.hpp:908] Performed allocation for 1 slaves in 314745ns
I0814 18:06:18.137032 26896 hierarchical.hpp:1008] No resources available to allocate!
I0814 18:06:18.137056 26896 hierarchical.hpp:908] Performed allocation for 1 slaves in 220073ns
W0814 18:06:18.391554 26885 status_update_manager.cpp:477] Resending status update TASK_RUNNING (UUID: 3c287ef4-ee95-45ca-a5d0-97b73a3d9825) for task a17705ba-09db-4a7c-a3ae-80588afbef81 of framework 20150814-180608-1828659978-44896-26867-0000
I0814 18:06:18.391623 26885 status_update_manager.cpp:376] Forwarding update TASK_RUNNING (UUID: 3c287ef4-ee95-45ca-a5d0-97b73a3d9825) for task a17705ba-09db-4a7c-a3ae-80588afbef81 of framework 20150814-180608-1828659978-44896-26867-0000 to the slave
I0814 18:06:18.391939 26901 slave.cpp:2975] Forwarding the update TASK_RUNNING (UUID: 3c287ef4-ee95-45ca-a5d0-97b73a3d9825) for task a17705ba-09db-4a7c-a3ae-80588afbef81 of framework 20150814-180608-1828659978-44896-26867-0000 to master@10.35.255.108:44896
I0814 18:06:18.392241 26884 master.cpp:4068] Status update TASK_RUNNING (UUID: 3c287ef4-ee95-45ca-a5d0-97b73a3d9825) for task a17705ba-09db-4a7c-a3ae-80588afbef81 of framework 20150814-180608-1828659978-44896-26867-0000 from slave 20150814-180608-1828659978-44896-26867-S0 at slave(6)@10.35.255.108:44896 (smfd-atr-11-sr1.devel.twitter.com)
I0814 18:06:18.392279 26884 master.cpp:4107] Forwarding status update TASK_RUNNING (UUID: 3c287ef4-ee95-45ca-a5d0-97b73a3d9825) for task a17705ba-09db-4a7c-a3ae-80588afbef81 of framework 20150814-180608-1828659978-44896-26867-0000
I0814 18:06:18.392741 26884 master.cpp:5575] Updating the latest state of task a17705ba-09db-4a7c-a3ae-80588afbef81 of framework 20150814-180608-1828659978-44896-26867-0000 to TASK_KILLED (status update state: TASK_RUNNING)
I0814 18:06:18.393023 26889 hierarchical.hpp:814] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on slave 20150814-180608-1828659978-44896-26867-S0 from framework 20150814-180608-1828659978-44896-26867-0000
../../src/tests/scheduler_tests.cpp:535: Failure
Value of: event.get().update().status().state()
  Actual: TASK_RUNNING
Expected: v1::TASK_KILLED
Which is: TASK_KILLED
I0814 18:06:18.395231 26867 master.cpp:859] Master terminating
I0814 18:06:18.395364 26867 master.cpp:5643] Removing task a17705ba-09db-4a7c-a3ae-80588afbef81 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework 20150814-180608-1828659978-44896-26867-0000 on slave 20150814-180608-1828659978-44896-26867-S0 at slave(6)@10.35.255.108:44896 (smfd-atr-11-sr1.devel.twitter.com)
I0814 18:06:18.395429 26891 hierarchical.hpp:571] Removed slave 20150814-180608-1828659978-44896-26867-S0
I0814 18:06:18.395603 26867 master.cpp:5672] Removing executor 'default' with resources  of framework 20150814-180608-1828659978-44896-26867-0000 on slave 20150814-180608-1828659978-44896-26867-S0 at slave(6)@10.35.255.108:44896 (smfd-atr-11-sr1.devel.twitter.com)
I0814 18:06:18.396123 26905 hierarchical.hpp:428] Removed framework 20150814-180608-1828659978-44896-26867-0000
I0814 18:06:18.396842 26904 slave.cpp:3143] master@10.35.255.108:44896 exited
W0814 18:06:18.396888 26904 slave.cpp:3146] Master disconnected! Waiting for a new master to be elected
E0814 18:06:18.397043 26895 scheduler.cpp:426] End-Of-File received from master. The master closed the event stream
I0814 18:06:18.403226 26895 slave.cpp:3399] Executor 'default' of framework 20150814-180608-1828659978-44896-26867-0000 exited with status 0
I0814 18:06:18.404217 26901 slave.cpp:564] Slave terminating
I0814 18:06:18.404310 26901 slave.cpp:1959] Asked to shut down framework 20150814-180608-1828659978-44896-26867-0000 by @0.0.0.0:0
I0814 18:06:18.404345 26901 slave.cpp:1984] Shutting down framework 20150814-180608-1828659978-44896-26867-0000
I0814 18:06:18.404397 26901 slave.cpp:3503] Cleaning up executor 'default' of framework 20150814-180608-1828659978-44896-26867-0000
I0814 18:06:18.404556 26899 gc.cpp:56] Scheduling '/tmp/ContentType_SchedulerTest_KillTask_1_gxVuMf/slaves/20150814-180608-1828659978-44896-26867-S0/frameworks/20150814-180608-1828659978-44896-26867-0000/executors/default/runs/c5935633-2c84-4455-b8d8-cb929848cd61' for gc 6.99999531832296days in the future
I0814 18:06:18.404623 26901 slave.cpp:3592] Cleaning up framework 20150814-180608-1828659978-44896-26867-0000
I0814 18:06:18.404675 26899 gc.cpp:56] Scheduling '/tmp/ContentType_SchedulerTest_KillTask_1_gxVuMf/slaves/20150814-180608-1828659978-44896-26867-S0/frameworks/20150814-180608-1828659978-44896-26867-0000/executors/default' for gc 6.9999953172563days in the future
I0814 18:06:18.404700 26888 status_update_manager.cpp:284] Closing status update streams for framework 20150814-180608-1828659978-44896-26867-0000
I0814 18:06:18.404743 26888 status_update_manager.cpp:530] Cleaning up status update stream for task a17705ba-09db-4a7c-a3ae-80588afbef81 of framework 20150814-180608-1828659978-44896-26867-0000
I0814 18:06:18.404814 26903 gc.cpp:56] Scheduling '/tmp/ContentType_SchedulerTest_KillTask_1_gxVuMf/slaves/20150814-180608-1828659978-44896-26867-S0/frameworks/20150814-180608-1828659978-44896-26867-0000' for gc 6.99999531523259days in the future
[  FAILED  ] ContentType/SchedulerTest.KillTask/1, where GetParam() = application/json (10460 ms)