search

cypht-org / cypht

Cypht: Lightweight Open Source webmail aggregator [PHP, JS]
http://cypht.org
GNU Lesser General Public License v2.1
977 stars 153 forks source link

FastCGI timeout (Not docker related) #1119

Closed indridieinarsson closed 1 hour ago

indridieinarsson commented 1 month ago

🐛 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 : 5e88e1463494b59ed3aca65a15402c2537e77afa OS : docker image, running on x64 host which is running debian.

indridieinarsson commented 1 month ago

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 commented 1 month ago

@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: https://github.com/cypht-org/cypht-docker/issues/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 commented 1 month ago

@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 commented 1 month ago

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 1a62fb449a), 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 commented 1 month ago

@josaphatim Can you take a look? That commit is from https://github.com/cypht-org/cypht/pull/1107

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

Thanks!

indridieinarsson commented 1 month ago

So, did some bisection: In commit 1a62fb449a this is not reproducible. In commit c08cac8a18 this is reproducible.

marclaporte commented 1 month ago

Well done @indridieinarsson !

So then, we need @kambereBr instead of @josaphatim to review https://github.com/cypht-org/cypht/pull/1051

josaphatim commented 1 month ago

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 https://github.com/cypht-org/cypht/commit/c08cac8a18a8ac038b71ed237ac2c26636861dd3 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 commented 1 month ago

@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 commented 1 month ago

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 commented 2 weeks ago

@indridieinarsson

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

indridieinarsson commented 2 weeks ago

@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 commented 2 weeks ago

@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 commented 2 weeks ago

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 1a62fb449. 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 commented 2 weeks ago

digging more, this part in _readliteral 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 commented 3 days ago

Thank you @indridieinarsson for your persistence on this.

marclaporte commented 1 hour ago

@indridieinarsson expects this to be solved by https://github.com/cypht-org/cypht/pull/1230#issuecomment-2338111218

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