AJAX request cancelled sometimes when api called several times

Question

In an application a url is being invoked 4 times via ajax. For some reason when the request is made the 4th time on a particular page the ajax request is cancelled.
The 4th request has "Provisional headers are shown" in its request headers and for some reason a 5th request(similar to 4th request) is made(not by the application).

I was able to do some digging in using chrome://net-internals. Below i have reproduced the 3rd and 4th request completely and the main differences are in HTTP_TRANSACTION_READ_HEADERS portion of the network log.
The following is the entire data in the 4th request(for some reason it gets a 302 back unlike the other 3 requests -

t=61558 [st=  0] +REQUEST_ALIVE  [dt=274]
                  --> priority = "MEDIUM"
                  --> url = "https://example.com/api/v1/track/login?time=1556662845627"
t=61559 [st=  1]    NETWORK_DELEGATE_BEFORE_URL_REQUEST  [dt=0]
t=61559 [st=  1]   +URL_REQUEST_START_JOB  [dt=273]
                    --> load_flags = 0 (NORMAL)
                    --> method = "POST"
                    --> privacy_mode = 0
                    --> upload_id = "0"
                    --> url = "https://example.com/api/v1/track/login?time=1556662845627"
t=61559 [st=  1]      NETWORK_DELEGATE_BEFORE_START_TRANSACTION  [dt=0]
t=61559 [st=  1]      HTTP_CACHE_GET_BACKEND  [dt=0]
t=61559 [st=  1]     +HTTP_STREAM_REQUEST  [dt=0]
t=61559 [st=  1]        HTTP_STREAM_JOB_CONTROLLER_BOUND
                        --> source_dependency = 1619753 (HTTP_STREAM_JOB_CONTROLLER)
t=61559 [st=  1]        HTTP_STREAM_REQUEST_BOUND_TO_JOB
                        --> source_dependency = 1619754 (HTTP_STREAM_JOB)
t=61559 [st=  1]     -HTTP_STREAM_REQUEST
t=61559 [st=  1]      UPLOAD_DATA_STREAM_INIT  [dt=0]
                      --> is_chunked = false
                      --> net_error = 0 (?)
                      --> total_size = 112
t=61559 [st=  1]     +HTTP_TRANSACTION_SEND_REQUEST  [dt=1]
t=61559 [st=  1]        HTTP_TRANSACTION_HTTP2_SEND_REQUEST_HEADERS
                        --> :method: POST
                            :authority: example.com
                            :scheme: https
                            :path: /api/v1/track/login?time=1556662845627
                            content-length: 112
                            accept: application/json, text/javascript, */*; q=0.01
                            origin: https://example.com
                            x-requested-with: XMLHttpRequest
                            user-agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/73.0.3683.103 Safari/537.36
                            content-type: application/x-www-form-urlencoded; charset=UTF-8
                            referer: https://example.com/index.php
                            accept-encoding: gzip, deflate, br
                            accept-language: en-US,en;q=0.9
                            cookie: [1570 bytes were stripped]
t=61560 [st=  2]        UPLOAD_DATA_STREAM_READ  [dt=0]
                        --> current_position = 0
t=61560 [st=  2]        HTTP2_STREAM_UPDATE_SEND_WINDOW
                        --> delta = -112
                        --> stream_id = 117
                        --> window_size = 65424
t=61560 [st=  2]     -HTTP_TRANSACTION_SEND_REQUEST
t=61560 [st=  2]     +HTTP_TRANSACTION_READ_HEADERS  [dt=270]
t=61830 [st=272]        HTTP_TRANSACTION_READ_RESPONSE_HEADERS
                        --> HTTP/1.1 302
                            status: 302
                            date: Tue, 30 Apr 2019 22:20:45 GMT
                            content-type: text/html; charset=UTF-8
                            content-length: 0
                            location: http://example.com/api/v1/track/login?time=1556662845627
                            server: Apache/2.4.25 (Debian)
                            x-powered-by: PHP/5.6.39
                            expires: Thu, 19 Nov 1981 08:52:00 GMT
                            cache-control: no-store, no-cache, must-revalidate, post-check=0, pre-check=0
                            pragma: no-cache
                            set-cookie: [74 bytes were stripped]
                            set-cookie: [77 bytes were stripped]
                            access-control-allow-origin: *
                            access-control-allow-headers: origin, x-requested-with, content-type
                            access-control-allow-methods: PUT, GET, POST, DELETE, OPTIONS
t=61830 [st=272]     -HTTP_TRANSACTION_READ_HEADERS
t=61830 [st=272]      NETWORK_DELEGATE_HEADERS_RECEIVED  [dt=0]
t=61830 [st=272]      URL_REQUEST_DELEGATE_RECEIVED_REDIRECT  [dt=2]
t=61832 [st=274]      CANCELLED
t=61832 [st=274] -REQUEST_ALIVE

The following is the entire data in the 3rd request -

t=61346 [st= 0] +REQUEST_ALIVE  [dt=97]
                 --> priority = "MEDIUM"
                 --> url = "https://test.undostres.com.mx/api/v1/track/login?time=1556662845405"
t=61346 [st= 0]    NETWORK_DELEGATE_BEFORE_URL_REQUEST  [dt=0]
t=61346 [st= 0]   +URL_REQUEST_START_JOB  [dt=97]
                   --> load_flags = 0 (NORMAL)
                   --> method = "POST"
                   --> privacy_mode = 0
                   --> upload_id = "0"
                   --> url = "https://test.undostres.com.mx/api/v1/track/login?time=1556662845405"
t=61346 [st= 0]      NETWORK_DELEGATE_BEFORE_START_TRANSACTION  [dt=0]
t=61346 [st= 0]      HTTP_CACHE_GET_BACKEND  [dt=0]
t=61346 [st= 0]     +HTTP_STREAM_REQUEST  [dt=1]
t=61346 [st= 0]        HTTP_STREAM_JOB_CONTROLLER_BOUND
                       --> source_dependency = 1619732 (HTTP_STREAM_JOB_CONTROLLER)
t=61347 [st= 1]        HTTP_STREAM_REQUEST_BOUND_TO_JOB
                       --> source_dependency = 1619733 (HTTP_STREAM_JOB)
t=61347 [st= 1]     -HTTP_STREAM_REQUEST
t=61347 [st= 1]      UPLOAD_DATA_STREAM_INIT  [dt=0]
                     --> is_chunked = false
                     --> net_error = 0 (?)
                     --> total_size = 105
t=61347 [st= 1]     +HTTP_TRANSACTION_SEND_REQUEST  [dt=1]
t=61347 [st= 1]        HTTP_TRANSACTION_HTTP2_SEND_REQUEST_HEADERS
                       --> :method: POST
                           :authority: test.undostres.com.mx
                           :scheme: https
                           :path: /api/v1/track/login?time=1556662845405
                           content-length: 105
                           accept: application/json, text/javascript, */*; q=0.01
                           origin: https://test.undostres.com.mx
                           x-requested-with: XMLHttpRequest
                           user-agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/73.0.3683.103 Safari/537.36
                           content-type: application/x-www-form-urlencoded; charset=UTF-8
                           referer: https://test.undostres.com.mx/index.php
                           accept-encoding: gzip, deflate, br
                           accept-language: en-US,en;q=0.9
                           cookie: [1345 bytes were stripped]
t=61348 [st= 2]        UPLOAD_DATA_STREAM_READ  [dt=0]
                       --> current_position = 0
t=61348 [st= 2]        HTTP2_STREAM_UPDATE_SEND_WINDOW
                       --> delta = -105
                       --> stream_id = 113
                       --> window_size = 65431
t=61348 [st= 2]     -HTTP_TRANSACTION_SEND_REQUEST
t=61348 [st= 2]     +HTTP_TRANSACTION_READ_HEADERS  [dt=95]
t=61443 [st=97]        HTTP_TRANSACTION_READ_RESPONSE_HEADERS
                       --> HTTP/1.1 200
                           status: 200
                           date: Tue, 30 Apr 2019 22:20:45 GMT
                           content-type: text/html; charset=UTF-8
                           content-length: 41
                           server: Apache/2.4.25 (Debian)
                           x-powered-by: PHP/5.6.39
                           expires: Thu, 19 Nov 1981 08:52:00 GMT
                           cache-control: no-store, no-cache, must-revalidate, post-check=0, pre-check=0
                           pragma: no-cache
                           access-control-allow-origin: *
                           access-control-allow-headers: origin, x-requested-with, content-type
                           access-control-allow-methods: PUT, GET, POST, DELETE, OPTIONS
t=61443 [st=97]     -HTTP_TRANSACTION_READ_HEADERS
t=61443 [st=97]      NETWORK_DELEGATE_HEADERS_RECEIVED  [dt=0]
t=61443 [st=97]   -URL_REQUEST_START_JOB
t=61443 [st=97]    URL_REQUEST_DELEGATE_RESPONSE_STARTED  [dt=0]
t=61443 [st=97]   +HTTP_TRANSACTION_READ_BODY  [dt=0]
t=61443 [st=97]      HTTP2_STREAM_UPDATE_RECV_WINDOW
                     --> delta = -41
                     --> stream_id = 113
                     --> window_size = 6291415
t=61443 [st=97]   -HTTP_TRANSACTION_READ_BODY
t=61443 [st=97]    URL_REQUEST_JOB_FILTERED_BYTES_READ
                   --> byte_count = 41
t=61443 [st=97]    HTTP_TRANSACTION_READ_BODY  [dt=0]
t=61443 [st=97] -REQUEST_ALIVE

While trying to fix this issue we were able to get it working with following code -

<meta http-equiv="Content-Security-Policy" content="upgrade-insecure-requests">

However it makes no sense.

PS - Here are some server logs. As you will notice, same api becomes 302 after some attempts. Also this seems related but didnt work.

 189.213.84.17 - - [30/Apr/2019:22:19:31 -0500] "POST /api/v1/track/login?time=1556680771692 HTTP/1.1" 200 1316 "https://example.com/index.php" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/73.0.3683.103 Safari/537.36"
189.213.84.17 - - [30/Apr/2019:22:19:32 -0500] "POST /api/v1/track/login?time=1556680772165 HTTP/1.1" 200 1316 "https://example.com/index.php" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/73.0.3683.103 Safari/537.36"
189.213.84.17 - - [30/Apr/2019:22:19:32 -0500] "POST /api/v1/track/login?time=1556680772167 HTTP/1.1" 200 1316 "https://example.com/index.php" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/73.0.3683.103 Safari/537.36"
189.213.84.17 - - [30/Apr/2019:22:19:32 -0500] "POST /api/v1/track/login?time=1556680772393 HTTP/1.1" 302 1534 "https://example.com/index.php" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/73.0.3683.103 Safari/537.36"

Can you reproduce this in any other browser? If it only happens in Chrome, you probably want to consider adding a tag to make that more clear. — sideshowbarker, May 01 '19 at 01:41

score 1 · Accepted Answer · answered May 01 '19 at 01:44

1

It looks like your web server is returning a redirect to a non secure URL

HTTP_TRANSACTION_READ_RESPONSE_HEADERS
                    --> HTTP/1.1 302
                        status: 302
                        date: Tue, 30 Apr 2019 22:20:45 GMT
                        content-type: text/html; charset=UTF-8
                        content-length: 0
                        location: http://example.com/api/v1/track/login?time=1556662845627

Chrome is refusing to redirect to that URL because it's already on HTTPS. I guess with the meta tag in place, Chrome is transforming that HTTP into HTTPS automatically and everything works.

So first place to look would be why the server is sending a redirect to a HTTP URL when it is already receiving a HTTPS request.

answered May 01 '19 at 01:44

AaronHolland

1,595
1
16
32

have added some server logs to the bottom of the question @AaronHolland – rnjai May 01 '19 at 03:24
1

The web server is sending you the redirect, so without having the source to the web server code it's hard to see what is different about the 4th request. Are the cookies being sent any different? Is the POSTed data any different? Is the web server rate-limiting you or something? Is it load balanced and hitting a different web server? Perhaps a base URL is configured differently in one web server vs another? – AaronHolland May 01 '19 at 03:55
Are the cookies being sent any different - can't tell since "Provisional headers are shown" . No rate limiting. No different server. No different configuration in picture. Thanks for the ideas though. – rnjai May 01 '19 at 05:02
actually i just started logging request headers on the server and saw that the 4th request has an extra cookie(key value) compared to the 3 other requests. how does this effect things? how to dig deeper into the issue? @AaronHolland – rnjai May 01 '19 at 14:41
it was an application level issue. thanks for the help. – rnjai May 01 '19 at 21:58

score 0 · Answer 2 · answered May 01 '19 at 21:57

0

The issue was an application level redirect(location:...) sent as a response to the ajax request.

answered May 01 '19 at 21:57

rnjai

1,065
2
17
32

AJAX request cancelled sometimes when api called several times

2 Answers2