Bug 60796 - Missing error message in Directive parsing portion of module
Summary: Missing error message in Directive parsing portion of module
Status: NEW
Alias: None
Product: Apache httpd-2
Classification: Unclassified
Component: Core (show other bugs)
Version: 2.4.25
Hardware: PC Linux
: P2 normal (vote)
Target Milestone: ---
Assignee: Apache HTTPD Bugs Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2017-03-01 21:22 UTC by Robert Bost
Modified: 2017-03-03 01:29 UTC (History)
0 users



Attachments
reproducer (1008 bytes, text/x-csrc)
2017-03-01 21:22 UTC, Robert Bost
Details

Note You need to log in before you can comment on or make changes to this bug.
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.