Bug 60796

Summary: Missing error message in Directive parsing portion of module
Product: Apache httpd-2 Reporter: Robert Bost <rbost>
Component: CoreAssignee: Apache HTTPD Bugs Mailing List <bugs>
Status: NEW ---    
Severity: normal    
Priority: P2    
Version: 2.4.25   
Target Milestone: ---   
Hardware: PC   
OS: Linux   
Attachments: reproducer

Description Robert Bost 2017-03-01 21:22:38 UTC
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.
Comment 1 Robert Bost 2017-03-03 00:25:36 UTC
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
Comment 2 Robert Bost 2017-03-03 01:29:22 UTC
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.