php.net |  support |  documentation |  report a bug |  advanced search |  search howto |  statistics |  random bug |  login

go to bug id or search bugs for

Bug #79928 fastcgi_finish_request() doesn't finish request
Submitted: 2020-08-04 13:47 UTC Modified: 2021-01-10 04:22 UTC
From: vedad at kajtaz dot net Assigned: bukka (profile)
Status: No Feedback Package: FPM related
PHP Version: 7.4.8 OS: FreeBSD 12.1-RELEASE
Private report: No CVE-ID: None
View Add Comment Developer Edit
Welcome! If you don't have a Git account, you can't do anything here.
You can add a comment by following this link or if you reported this bug, you can edit this bug over here.
(description)
Block user comment
Status: Assign to:
Package:
Bug Type:
Summary:
From: vedad at kajtaz dot net
New email:
PHP Version: OS:

 

 [2020-08-04 13:47 UTC] vedad at kajtaz dot net 
Description:
------------
Hi,

I have a FPM (unix socket) + nginx setup.

I have a couple of scripts, invoked from cron through nginx, that are designed to run lengthy tasks.

The very first thing these scripts do is to invoke fastcgi_finish_request() (after going through some routing logic).

They don't produce any output, neither before nor after invoking fastcgi_finish_request(). I did try writing to stdout and/or seanding headers before the call, the behavior remains the same.

Seldomly (roughly one request out of 10), FPM doesn't seem to notify nginx, which results in nginx reporting a timeout (which is configured to 30 seconds):

	2020/08/03 18:38:33 [error] 82940#103032: *41412 upstream timed out (60: Operation timed out) while reading response header from upstream, client: XX.XXX.XXX.XXX, server: XXXXXXXXX.XXXXXXXXXX.com, request: "GET /cron/XXXXXXXXXX HTTP/1.1", upstream: "fastcgi://unix:/tmp/XXXXXXXXX.sock", host: "XXXXXXXXX.XXXXXXXXXX.com"

Even when the 30 seconds timeout is not reached, I see instances of scripts running for more that a couple of milliseconds one would except when fastcgi_finish_request() is invoked straight away (first column = response time in seconds):

	0.001 XX.XXX.XXX.XXX - - [04/Aug/2020:14:34:17 +0200] "GET /cron/XXXXXXXXXX HTTP/1.1" 200 5 "-" "cron"
	17.253 XX.XXX.XXX.XXX - - [04/Aug/2020:14:34:17 +0200] "GET /cron/XXXXXXXXXX HTTP/1.1" 200 5 "-" "cron"

I have no idea where to start to try debugging this issue.

Any ideas?

Patches

Add a Patch

Pull Requests

Add a Pull Request

History

AllCommentsChangesGit/SVN commitsRelated reports
 [2020-12-28 20:00 UTC] bukka@php.net
-Assigned To: +Assigned To: bukka
 [2020-12-28 20:00 UTC] bukka@php.net 
It's a bit late reply but you might want to read the comment in https://www.php.net/manual/en/function.fastcgi-finish-request.php which explains what can potentially happen. I would probably first check fpm status or even better set some monitoring to see how busy the children are and if you are using pm.max_children. Basically the timeout can happen if all children are overloaded with the lengthy tasks.

Please update this bug if you notice something that you think doesn't look right in FPM.
 [2020-12-28 20:00 UTC] bukka@php.net
-Status: Assigned +Status: Feedback
 [2021-01-10 04:22 UTC] php-bugs at lists dot php dot net 
No feedback was provided. The bug is being suspended because
we assume that you are no longer experiencing the problem.
If this is not the case and you are able to provide the
information that was requested earlier, please do so and
change the status of the bug back to "Re-Opened". Thank you.
 
PHP Copyright © 2001-2021 The PHP Group
All rights reserved. 		Last updated: Sun Jan 17 07:01:23 2021 UTC