Timeout waiting for output from CGI script

ph4ntomJ · May 2022

Hello,

I can see a lot of errors like these below in httpd error_log:

[Mon May 09 21:48:16.180761 2022] [mpm_prefork:notice] [pid 17957050] AH00163: Apache/2.4.52 (Unix) configured -- resuming normal operations

[Mon May 09 21:48:16.181178 2022] [core:notice] [pid 17957050] AH00094: Command line: '/opt/freeware/sbin/httpd'

[Mon May 09 22:03:29.064473 2022] [cgi:warn] [pid 11796482] [client X.X.X.X:51622] AH01220: Timeout waiting for output from CGI script /lpar2rrd/lpar2rrd-cgi/detail-graph.sh, referer: http://X.X.X.X/lpar2rrd/?menu=562e259&tab=0

[Mon May 09 22:03:29.064606 2022] [cgi:error] [pid 11796482] [client X.X.X.X:51622] Script timed out before returning headers: detail-graph.sh, referer: http://172.31.209.49/lpar2rrd/?menu=562e259&tab=0

[Mon May 09 22:03:29.123358 2022] [cgi:warn] [pid 22675624] [client X.X.X.X:51646] AH01220: Timeout waiting for output from CGI script /lpar2rrd/lpar2rrd-cgi/detail-graph.sh, referer: http:// X.X.X.X/lpar2rrd/?menu=562e259&tab=0

[Mon May 09 22:03:29.123520 2022] [cgi:error] [pid 22675624] [client X.X.X.X:51646] Script timed out before returning headers: detail-graph.sh, referer: http://172.31.209.49/lpar2rrd/?menu=562e259&tab=0

[Mon May 09 22:03:29.123974 2022] [cgi:warn] [pid 6160604] [client X.X.X.X:51645] AH01220: Timeout waiting for output from CGI script /lpar2rrd/lpar2rrd-cgi/detail-graph.sh, referer: http://X.X.X.X/lpar2rrd/?menu=562e259&tab=0

[Mon May 09 22:03:29.124088 2022] [cgi:error] [pid 6160604] [client X.X.X.X:51645] Script timed out before returning headers: detail-graph.sh, referer: http://172.31.209.49/lpar2rrd/?menu=562e259&tab=0

[Mon May 09 22:03:29.125907 2022] [cgi:warn] [pid 21037258] [client X.X.X.X:51644] AH01220: Timeout waiting for output from CGI script /lpar2rrd/lpar2rrd-cgi/detail-graph.sh, referer: http:// X.X.X.X/lpar2rrd/?menu=562e259&tab=0

[Mon May 09 22:03:29.126022 2022] [cgi:error] [pid 21037258] [client X.X.X.X:51644] Script timed out before returning headers: detail-graph.sh, referer: http:// X.X.X.X/lpar2rrd/?menu=562e259&tab=0

Sometimes it loads fine, but now it's very slow and often gives me these timeout errors, therefore info can't be loaded in lpar2rrd ui properly.

I'm using latest lpar2rrd server version:

tail -1 etc/vers*

7.40 2022-04-05_19:02

I'm also using latest httpd server: 2.4.53-1

But I had to go back and use old perl (5.8.8) because of reporter. Previously, I did the installation using new lpar2rrd via yum but reporter kept complaining about missing perl-compress-raw-zlib package to generate the reporter, so after a long battle (ERROR : ERROR: rrd->ds_def malloc at /lpar2rrd/bin/LoadDataModule.pm line 660 : `), I'm back using perl 5.8.8 with rrdtool 1.7.0-6 but receiving these timeouts from time to time.

Can you give me a hint of what could be wrong?

Thanks in advance.

Pavel · May 2022

Hi,

Increase timeout in Apache httpd.conf to 10 minutes to be safe:
                KeepAlive On
                KeepAliveTimeout 5
                TimeOut 1200

Under root:
apachectl restart

is that happen for every page/graph you request via the browser?

ph4ntomJ · May 2022

Hi Pavel,

Yes, sometimes affect only a portion of it, sometimes affects all of them.

I can see also this error:

[Tue May 10 09:17:04.376041 2022] [auth_basic:error] [pid 9699444] [client X.X.X.X:46032] AH01618: user not found: /lpar2rrd-cgi/genjson.sh, referer: http://X.X.X.X/lpar2rrd/?menu=1bf6215&tab=0

Not sure what this one means...

Regarding the timeout, I've set:

# KeepAlive: Enable/disable persistent connections

KeepAlive On

# KeepAliveTimeout: Number of seconds to wait for the next request from the

# same client on the same connection. Default is 5 seconds

KeepAliveTimeout 15

TimeOut 1200

Before my restart:

[Mon May 09 22:03:29.126022 2022] [cgi:error] [pid 21037258] [client X.X.X.X:51644] Script timed out before returning headers: detail-graph.sh, referer: http://X.X.X.X/lpar2rrd/?menu=562e259&tab=0

[Tue May 10 00:05:40.931602 2022] [cgi:warn] [pid 13566056] [client X.X.X.X:59622] AH01220: Timeout waiting for output from CGI script /lpar2rrd/lpar2rrd-cgi/detail-graph.sh, referer: http://X.X.X.X/lpar2rrd/?menu=3fe22db&tab=4

[Tue May 10 00:05:40.932988 2022] [cgi:warn] [pid 16711810] [client X.X.X.X:59624] AH01220: Timeout waiting for output from CGI script /lpar2rrd/lpar2rrd-cgi/detail-graph.sh, referer: http://X.X.X.X/lpar2rrd/?menu=3fe22db&tab=4

[Tue May 10 00:05:40.935757 2022] [cgi:warn] [pid 4390976] [client X.X.X.X:59623] AH01220: Timeout waiting for output from CGI script /lpar2rrd/lpar2rrd-cgi/detail-graph.sh, referer: http://X.X.X.X/lpar2rrd/?menu=3fe22db&tab=4

[Tue May 10 00:05:40.937104 2022] [cgi:error] [pid 13566056] [client X.X.X.X:59622] Script timed out before returning headers: detail-graph.sh, referer: http://X.X.X.X/lpar2rrd/?menu=3fe22db&tab=4

[Tue May 10 00:05:40.937648 2022] [cgi:error] [pid 16711810] [client X.X.X.X:59624] Script timed out before returning headers: detail-graph.sh, referer: http://X.X.X.X/lpar2rrd/?menu=3fe22db&tab=4

[Tue May 10 00:05:40.937713 2022] [cgi:error] [pid 4390976] [client X.X.X.X:59623] Script timed out before returning headers: detail-graph.sh, referer: http://X.X.X.X/lpar2rrd/?menu=3fe22db&tab=4

[Tue May 10 00:15:56.419868 2022] [cgi:warn] [pid 13566056] [client X.X.X.X:60263] AH01220: Timeout waiting for output from CGI script /lpar2rrd/lpar2rrd-cgi/detail-graph.sh, referer: http://X.X.X.X/lpar2rrd/?menu=3fe22db&tab=4

[Tue May 10 00:15:56.419989 2022] [cgi:error] [pid 13566056] [client X.X.X.X:60263] Script timed out before returning headers: detail-graph.sh, referer: http://X.X.X.X/lpar2rrd/?menu=3fe22db&tab=4

[Tue May 10 00:36:55.370398 2022] [auth_basic:error] [pid 21037258] [client X.X.X.X:54859] AH01618: user not found: /lpar2rrd-cgi/genjson.sh, referer: http://X.X.X.X/lpar2rrd/

[Tue May 10 00:36:58.810520 2022] [auth_basic:error] [pid 21037258] [client X.X.X.X:54859] AH01618: user not found: /lpar2rrd-cgi/genjson.sh, referer: http://X.X.X.X/lpar2rrd/

[Tue May 10 09:17:02.400951 2022] [auth_basic:error] [pid 9699444] [client X.X.X.X:46032] AH01618: user not found: /lpar2rrd-cgi/genjson.sh, referer: http://X.X.X.X/lpar2rrd/?menu=1bf6215&tab=0

[Tue May 10 09:17:03.519406 2022] [auth_basic:error] [pid 9699444] [client X.X.X.X:46032] AH01618: user not found: /lpar2rrd-cgi/genjson.sh, referer: http://X.X.X.X/lpar2rrd/?menu=1bf6215&tab=0

[Tue May 10 09:17:04.376041 2022] [auth_basic:error] [pid 9699444] [client X.X.X.X:46032] AH01618: user not found: /lpar2rrd-cgi/genjson.sh, referer: http://X.X.X.X/lpar2rrd/?menu=1bf6215&tab=0

after:

[Tue May 10 10:11:46.609263 2022] [mpm_prefork:notice] [pid 19661014] AH00173: SIGHUP received. Attempting to restart

[Tue May 10 10:11:46.644498 2022] [mpm_prefork:notice] [pid 19661014] AH00163: Apache/2.4.53 (Unix) configured -- resuming normal operations

[Tue May 10 10:11:46.644666 2022] [core:notice] [pid 19661014] AH00094: Command line: '/opt/freeware/sbin/httpd'

I'll monitor for few hours, to see if I spot the timeout again. But I can see that the data loading is quite slow in the UI if I compare with other boxes where I have the tool working.

Thanks in advance

Pavel · May 2022

Hi,

vmstat 30 2

ps -ef| grep lpar2rrd

is that an AIX?

ph4ntomJ · May 2022

Hi Pavel,

yes... AIX.

ps -ef| grep lpar2rrd:

lpar2rrd 5111958 10944540 0 0:00 <defunct>

lpar2rrd 6881376 14352512 0 11:07:00 - 0:00 /usr/bin/perl /opt/lpar2rrd-agent/lpar2rrd-agent.pl HOSTNAME

apache 7536770 7340280 99 11:07:40 - 0:02 /opt/freeware/bin/perl /lpar2rrd/bin/detail-graph-cgi.pl

lpar2rrd 8519774 1 0 12:37:03 - 0:03 /opt/freeware/bin/perl -w /lpar2rrd/bin/lpar2rrd-daemon.pl

lpar2rrd 9044006 13762630 99 15:02:52 - 432:51 /opt/freeware/bin/perl -w /lpar2rrd/bin/lpar2rrd.pl

lpar2rrd 9961558 14352512 0 0:00 <defunct>

lpar2rrd 10747984 19923128 0 0:00 <defunct>

lpar2rrd 10944540 1 0 20:00:08 - 0:00 /opt/freeware/bin/perl -w /lpar2rrd/bin/lpar2rrd.pl

lpar2rrd 11468812 6881376 0 11:07:00 - 0:00 iostat -Dsal 60 1

lpar2rrd 11927766 9044006 0 0:00 <defunct>

lpar2rrd 13041902 13762630 0 0:00 <defunct>

lpar2rrd 13435032 8519774 0 0:00 <defunct>

lpar2rrd 13762630 1 0 15:00:03 - 0:00 /opt/freeware/bin/perl -w /lpar2rrd/bin/lpar2rrd.pl

lpar2rrd 14352512 4325584 0 11:07:00 - 0:00 /usr/bin/perl /opt/lpar2rrd-agent/lpar2rrd-agent.pl HOSTNAME

lpar2rrd 15073366 14352512 0 11:07:00 - 0:00 vmstat -I -W -t 60 1

apache 16187556 18612278 46 11:07:40 - 0:01 /opt/freeware/bin/perl /lpar2rrd/bin/detail-graph-cgi.pl

apache 18022506 9568476 92 11:07:40 - 0:02 /opt/freeware/bin/perl /lpar2rrd/bin/detail-graph-cgi.pl

lpar2rrd 18284794 10944540 0 0:00 <defunct>

lpar2rrd 19923128 10944540 101 20:01:47 - 350:37 /opt/freeware/bin/perl -w /lpar2rrd/bin/lpar2rrd.pl

apache 20185136 19529924 48 11:07:40 - 0:01 /opt/freeware/bin/perl /lpar2rrd/bin/detail-graph-cgi.pl

lpar2rrd 20774932 10944540 0 0:00 <defunct>

root 21954606 21168230 0 11:07:52 pts/0 0:00 grep lpar2rrd

---

System configuration: lcpu=8 mem=12288MB ent=1.00

kthr memory page faults cpu

----- ----------- ------------------------ ------------ -----------------------

r b avm fre re pi po fr sr cy in sy cs us sy id wa pc ec

3 0 2463308 103237 0 0 0 0 0 0 2872 191609 22261 66 12 22 0 1.93 192.5

4 0 2461280 105265 0 0 0 0 0 0 3151 188559 24417 64 12 23 0 1.92 191.5

And EC is not great, we will bump them up later this week, just waiting to free up some resources.

Thanks!

Pavel · May 2022

Hi,

ok, I see an AIX.

1.

kill this process

lpar2rrd 19923128 10944540 101 20:01:47 - 350:37 /opt/freeware/bin/perl -w /lpar2rrd/bin/lpar2rrd.pl

2. try this, let us know if that speeds it up

under root:
umask 022
fc-cache -fv
ls -la /opt/freeware/var/cache/fontconfig/

su - lpar2rrd
umask 022
fc-cache -fv
HOME=/home/lpar2rrd/tmp/home; fc-cache -fv

3. lpar2rrd version

ph4ntomJ · May 2022

Hi Pavel,

Here:

kill -9 19923128

[HOSTNAME:root:/var/log/httpd:] ps -ef |grep -i 19923128

root 10747986 21168230 0 11:57:35 pts/0 0:00 grep -i 19923128

[HOSTNAME:root:/var/log/httpd:] umask

022

fc-cache -fv

/usr/share/fonts: skipping, no such directory

/usr/X11R6/lib/X11/fonts: caching, new cache contents: 70 fonts, 9 dirs

/usr/X11R6/lib/X11/fonts/100dpi: caching, new cache contents: 212 fonts, 0 dirs

/usr/X11R6/lib/X11/fonts/75dpi: caching, new cache contents: 212 fonts, 0 dirs

/usr/X11R6/lib/X11/fonts/JP: caching, new cache contents: 0 fonts, 0 dirs

/usr/X11R6/lib/X11/fonts/TrueType: caching, new cache contents: 19 fonts, 1 dirs

/usr/X11R6/lib/X11/fonts/TrueType/complete: caching, new cache contents: 0 fonts, 0 dirs

/usr/X11R6/lib/X11/fonts/Type1: caching, new cache contents: 61 fonts, 0 dirs

/usr/X11R6/lib/X11/fonts/deform_JP: caching, new cache contents: 0 fonts, 0 dirs

/usr/X11R6/lib/X11/fonts/encodings: caching, new cache contents: 0 fonts, 0 dirs

/usr/X11R6/lib/X11/fonts/i18n: caching, new cache contents: 0 fonts, 0 dirs

/usr/X11R6/lib/X11/fonts/misc: caching, new cache contents: 43 fonts, 0 dirs

/home/root/.local/share/fonts: skipping, no such directory

/home/root/.fonts: skipping, no such directory

/opt/freeware/var/cache/fontconfig: cleaning cache directory

/home/root/.cache/fontconfig: not cleaning non-existent cache directory

/home/root/.fontconfig: not cleaning non-existent cache directory

fc-cache: succeeded

---

ls -la /opt/freeware/var/cache/fontconfig/

total 1176

drwxr-xr-x 2 root system 4096 May 10 11:58 .

drwxr-xr-x 3 root system 256 May 10 11:57 ..

-rw-r--r-- 1 root system 186728 May 10 11:57 0fe0af1d5898cfe43064332244d1dc15-be32d4.cache-7

-rw-r--r-- 1 root system 63120 May 10 11:57 2cee944125173ffd13126fb55c9a0dc1-be32d4.cache-7

-rw-r--r-- 1 root system 88 May 10 11:58 5a781e57f2cfdb5bc7c89e60979df205-be32d4.cache-7

-rw-r--r-- 1 root system 96 May 10 11:58 68418e0da60dfe4003a8c2435e92b1d3-be32d4.cache-7

-rw-r--r-- 1 root system 52968 May 10 11:58 6ac606a6cc613b1dd45fa75d9315a55e-be32d4.cache-7

-rw-r--r-- 1 root system 186712 May 10 11:57 8b934b58f0acb2e86a0bbbb5d24d97c0-be32d4.cache-7

-rw-r--r-- 1 root system 88 May 10 11:57 9e926412728acf7de0ac0fec65973384-be32d4.cache-7

-rw-r--r-- 1 root system 200 May 10 11:58 CACHEDIR.TAG

-rw-r--r-- 1 root system 33184 May 10 11:58 cea65ab3a5a3b5f0104cdab7d1a740e4-be32d4.cache-7

-rw-r--r-- 1 root system 96 May 10 11:58 e589cd651dc00b4c4ecb38a517c1c667-be32d4.cache-7

-rw-r--r-- 1 root system 38960 May 10 11:58 f8033d5e4c6effb98c84b18a50eef42d-be32d4.cache-7

-rw-r--r-- 1 root system 104 May 10 11:58 fc01d863d0baf43148b576cc17fe458d-be32d4.cache-7

---

su - lpar2rrd

[HOSTNAME:lpar2rrd:/lpar2rrd:] umask 022

[HOSTNAME:lpar2rrd:/lpar2rrd:] fc-cache -fv