nginx worker hangs while logging to the audit log

[wutchzone]

Hello,
In our company we use ModSecurity in our nginx. We noticed that sometimes nginx workers just hangs and do nothing, however when we strace the process (or attach the gdb), then the worker starts spinning again. This problem happens when we enable audit logging (ex: SecAuditLog /var/log/modsec_audit.log), I have traced the issues to the following line https://github.com/SpiderLabs/ModSecurity/blob/0eb3c123f447b8787ea726ad4d4439018a07ee31/src/utils/shared_files.cc#L236 it appers that proccess is unable to wakeup and acquire the lock for the file and it is just waiting.

backtrace:

#1  0x00007f31debc4714 in __GI___pthread_mutex_lock (mutex=0x7f31debef008) at ../nptl/pthread_mutex_lock.c:80
#2  0x00007f31de95474a in modsecurity::utils::SharedFiles::write(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >*) () from /usr/lib/x86_64-linux-gnu/libmodsecurity.so.3
#3  0x00007f31de8dd9a4 in modsecurity::audit_log::writer::Serial::write(modsecurity::Transaction*, int, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >*) () from /usr/lib/x86_64-linux-gnu/libmodsecurity.so.3
#4  0x00007f31de8dcc0e in modsecurity::audit_log::AuditLog::saveIfRelevant(modsecurity::Transaction*, int) () from /usr/lib/x86_64-linux-gnu/libmodsecurity.so.3
#5  0x00007f31de8cd966 in modsecurity::Transaction::processLogging() () from /usr/lib/x86_64-linux-gnu/libmodsecurity.so.3
#6  0x0000563cedc9d11c in ngx_http_modsecurity_log_handler (r=<optimized out>) at ../modules/ngx_modsecurity_module/src/ngx_http_modsecurity_log.c:83
#7  0x0000563cedc0b41d in ngx_http_log_request (r=0x563cf1a308e0) at src/http/ngx_http_request.c:3684
#8  ngx_http_free_request (r=r@entry=0x563cf1a308e0, rc=<optimized out>) at src/http/ngx_http_request.c:3630
#9  0x0000563cedc0b4f8 in ngx_http_close_request (rc=0, r=<optimized out>) at src/http/ngx_http_request.c:3576
#10 0x0000563cedc1e90d in ngx_http_upstream_process_request (r=0x563cf1a308e0, u=0x563cf20a8538) at src/http/ngx_http_upstream.c:4122
#11 0x0000563cedc2275b in ngx_http_upstream_send_response (u=0x563cf20a8538, r=0x563cf1a308e0) at src/http/ngx_http_upstream.c:3306
#12 ngx_http_upstream_process_header (r=0x563cf1a308e0, u=0x563cf20a8538) at src/http/ngx_http_upstream.c:2479
#13 0x0000563cedc1dd92 in ngx_http_upstream_handler (ev=<optimized out>) at src/http/ngx_http_upstream.c:1329
#14 0x0000563cedbf6836 in ngx_epoll_process_events (cycle=<optimized out>, timer=<optimized out>, flags=<optimized out>) at src/event/modules/ngx_epoll_module.c:901
#15 0x0000563cedbece76 in ngx_process_events_and_timers (cycle=cycle@entry=0x563cf02d4250) at src/event/ngx_event.c:260
#16 0x0000563cedbf4a18 in ngx_worker_process_cycle (cycle=cycle@entry=0x563cf02d4250, data=data@entry=0x1) at src/os/unix/ngx_process_cycle.c:767
#17 0x0000563cedbf3159 in ngx_spawn_process (cycle=cycle@entry=0x563cf02d4250, proc=proc@entry=0x563cedbf4990 <ngx_worker_process_cycle>, data=data@entry=0x1, name=name@entry=0x563ceded3328 "worker process", respawn=respawn@entry=-3) at src/os/unix/ngx_process.c:203
#18 0x0000563cedbf5366 in ngx_start_worker_processes (cycle=cycle@entry=0x563cf02d4250, n=40, type=type@entry=-3) at src/os/unix/ngx_process_cycle.c:372
#19 0x0000563cedbf581b in ngx_master_process_cycle (cycle=0x563cf02d4250) at src/os/unix/ngx_process_cycle.c:144
#20 0x0000563cedbc8cad in main (argc=<optimized out>, argv=<optimized out>) at src/core/nginx.c:382

We use the following connector

server:

• nginx 1.17 - 40 workers
• Debian 10 (buster)
• libmodsecurity3 (3.0.3)

Is this a bug or this directive cannot be used with multiple processes logging to the same file?

[zimmerle]

Hi, @wutchzone

That sounds to be a bug. Further investigation is needed. Do you happen to have the audit log in Serial or Parallel mode?

[wutchzone]

We have set it as SecAuditLogType Serial.

I will try to create a reproducible example on local machine. For now I am able to reproduce this behavior only in production, where we have multiple CPU cores (40+). I will also experiment with other types of locks.

[martinhsv]

Hi @wutchzone ,

I'm not certain whether this would help your particular situation, but you might want to consider upgrading your libmodsecurity version to v3.0.4. There were some fixes post-v3.0.3 that might be relevant. I'm thinking in particular of:
3d20304

[zimmerle]

@wutchzone did you had the chance to test v3.0.4?

[mrwizard64]

Here's the solution:

I was experiencing the same problem, and it would appear that Atomicorp wrote some 'bad rules' which have caused nginx processes to hang. If you are running ASL or if you are just using atomicorp's modsecurity package, this is why your nginx processes are getting stuck. They have pushed out an update, so you will need to update your modsecurity package as soon as possible, or you will probably continue getting the same errors.

Good luck.

[wutchzone]

We wil update the library by the end of the week. I will let you know once I will have the results.

Thank you all for quick response and help.

[wutchzone]

@zimmerle Sadly updating the package to the latest version did not help either. Workers are still getting stuck as cen bee see on the image below.

@mrwizard64 I am not aware of that we are using rules from Atomicorp. We are using this.

[wutchzone]

But after the update it stucks less frequent. Once i catch it again I will provide full backtrace.

[zimmerle]

But after the update it stucks less frequent. Once i catch it again I will provide full backtrace.

thank you. The core flie will lead you to the fullbacktrace. It could help a lot

[mrwizard64]

Thanks buddy

…

On Mon, Aug 3, 2020 at 7:35 AM Daniel Sedlak ***@***.***> wrote: But after the update it stucks less frequent. Once i catch it again I will provide full backtrace. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#2373 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AIL6PLCVD7T5N3XUU5WHM7LR62OGHANCNFSM4PITTMIA> .

[wutchzone]

It looks like it is stuck on another pthread_mutex_lock(). I am unable to locate pthread_mutex_lock in this function (modsecurity::utils::find_resource), maybe something got inlined.

#0  __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:103
#1  0x00007fa81d99a714 in __GI___pthread_mutex_lock (mutex=0x7fa81d9c5008) at ../nptl/pthread_mutex_lock.c:80
#2  0x00007fa81d72a74a in modsecurity::utils::find_resource(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >*)
    () from /usr/lib/x86_64-linux-gnu/libmodsecurity.so.3
#3  0x0000000000000008 in ?? ()
#4  0x384b505942563964 in ?? ()
#5  0x0000292934302100 in ?? ()
#6  0x00007fff254c5710 in ?? ()
#7  0x0000000000000000 in ?? ()

But this time it happens less often. When we turn off Audit Log workers no longer stucks.