Bug 1665692 - httpd consumes 100% CPU after upgrade to Fedora 29 or after a few days after a restart
Summary: httpd consumes 100% CPU after upgrade to Fedora 29 or after a few days after ...
Keywords:
Status: CLOSED DUPLICATE of bug 1664414
Alias: None
Product: Fedora
Classification: Fedora
Component: httpd
Version: 29
Hardware: x86_64
OS: Linux
unspecified
high
Target Milestone: ---
Assignee: Luboš Uhliarik
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2019-01-13 00:43 UTC by RobbieTheK
Modified: 2019-01-18 15:08 UTC (History)
6 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2019-01-18 15:08:46 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)

Description RobbieTheK 2019-01-13 00:43:25 UTC
httpd-2.4.37-5.fc29.x86_64
kernel: 4.19.13-300.fc29.x86_64

I've had this happen on 3 Fedora 28 --> 29 upgrades. Here's a sample top:

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND                                                                                             
 9092 apache    20   0 2329308  16992   8600 S 100.0   0.0 809:23.75 https    

What's odd is that there are no (helpful) logs, no errors, so sign of a DOS.

Here are some logs showing scans from Qualys:
[Sat Jan 12 04:43:36.236895 2019] [core:error] [pid 9366:tid 139768940295936] [client 64.39.99.177:51996] AH00126: Invalid URI in request GET /../../../../../../../../../
../../ HTTP/1.1
[Sat Jan 12 04:43:43.902369 2019] [core:error] [pid 9089:tid 139768000132864] [client 64.39.99.177:50795] AH00126: Invalid URI in request GET /../../../../../../../../../
../../ HTTP/1.1
[Sat Jan 12 04:43:44.924024 2019] [proxy_fcgi:error] [pid 9092:tid 139768251782912] [client 64.39.99.177:51917] AH01071: Got error 'Primary script unknown\n'
[Sat Jan 12 04:43:45.088652 2019] [cgid:error] [pid 9366:tid 139767672981248] [client 64.39.99.177:52083] AH01262: Options ExecCGI is off in this directory: /var/www/html
/index.cgi
[Sat Jan 12 04:43:45.329282 2019] [cgid:error] [pid 9366:tid 139768369248000] [client 64.39.99.177:52319] AH01262: Options ExecCGI is off in this directory: /var/www/html
/index.pl
[Sat Jan 12 04:43:46.552669 2019] [proxy_fcgi:error] [pid 9089:tid 139767983347456] [client 64.39.99.177:53505] AH01071: Got error 'Primary script unknown\n'
[Sat Jan 12 04:43:46.716493 2019] [proxy_fcgi:error] [pid 9089:tid 139768721348352] [client 64.39.99.177:53671] AH01071: Got error 'Primary script unknown\n'

A few of these:
gzip: stdout: Broken pipe

gzip: stdout: Broken pipe

gzip: stdout: Broken pipe

Last log before restoring Apache:
[Sat Jan 12 18:05:24.727397 2019] [proxy_fcgi:error] [pid 9092:tid 139768931903232] [client 89.238.154.242:34004] AH01071: Got error 'Primary script unknown\n'

And a strace -s 80 -fp 9092
strace: Process 9092 attached with 65 threads
strace: [ Process PID=9301 runs in x32 mode. ]
[pid  9302] epoll_wait(16,  <unfinished ...>
[pid  9300] futex(0x55987eef8a30, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  9299] futex(0x55987eef8a34, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  9298] futex(0x55987eef8a34, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[...]
[pid  9153] futex(0x55987eea9558, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid  9110] select(0, NULL, NULL, NULL, {tv_sec=0, tv_usec=14630} <unfinished ...>
[pid  9092] read(7,  <unfinished ...>
[pid  9110] <... select resumed> )      = 0 (Timeout)
[pid  9110] semop(8126477, [{0, -1, SEM_UNDO|IPC_NOWAIT}], 1) = -1 EAGAIN (Resource temporarily unavailable)
[pid  9110] select(0, NULL, NULL, NULL, {tv_sec=0, tv_usec=100000}) = 0 (Timeout)

then lsof -n -p 9092 | egrep -v '(DIR|REG)'
COMMAND  PID   USER   FD      TYPE             DEVICE SIZE/OFF       NODE NAME
httpd   9092 apache    0r      CHR                1,3      0t0      12290 /dev/null
httpd   9092 apache    1u     unix 0x00000000c4e538fa      0t0    3979515 type=STREAM
httpd   9092 apache    3u     IPv4            3982730      0t0        TCP *:http (LISTEN)
httpd   9092 apache    4u     sock                0,9      0t0    3961475 protocol: TCP
httpd   9092 apache    5r      CHR                1,9      0t0      12295 /dev/urandom
httpd   9092 apache    6u     IPv6            3961476      0t0        TCP *:https (LISTEN)
httpd   9092 apache    7r     FIFO               0,12      0t0    3961490 pipe
httpd   9092 apache    8w     FIFO               0,12      0t0    3961490 pipe
httpd   9092 apache   14u     unix 0x00000000bad8d116      0t0    3961494 type=DGRAM
httpd   9092 apache   15u     sock                0,9      0t0    3980681 protocol: TCP
httpd   9092 apache   16u  a_inode               0,13        0      11783 [eventpoll]
httpd   9092 apache   17r     FIFO               0,12      0t0    3980682 pipe
httpd   9092 apache   18w     FIFO               0,12      0t0    3980682 pipe
httpd   9092 apache   21u     sock                0,9      0t0    4309408 protocol: TCPv6

lsof -n | grep /dev/null
httpd      9086                     root    0r      CHR                1,3       0t0      12290 /dev/null
httpd      9088                   apache    0r      CHR                1,3       0t0      12290 /dev/null
httpd      9089                   apache    0r      CHR                1,3       0t0      12290 /dev/null
httpd      9089  9091 httpd       apache    0r      CHR                1,3       0t0      

lsof -n | grep /dev/urandom
httpd      9086                     root    5r      CHR                1,9       0t0      12295 /dev/urandom
httpd      9088                   apache    5r      CHR                1,9       0t0      12295 /dev/urandom
httpd      9089                   apache    5r      CHR                1,9       0t0      12295 /dev/urandom
httpd      9089  9091 httpd       apache    5r      CHR                1,9       0t0      12295 /dev/urandom
httpd      9089  9093 httpd       apache    5r      CHR                1,9       0t0      12295 /dev/urandom
httpd      9089  9094 httpd       apache    5r      CHR                1,9       0t0      

(gdb) bt
#0  0x00007f1e93e08df4 in read () from target:/lib64/libpthread.so.0
#1  0x000055987de064cb in ap_mpm_podx_check ()
#2  0x00007f1e93498f57 in ?? () from target:/etc/httpd/modules/mod_mpm_event.so
#3  0x00007f1e9349928a in ?? () from target:/etc/httpd/modules/mod_mpm_event.so
#4  0x00007f1e9349931b in ?? () from target:/etc/httpd/modules/mod_mpm_event.so
#5  0x00007f1e9349a017 in ?? () from target:/etc/httpd/modules/mod_mpm_event.so
#6  0x000055987dddabde in ap_run_mpm ()
#7  0x000055987ddd32d3 in main ()

Anything else I can provide? httpd.conf? ssl.conf?

Comment 1 RobbieTheK 2019-01-14 14:53:03 UTC
This appears to continue to build up after a few days:

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND                                                                                                                                                         
12145 apache    20   0 2335612  19432   9208 S 398.3   0.0  15779:23 httpd                                                                                                                                                           
12140 apache    20   0 2425868  18760   9164 S  99.7   0.0   4339:25 httpd                                                                                                                                                           
12590 apache    20   0 2335612  18924   9200 S  99.7   0.0   3560:12 httpd  

from a gdb:
0x00007f92f7290acd in __pthread_timedjoin_ex () from target:/lib64/libpthread.so.0
(gdb) bt
#0  0x00007f92f7290acd in __pthread_timedjoin_ex () from target:/lib64/libpthread.so.0
#1  0x00007f92f72d5dbf in apr_thread_join () from target:/lib64/libapr-1.so.0
#2  0x00007f92f6940706 in ?? () from target:/etc/httpd/modules/mod_mpm_event.so
#3  0x00007f92f6940f88 in ?? () from target:/etc/httpd/modules/mod_mpm_event.so
#4  0x00007f92f694128a in ?? () from target:/etc/httpd/modules/mod_mpm_event.so
#5  0x00007f92f69420e4 in ?? () from target:/etc/httpd/modules/mod_mpm_event.so
#6  0x0000561095196bde in ap_run_mpm ()
#7  0x000056109518f2d3 in main ()
(gdb) quit
A debugging session is active.

	Inferior 1 [process 12145] will be detached.

Not sure if this is related but after restarting httpd the avahi-daemon starts using CPU:
  PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND                                                                                                                                                         
  794 avahi     20   0   16336  13120   4220 R  90.0   0.0   5:44.02 avahi-daemon  

spams the logs with:
Jan 14 09:51:23 storm avahi-daemon[794]: Too many objects for client ':1.20169', client request failed.

then eventually settles down.

Comment 2 Joe Orton 2019-01-18 12:53:46 UTC
Do you have mod_ssl installed?  If so please check for log message AH02042 in (e.g.) /var/log/httpd/ssl_error_log, could be a duplicate of bug 1664414.

Comment 3 RobbieTheK 2019-01-18 14:40:44 UTC
openssl version
OpenSSL 1.1.1a FIPS  20 Nov 2018

httpd -t -D DUMP_MODULES | grep ssl
ssl_module (shared)

And yes a few AH02042 and if it helps to know these are from the Qualys vulnerability scanner.

[Mon Jan 14 20:15:31.870898 2019] [ssl:error] [pid 25317:tid 140359254402816] [client qualys:33448] AH02042: rejecting client initiated renegotiation
[Mon Jan 14 20:15:41.937909 2019] [ssl:error] [pid 25757:tid 140359715772160] [client qualys:34784] AH02042: rejecting client initiated renegotiation
[Mon Jan 14 20:15:52.020408 2019] [ssl:error] [pid 25321:tid 140359447336704] [client qualys:38195] AH02042: rejecting client initiated renegotiation

Comment 4 Joe Orton 2019-01-18 15:08:46 UTC

*** This bug has been marked as a duplicate of bug 1664414 ***


Note You need to log in before you can comment on or make changes to this bug.