Bug 57045 - dumpio output strings are missing
Summary: dumpio output strings are missing
Status: NEW
Alias: None
Product: Apache httpd-2
Classification: Unclassified
Component: mod_dumpio (show other bugs)
Version: 2.4.16
Hardware: All All
: P2 normal (vote)
Target Milestone: ---
Assignee: Apache HTTPD Bugs Mailing List
URL:
Keywords: PatchAvailable, PortBack
Depends on:
Blocks:
 
Reported: 2014-09-30 01:28 UTC by HK.Bae
Modified: 2018-03-06 02:21 UTC (History)
1 user (show)



Attachments
fixed mod_dumpio.c module (11.54 KB, text/plain)
2015-10-05 01:48 UTC, Kurtis Rader
Details
Patch against 2.4.16 (14.63 KB, patch)
2015-10-05 02:30 UTC, Kurtis Rader
Details | Diff
Program to decode output of fixed mod_dumpio (3.68 KB, text/plain)
2015-10-05 03:10 UTC, Kurtis Rader
Details
Patch against 2.4.16 (26.28 KB, patch)
2015-10-12 01:00 UTC, Kurtis Rader
Details | Diff
fixed mod_dumpio.c module (12.92 KB, text/plain)
2015-10-12 01:01 UTC, Kurtis Rader
Details
Program to decode output of fixed mod_dumpio (4.62 KB, text/plain)
2015-10-12 01:04 UTC, Kurtis Rader
Details

Note You need to log in before you can comment on or make changes to this bug.
Description HK.Bae 2014-09-30 01:28:25 UTC
I installed the mod_dumpio, and getting request and reponse information from error.log.
But in case of "GIF"(image) file, output bytes are missing.

(Example) test.gif
①[binary of gif] ...d8 ff e0 00 10 4a 46 49 46 00 01 01 01 00 48 00...
②[dumpio_out log] ...4a 46 49 46...
※Therefore, binary source data("d8 ff e0 00 10","00 01 01 01 00 48 00") are missing.

It seems that this occur in all image file (not only gif).

Is there any solution of getting all binary bytes of image file?
(apache or mod_dumpio's setting?)

Thank you very much for your help.
Comment 1 Christophe JAILLET 2015-04-04 20:10:15 UTC
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?
Comment 2 Kurtis Rader 2015-10-05 01:37:57 UTC
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/
Comment 3 Kurtis Rader 2015-10-05 01:46:03 UTC
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.
Comment 4 Kurtis Rader 2015-10-05 01:48:05 UTC
Created attachment 33162 [details]
fixed mod_dumpio.c module
Comment 5 Kurtis Rader 2015-10-05 02:30:11 UTC
Created attachment 33163 [details]
Patch against 2.4.16
Comment 6 Kurtis Rader 2015-10-05 03:10:21 UTC
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

=#==#==#==#==#==#==#==#==#==#==#==#==#==#==#==#==#==#==#==#==#==#==#==#==#==#=
Comment 7 Yann Ylavic 2015-10-05 07:20:09 UTC
(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?
Comment 8 Kurtis Rader 2015-10-06 00:37:20 UTC
> 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.
Comment 9 Eric Covener 2015-10-06 01:40:22 UTC
> 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
Comment 10 Kurtis Rader 2015-10-12 01:00:56 UTC
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.
Comment 11 Kurtis Rader 2015-10-12 01:01:46 UTC
Created attachment 33180 [details]
fixed mod_dumpio.c module
Comment 12 Kurtis Rader 2015-10-12 01:04:40 UTC
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 13 Eric Covener 2015-10-12 01:11:42 UTC
Comment on attachment 33180 [details]
fixed mod_dumpio.c module

Can you please post changes as diff -u output?
Comment 14 Kurtis Rader 2015-10-12 01:22:15 UTC
"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.
Comment 15 Eric Covener 2015-10-12 01:34:49 UTC
(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.
Comment 16 Kurtis Rader 2015-10-12 01:41:35 UTC
> 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.
Comment 17 Kurtis Rader 2018-03-06 02:21:40 UTC
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.