Error : 429 : Too Many Requests: retry after 1
monich opened this issue · 13 comments
Sometimes when you open a chat, Fernschreiber goes into a loop of some sort consuming lots of CPU and printing tons of messages like this:
[ 2][t 4][1609955073.875465631][FileManager.cpp:3585][#1][!FileManager] Failed to DownloadWaitFileReference file 8183(0) of type photos: [Error : 429 : Too Many Requests: retry after 1]
[ 2][t 4][1609955073.876463651][FileManager.cpp:3585][#1][!FileManager] Failed to DownloadWaitFileReference file 8183(0) of type photos: [Error : 429 : Too Many Requests: retry after 1]
[ 2][t 4][1609955073.877481460][FileManager.cpp:3585][#1][!FileManager] Failed to DownloadWaitFileReference file 8183(0) of type photos: [Error : 429 : Too Many Requests: retry after 1]
[ 2][t 4][1609955073.893348217][FileManager.cpp:3585][#1][!FileManager] Failed to DownloadWaitFileReference file 8183(0) of type photos: [Error : 429 : Too Many Requests: retry after 1]
[ 2][t 4][1609955073.894533395][FileManager.cpp:3585][#1][!FileManager] Failed to DownloadWaitFileReference file 8183(0) of type photos: [Error : 429 : Too Many Requests: retry after 1]
[ 2][t 4][1609955073.895529031][FileManager.cpp:3585][#1][!FileManager] Failed to DownloadWaitFileReference file 8183(0) of type photos: [Error : 429 : Too Many Requests: retry after 1]
[ 2][t 4][1609955073.896537542][FileManager.cpp:3585][#1][!FileManager] Failed to DownloadWaitFileReference file 8183(0) of type photos: [Error : 429 : Too Many Requests: retry after 1]
[ 2][t 4][1609955073.897451400][FileManager.cpp:3585][#1][!FileManager] Failed to DownloadWaitFileReference file 8183(0) of type photos: [Error : 429 : Too Many Requests: retry after 1]
[ 2][t 4][1609955073.908968448][FileManager.cpp:3585][#1][!FileManager] Failed to DownloadWaitFileReference file 8183(0) of type photos: [Error : 429 : Too Many Requests: retry after 1]
[ 2][t 4][1609955073.918757200][FileManager.cpp:3585][#1][!FileManager] Failed to DownloadWaitFileReference file 8183(0) of type photos: [Error : 429 : Too Many Requests: retry after 1]
Whatever is submitting those requests (most likely it's TDLibFile object) needs to apply some throttling when it's seeing those fail too often.
Huh, never seen that. Is that a chat with a lot of images?
Huh, never seen that. Is that a chat with a lot of images?
Yes, and it's not happening every time. But I've seen it significantly more than once.
And I'm pretty sure that it started happening after tdlib 1.7.0 update.
Any link to be able to reproduce that? We could disable TDLibFile in a test build and try to isolate it...
It's not TDLibFile as such. That loop can easily be stopped by restricting number of attempts to 1. Some pictures just will never be downloaded, like it sometimes happens with requests submitted from JavaScript. But is that the desired behavior?
To reproduce it, you need a channel with lots of pictures or web previews, scroll all the way up to generate as many download requests as possible. It's a random thing, you may have to retry a few times.
The problem is that tdlib becomes unhappy but doesn't indicate its unhappiness in any detectable way (printing this DownloadWaitFileReference message doesn't count - how do we detect that?). It just tells us in the form of "@type": "file" and/or "@type": "updateFile" messages (usually both with 1.7.0) - the file is updated, it's not downloaded yet ("is_downloading_completed": false), can be downloaded ("can_be_downloaded": true) but for whatever reason is not being downloaded ("is_downloading_active": false). Of course TDLibFile starts downloading it again.
It's easy enough to try downloading no more than once but then the file is going to stay unavailable because the previous download attempt failed and the new one was never made.
It looks like this in debug log:
[ 2][t 4][1610062505.722564697][FileManager.cpp:3585][#1][!FileManager] Failed to DownloadWaitFileReference file 8977(0) of type photos: [Error : 429 : Too Many Requests: retry after 1]
[D] TDLibReceiver::receiverLoop:160 - [TDLibReceiver] Raw result: {
"@type": "updateFile",
"file": {
"@type": "file",
"expected_size": 144559,
"id": 8977,
"local": {
"@type": "localFile",
"can_be_deleted": false,
"can_be_downloaded": true,
"download_offset": 0,
"downloaded_prefix_size": 0,
"downloaded_size": 0,
"is_downloading_active": false,
"is_downloading_completed": false,
"path": ""
},
"remote": {
"@type": "remoteFile",
"id": "AgACAgQAAwEjAALLqzEbjfZlU5JFnH6vrKMykpAGJ10AAwEAAwIAA3kAA4HEAwABHgQ",
"is_uploading_active": false,
"is_uploading_completed": true,
"unique_id": "AQADkpAGJ10AA4HEAwAB",
"uploaded_size": 144559
},
"size": 144559
}
}
[D] TDLibReceiver::processUpdateFile:226 - [TDLibReceiver] File was updated: "8977"
[D] TDLibFile::handleFileUpdated:217 - [TDLibFile] File 8977 updated
[D] TDLibWrapper::downloadFile:239 - [TDLibWrapper] Downloading file 8977
[D] TDLibReceiver::receiverLoop:160 - [TDLibReceiver] Raw result: {
"@type": "file",
"expected_size": 144559,
"id": 8977,
"local": {
"@type": "localFile",
"can_be_deleted": false,
"can_be_downloaded": true,
"download_offset": 0,
"downloaded_prefix_size": 0,
"downloaded_size": 0,
"is_downloading_active": false,
"is_downloading_completed": false,
"path": ""
},
"remote": {
"@type": "remoteFile",
"id": "AgACAgQAAwEjAALLqzEbjfZlU5JFnH6vrKMykpAGJ10AAwEAAwIAA3kAA4HEAwABHgQ",
"is_uploading_active": false,
"is_uploading_completed": true,
"unique_id": "AQADkpAGJ10AA4HEAwAB",
"uploaded_size": 144559
},
"size": 144559
}
[D] TDLibWrapper::sendRequest:161 - [TDLibWrapper] Sending request to TD Lib, object type name: "downloadFile"
[D] TDLibReceiver::processFile:233 - [TDLibReceiver] File was updated: "8977"
[D] TDLibWrapper::sendRequest:163 - [TDLibWrapper] {
"@type": "downloadFile",
"file_id": 8977,
"limit": 0,
"offset": 0,
"priority": 1,
"synchronous": false
And so on.
I tried ignoring "@type": "file" and only handling "@type": "updateFile" but it didn't help 😕
An asynchronous request with no reply whatsoever is generally a strange approach. How am I supposed to know what happened to my request?
But the infinite loop actually happens (at least in the case which I was able to analyze) because we get "updateMessageContent" with a new file id and I even see something like this in the log:
[D] TDLibReceiver::processUpdateMessageContent:406 - [TDLibReceiver] Message content updated -1001140809683 12096372736
[D] ChatModel::handleMessageContentUpdated:447 - [ChatModel] Message content updated -1001140809683 12096372736
[D] ChatModel::handleMessageContentUpdated:449 - [ChatModel] We know the message that was updated 12096372736
[D] ChatModel::handleMessageContentUpdated:453 - [ChatModel] Message was replaced at index 32
[D] expression for onMessageUpdated:164 - [ChatModel] This message was updated, index 32 , updating content...
but is appears that TDLibFile's fileInformation doesn't get updated and poor thing keeps asking for the old file. Some changes are required on the QML side. Download rate reducer still makes sense, though. As does the retry logic - sometimes retries do succeed.
Is this issue still there or did #297 really fix the root cause?