AF5: sometimes a request just disappears after internal createTask event #3396

alexhunsley · 2021-01-19T15:23:17Z

I've read, understood, and done my best to follow the *CONTRIBUTING guidelines.

NOTE: this is almost the same issue as #3392, but using plain HTTP and only one concurrent request, and we are not creating sessions per request -- just the one Session for all the requests now.

What did you do?

Our iOS app was using Alamofire 4 successfully; as part of upgrading to iOS14, we moved to Alamofire 5. Our application connects to a backend from iPad on wifi. Connection goes over local network to a locally hosted apache webserver.

Our application isn't doing anything very complicated. It now makes plain HTTP requests, and only one at time (that is limited by an NSOperationQueue with a concurrency limit of 1), using a single Session object which we keep as long as we want to make those requests.

Pseudocode for making our requests in AF5:

// executed just once
session = Alamofire.Session([...])

// then later, executed many times, only one active at once:
session.request(url, method: method, parameters: parameters, encoding: encoding, headers: httpHeaders)
        .debug()
        .validate()
        .responseData(emptyResponseCodes: emptyBodyAllowedForCodes) { response in
                   // handle result
        }

What did you expect to happen?

We expect all HTTP requests to result in the completion block being called.

What happened instead?

Very occasionally (like, once in thousands of requests), the completion block isn't called, and as far as I can tell, the request is never made to the server (since the logs are missing a corresponding entry around that time).

I attached an AF Logger and logged everything I could. From that I can see the following in the log for one of the 'dropped' HTTP requests:

HTTPAlamofireRequester.request called...
in AlamoFireRequester: url = http://redacted/indexedDocument/64317069, method = HTTPMethod(rawValue: "GET"), headers = ["Date": "Wed, 13 Jan 2021 23:02:47 GMT", 
AHAFLogger session became invalid  = <__NSURLSessionLocal: 0x121110f60>
AHAFLogger requestDidResume: GET http://redacted/indexedDocument/64317069
AHAFLogger didCreateInitialURLRequest: http://redacted/indexedDocument/64317069
AHAFLogger didAdaptInitialRequest: req = http://redacted/indexedDocument/64317069 adapted req =http://redacted/indexedDocument/64317069
AHAFLogger didCreateURLRequest: http://redacted/indexedDocument/64317069
AHAFLogger didCreateTask: task = LocalDataTask <5F05B7E2-C6C0-4F4B-9F42-DBC9C3CEF521>.<1> orig req = Optional(http://redacted/indexedDocument/64317069)

The AHAFlogger lines are reporting Alamofire.Logger callbacks, so are a good sign of progress inside AF.

After the above log lines, there are no more lines mentioning the URL indexedDocument/64317069, and the completion block for that request is never called. So didCreateTask: task = is the last we hear about the request from AF.

When I check the server logs for recent requests, I can't find any trace of the request that seemed to disappear.

For comparison, here's the same verbose logging output for an HTTPS request that completed as expected:

NMNM alamoFireRequester: url = http://redacted/indexedDocument/64950467, method = HTTPMethod(rawValue: "GET"), headers = ["Date": "Wed, 13 Jan 2021 23:02:41 GMT", "X-Nonce": "(redacted)"]
AHAFLogger requestDidResume: GET http://redacted/indexedDocument/64950467
AHAFLogger session became invalid  = <__NSURLSessionLocal: 0x12101bd80>
AHAFLogger didCreateInitialURLRequest: http://redacted/indexedDocument/64950467
AHAFLogger didAdaptInitialRequest: req = http://redacted/indexedDocument/64950467 adapted req =http://redacted/indexedDocument/64950467
AHAFLogger didCreateURLRequest: http://redacted/indexedDocument/64950467
AHAFLogger didCreateTask: task = LocalDataTask <C30B71C0-5EFF-4DC5-9666-476B43B05B58>.<1> orig req = Optional(http://redacted/indexedDocument/64950467)
AHAFLogger didResumeTask: LocalDataTask <C30B71C0-5EFF-4DC5-9666-476B43B05B58>.<1>
[connection] nw_resolver_start_query_timer_block_invoke [C810] Query fired: did not receive all answers in time for redacted:443
AHAFLogger didReceiveChallenge: task = LocalDataTask <C30B71C0-5EFF-4DC5-9666-476B43B05B58>.<1>, orig req = Optional(http://redacted/indexedDocument/64950467)
[connection] nw_resolver_start_query_timer_block_invoke [C811] Query fired: did not receive all answers in time for redacted:443
AHAFLogger dataTask: didReceive data: origReq = Optional(http://redacted/indexedDocument/64950467)
AHAFLogger dataTask: didReceive data: origReq = Optional(http://redacted/indexedDocument/64950467)
    [ ... multiple didReceive data lines removed for brevity...]
AHAFLogger dataTask: didReceive data: origReq = Optional(http://redacted/indexedDocument/64950467)
AHAFLogger dataTask: willCacheResponse: origReq = Optional(http://redacted/indexedDocument/64950467)
[Request]: GET http://redacted/indexedDocument/64950467
    [Headers]:
        Authorization: Basic (redacted)
        Date: Wed, 13 Jan 2021 23:02:41 GMT
        X-Nonce: (redacted)
    [Body]: None
[Response]:
    [Status Code]: 200
    [Headers]:
        Content-Length: 121529
        Content-Type: application/octet-stream
        Date: Wed, 13 Jan 2021 23:02:40 GMT
        Server: (redacted)
        X-Powered-By: (redacted)
    [Body]: 121529 bytes
[Network Duration]: 0.7587810754776001s
[Serialization Duration]: 2.0541716367006302e-05s
[Result]: success(121529 bytes)
2021-01-13 23:02:41.855298+0000 CMIC PP[9284:9086514] url = http://redacted/indexedDocument/64950467, response code = 200 headers = Optional([AnyHashable("Server"): (redacted), AnyHashable("Content-Type"): application/octet-stream, AnyHashable("Content-Length"): 121529, AnyHashable("X-Powered-By"): (redacted), AnyHashable("Date"): Wed, 13 Jan 2021 23:02:40 GMT])
SGSG response headers: Optional([AnyHashable("Server"): (redacted), AnyHashable("Content-Type"): application/octet-stream, AnyHashable("Content-Length"): 121529, AnyHashable("X-Powered-By"): (redacted), AnyHashable("Date"): Wed, 13 Jan 2021 23:02:40 GMT])
SGSG response error: nil
SGSG underlying error: nil
 QOQO req done for http://redacted/indexedDocument/64950467, status = 200
AHAFLogger didGatherMetrics: req = GET http://redacted/indexedDocument/64950467 (200)
 NMNM caseFileDocumentOperation:didFinishForCaseFile: id = 64950467
AHAFLogger didValidateRequest: req: Optional(http://redacted/indexedDocument/64950467)
AHAFLogger didValidateRequest: req: Optional(http://redacted/indexedDocument/64950467)
No request created yet.
AHAFLogger didCompleteTask: LocalDataTask <C30B71C0-5EFF-4DC5-9666-476B43B05B58>.<1> orig req = Optional(http://redacted/indexedDocument/64950467)
AHAFLogger requestDidFinish: GET http://redacted/indexedDocument/64950467 (200)
AHAFLogger request(Value): req: GET http://redacted/indexedDocument/64950467 (200) didParseResp: success(121529 bytes)

Of note this is that we get more AF events after the AHAFLogger didCreateTask:. And of course the web server log shows these successful requests as 200 OK codes.

Alamofire Environment

Alamofire version: 5.4.1
Xcode version: 12.3
Swift version: Swift 5 (as per Xcode build settings)
Platform(s) running Alamofire: iOS 14.2 on iPad
macOS version running Xcode: 11.1
Alamofire integration method: Carthage
Project language: mixed ObjC + Swift

Demo Project

Apologies, I don't have a demo project at the current time, but wondering if the above info is useful in seeing what the issue could be.

The text was updated successfully, but these errors were encountered:

jshier · 2021-01-19T16:19:24Z

Thanks for the detailed report. How many requests are we talking about before a failure occurs? And your server logs show that the request is actually made, it just never calls back to the Session?

I would suggest adding more logging, in addition to what's available through EventMonitor, so you can track requests more closely, especially for the state of the Request. It's odd that you never get additional callbacks for requests that are actually made, since didCreateTask is only a few lines away from didResumeTask.

alexhunsley · 2021-01-19T21:08:17Z

Failure to call the completion can happen relatively quickly - in the first 500 requests -- or it can take 10,000 or more. It's really unpredictable. It failed after 8,560 requests just now in a test.

Server log shows request doesn't reach it. It almost looks like after createTask is logged, AF isn't auto-calling resume internally. I actually disabled auto-resume and manually called resume myself on each request after making it, just to explore that idea, but the problem still occurred.

I've clarified the issue description to make it clear that the request doesn't seem to hit the server.

So it look like the HTTP request isn't even leaving the iPad, but I'd need to use Wireshark or similar to make absolutely sure of that.

Thanks for the state logging idea, I'll do some logging on that and update.

jshier · 2021-01-20T00:11:24Z

Can you share the code you're using to enqueue requests onto the OperationQueue? I set up a simple test and repeatedly ran 100,000 requests to a local test server without issue.

alexhunsley · 2021-01-20T10:29:07Z

Hi, unfortunately I've run out of time with the client for investigating AF side, and they want to see what the app will do if we just use the usual iOS comms APIs directly.
I'll certainly update you here with the results as it might be useful. It could well be an iOS level comms thing, regardless of Alamofire.

alexhunsley · 2021-01-21T15:21:42Z

Hi again, we're still looking at AF.

I've found that if I run our app in the profiler (using Allocations instrument), we get the issue really fast - within hundreds of attempts, not thousands. Does your example run ok in the profiler?

Profiler shows the issue quickly for both Debug and Release modes.

jshier · 2021-01-25T00:43:14Z

It would be useful if you posted your enqueueing code, otherwise I'm just guessing at how you're enqueueing all of those requests. I'll give it a try in Instruments.

jshier · 2021-01-25T01:33:01Z

I've created a simple app which runs 10,000 requests in an OperationQueue one at a time and haven't been able to replicate a failure. It would be great if you could create a test project which replicates the issue (I can provide my own request URL).

alexhunsley · 2021-01-25T11:00:21Z

I'll do it if I have time, but client has other ideas. They're asking me to submit a ticket to Apple support about this, against my advice. We all know the result of a TSI will be "Not our API, not our problem!"

thatsxiao5 · 2022-04-18T01:56:44Z

Have you solved it? I also have the same result. very occasionally and randomly. Do you use Alamofire 4 instead of 5?

thatsxiao5 · 2022-04-25T08:21:27Z

Hi, I forgot to provide a information that, I cancel a request everytime before session request( Base on our app). I don't know if this will help.

jackiossy · 2023-07-16T09:15:42Z

Mark. I also have this question.

PriyankaThread · 2023-11-08T12:48:42Z

Hi Team, Any update for this issue, we are commonly facing the same issue on iPhone 13 so please let us know how we can deal with and resolve it from our side.
When we checked and debugged Alamofire task session LocalDataTask did not execute. Our API and Server both are working properly.

 [LocalDataTask
<5127CF78-4526-4AE5-9A23-1C2F6C3BDA09>. <70›, LocalDataTask
<6784E32E-4FF1-49E5-A77F-CA43906F5C64>.<71>,
LocalDataTask
<7CA70A66-0B44-434C-9AC9-E7B6897DCBDD>. <72›, LocalDataTask
<2099A752-4499-4524-B144-DC4BBE6DCDF5>. <74>, LocalDataTask
<D10BAEED-CE41-423C-AE1C-01F7D7E50CB8>.<77>, LocalDataTask
<2BD6AE21-DFE9-4F2C-931A-48CD3BEC6511>. <78>, LocalDataTask
<AEF68696-7385-4545-90EA-8EAE62214A92>.<79>,
LocalDataTask
<79E98006-D02E-42DB-BA08-D706EC30CE33>. <80>,
LocalDataTask
<9568184D-8658-4971-82C6-9D7E6C8F1280>.<81>,
LocalDataTask
<7212BADF-C4DF-4E31-A5D3-80F60883D584>. <82>,
LocalDataTask
<A23108C1-E527-460F-9FB1-CDC6AF7FE37A>. <83>, LocalDataTask
<B0C30D69-36A0-4906-A7CE-549A259B014B>. <84>, LocalDataTask
<B706454C-A4A7-4D61-859E-48A12EFAD736>.<85›, LocalDataTask
<014E64D4-2571-4875-9BC4-6FDABF@CAC15>. <86>, LocalDataTask
<BOD&CADE-D88E-4D99-B915-36092524A185>.<87>, LocalDataTask
<AD3B5D9D-4B3C-448A-A944-C90D6AB1D8F1>) <88>,
LocalDataTask
<34900E16-187-4A85-AE27-ABAE801E5D0B>.<89>,
LocalDataTask
<5E81D5EF-F18F-4CE7-BCFE-281597C68EC1>, <90> ]

jshier self-assigned this Jan 25, 2021

jshier added the needs investigation label Jan 25, 2021

thatsxiao5 mentioned this issue Apr 24, 2022

Alamofire 5 never call back after session request (very occasionally and randomly.) #3602

Closed

1 task

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

AF5: sometimes a request just disappears after internal createTask event #3396

AF5: sometimes a request just disappears after internal createTask event #3396

alexhunsley commented Jan 19, 2021 •

edited

jshier commented Jan 19, 2021

alexhunsley commented Jan 19, 2021 •

edited

jshier commented Jan 20, 2021

alexhunsley commented Jan 20, 2021 •

edited

alexhunsley commented Jan 21, 2021 •

edited

jshier commented Jan 25, 2021

jshier commented Jan 25, 2021

alexhunsley commented Jan 25, 2021

thatsxiao5 commented Apr 18, 2022

thatsxiao5 commented Apr 25, 2022

jackiossy commented Jul 16, 2023

PriyankaThread commented Nov 8, 2023

AF5: sometimes a request just disappears after internal createTask event #3396

AF5: sometimes a request just disappears after internal createTask event #3396

Comments

alexhunsley commented Jan 19, 2021 • edited

What did you do?

What did you expect to happen?

What happened instead?

Alamofire Environment

Demo Project

jshier commented Jan 19, 2021

alexhunsley commented Jan 19, 2021 • edited

jshier commented Jan 20, 2021

alexhunsley commented Jan 20, 2021 • edited

alexhunsley commented Jan 21, 2021 • edited

jshier commented Jan 25, 2021

jshier commented Jan 25, 2021

alexhunsley commented Jan 25, 2021

thatsxiao5 commented Apr 18, 2022

thatsxiao5 commented Apr 25, 2022

jackiossy commented Jul 16, 2023

PriyankaThread commented Nov 8, 2023

alexhunsley commented Jan 19, 2021 •

edited

alexhunsley commented Jan 19, 2021 •

edited

alexhunsley commented Jan 20, 2021 •

edited

alexhunsley commented Jan 21, 2021 •

edited