[
https://issues.apache.org/jira/browse/MESOS-3263?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14697941#comment-14697941
]
Vinod Kone commented on MESOS-3263:
-----------------------------------
Linking the ticket that broke this.
> SchedulerTask.KillTest fails for JSON Requests
> ----------------------------------------------
>
> Key: MESOS-3263
> URL: https://issues.apache.org/jira/browse/MESOS-3263
> Project: Mesos
> Issue Type: Bug
> Reporter: Anand Mazumdar
> Fix For: 0.24.0
>
>
> 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.
> {code}
> [ 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
> [email protected]: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
> [email protected]:44896
> I0814 18:06:08.323604 26899 slave.cpp:747] Authenticating with master
> [email protected]: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
> [email protected]: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 [email protected]: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
> [email protected]: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 [email protected]: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 [email protected]: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] [email protected]: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)
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
