Description
Currently, SchedulerTests.KillTask fails when the ContentType specified is JSON in the request.
The crash happens in Master when it tries to process the Acknowledge call from client. The sent UUID escaped string in JSON from the client is unable to be correctly parsed by the master leading to the crash.
[ 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)
Attachments
Issue Links
- is broken by
-
MESOS-3267 JSON serialization/deserialization of bytes is incorrect
-
- Resolved
-