Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

FastCGI timeout (Not docker related) #1119

Closed
indridieinarsson opened this issue Jul 15, 2024 · 17 comments
Closed

FastCGI timeout (Not docker related) #1119

indridieinarsson opened this issue Jul 15, 2024 · 17 comments
Assignees

Comments

@indridieinarsson
Copy link
Contributor

🐛 Bugreport

I am running cypht using docker compose. Building the docker image from source locally.
Previous version ran without the issue described here (master branch ca. month ago). After updating to the most recent master branch, the issue began.

Cypht comes up as regular, and is usable (there are some issues regarding the Everything folder not displaying all accounts, but that was unchanged between versions).
After some usage, usually just a few minutes, cypth becomes unreachable, with the browser displaying just: "504 Gateway Time-out
nginx/1.26.1". Sometimes, browser says "404 page not found".

In the docker logs, I get the following:

<< fastCGI error is repeated a lot >>
cypht-1  | 172.22.0.2 - - [15/Jul/2024:11:17:56 +0000] "POST / HTTP/1.1" 504 569 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/125.0.0.0 Safari/537.36"
cypht-1  | 127.0.0.1 -  15/Jul/2024:11:18:10 +0000 "POST /index.php" 200
cypht-1  | 172.22.0.2 - - [15/Jul/2024:11:18:10 +0000] "POST / HTTP/1.1" 200 78 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/125.0.0.0 Safari/537.36"
cypht-1  | 127.0.0.1 -  15/Jul/2024:11:18:14 +0000 "GET /index.php" 200
cypht-1  | 127.0.0.1 - - [15/Jul/2024:11:18:14 +0000] "GET / HTTP/1.1" 200 510848 "-" "curl/8.7.1"
cypht-1  | 127.0.0.1 -  15/Jul/2024:11:18:26 +0000 "POST /index.php" 200
cypht-1  | 172.22.0.2 - - [15/Jul/2024:11:18:26 +0000] "POST / HTTP/1.1" 200 21209 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/125.0.0.0 Safari/537.36"
cypht-1  | 127.0.0.1 -  15/Jul/2024:11:18:26 +0000 "POST /index.php" 200
cypht-1  | 172.22.0.2 - - [15/Jul/2024:11:18:27 +0000] "POST / HTTP/1.1" 200 21209 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/125.0.0.0 Safari/537.36"
cypht-1  | 127.0.0.1 -  15/Jul/2024:11:18:27 +0000 "POST /index.php" 200
cypht-1  | 172.22.0.2 - - [15/Jul/2024:11:18:27 +0000] "POST / HTTP/1.1" 200 276 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/125.0.0.0 Safari/537.36"
cypht-1  | 127.0.0.1 -  15/Jul/2024:11:18:27 +0000 "POST /index.php" 200
cypht-1  | 172.22.0.2 - - [15/Jul/2024:11:18:28 +0000] "POST / HTTP/1.1" 200 20364 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/125.0.0.0 Safari/537.36"
cypht-1  | 127.0.0.1 -  15/Jul/2024:11:18:28 +0000 "POST /index.php" 200
cypht-1  | 172.22.0.2 - - [15/Jul/2024:11:18:28 +0000] "POST / HTTP/1.1" 200 285 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/125.0.0.0 Safari/537.36"
cypht-1  | 127.0.0.1 -  15/Jul/2024:11:18:44 +0000 "GET /index.php" 200
cypht-1  | 127.0.0.1 - - [15/Jul/2024:11:18:44 +0000] "GET / HTTP/1.1" 200 510848 "-" "curl/8.7.1"
cypht-1  | 127.0.0.1 -  15/Jul/2024:11:19:10 +0000 "POST /index.php" 200
cypht-1  | 172.22.0.2 - - [15/Jul/2024:11:19:10 +0000] "POST / HTTP/1.1" 200 78 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/125.0.0.0 Safari/537.36"
cypht-1  | 127.0.0.1 -  15/Jul/2024:11:19:14 +0000 "GET /index.php" 200
cypht-1  | 127.0.0.1 - - [15/Jul/2024:11:19:14 +0000] "GET / HTTP/1.1" 200 510840 "-" "curl/8.7.1"
cypht-1  | 172.22.0.2 - - [15/Jul/2024:11:19:20 +0000] "POST / HTTP/1.1" 504 569 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/125.0.0.0 Safari/537.36"
cypht-1  | 2024/07/15 11:19:20 [error] 26#26: *23322 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 172.22.0.2, server: localhost, request: "POST / HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "mail.example.com <<I replaced the actual host of my mail server here>>"
cypht-1  | 127.0.0.1 -  15/Jul/2024:11:19:45 +0000 "GET /index.php" 200
cypht-1  | 127.0.0.1 - - [15/Jul/2024:11:19:45 +0000] "GET / HTTP/1.1" 200 510848 "-" "curl/8.7.1"
cypht-1  | NOTICE: PHP message: PHP Fatal error:  Maximum execution time of 30 seconds exceeded in /usr/local/share/cypht/modules/imap/hm-imap-base.php on line 80
cypht-1  | NOTICE: PHP message: PHP Stack trace:
cypht-1  | NOTICE: PHP message: PHP   1. {main}() /usr/local/share/cypht/site/index.php:0
cypht-1  | NOTICE: PHP message: PHP   2. Hm_Dispatch->__construct($config = class Hm_Site_Config_File { protected $so


After the "PHP Fatal error" is displayed, cypht becomes reachable again.
Once I'm in again, I notice, that the email I was reading once it became unresponsive (mail from a gmail account) is still marked as unread in the mail listing. Otherwise, marking unread mails as read once I have opened them works as expected.

Version & Environment

git commit : 5e88e14
OS : docker image, running on x64 host which is running debian.

@indridieinarsson
Copy link
Contributor Author

Somewhere on the internet, adding the following lines to the nginx.conf was suggested as a solution to a similar problem:

fastcgi_read_timeout 600;
fastcgi_send_timeout 600;
fastcgi_connect_timeout 600;

I tried that, but it did not solve anything. It seems, however, to prolong the waiting for the "PHP Fatal error".

@marclaporte
Copy link
Member

@indridieinarsson Thank you for your report.

FYI, we did a major change to Cypht Docker:

In summary, https://hub.docker.com/u/cypht replaced https://hub.docker.com/r/sailfrog/cypht-docker

Details: cypht-org/cypht-docker#31

In doing so, many things changed. For example:
https://github.com/search?q=repo%3Acypht-org%2Fcypht+docker&type=pullrequests&s=created&o=desc

@jonocodes @Yannick243 @Shadow243 any ideas?

@indridieinarsson
Copy link
Contributor Author

@marclaporte thanks for the tip.
I only briefly tried the old (sailfrog) docker image. When I upgraded to the new docker image, I started fresh and set up everything anew (the setup is quite different from the old one).

The upgrade, at which this issue started, was when upgrading from the already new setup, compiled from master 2-3 weeks ago, and to master from a couple of days ago, so it was already working with the new docker setup.

@indridieinarsson
Copy link
Contributor Author

indridieinarsson commented Jul 18, 2024

So, the timeout seems to be happening in hm-imap-base.php, which saw some changes in a series of commits recently (July 9.).

I tried reverting to the commit before that (commit 1a62fb4), and now the issue seems to be gone (running using the exact same config as before, just pulled, re-built the docker image and started).

So the primary cause is probably not in docker or nginx.

@marclaporte
Copy link
Member

@josaphatim Can you take a look? That commit is from #1107

@indridieinarsson Thank you for this investigation. It is very helpful.

Thanks!

@marclaporte marclaporte changed the title fastCGI timeout - probably docker related. FastCGI timeout (Not docker related) Jul 18, 2024
@indridieinarsson
Copy link
Contributor Author

So, did some bisection:
In commit 1a62fb4 this is not reproducible.
In commit c08cac8 this is reproducible.

@marclaporte
Copy link
Member

Well done @indridieinarsson !

So then, we need @kambereBr instead of @josaphatim to review #1051

@josaphatim
Copy link
Member

Sorry I forgot to give my feedback yesterday. There are 3 commits that affected the file mentioned in the previous comment. I suspected only one c08cac8 as my commit didn't changed anything and Victor's commit came after @indridieinarsson addressed this issue. But I wasn't able to reproduce @indridieinarsson issue as on my side everything is working as expected.

@indridieinarsson
Copy link
Contributor Author

@josaphatim : I'm not really familiar with php, so not really useful for any coding. But perhaps it would be possible to add some debug-logging statements around where this is happening (log says "imap/hm-imap-base.php on line 80"), just to find out more. I have 3 different accounts, and most of my mails contain some "funny symbols", as my native language (Icelandic) has some special symbols - perhaps that's relevant, since this seems to be about multibyte strings.

@marclaporte
Copy link
Member

But I wasn't able to reproduce @indridieinarsson issue as on my side everything is working as expected.

@indridieinarsson Please pop by our chat room at https://gitter.im/cypht-org/community and find @kambereBr or @josaphatim to organize a screenshare.

@marclaporte
Copy link
Member

@indridieinarsson

We can't reproduce issue. Can you please try https://github.com/cypht-org/cypht/releases/tag/v2.2.0 ?

@indridieinarsson
Copy link
Contributor Author

@indridieinarsson

We can't reproduce issue. Can you please try https://github.com/cypht-org/cypht/releases/tag/v2.2.0 ?

I'll do that. And sorry for ghosting your previous reply, was on vacation and not reading messages.

@indridieinarsson
Copy link
Contributor Author

@marclaporte : this issue is still present on tag v2.2.0
I nuked the data and set it up using an imap server as authenticating agent as before, but this time a different imap server.
I also did not add my gmail account in there, only two accounts on two separate, independent mail servers (one of them run by me, on the same machine as the cypht instance).

And I still get stuff like below in the log, and the cypht web page becomes unresponsive.

When I think about it, it might be relevant, that I'm running this in a docker container, behind a traefik reverse proxy...

docker compose logs --follow cypht|grep -i 'fastcgi\|fatal'
cypht-1  | 2024/08/20 12:53:53 [error] 25#25: *190 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 172.22.0.2, server: localhost, request:
"POST /?page=message&uid=11269&list_path=imap_66c490c0578fe_494e424f58&list_parent=imap_66c490c0578fe_494e424f58&list_page=1 HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "cypht.example.com"
cypht-1  | NOTICE: PHP message: PHP Fatal error:  Maximum execution time of 30 seconds exceeded in /usr/local/share/cypht/modules/imap/hm-imap-base.php on line 76
cypht-1  | 2024/08/20 14:33:00 [error] 24#24: *751 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 172.22.0.2, server: localhost, request:
"POST /?page=message&uid=11278&list_path=imap_66c490c0578fe_494e424f58&list_parent=imap_66c490c0578fe_494e424f58&list_page=1 HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "cypht.example.com"
cypht-1  | NOTICE: PHP message: PHP Fatal error:  Maximum execution time of 30 seconds exceeded in /usr/local/share/cypht/modules/imap/hm-imap-base.php on line 80
cypht-1  | 2024/08/20 15:55:59 [error] 23#23: *1383 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 172.22.0.2, server: localhost, request: "POST /?page=message&uid=11280&list_path=imap_66c490c0578fe_494e424f58&list_parent=imap_66c490c0578fe_494e424f58&list_page=1 HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "cypht.example.com"
cypht-1  | 2024/08/20 15:56:28 [error] 25#25: *1442 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 172.22.0.2, server: localhost, request: "POST /?page=message&uid=11280&list_path=imap_66c490c0578fe_494e424f58&list_parent=imap_66c490c0578fe_494e424f58&list_page=1 HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "cypht.example.com"
cypht-1  | 2024/08/20 15:59:10 [error] 23#23: *1508 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 172.22.0.2, server: localhost, request: "POST /?page=message&uid=11280&list_path=imap_66c490c0578fe_494e424f58&list_parent=imap_66c490c0578fe_494e424f58&list_page=1&sort=arrival HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "cypht.example.com"
cypht-1  | 2024/08/20 16:00:04 [error] 24#24: *1537 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 172.22.0.2, server: localhost, request: "POST /?page=message&uid=11280&list_path=imap_66c490c0578fe_494e424f58&list_parent=imap_66c490c0578fe_494e424f58&list_page=1&sort=arrival HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "cypht.example.com"
cypht-1  | 2024/08/20 16:00:04 [error] 24#24: *1577 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 172.22.0.2, server: localhost, request: "POST /?page=message&uid=11280&list_path=imap_66c490c0578fe_494e424f58&list_parent=imap_66c490c0578fe_494e424f58&list_page=1&sort=arrival HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "cypht.example.com"
cypht-1  | 2024/08/20 16:00:04 [error] 23#23: *1510 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 172.22.0.2, server: localhost, request: "POST /?page=message&uid=11280&list_path=imap_66c490c0578fe_494e424f58&list_parent=imap_66c490c0578fe_494e424f58&list_page=1&sort=arrival HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "cypht.example.com"
cypht-1  | 2024/08/20 16:00:05 [error] 23#23: *1457 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 172.22.0.2, server: localhost, request: "GET /modules/themes/assets/default/css/bootstrap.min.css.map HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "cypht.example.com"
cypht-1  | 2024/08/20 16:00:23 [error] 24#24: *1580 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 127.0.0.1, server: localhost, request:
"GET / HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "localhost"
cypht-1  | 2024/08/20 16:00:41 [error] 24#24: *1583 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 172.22.0.2, server: localhost, request: "POST /?page=message&uid=11280&list_path=imap_66c490c0578fe_494e424f58&list_parent=imap_66c490c0578fe_494e424f58&list_page=1&sort=arrival HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "cypht.example.com"
cypht-1  | 2024/08/20 16:00:41 [error] 23#23: *1508 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 172.22.0.2, server: localhost, request: "POST /?page=message&uid=11280&list_path=imap_66c490c0578fe_494e424f58&list_parent=imap_66c490c0578fe_494e424f58&list_page=1&sort=arrival HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "cypht.example.com"
cypht-1  | 2024/08/20 16:00:41 [error] 23#23: *1557 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 172.22.0.2, server: localhost, request: "POST /?page=message&uid=11280&list_path=imap_66c490c0578fe_494e424f58&list_parent=imap_66c490c0578fe_494e424f58&list_page=1&sort=arrival HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "cypht.example.com"
cypht-1  | 2024/08/20 16:00:59 [error] 24#24: *1586 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 172.22.0.2, server: localhost, request: "POST /?page=message&uid=11280&list_path=imap_66c490c0578fe_494e424f58&list_parent=imap_66c490c0578fe_494e424f58&list_page=1&sort=arrival HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "cypht.example.com"
cypht-1  | 2024/08/20 16:01:04 [error] 24#24: *1588 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 172.22.0.2, server: localhost, request: "POST /?page=message&uid=11280&list_path=imap_66c490c0578fe_494e424f58&list_parent=imap_66c490c0578fe_494e424f58&list_page=1&sort=arrival HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "cypht.example.com"
cypht-1  | 2024/08/20 16:01:23 [error] 24#24: *1577 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 172.22.0.2, server: localhost, request: "POST /?page=message&uid=11280&list_path=imap_66c490c0578fe_494e424f58&list_parent=imap_66c490c0578fe_494e424f58&list_page=1&sort=arrival HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "cypht.example.com"
cypht-1  | 2024/08/20 16:01:23 [error] 23#23: *1457 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 172.22.0.2, server: localhost, request: "POST /?page=message&uid=11280&list_path=imap_66c490c0578fe_494e424f58&list_parent=imap_66c490c0578fe_494e424f58&list_page=1&sort=arrival HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "cypht.example.com"
cypht-1  | 2024/08/20 16:01:23 [error] 23#23: *1510 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 172.22.0.2, server: localhost, request: "POST /?page=message&uid=11280&list_path=imap_66c490c0578fe_494e424f58&list_parent=imap_66c490c0578fe_494e424f58&list_page=1&sort=arrival HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "cypht.example.com"
cypht-1  | 2024/08/20 16:01:23 [error] 24#24: *1593 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 127.0.0.1, server: localhost, request:
"GET / HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "localhost"
cypht-1  | 2024/08/20 16:01:45 [error] 23#23: *1557 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 172.22.0.2, server: localhost, request: "POST /?page=message&uid=11280&list_path=imap_66c490c0578fe_494e424f58&list_parent=imap_66c490c0578fe_494e424f58&list_page=1&sort=arrival HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "cypht.example.com"
cypht-1  | 2024/08/20 16:02:04 [error] 24#24: *1588 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 172.22.0.2, server: localhost, request: "POST /?page=message&uid=11280&list_path=imap_66c490c0578fe_494e424f58&list_parent=imap_66c490c0578fe_494e424f58&list_page=1&sort=arrival HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "cypht.example.com"
cypht-1  | 2024/08/20 16:02:07 [error] 24#24: *1583 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 172.22.0.2, server: localhost, request: "POST /?page=message&uid=11280&list_path=imap_66c490c0578fe_494e424f58&list_parent=imap_66c490c0578fe_494e424f58&list_page=1&sort=arrival HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "cypht.example.com"
cypht-1  | 2024/08/20 16:02:07 [error] 24#24: *1586 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 172.22.0.2, server: localhost, request: "POST /?page=message&uid=11280&list_path=imap_66c490c0578fe_494e424f58&list_parent=imap_66c490c0578fe_494e424f58&list_page=1&sort=arrival HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "cypht.example.com"
cypht-1  | 2024/08/20 16:02:07 [error] 23#23: *1508 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 172.22.0.2, server: localhost, request: "POST /?page=message&uid=11280&list_path=imap_66c490c0578fe_494e424f58&list_parent=imap_66c490c0578fe_494e424f58&list_page=1&sort=arrival HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "cypht.example.com"
cypht-1  | 2024/08/20 16:02:23 [error] 24#24: *1600 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 127.0.0.1, server: localhost, request:
"GET / HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "localhost"
cypht-1  | 2024/08/20 16:03:24 [error] 24#24: *1602 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 127.0.0.1, server: localhost, request:
"GET / HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "localhost"
cypht-1  | 2024/08/20 16:04:24 [error] 24#24: *1604 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 127.0.0.1, server: localhost, request:
"GET / HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "localhost"
cypht-1  | 2024/08/20 16:05:26 [error] 24#24: *1606 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 127.0.0.1, server: localhost, request:
"GET / HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "localhost"
cypht-1  | 2024/08/20 16:06:28 [error] 24#24: *1608 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 127.0.0.1, server: localhost, request:
"GET / HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "localhost"
cypht-1  | 2024/08/20 16:07:28 [error] 24#24: *1610 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 127.0.0.1, server: localhost, request:
"GET / HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "localhost"
cypht-1  | 2024/08/20 16:08:28 [error] 24#24: *1612 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 127.0.0.1, server: localhost, request:
"GET / HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "localhost"
cypht-1  | 2024/08/20 16:09:28 [error] 24#24: *1614 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 127.0.0.1, server: localhost, request:
"GET / HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "localhost"
cypht-1  | 2024/08/20 16:10:28 [error] 24#24: *1616 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 127.0.0.1, server: localhost, request:
"GET / HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "localhost"
cypht-1  | 2024/08/20 16:11:29 [error] 26#26: *1618 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 127.0.0.1, server: localhost, request:
"GET / HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "localhost"
cypht-1  | 2024/08/20 16:12:29 [error] 26#26: *1620 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 127.0.0.1, server: localhost, request:
"GET / HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "localhost"
cypht-1  | 2024/08/20 16:13:29 [error] 26#26: *1622 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 127.0.0.1, server: localhost, request:
"GET / HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "localhost"
cypht-1  | 2024/08/20 16:14:29 [error] 26#26: *1624 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 127.0.0.1, server: localhost, request:
"GET / HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "localhost"
cypht-1  | 2024/08/20 16:15:29 [error] 26#26: *1626 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 127.0.0.1, server: localhost, request:
"GET / HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "localhost"
cypht-1  | 2024/08/20 16:16:29 [error] 26#26: *1628 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 127.0.0.1, server: localhost, request:
"GET / HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "localhost"
cypht-1  | 2024/08/20 16:17:29 [error] 26#26: *1630 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 127.0.0.1, server: localhost, request:
"GET / HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "localhost"
cypht-1  | 2024/08/20 16:18:29 [error] 26#26: *1632 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 127.0.0.1, server: localhost, request:
"GET / HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "localhost"
cypht-1  | 2024/08/20 16:19:30 [error] 26#26: *1634 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 127.0.0.1, server: localhost, request:
"GET / HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "localhost"
cypht-1  | 2024/08/20 16:20:30 [error] 26#26: *1636 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 127.0.0.1, server: localhost, request:
"GET / HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "localhost"
cypht-1  | 2024/08/20 16:21:32 [error] 26#26: *1638 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 127.0.0.1, server: localhost, request:
"GET / HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "localhost"
cypht-1  | 2024/08/20 16:22:32 [error] 26#26: *1640 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 127.0.0.1, server: localhost, request:
"GET / HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "localhost"
cypht-1  | 2024/08/20 16:23:34 [error] 26#26: *1642 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 127.0.0.1, server: localhost, request:
"GET / HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "localhost"
cypht-1  | 2024/08/20 16:24:34 [error] 26#26: *1644 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 127.0.0.1, server: localhost, request:
"GET / HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "localhost"
cypht-1  | NOTICE: PHP message: PHP Fatal error:  Maximum execution time of 30 seconds exceeded in /usr/local/share/cypht/modules/imap/hm-imap-base.php on line 205
cypht-1  | NOTICE: PHP message: PHP Fatal error:  Maximum execution time of 30 seconds exceeded in /usr/local/share/cypht/modules/imap/hm-imap-base.php on line 76
cypht-1  | 2024/08/20 16:25:34 [error] 26#26: *1646 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 127.0.0.1, server: localhost, request:
"GET / HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "localhost"
cypht-1  | NOTICE: PHP message: PHP Fatal error:  Maximum execution time of 30 seconds exceeded in /usr/local/share/cypht/modules/imap/hm-imap-base.php on line 205
cypht-1  | NOTICE: PHP message: PHP Fatal error:  Maximum execution time of 30 seconds exceeded in /usr/local/share/cypht/modules/imap/hm-imap-base.php on line 205
cypht-1  | NOTICE: PHP message: PHP Fatal error:  Maximum execution time of 30 seconds exceeded in /usr/local/share/cypht/modules/imap/hm-imap-base.php on line 76
cypht-1  | 2024/08/20 16:45:40 [error] 26#26: *1729 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 172.22.0.2, server: localhost, request: "POST /?page=message&uid=11280&list_path=imap_66c490c0578fe_494e424f58&list_parent=imap_66c490c0578fe_494e424f58&list_page=1&sort=arrival HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "cypht.example.com"

@indridieinarsson
Copy link
Contributor Author

I've been poking around a bit. A bit difficult to pinpoint. Going from tag 2.2.0, I replaced hm-imap-base.php with the version from commit 1a62fb4. In that constellation, the timeout is not reproducible.
According to this SO post , mb_strlen is significantly slower than strlen - is it possible this is causing my issue?

@indridieinarsson
Copy link
Contributor Author

indridieinarsson commented Aug 23, 2024

digging more, this part in read_literal from hm-imap-base.php is interesting (with some additional logging statement from me).

    while ($lit_size < $size) {
        $chunk = $this->fgets($line_length);
        $chunk_size = strlen($chunk);
        if ($chunk_size != mb_strlen($chunk))
        {
                Hm_Functions::error_log(sprintf('size discrepancy chunk size '. $chunk_size . '  vs  ' . mb_strlen($chunk)));
        }
        $lit_size += $chunk_size;

Every now and then, strlen and mb_strlen are different, which in turn affects $lit_size. This is due to the fact, that strlen returns the number of bytes in the string, while mb_strlen returns the number of characters (the length of the actual string). For single-byte strings, this is obviously equal, but for strings with some multi-byte characters, it is not. As for myself, I come from Iceland, and we have a lot of "funny characters" (like ðÐþÞæÆöÖáÁ etc) in our language, which take more than one byte, so my mailbox is full of this stuff.

On the other hand, $size originates from this line :

                $literal_size  = substr($line, ($i + 1), ($end - $i - 1));

which is just a substring, and should be the same regards of mb or not.
So, the stop condition is hit earlier in case of mb_strlen than with the strlen variant.

Anyone around wise enough to know what number it is that being drawn out as substring. Is it number of characters, or number of bytes?

@marclaporte
Copy link
Member

Thank you @indridieinarsson for your persistence on this.

@marclaporte
Copy link
Member

@indridieinarsson expects this to be solved by #1230 (comment)

So closing, and we'll reopen if the issue persists.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
4 participants