You are viewing a plain text version of this content. The canonical link for it is here.
Posted to bugs@httpd.apache.org by bu...@apache.org on 2017/03/01 21:22:38 UTC

[Bug 60796] New: Missing error message in Directive parsing portion of module

https://bz.apache.org/bugzilla/show_bug.cgi?id=60796

            Bug ID: 60796
           Summary: Missing error message in Directive parsing portion of
                    module
           Product: Apache httpd-2
           Version: 2.4.25
          Hardware: PC
                OS: Linux
            Status: NEW
          Severity: normal
          Priority: P2
         Component: Core
          Assignee: bugs@httpd.apache.org
          Reporter: rbost@redhat.com
  Target Milestone: ---

Created attachment 34789
  --> https://bz.apache.org/bugzilla/attachment.cgi?id=34789&action=edit
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.

-- 
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org


[Bug 60796] Missing error message in Directive parsing portion of module

Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=60796

--- Comment #1 from Robert Bost <rb...@redhat.com> ---
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

-- 
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org


[Bug 60796] Missing error message in Directive parsing portion of module

Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=60796

--- Comment #2 from Robert Bost <rb...@redhat.com> ---
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.

-- 
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org