Bug 57045

This is maybe related to PR54179.

This has been fixed in 2.4.4.

Could you test with a newer version to see if your issue is solved?

The problem is that null (i.e., zero) bytes are dropped because the logging code treats all data as null-terminated strings. See my blog post at http://www.skepticism.us/2015/09/apache-module-dumpio-doesnt-dump-null-zero-bytes/. I have a fix for this and will work to get it integrated into the project. You'll find the fixed source for the mod_dumpio.c file linked from my post where I announced the availability of the fix: http://www.skepticism.us/2015/10/a-fix-for-the-apache-mod_dumpio-module-not-dumping-null-bytes/

Also, I changed the version to 2.4.16 since the bug exists in all versions up to and including the most recent production release. I also changed the hardware to "all" because the bug is independent of the hardware platform.

Created attachment 33162 [details]
fixed mod_dumpio.c module

Created attachment 33163 [details]
Patch against 2.4.16

Created attachment 33164 [details]
Program to decode output of fixed mod_dumpio

This Python program extracts the data from the error log lines written by mod_dumpio and decodes the logged data to reconstruct the original data. Below is an example from my error log. The "=#" lines are included to clearly delineate the reconstructed data from the lines in the error log (both sets of lines are written to stdout).

=#==#==#==#==#==#==#==#==#==#==#==#==#==#==#==#==#==#==#==#==#==#==#==#==#==#=
GET /wp-admin/admin-ajax.php?action=revslider_show_image&img=..%2Fwp-config.php HTTP/1.1
User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:31.0) Gecko/20100101 Firefox/31.0
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
Accept-Encoding: gzip, deflate
Accept-Language: en-US,en;q=0.5
Host: skepticism.us
Content-Length: 0

=#==#==#==#==#==#==#==#==#==#==#==#==#==#==#==#==#==#==#==#==#==#==#==#==#==#=

(In reply to Kurtis Rader from comment #5)
> Created attachment 33163 [details]
> Patch against 2.4.16

This patch looks not thread-safe (static encoded_{buf,idx} and space_left can't be accessed concurrently).

How about using ap_log_[r]data() introduced in 2.4.11?

> This patch looks not thread-safe...

It's definitely not thread-safe. I should have mentioned that this version only works reliably with MPM pre-fork; which is what I'm currently using since my site runs WordPress. I threw this together over a couple of evenings and wanted to get it out there for feedback. Assuming no one has any other problems with the code I'll add the necessary support for thread local data to make it thread-safe.

> How about using ap_log_[r]data() introduced in 2.4.11?

That looks like it will emit data in a non-backward compatible format. It would also mean the code can't be used with 2.2.x. For this change I'd prefer to be conservative and keep the logged format unchanged to the extent possible and remain compatible with 2.2.x. Obviously I'm changing how 0xff is represented in the error log but it's a safe bet no one will care because they've obviously never tried to use the binary data that is logged.


P.S., I looked at the existing uses of ap_log_rdata() in the 2.4.16 tree and they all appear to be incorrect. The ap_log_rdata function declaration doesn't match any of the uses. Consider the sole use in modules/proxy/mod_proxy_fcgi.c:

    ap_log_rdata(APLOG_MARK, APLOG_TRACE8, r, "FastCGI header",
                 farray, AP_FCGI_HEADER_LEN, 0);

The only reason this compiles is because "r" is defined at function scope. If you rename "r" to "req" throughout the function it fails to compile with this error:

mod_proxy_fcgi.c:577:13: error: use of undeclared identifier 'r'
            ap_log_rdata(APLOG_MARK, APLOG_TRACE8, req, "FastCGI header",
            ^
/Users/krader/brew-httpd-2.4.16/include/http_log.h:636:27: note: expanded from macro 'ap_log_rdata'


P.P.S., That magic zero as the last parameter of the call rather than AP_LOG_DATA_DEFAULT is gross.

> mod_proxy_fcgi.c:577:13: error: use of undeclared identifier 'r'
>             ap_log_rdata(APLOG_MARK, APLOG_TRACE8, req, "FastCGI header",
>             ^
> /Users/krader/brew-httpd-2.4.16/include/http_log.h:636:27: note: expanded
> from macro 'ap_log_rdata'

fixed in trunk / proposed for backport

Created attachment 33179 [details]
Patch against 2.4.16

This version, unlike my first submission, is thread-safe. I've tested this on Mac OS X and Ubuntu with both input and output logging enabled.

Created attachment 33180 [details]
fixed mod_dumpio.c module

Created attachment 33181 [details]
Program to decode output of fixed mod_dumpio

This is an updated version of the program I posted earlier. This version takes advantage of the "new request" log message I introduced in the latest version of my mod_dumpio patch.

Comment on attachment 33180 [details]
fixed mod_dumpio.c module

Can you please post changes as diff -u output?

"Can you please post changes as diff -u output?"

I did. See the first attachment: https://bz.apache.org/bugzilla/attachment.cgi?id=33179

I posted the entire module to make it easy for someone to see the entirety of the change since the patch is twice the length of the original module.

(In reply to Kurtis Rader from comment #14)
> "Can you please post changes as diff -u output?"
> 
> I did. See the first attachment:
> https://bz.apache.org/bugzilla/attachment.cgi?id=33179
> 
> I posted the entire module to make it easy for someone to see the entirety
> of the change since the patch is twice the length of the original module.

Sorry, assumed it superceded.  

It looks like a large part of the diff (other than that there's info for 2 copies of the mod?) is refactoring and changing C comments to C++/c99 comments.  Noise aside, the latter should be avoided for modules. The refactoring/all-in-one patch makes it a lot of labor to review.

> It looks like a large part of the diff (other than that there's
> info for 2 copies of the mod?) is refactoring and changing
> C comments to C++/c99 comments.  Noise aside, the latter should
> be avoided for modules.

I wholly agree. However, in this case the only gratuitous comment style change I made was the comments in the AP_DECLARE_MODULE stanza at the end of the file. I'm happy to revert that portion of the patch. There are a couple of other places where I changed the comment style but it doesn't materially affect the size of the diff because I modified the comment as a consequence of changing the actual logic. The diff is huge because of the significant rewrite of the core dumpit() function.

Ping? I got tired of building httpd from source and am now relying on my distro which currently provides httpd 2.4.29. It's a trifle annoying that this still isn't fixed. Especially since I provided a patch that fixed the problem and other than some grumbling about changing some comments to use "//" style comments I didn't get any constructive feedback on my patch. As I wrote in a previous comment "The diff is huge because of the significant rewrite of the core dumpit() function." And that's because the original implementation does not work as advertised.

I've given up on Apache+Wordpress. In part because issues like this are not resolved in a timely manner. This issue has been open four years. I submitted a fix three years ago. If my fix is not acceptable it would be nice to know why not. I've switched to Caddy+Hugo for my blog. Setting up the Caddy web server was trivial and immediately gave me a HTTPS enabled site. Subsequent changes to my Caddy web server config was far simpler than any change I made to my Apache web server config.

I appreciate that this project has to support a lot of baggage from earlier releases in order to avoid gratuitously breaking existing uses. But fixing this issue by incorporating my change wouldn't break any existing use other than the most pathological. That this is still broken tells me the project is dead.

Eric Covener (or anyone else) may I ask what is hindering this patch from being processed? We just fell in the same trap of not being able to reproduce the binary data dumped to investigate a bug.