ModSecurity is an open source, cross platform web application firewall (WAF) engine for Apache, IIS and Nginx. It has a robust event-based programming language which provides protection from a range of attacks against web applications and allows for HTTP traffic monitoring, logging and real-time analysis.
Hey,
I've just been investigating a steady increase on nginx reloads that I would like to share.
When I reload nginx I am noticing that some of the worker processes are shutting down or go into a shutting down state, which is what I would expect, but sometimes I see the below
root 39997 0.0 1.9 234784156 2623652 ? Ss Oct12 2:50 nginx: master process /usr/sbin/nginx -c /etc/nginx/nginx.conf
nginx 67968 0.9 2.1 233965092 2820912 ? S 00:01 5:26 \_ nginx: worker process
nginx 67975 0.9 2.1 234014024 2896572 ? S 00:01 5:46 \_ nginx: worker process is shutting down
nginx 69562 1.7 2.0 234374692 2688636 ? S 09:05 0:53 \_ nginx: worker process
nginx 82259 2.3 2.0 234784292 2669448 ? S 09:40 0:22 \_ nginx: worker process
nginx 82260 4.4 2.0 234784292 2667300 ? S 09:40 0:43 \_ nginx: worker process
nginx 82261 3.1 2.0 234784292 2666204 ? S 09:40 0:30 \_ nginx: worker process
nginx 82262 4.4 2.0 234784292 2681620 ? S 09:40 0:43 \_ nginx: worker process
nginx 82263 2.1 2.0 234784292 2654752 ? S 09:40 0:21 \_ nginx: worker process
nginx 82264 2.6 2.0 234784292 2675484 ? S 09:40 0:25 \_ nginx: worker process
nginx 82265 1.6 2.0 234784292 2653668 ? S 09:40 0:16 \_ nginx: worker process
nginx 82266 2.2 2.0 234784292 2661800 ? S 09:40 0:22 \_ nginx: worker process
nginx 82267 1.4 2.0 234784292 2656688 ? S 09:40 0:14 \_ nginx: worker process
nginx 82268 2.3 2.0 234784292 2675436 ? S 09:40 0:22 \_ nginx: worker process
nginx 82269 1.8 2.0 234784292 2662960 ? S 09:40 0:18 \_ nginx: worker process
nginx 82270 1.0 2.0 234784292 2641008 ? S 09:40 0:10 \_ nginx: worker process
nginx 82271 0.0 1.9 234784032 2619188 ? S 09:40 0:00 \_ nginx: cache manager process
As you can see there are worker processes from 00:01 and 09:05 that aren't shutting down. A quick look at cat /proc/69562/wchan Gives back futex_wait_queue_me and when I strace the processes it will quit shortly after.
Doing a GDB on a process seems to indicate an issue with the modsecurity logs. The servers are failrly busy and it seems to relate to how busy our sites are. As a work around, does modsecurity have syslog facility?
[root@10 ~]# gdb -p 48826
GNU gdb (GDB) Red Hat Enterprise Linux 7.6.1-110.el7
Copyright (C) 2013 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law. Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-redhat-linux-gnu".
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Attaching to process 48826
Reading symbols from /usr/sbin/nginx...Reading symbols from /usr/lib/debug/usr/sbin/nginx.debug...done.
done.
Reading symbols from /lib64/libdl.so.2...Reading symbols from /usr/lib/debug/usr/lib64/libdl-2.17.so.debug...done.
done.
Loaded symbols for /lib64/libdl.so.2
Reading symbols from /lib64/libpthread.so.0...Reading symbols from /usr/lib/debug/usr/lib64/libpthread-2.17.so.debug...done.
done.
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
Loaded symbols for /lib64/libpthread.so.0
Reading symbols from /lib64/libcrypt.so.1...Reading symbols from /usr/lib/debug/usr/lib64/libcrypt-2.17.so.debug...done.
done.
Loaded symbols for /lib64/libcrypt.so.1
Reading symbols from /lib64/libm.so.6...Reading symbols from /usr/lib/debug/usr/lib64/libm-2.17.so.debug...done.
done.
Loaded symbols for /lib64/libm.so.6
Reading symbols from /lib64/libluajit-5.1.so.2...Reading symbols from /usr/lib/debug/usr/lib64/libluajit-5.1.so.2.0.4.debug...done.
done.
Loaded symbols for /lib64/libluajit-5.1.so.2
Reading symbols from /opt/libmodsecurity/lib64/libmodsecurity.so.3...done.
Loaded symbols for /opt/libmodsecurity/lib64/libmodsecurity.so.3
Reading symbols from /lib64/libmaxminddb.so.0...Reading symbols from /usr/lib/debug/usr/lib64/libmaxminddb.so.0.0.7.debug...done.
done.
Loaded symbols for /lib64/libmaxminddb.so.0
Reading symbols from /opt/pcre/lib64/libpcre.so.1...
warning: the debug information found in "/usr/lib/debug//opt/pcre/lib64/libpcre.so.1.2.9.debug" does not match "/opt/pcre/lib64/libpcre.so.1" (CRC mismatch).
warning: the debug information found in "/usr/lib/debug/opt/pcre/lib64/libpcre.so.1.2.9.debug" does not match "/opt/pcre/lib64/libpcre.so.1" (CRC mismatch).
Missing separate debuginfo for /opt/pcre/lib64/libpcre.so.1
Try: yum --enablerepo='*debug*' install /usr/lib/debug/.build-id/d7/492050aa0526046bf7917bc6e64f1fef7d22c8.debug
Reading symbols from /opt/pcre/lib64/libpcre.so.1...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /opt/pcre/lib64/libpcre.so.1
Reading symbols from /lib64/libz.so.1...Reading symbols from /usr/lib/debug/usr/lib64/libz.so.1.2.7.debug...done.
done.
Loaded symbols for /lib64/libz.so.1
Reading symbols from /lib64/libc.so.6...Reading symbols from /usr/lib/debug/usr/lib64/libc-2.17.so.debug...done.
done.
Loaded symbols for /lib64/libc.so.6
Reading symbols from /lib64/ld-linux-x86-64.so.2...Reading symbols from /usr/lib/debug/usr/lib64/ld-2.17.so.debug...done.
done.
Loaded symbols for /lib64/ld-linux-x86-64.so.2
Reading symbols from /lib64/libfreebl3.so...Reading symbols from /usr/lib/debug/usr/lib64/libfreebl3.so.debug...done.
done.
Loaded symbols for /lib64/libfreebl3.so
Reading symbols from /lib64/libgcc_s.so.1...Reading symbols from /usr/lib/debug/usr/lib64/libgcc_s-4.8.5-20150702.so.1.debug...done.
done.
Loaded symbols for /lib64/libgcc_s.so.1
Reading symbols from /lib64/libcurl.so.4...Reading symbols from /usr/lib/debug/usr/lib64/libcurl.so.4.3.0.debug...done.
done.
Loaded symbols for /lib64/libcurl.so.4
Reading symbols from /lib64/libGeoIP.so.1...Reading symbols from /usr/lib/debug/usr/lib64/libGeoIP.so.1.5.0.debug...done.
done.
Loaded symbols for /lib64/libGeoIP.so.1
Reading symbols from /lib64/librt.so.1...Reading symbols from /usr/lib/debug/usr/lib64/librt-2.17.so.debug...done.
done.
Loaded symbols for /lib64/librt.so.1
Reading symbols from /lib64/libxml2.so.2...Reading symbols from /usr/lib/debug/usr/lib64/libxml2.so.2.9.1.debug...done.
done.
Loaded symbols for /lib64/libxml2.so.2
Reading symbols from /lib64/libyajl.so.2...Reading symbols from /usr/lib/debug/usr/lib64/libyajl.so.2.0.4.debug...done.
done.
Loaded symbols for /lib64/libyajl.so.2
Reading symbols from /lib64/libstdc++.so.6...Reading symbols from /usr/lib/debug/usr/lib64/libstdc++.so.6.0.19.debug...done.
done.
Loaded symbols for /lib64/libstdc++.so.6
Reading symbols from /lib64/libidn.so.11...Reading symbols from /usr/lib/debug/usr/lib64/libidn.so.11.6.11.debug...done.
done.
Loaded symbols for /lib64/libidn.so.11
Reading symbols from /lib64/libssh2.so.1...Reading symbols from /usr/lib/debug/usr/lib64/libssh2.so.1.0.1.debug...done.
done.
Loaded symbols for /lib64/libssh2.so.1
Reading symbols from /lib64/libssl3.so...Reading symbols from /usr/lib/debug/usr/lib64/libssl3.so.debug...done.
done.
Loaded symbols for /lib64/libssl3.so
Reading symbols from /lib64/libsmime3.so...Reading symbols from /usr/lib/debug/usr/lib64/libsmime3.so.debug...done.
done.
Loaded symbols for /lib64/libsmime3.so
Reading symbols from /lib64/libnss3.so...Reading symbols from /usr/lib/debug/usr/lib64/libnss3.so.debug...done.
done.
Loaded symbols for /lib64/libnss3.so
Reading symbols from /lib64/libnssutil3.so...Reading symbols from /usr/lib/debug/usr/lib64/libnssutil3.so.debug...done.
done.
Loaded symbols for /lib64/libnssutil3.so
Reading symbols from /lib64/libplds4.so...Reading symbols from /usr/lib/debug/usr/lib64/libplds4.so.debug...done.
done.
Loaded symbols for /lib64/libplds4.so
Reading symbols from /lib64/libplc4.so...Reading symbols from /usr/lib/debug/usr/lib64/libplc4.so.debug...done.
done.
Loaded symbols for /lib64/libplc4.so
Reading symbols from /lib64/libnspr4.so...Reading symbols from /usr/lib/debug/usr/lib64/libnspr4.so.debug...done.
done.
Loaded symbols for /lib64/libnspr4.so
Reading symbols from /lib64/libgssapi_krb5.so.2...Reading symbols from /usr/lib/debug/usr/lib64/libgssapi_krb5.so.2.2.debug...done.
done.
Loaded symbols for /lib64/libgssapi_krb5.so.2
Reading symbols from /lib64/libkrb5.so.3...Reading symbols from /usr/lib/debug/usr/lib64/libkrb5.so.3.3.debug...done.
done.
Loaded symbols for /lib64/libkrb5.so.3
Reading symbols from /lib64/libk5crypto.so.3...Reading symbols from /usr/lib/debug/usr/lib64/libk5crypto.so.3.1.debug...done.
done.
Loaded symbols for /lib64/libk5crypto.so.3
Reading symbols from /lib64/libcom_err.so.2...Reading symbols from /usr/lib/debug/usr/lib64/libcom_err.so.2.1.debug...done.
done.
Loaded symbols for /lib64/libcom_err.so.2
Reading symbols from /lib64/liblber-2.4.so.2...Reading symbols from /usr/lib/debug/usr/lib64/liblber-2.4.so.2.10.7.debug...done.
done.
Loaded symbols for /lib64/liblber-2.4.so.2
Reading symbols from /lib64/libldap-2.4.so.2...Reading symbols from /usr/lib/debug/usr/lib64/libldap-2.4.so.2.10.7.debug...done.
done.
Loaded symbols for /lib64/libldap-2.4.so.2
Reading symbols from /lib64/liblzma.so.5...Reading symbols from /usr/lib/debug/usr/lib64/liblzma.so.5.2.2.debug...done.
done.
Loaded symbols for /lib64/liblzma.so.5
Reading symbols from /lib64/libssl.so.10...Reading symbols from /usr/lib/debug/usr/lib64/libssl.so.1.0.2k.debug...done.
done.
Loaded symbols for /lib64/libssl.so.10
Reading symbols from /lib64/libcrypto.so.10...Reading symbols from /usr/lib/debug/usr/lib64/libcrypto.so.1.0.2k.debug...done.
done.
Loaded symbols for /lib64/libcrypto.so.10
Reading symbols from /lib64/libkrb5support.so.0...Reading symbols from /usr/lib/debug/usr/lib64/libkrb5support.so.0.1.debug...done.
done.
Loaded symbols for /lib64/libkrb5support.so.0
Reading symbols from /lib64/libkeyutils.so.1...Reading symbols from /usr/lib/debug/usr/lib64/libkeyutils.so.1.5.debug...done.
done.
Loaded symbols for /lib64/libkeyutils.so.1
Reading symbols from /lib64/libresolv.so.2...Reading symbols from /usr/lib/debug/usr/lib64/libresolv-2.17.so.debug...done.
done.
Loaded symbols for /lib64/libresolv.so.2
Reading symbols from /lib64/libsasl2.so.3...Reading symbols from /usr/lib/debug/usr/lib64/libsasl2.so.3.0.0.debug...done.
done.
Loaded symbols for /lib64/libsasl2.so.3
Reading symbols from /lib64/libselinux.so.1...Reading symbols from /usr/lib/debug/usr/lib64/libselinux.so.1.debug...done.
done.
Loaded symbols for /lib64/libselinux.so.1
Reading symbols from /lib64/libnss_files.so.2...Reading symbols from /usr/lib/debug/usr/lib64/libnss_files-2.17.so.debug...done.
done.
Loaded symbols for /lib64/libnss_files.so.2
__lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
135 2: movl %edx, %eax
(gdb) info threads
Id Target Id Frame
* 1 Thread 0x7f614ec0f880 (LWP 48826) "nginx" __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
(gdb) thread 1
[Switching to thread 1 (Thread 0x7f614ec0f880 (LWP 48826))]
#0 __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
135 2: movl %edx, %eax
(gdb) where
#0 __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
#1 0x00007f614e5f7e1b in _L_lock_812 () from /lib64/libpthread.so.0
#2 0x00007f614e5f7ce8 in __GI___pthread_mutex_lock (mutex=0x7f614ec2d008) at ../nptl/pthread_mutex_lock.c:79
#3 0x00007f614db9dfc8 in modsecurity::utils::SharedFiles::write (this=this@entry=0x7f614de45420 <modsecurity::utils::SharedFiles::getInstance()::instance>, fileName="/var/log/nginx/modsec_audit.log",
msg="{\"transaction\":{\"client_ip\":\"40.101.73.45\",\"time_stamp\":\"Tue Oct 16 09:34:26 2018\",\"server_id\":\"e80911fb1cfae6dfdd79276df625fc74a645d197\",\"client_port\":11660,\"host_ip\":\"40.101.73.45\",\"host_port\":443,\""..., error=error@entry=0x7ffd0385a1d0) at utils/shared_files.cc:230
#4 0x00007f614db2ad79 in modsecurity::audit_log::writer::Serial::write (this=<optimized out>, transaction=<optimized out>, parts=4430, error=0x7ffd0385a1d0) at audit_log/writer/serial.cc:49
#5 0x00007f614db29eaa in modsecurity::audit_log::AuditLog::saveIfRelevant (this=<optimized out>, transaction=transaction@entry=0x558ec1816af0, parts=parts@entry=4430) at audit_log/audit_log.cc:316
#6 0x00007f614db19ebb in modsecurity::Transaction::processLogging (this=0x558ec1816af0) at transaction.cc:1332
#7 0x00007f614db1a055 in modsecurity::msc_process_logging (transaction=<optimized out>) at transaction.cc:2220
#8 0x0000558e769347b2 in ngx_http_modsecurity_log_handler (r=<optimized out>) at /usr/src/debug/ModSecurity-nginx-master/src/ngx_http_modsecurity_log.c:72
#9 0x0000558e7686fe50 in ngx_http_log_request (r=r@entry=0x558eac8fd600) at src/http/ngx_http_request.c:3566
#10 0x0000558e7687158c in ngx_http_free_request (r=r@entry=0x558eac8fd600, rc=rc@entry=0) at src/http/ngx_http_request.c:3513
#11 0x0000558e76872121 in ngx_http_set_keepalive (r=0x558eac8fd600) at src/http/ngx_http_request.c:2967
#12 ngx_http_finalize_connection (r=<optimized out>) at src/http/ngx_http_request.c:2618
#13 0x0000558e7686de4c in ngx_http_core_content_phase (r=0x558eac8fd600, ph=<optimized out>) at src/http/ngx_http_core_module.c:1169
#14 0x0000558e768684fd in ngx_http_core_run_phases (r=r@entry=0x558eac8fd600) at src/http/ngx_http_core_module.c:858
#15 0x0000558e768685f2 in ngx_http_handler (r=r@entry=0x558eac8fd600) at src/http/ngx_http_core_module.c:841
#16 0x0000558e7687341e in ngx_http_process_request (r=0x558eac8fd600) at src/http/ngx_http_request.c:1952
#17 0x0000558e76873ccd in ngx_http_process_request_line (rev=0x558eb0b6ca70) at src/http/ngx_http_request.c:1052
#18 0x0000558e7685c0a7 in ngx_epoll_process_events (cycle=<optimized out>, timer=<optimized out>, flags=<optimized out>) at src/event/modules/ngx_epoll_module.c:902
#19 0x0000558e76852c0a in ngx_process_events_and_timers (cycle=cycle@entry=0x558e9a265180) at src/event/ngx_event.c:242
#20 0x0000558e7685a351 in ngx_worker_process_cycle (cycle=cycle@entry=0x558e9a265180, data=data@entry=0x0) at src/os/unix/ngx_process_cycle.c:750
#21 0x0000558e768587eb in ngx_spawn_process (cycle=cycle@entry=0x558e9a265180, proc=proc@entry=0x558e7685a2d0 <ngx_worker_process_cycle>, data=data@entry=0x0, name=name@entry=0x558e76b196c6 "worker process",
respawn=respawn@entry=-4) at src/os/unix/ngx_process.c:199
#22 0x0000558e768599f0 in ngx_start_worker_processes (cycle=cycle@entry=0x558e9a265180, n=12, type=type@entry=-4) at src/os/unix/ngx_process_cycle.c:359
#23 0x0000558e7685ae30 in ngx_master_process_cycle (cycle=0x558e9a265180, cycle@entry=0x558e778eded0) at src/os/unix/ngx_process_cycle.c:244
#24 0x0000558e76832cbf in main (argc=<optimized out>, argv=<optimized out>) at src/core/nginx.c:382
Adding gdb back trace
(gdb) bt
#0 __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
#1 0x00007f614e5f7e1b in _L_lock_812 () from /lib64/libpthread.so.0
#2 0x00007f614e5f7ce8 in __GI___pthread_mutex_lock (mutex=0x7f614ec2d008) at ../nptl/pthread_mutex_lock.c:79
#3 0x00007f614db9dfc8 in modsecurity::utils::SharedFiles::write (this=this@entry=0x7f614de45420 <modsecurity::utils::SharedFiles::getInstance()::instance>, fileName="/var/log/nginx/modsec_audit.log",
msg="{\"transaction\":{\"client_ip\":\"40.101.73.45\",\"time_stamp\":\"Tue Oct 16 09:34:26 2018\",\"server_id\":\"e80911fb1cfae6dfdd79276df625fc74a645d197\",\"client_port\":11660,\"host_ip\":\"40.101.73.45\",\"host_port\":443,\""..., error=error@entry=0x7ffd0385a1d0) at utils/shared_files.cc:230
#4 0x00007f614db2ad79 in modsecurity::audit_log::writer::Serial::write (this=<optimized out>, transaction=<optimized out>, parts=4430, error=0x7ffd0385a1d0) at audit_log/writer/serial.cc:49
#5 0x00007f614db29eaa in modsecurity::audit_log::AuditLog::saveIfRelevant (this=<optimized out>, transaction=transaction@entry=0x558ec1816af0, parts=parts@entry=4430) at audit_log/audit_log.cc:316
#6 0x00007f614db19ebb in modsecurity::Transaction::processLogging (this=0x558ec1816af0) at transaction.cc:1332
#7 0x00007f614db1a055 in modsecurity::msc_process_logging (transaction=<optimized out>) at transaction.cc:2220
#8 0x0000558e769347b2 in ngx_http_modsecurity_log_handler (r=<optimized out>) at /usr/src/debug/ModSecurity-nginx-master/src/ngx_http_modsecurity_log.c:72
#9 0x0000558e7686fe50 in ngx_http_log_request (r=r@entry=0x558eac8fd600) at src/http/ngx_http_request.c:3566
#10 0x0000558e7687158c in ngx_http_free_request (r=r@entry=0x558eac8fd600, rc=rc@entry=0) at src/http/ngx_http_request.c:3513
#11 0x0000558e76872121 in ngx_http_set_keepalive (r=0x558eac8fd600) at src/http/ngx_http_request.c:2967
#12 ngx_http_finalize_connection (r=<optimized out>) at src/http/ngx_http_request.c:2618
#13 0x0000558e7686de4c in ngx_http_core_content_phase (r=0x558eac8fd600, ph=<optimized out>) at src/http/ngx_http_core_module.c:1169
#14 0x0000558e768684fd in ngx_http_core_run_phases (r=r@entry=0x558eac8fd600) at src/http/ngx_http_core_module.c:858
#15 0x0000558e768685f2 in ngx_http_handler (r=r@entry=0x558eac8fd600) at src/http/ngx_http_core_module.c:841
#16 0x0000558e7687341e in ngx_http_process_request (r=0x558eac8fd600) at src/http/ngx_http_request.c:1952
#17 0x0000558e76873ccd in ngx_http_process_request_line (rev=0x558eb0b6ca70) at src/http/ngx_http_request.c:1052
#18 0x0000558e7685c0a7 in ngx_epoll_process_events (cycle=<optimized out>, timer=<optimized out>, flags=<optimized out>) at src/event/modules/ngx_epoll_module.c:902
#19 0x0000558e76852c0a in ngx_process_events_and_timers (cycle=cycle@entry=0x558e9a265180) at src/event/ngx_event.c:242
#20 0x0000558e7685a351 in ngx_worker_process_cycle (cycle=cycle@entry=0x558e9a265180, data=data@entry=0x0) at src/os/unix/ngx_process_cycle.c:750
#21 0x0000558e768587eb in ngx_spawn_process (cycle=cycle@entry=0x558e9a265180, proc=proc@entry=0x558e7685a2d0 <ngx_worker_process_cycle>, data=data@entry=0x0, name=name@entry=0x558e76b196c6 "worker process",
respawn=respawn@entry=-4) at src/os/unix/ngx_process.c:199
#22 0x0000558e768599f0 in ngx_start_worker_processes (cycle=cycle@entry=0x558e9a265180, n=12, type=type@entry=-4) at src/os/unix/ngx_process_cycle.c:359
#23 0x0000558e7685ae30 in ngx_master_process_cycle (cycle=0x558e9a265180, cycle@entry=0x558e778eded0) at src/os/unix/ngx_process_cycle.c:244
#24 0x0000558e76832cbf in main (argc=<optimized out>, argv=<optimized out>) at src/core/nginx.c:382
Hey, I've just been investigating a steady increase on nginx reloads that I would like to share.
When I reload nginx I am noticing that some of the worker processes are shutting down or go into a shutting down state, which is what I would expect, but sometimes I see the below
As you can see there are worker processes from 00:01 and 09:05 that aren't shutting down. A quick look at
cat /proc/69562/wchan
Gives backfutex_wait_queue_me
and when I strace the processes it will quit shortly after.Doing a GDB on a process seems to indicate an issue with the modsecurity logs. The servers are failrly busy and it seems to relate to how busy our sites are. As a work around, does modsecurity have syslog facility?
Thanks, Liam
Modsecurity configuration:
Output from GDB:
Adding gdb back trace
Nginx/Modsecurity versions: