[17:31:35] looking into a curious issue, reqId bbebe293-bf71-43a9-ab67-1c8e12e2453b at 2024-09-06T4:51 logged something, there is a matching edit, but then the same server emits logs for the same reqId about Deferred's failing at 07:00:00. Anyone seen something like that before? Could it be logs landing late? It seems it shouldn't be possible for the request to stay open that long [17:49:19] Some deferred updates can happen after the request is sent, but i would assume timeouts would still apply to that [17:59:35] yea i would expect the same. It looks like this isn't isolated, poking through reqId's that trigered timeouts i found a8ea1282-dc5c-4265-a35d-38374f2731a5 and bb7130ad-59a0-4075-939b-0c75c35cb2ce which have the same behaviour of failing deferreds from same host and reqId hours later [17:59:58] and i only checked a few dozen, since i'm copying reqid's into logstash searches by hand [18:01:34] eximer docs say ""If an Eximer timer, or profile sample period, elapses while the engine is busy running a C function (such as mysqli_connect), then your callback or profile sample will take place immediately after that function completes" which suggests maybe it was stuck in a mysql call for a few hours? [18:03:27] they are all edit related too, which is how i started looking into it. We are missing things that are supposed to happen post-edit [18:14:28] I see some that aren't edit related, but those that aren't do seem parser related [19:01:29] we may be using the same reqid for jobs generated by the original request or something [19:04:13] true, but then the log entries should have a different host field [21:25:54] Filed T374662 about the problem ^^ with some context on how often (typically < 10 per day, max 20. Longest runtime 173 minutes) [21:25:54] T374662: PHP web requests running for multiple hours - https://phabricator.wikimedia.org/T374662