ModSecurity can cause hang of apache httpd during graceful restart

[TomasKorbar]

Describe the bug

When modsec is configured to pipe logs to different process (like rotatelogs for example) it can cause hang of apache httpd during graceful restart.

When SecAuditLog directive is set as for exampleSecAuditLog "|/usr/sbin/rotatelogs -l -n 3 /var/log/httpd/modsec_audit.log 50M"
modsec opens pipe to rotatelogs during its configuration in cmd_audit_log function in apache2/apache2_config.c:1210

    if (dcfg->auditlog_name[0] == '|') {
        const char *pipe_name = dcfg->auditlog_name + 1;
        piped_log *pipe_log;

        pipe_log = ap_open_piped_log(cmd->pool, pipe_name);  <------------
        if (pipe_log == NULL) {
            return apr_psprintf(cmd->pool, "ModSecurity: Failed to open the audit log pipe: %s",
                    pipe_name);
        }
        dcfg->auditlog_fd = ap_piped_log_write_fd(pipe_log);

There is a problem that child processes created by httpd inherit the read side of pipe even when they are not using it and are meant to close them on startup which is ensured by read_handles global variable in server/log.c in apache httpd source.
For illustration here is code handling recording of the read handle:

/* remember to close this handle in the child process
 *
 * On Win32 this makes zero sense, because we don't
 * take the parent process's child procs.
 * If the win32 parent instead passed each and every
 * logger write handle from itself down to the child,
 * and the parent manages all aspects of keeping the
 * reliable pipe log children alive, this would still
 * make no sense :)  Cripple it on Win32.
 */
static void close_handle_in_child(apr_pool_t *p, apr_file_t *f)
{
#ifndef WIN32
    read_handle_t *new_handle;

    new_handle = apr_pcalloc(p, sizeof(read_handle_t));
    new_handle->next = read_handles;
    new_handle->handle = f;
    read_handles = new_handle;
#endif
}

These handles get cleared when plog memory pool gets cleared which happens after the configuration is loaded and before open logs
hooks are called. That means that child will get no reference to opened read side of the pipe and thus can not close it. This causes that process can wait for the write inside of the pipe indefinitely and will never get EPIPE from the OS informing the process about rotatelogs being already killed. This is why process waiting for write will hang.

Logs and dumps

Output of:

1. DebugLogs (level 9)

modsec_debug.log.tar.gz

2. AuditLogs

Empty because reproducing requires to stop rotatelogs process.

3. Error logs

error_log.txt

4. If there is a crash, the core dump file.

Backtrace seems sufficient to me.
#0 0x00007f560757259f in write () from target:/lib64/libc.so.6
#1 0x00007f560767aa1f in apr_file_write () from target:/lib64/libapr-1.so.0
#2 0x00007f560767ac4a in apr_file_write_full () from target:/lib64/libapr-1.so.0
#3 0x00007f56067a8ea1 in sec_auditlog_write.isra () from target:/etc/httpd/modules/mod_security2.so
#4 0x00007f5606784d21 in sec_audit_logger_native () from target:/etc/httpd/modules/mod_security2.so
#5 0x00007f560677c10c in modsecurity_process_phase () from target:/etc/httpd/modules/mod_security2.so
#6 0x00007f560676f9bd in hook_log_transaction () from target:/etc/httpd/modules/mod_security2.so
#7 0x000055f66b95ba98 in ap_run_log_transaction ()
#8 0x000055f66b96f89b in eor_bucket_cleanup ()
#9 0x00007f560767dade in apr_pool_destroy () from target:/lib64/libapr-1.so.0
#10 0x000055f66b964cc2 in eor_bucket_destroy ()
#11 0x000055f66b96fa89 in ap_core_output_filter ()
#12 0x000055f66b979dab in ap_process_request ()
#13 0x000055f66b97a073 in ap_process_http_connection ()
#14 0x000055f66b945e98 in ap_run_process_connection ()
#15 0x00007f5606ff3292 in child_main () from target:/etc/httpd/modules/mod_mpm_prefork.so
#16 0x00007f5606ff3607 in make_child () from target:/etc/httpd/modules/mod_mpm_prefork.so
#17 0x00007f5606ff3669 in startup_children () from target:/etc/httpd/modules/mod_mpm_prefork.so
#18 0x00007f5606ff3d93 in prefork_run () from target:/etc/httpd/modules/mod_mpm_prefork.so
#19 0x000055f66b9467c8 in ap_run_mpm ()
#20 0x000055f66b9346d5 in main ()

To Reproduce
This problem is tricky to reproduce so forgive me for a complex reproducer, repeat these steps:

1. Set SecAuditLog directive inside the modsec configuration to:
   SecAuditLog "|/usr/sbin/rotatelogs -l -n 3 /var/log/httpd/modsec_audit.log 50M"
2. enable mpm prefork module like this:
   LoadModule mpm_prefork_module modules/mod_mpm_prefork.so
3. Add mpm prefork module configuration

<IfModule prefork.c>
StartServers           1
MinSpareServers        1
MaxSpareServers        1
ServerLimit            1
MaxRequestWorkers      1
MaxRequestsPerChild    0
MaxConnectionsPerChild 0
</IfModule>

These steps make it easier to reproduce the issue
4. Create index page for httpd

$ touch /var/www/html/index.html

5. Start httpd (i am using systemd since its easier to keep track of processes)

# systemctl start httpd

6. Find rotatelogs process

$ systemctl status httpd

7. stop the rotatelogs process

# kill -STOP <rotatelogs_pid>

8. Perform requests to fill pipes buffer with modsecurity logs (you must have active rules that log something for this request)

$ while true; do curl http://127.0.0.1 -m 5; [ $? -eq 28 ] && break; done

9. Try to perform graceful restart

# systemctl reload httpd

10. Resume rotatelogs process

# kill -CONT <rotatelogs_pid>

11. Find httpd processes with systemctl and check whether one of them is not stuck

$ systemctl status httpd

# for PID in '<httpd_pids>'; do pstack $PID >> ./pstack_logs; done;

$ cat ./pstack_logs | grep 'in write ('

12. If grep find string in write ( then one of the processes is still waiting for other process to read from previously created pipe.

Expected behavior

No hanging process.

Server (please complete the following information):

• ModSecurity version (and connector): 2.9.6
• WebServer: 2.4.54
• OS (and distro): Linux Fedora Rawhide

Rule Set (please complete the following information):

• Running any public or commercial rule set?
  Yes coreruleset mod_security_crs 3.3.4 from Fedora
• What is the version number? [e.g. 2018-08-11]
  3.3.4-1

Additional context
I am creating a PR that fixes this issue.
It is sufficient that the code which opens the auditlog is moved to a open_logs hook instead of being executed in a configuration command.

Please do not hesitate to ask further questions.