Created attachment 34789 [details] reproducer If I return an error in my directive parsing code of module during the second pass , the error message is never logged. I've attached a module that reproduces this issue. Here are reproduction steps and steps on how to spot the error message being logged out incorrectly: # apxs -i -a -c mod_test.c # echo IntoTheVoid >> /usr/local/apache2/conf/httpd.conf # /usr/local/apache2/bin/apachectl -f /usr/local/apache2/conf/httpd.conf -k start [Wed Mar 01 16:17:34.993411 2017] [intothevoid:error] [pid 14151:tid 139904119781248] AH11111: Test: A [Wed Mar 01 16:17:34.993438 2017] [intothevoid:warn] [pid 14151:tid 139904119781248] AH11111: Test: B But, if you strace, we can see the error messages being written out to nowhere in second pass. # strace -Tttvfs 1024 -e write /usr/local/apache2/bin/apachectl -f /usr/local/apache2/conf/httpd.conf -k start strace: Process 14353 attached [pid 14353] 16:20:44.793792 write(1, "4096\n", 5) = 5 <0.000033> [pid 14353] 16:20:44.794046 +++ exited with 0 +++ 16:20:44.794061 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=14353, si_uid=0, si_status=0, si_utime=0, si_stime=0} --- strace: Process 14354 attached [pid 14354] 16:20:44.952021 write(2, "[Wed Mar 01 16:20:44.951909 2017] [intothevoid:error] [pid 14354:tid 140439900153728] AH11111: Test: A\n", 103[Wed Mar 01 16:20:44.951909 2017] [intothevoid:error] [pid 14354:tid 140439900153728] AH11111: Test: A ) = 103 <0.000019> [pid 14354] 16:20:44.952081 write(2, "[Wed Mar 01 16:20:44.952072 2017] [intothevoid:warn] [pid 14354:tid 140439900153728] AH11111: Test: B\n", 102[Wed Mar 01 16:20:44.952072 2017] [intothevoid:warn] [pid 14354:tid 140439900153728] AH11111: Test: B ) = 102 <0.000010> [pid 14354] 16:20:44.952853 write(2, "[Wed Mar 01 16:20:44.952846 2017] [core:crit] [pid 14354:tid 140439900153728] AH123123: \n", 89) = 89 <0.000032> strace: Process 14355 attached [pid 14354] 16:20:44.958263 +++ exited with 0 +++ [pid 14352] 16:20:44.958330 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=14354, si_uid=0, si_status=0, si_utime=0, si_stime=6} --- [pid 14355] 16:20:44.958545 write(2, "[Wed Mar 01 16:20:44.958535 2017] [intothevoid:error] [pid 14355:tid 140439900153728] AH11111: Test: A\n", 103) = 103 <0.000008> [pid 14352] 16:20:44.958588 +++ exited with 0 +++ 16:20:44.958596 write(2, "[Wed Mar 01 16:20:44.958581 2017] [intothevoid:warn] [pid 14355:tid 140439900153728] AH11111: Test: B\n", 102) = 102 <0.000011> 16:20:44.958625 write(2, "[Wed Mar 01 16:20:44.958619 2017] [intothevoid:warn] [pid 14355:tid 140439900153728] AH11111: Test: C\n", 102) = 102 <0.000008> 16:20:44.958652 write(2, "AH00526: Syntax error on line 507 of /usr/local/apache2/conf/httpd.conf:\n", 73) = 73 <0.000008> 16:20:44.958674 write(2, "A second pass error.\n", 21) = 21 <0.000006> 16:20:44.970353 +++ exited with 1 +++ The lack of error output in second pass makes it difficult to troubleshoot configuration issues without the use of external tool like strace.
http://marc.info/?l=apache-httpd-dev&m=148034201402737&w=2 Seems like only sane place dup2 can be called from is this freopen: https://github.com/apache/httpd/blob/trunk/server/log.c#L442
Just some more brainstorming for a root cause here... https://github.com/apache/apr/blob/trunk/threadproc/unix/procsup.c#L79 Issue is not reproducible when running in debug mode (i.e. no child process). This leads me to believe when child process is being spawned off, apr_proc_detach is spinning off a child and the logs aren't being reinitialized in a timely manner.