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 2024/08/16 09:17:33 UTC
[Bug 69264] New: Broken entries in forensic log (start missing)
https://bz.apache.org/bugzilla/show_bug.cgi?id=69264
Bug ID: 69264
Summary: Broken entries in forensic log (start missing)
Product: Apache httpd-2
Version: 2.4.61
Hardware: PC
OS: Linux
Status: NEW
Severity: normal
Priority: P2
Component: mod_log_forensic
Assignee: bugs@httpd.apache.org
Reporter: G.Jaekel@DNB.DE
Target Milestone: ---
The expected (and hardcoded) format of the forensic log entire consist of
* the marker char '+' or '-'
* the unique id of the request
* the request line, prefixed with the delimiter '|'
* all request header lines, prefixed with the delimiter '|'
On our Apache httpd's uses as reverse proxies, I actually observed "broken"
entries in the log:
* There are lines that just contain the tail of the expected log line (which is
a long query string)
* All this broken tails are exactly 4k in site
I take a look on the source (httpd/modules/loggers/mod_log_forensic.c), but I
can't imagine any code issue resulting into this strange behavior.
--
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 69264] Broken entries in forensic log (start missing)
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=69264
Guido Jäkel <G....@DNB.DE> changed:
What |Removed |Added
----------------------------------------------------------------------------
Hardware|PC |Other
--- Comment #3 from Guido Jäkel <G....@DNB.DE> ---
As a reference, some undamaged log lines. The first is a "working one" of the
kind that is sometime damaged.
root@prodchi0 ~ # head forensic.log.20240814-003715.log
20240814-003715.000189|+ZrvgGxomNW9XyoUwnxNMeQAAAME|GET
/pica-record-tree-service/records/idn/1195408781?&l=039B%25239%253E0%252821A%257C39B%2529%25239&l=013%255BDE%255D%25239&l=022A%2528%252F01%2529?%25239&l=028A%25239%253E028R%25239&l=028C%2528%252F09%2529?%25239%253E028R%25239&l=029A%25239%253E%2528029%257C030%257C065%2529R%25239&l=029F%2528%252F09%2529?%25239%253E%2528029%257C030%257C065%2529R%25239&l=036H%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E021A%25239%253E004E%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E021A%25239%253E02%255B89%255DA%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E021A%25239%253E02%25288C%257C9F%2529%2528%252F09%2529?%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E021A%25239%253E033%255BAD%255D%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E021A%25239%253E041A%2528%252F%255B0-9%255D%255B0-5%255D%2529?%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E021A%25239%253E041A%2528%252F%255B0-9%255D%255B0-5%255D%2529?%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E021A%25239%253E041A%2528%252F%255B0-9%255D%255B0-5%255D%2529?%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E021A%25239%253E044G%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E021A%25239%253E044%255BHK%255D%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E021A%25239%253E044%255BHK%255D%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E021A%25239%253E044%255BHK%255D%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E039B%25239%253E013D%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E039B%25239%253E021A%25239%253E033%255BAD%255D%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E039B%25239%253E02%255B89%255DA%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E039B%25239%253E02%25288C%257C9F%2529%2528%252F09%2529?%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E039B%25239%253E033%255BAD%255D%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E039B%25239%253E039B%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E039B%25239%253E041A%2528%252F%255B0-9%255D%255B0-5%255D%2529?%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E039B%25239%253E041A%2528%252F%255B0-9%255D%255B0-5%255D%2529?%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E039B%25239%253E041A%2528%252F%255B0-9%255D%255B0-5%255D%2529?%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E039B%25239%253E044%255BHK%255D%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E039B%25239%253E044%255BHK%255D%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E039B%25239%253E044%255BHK%255D%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=039E%25239%253E021A%25239&l=041A%2528%252F%255B0-9%255D%255B0-5%255D%2529?%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=041A%2528%252F%255B0-9%255D%255B0-5%255D%2529?%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=041A%2528%252F%255B0-9%255D%255B0-5%255D%2529?%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=044G%25239&l=044%255BHK%255D%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=044%255BHK%255D%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=044%255BHK%255D%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=044P%2528%252F0%255B1-9%255D%2529?%25239%253E%2528029%257C030%257C065%2529R%25239&l=045P%25239&l=07%255B01%255D%255BBDNP%255D%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239
HTTP/1.1|Host:etc.dnb.de|Connection:Keep-Alive|User-Agent:Apache-HttpClient/4.5.13
(Java/17.0.12)
20240814-003715.000871|-ZrvgGpvvk1EExc8DKUceZAAAAJ4
20240814-003715.001324|+ZrvgG8bPOhrfFHs-fLqyDAAAAVk|GET
/catmir/api/v1/records/idn/1195408781
HTTP/1.1|Host:etc.dnb.de|Connection:Keep-Alive|User-Agent:Apache-HttpClient/4.5.13
(Java/17.0.12)
20240814-003715.001877|-ZrvgGq_yvmQt7JfNhSyrIgAAAAQ
20240814-003715.002037|-ZrvgG8bPOhrfFHs-fLqyDAAAAVk
20240814-003715.002469|+ZrvgGxomNW9XyoUwnxNMegAAAOg|GET
/solr/zdb.cur/select?rows=4000&q=recordType%253ATITLE+AND+issn%253A0957-4239+AND+-frm%253AO&sort=titel_sort+asc&wt=javabin&version=2
HTTP/1.1|User-Agent:Solr[org.apache.solr.client.solrj.impl.HttpSolrServer]
1.0|Host:etc.dnb.de|Connection:Keep-Alive
20240814-003715.002553|+ZrvgG8bPOhrfFHs-fLqyDQAAAVk|GET
/catmir/api/v1/records/idn/019711913
HTTP/1.1|Host:etc.dnb.de|Connection:Keep-Alive|User-Agent:Apache-HttpClient/4.5.13
(Java/17.0.12)
20240814-003715.002762|+ZrvgG8bPOhrfFHs-fLqyDgAAAWc|GET
/pica-record-tree-service/records/idn/1316313271?&
HTTP/1.1|Host:etc.dnb.de|Connection:Keep-Alive|User-Agent:Apache-HttpClient/4.5.13
(Java/17.0.12)
20240814-003715.004400|-ZrvgGxomNW9XyoUwnxNMegAAAOg
20240814-003715.004688|+ZrvgG6_yvmQt7JfNhSyrIwAAAAQ|GET
/catmir/api/v1/records/idn/1316313271
HTTP/1.1|Host:etc.dnb.de|Connection:Keep-Alive|User-Agent:Apache-HttpClient/4.5.13
(Java/17.0.12)
--
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 69264] Broken entries in forensic log (start missing)
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=69264
--- Comment #29 from Guido Jäkel <G....@DNB.DE> ---
Oh, let's clarify: In case of splitting the log lines, should we use the
continuation symbol for
A) all lines but the last (>,>,>,+)
B) all lines but the first (+,>,>,>)
The first give a forward promise and therefore it's reliable to process by the
consumer. But is a breaking change in semantics concerning the "start of
request". However, in case of the issue strikes at the moment, syntax and
semantic are much more broken.
The second will not break historic semantics "most of the time". But it's more
difficult to consume, because one will modify received information
retrospectively. And this without a final mark; this might break the promise of
"forensic logging". In this case, maybe we need a "final slice identifier" over
and beyond. Which lead to
C) Use a continuation and finality symbol (+,>,>,.)
I vote for A)
--
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 69264] Broken entries in forensic log (start missing)
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=69264
--- Comment #31 from Guido Jäkel <G....@DNB.DE> ---
Good point!
Let the algorithm use '>' instead of '+' whenever there's the need (because of
pipe mode) to send not the whole but just the leading part with a maximum size
of PIPE_BUF
--
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 69264] Broken entries in forensic log (start missing)
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=69264
--- Comment #14 from Ruediger Pluem <rp...@apache.org> ---
What happens with
ForensicLog "|/bin/sh -c \"cat > /usr/lib/apache2/logs/forensic-raw.log\""
Is this file corrupted as well?
--
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 69264] Broken entries in forensic log (start missing)
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=69264
--- Comment #21 from Guido Jäkel <G....@DNB.DE> ---
OK, the summary is: Writes to pipe are guaranteed to be atomic only for write
sizes smaller than PIPE_BUF, which is 4k and may be interleaved at the reader
otherwise; regardless if writing is blocking or not!
By comparing with the module mod_log_config used for access and error
logging, there seems to be some special handling about to ensure atomic writing
to pipes.
Should this be ported to mod_log_forensic?
--
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 69264] Broken entries in forensic log (start missing)
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=69264
--- Comment #8 from Guido Jäkel <G....@DNB.DE> ---
I've thought about Ruedigers suggestion to check if apr_file_write_full()
will report bytes written as commissioned.
I'm currently using apr-1.7.4. Staring at the goats, aeh code of
apr_file_write_full()
(https://github.com/apache/apr/blob/b4197909d26042ece777727cc6152deeea75a3ab/file_io/unix/fullrw.c#L42)
this uses a vanilla copy loop. I can't see any possibility either to return
successful; and then the calculated bytes_written MUST be the number of
nbytes instructed to transfer. Or to return unsuccessful with a different
value, which will be reported by the suggested patch.
But the end of the string is received and this CAN'T happen, if the loop exit
before reaching it's normal end. Therefore, it MUST have instructed to transfer
any slice before the end, including the start. In other words, I don't see any
logic to skip over some leading parts of the string.
The copy loop uses apr_file_write()
(https://github.com/apache/apr/blob/b4197909d26042ece777727cc6152deeea75a3ab/file_io/unix/readwrite.c#L147)
to do thew work. "Loosing" something to transfer while reporting it to be done
MUST be happen here. Therefore, IMHO it must be a bug or thread race condition
inside this much more complex code.
What do you think about?
--
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 69264] Broken entries in forensic log (start missing)
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=69264
--- Comment #24 from Ruediger Pluem <rp...@apache.org> ---
(In reply to Guido Jäkel from comment #21)
> OK, the summary is: Writes to pipe are guaranteed to be atomic only for
> write sizes smaller than PIPE_BUF, which is 4k and may be interleaved at the
> reader otherwise; regardless if writing is blocking or not!
>
> By comparing with the module mod_log_config used for access and error
> logging, there seems to be some special handling about to ensure atomic
> writing to pipes.
Having a look at this I can only see that this guarantees atomicity across
threads not across processes. Furthermore the core point of it seems to be to
buffer logs before writing and not to ensure general and overall atomicity.
--
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 69264] Broken entries in forensic log (start missing)
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=69264
--- Comment #1 from Guido Jäkel <G....@DNB.DE> ---
Edit:
* Most fragments are 4k. I found no longer, but there are shorter ones.
--
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 69264] Broken entries in forensic log (start missing)
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=69264
--- Comment #9 from Guido Jäkel <G....@DNB.DE> ---
TL;DR
* was yet able to reproduce it on evaluation stage with a brute force testcase:
Firing against "/server-status?auto&<about 800 chars>" with 1000 request in
parallel
* looks to be a race condition, happens "time to time" with about 10 hits per
run.
* appear using *ANY* piped output, in particular:
ForensicLog "|/bin/sh -c \"cat - | /usr/sbin/rotatelogs2 -l
/usr/lib/apache2/logs/forensic-raw.log.%Y%m%d 86401\""
ForensicLog "|/bin/sh -c \"/usr/sbin/rotatelogs2 -l
/usr/lib/apache2/logs/forensic-raw.log.%Y%m%d 86401\""
ForensicLog "|/usr/sbin/rotatelogs2 -l
/usr/lib/apache2/logs/forensic-raw.log.%Y%m%d 86401"
but seems *NOT* to happen using a file output
ForensicLog "/usr/lib/apache2/logs/forensic-raw.log"
BTW: It's not possible to use more than one forensic log; last ForensicLog
configuration tag wins.
--
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 69264] Broken entries in forensic log (start missing)
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=69264
--- Comment #25 from Ruediger Pluem <rp...@apache.org> ---
(In reply to Joe Orton from comment #23)
> I agree it should be evident somehow in the logs if interleaved writes are
> the issue. I would guess the second read() call is showing it in the strace
> output - it should be true that every read() call is on a "packet" boundary
> i.e. starts with a + or -. (Right?)
>
> read(0, "+ZsMivuUetIn_ZSVBVWzmeQAAAQo|GET"..., 131072) = 45786
> ...
> read(0, "nt:Wget/1.21.4|Accept:*/*|Accept"..., 131072) = 16749
Out of curiosity: Why do we see reads much larger than the value of PIPE_BUF
which is 4096?
--
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 69264] Broken entries in forensic log (start missing)
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=69264
--- Comment #22 from Ruediger Pluem <rp...@apache.org> ---
Thanks for the additional insight Joe. But as you mention interleaved output
Guido probably should find lines in his log that have a '+' or '-' plus id in
the middle of a logline. Can these examples be found?
--
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 69264] Broken entries in forensic log (start missing)
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=69264
--- Comment #26 from Guido Jäkel <G....@DNB.DE> ---
To my understanding PIPE_BUF is not the size of the pipe buffer but just the
size to be guaranteed to be atomic. The POSIX-defined value is 512, an Linux
lift this to 4k.
But the usual pipe buffer size is bigger, the default on Linux seems to be 64k
(16 pages) and is configurable.
My test case request are about 8k. By a compare to the access log (piped to
rotatelog2, too, but undamaged!), it seems to me that different workers just
have put a whole bunch of individual log lines into the buffer. That is close
to the edge of the abyss and in the next moments, at least one worker can't
write it's logline in entirety.
--
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 69264] Broken entries in forensic log (start missing)
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=69264
--- Comment #28 from Guido Jäkel <G....@DNB.DE> ---
> IMO mod_log_forensic should split lines longer than PIPE_BUF with some continuation identifier + the ID.
(+1), maybe using a '>' (as a mnemonic to the PS1-prompt). It should be
possible to code this down in a clean way at top level at mod_log_forensic.c
.
--
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 69264] Broken entries in forensic log (start missing)
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=69264
--- Comment #19 from Joe Orton <jo...@redhat.com> ---
Sorry hit enter too soon, meant to add something useful.
With piped logging you are only guaranteed atomicity for writes <= 4K
(PIPE_BUF)
If mod_log_forensic is writing >4K per call then I think it would be expected
to have interleaved output seen by the piped logger.
--
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 69264] Broken entries in forensic log (start missing)
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=69264
--- Comment #20 from Guido Jäkel <G....@DNB.DE> ---
Dear Joe,
thank you for this *very* useful information. Would this mean, that offering
piped output by the Apache httpd *Logger is broken by design? Because even the
default for the accepted request line length is about 8k and there are
typically a whole bunch of other information logged together with it.
I use this kind of piped logging for the access (and error) logging for decades
but never notice this issue. In the other hand, most of the logs are never read
by eyes and other scripts using it may just skip over broken lines.
I stepped into this issue with the forensic log because I activated the
forensic log about one month before as a *tool* to investigate a problem
related to proxy requests to another application. And here my script to check
for the {+,-}uid-pairs bails out because of the leading char wasn't in this
set.
--
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 69264] Broken entries in forensic log (start missing)
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=69264
--- Comment #2 from Guido Jäkel <G....@DNB.DE> ---
Additional information:
To make it usable for us, the output of the forensic logger is piped though a
(pyhton) script that prepends a timestamp to every line:
ForensicLog "|/bin/sh -c \"/opt/apache/bin/timestamp-forensic |
/usr/sbin/rotatelogs2 -l /usr/lib/apache2/logs/forensic.log.%Y%m%d 86400\""
In core, this script will just prepend every line with the current timestamp
and the delimiter '|':
[...]
timestamp = f'{now:%Y%m%d-%H%M%S.%f}' # YYYYmmdd-HHMMSS.mmmuuu
line = timestamp + '|' + line
[...]
Therefore, all example logs will contain this timestamp. Please notice, that
this timestamp *is* recorded in the logfile. This means IMHO, that the piped
input to the script -- i.e. the output of mod_log_forensic -- is broken in the
described matter.
Example:
Because of the size of the forensic log, I used a pre-sliced part (one second,
selected by timestamp) for the following:
root@prodchi0 ~ # cat forensic.log.20240814-003715.log | grep '^.\{22\}|[+-].*'
-v | while read line; do printf "%4d %s\n\n" "$(echo -n "${line:23}" | wc -c)"
"$line"; done
4095
20240814-003715.504800|%255B289%255D%257C030%257C041%257C065%2529P%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E021A%25239%253E041A%2528%252F%255B0-9%255D%255B0-5%255D%2529?%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E021A%25239%253E041A%2528%252F%255B0-9%255D%255B0-5%255D%2529?%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E021A%25239%253E044G%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E021A%25239%253E044%255BHK%255D%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E021A%25239%253E044%255BHK%255D%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E021A%25239%253E044%255BHK%255D%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E039B%25239%253E013D%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E039B%25239%253E021A%25239%253E033%255BAD%255D%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E039B%25239%253E02%255B89%255DA%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E039B%25239%253E02%25288C%257C9F%2529%2528%252F09%2529?%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E039B%25239%253E033%255BAD%255D%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E039B%25239%253E039B%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E039B%25239%253E041A%2528%252F%255B0-9%255D%255B0-5%255D%2529?%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E039B%25239%253E041A%2528%252F%255B0-9%255D%255B0-5%255D%2529?%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E039B%25239%253E041A%2528%252F%255B0-9%255D%255B0-5%255D%2529?%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E039B%25239%253E044%255BHK%255D%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E039B%25239%253E044%255BHK%255D%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E039B%25239%253E044%255BHK%255D%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=039E%25239%253E021A%25239&l=041A%2528%252F%255B0-9%255D%255B0-5%255D%2529?%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=041A%2528%252F%255B0-9%255D%255B0-5%255D%2529?%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=041A%2528%252F%255B0-9%255D%255B0-5%255D%2529?%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=044G%25239&l=044%255BHK%255D%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=044%255BHK%255D%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=044%255BHK%255D%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=044P%2528%252F0%255B1-9%255D%2529?%25239%253E%2528029%257C030%257C065%2529R%25239&l=045P%25239&l=07%255B01%255D%255BBDNP%255D%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239
HTTP/1.1|Host:etc.dnb.de|Connection:Keep-Alive|User-Agent:Apache-HttpClient/4.5.13
(Java/17.0.12)
821
20240814-003715.504989|89%255D%257C030%257C041%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=044G%25239&l=044%255BHK%255D%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=044%255BHK%255D%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=044%255BHK%255D%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=044P%2528%252F0%255B1-9%255D%2529?%25239%253E%2528029%257C030%257C065%2529R%25239&l=045P%25239&l=07%255B01%255D%255BBDNP%255D%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239
HTTP/1.1|Host:etc.dnb.de|Connection:Keep-Alive|User-Agent:Apache-HttpClient/4.5.13
(Java/17.0.12)
4095
20240814-003715.505030|%255B289%255D%257C030%257C041%257C065%2529P%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E021A%25239%253E041A%2528%252F%255B0-9%255D%255B0-5%255D%2529?%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E021A%25239%253E041A%2528%252F%255B0-9%255D%255B0-5%255D%2529?%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E021A%25239%253E044G%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E021A%25239%253E044%255BHK%255D%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E021A%25239%253E044%255BHK%255D%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E021A%25239%253E044%255BHK%255D%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E039B%25239%253E013D%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E039B%25239%253E021A%25239%253E033%255BAD%255D%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E039B%25239%253E02%255B89%255DA%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E039B%25239%253E02%25288C%257C9F%2529%2528%252F09%2529?%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E039B%25239%253E033%255BAD%255D%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E039B%25239%253E039B%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E039B%25239%253E041A%2528%252F%255B0-9%255D%255B0-5%255D%2529?%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E039B%25239%253E041A%2528%252F%255B0-9%255D%255B0-5%255D%2529?%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E039B%25239%253E041A%2528%252F%255B0-9%255D%255B0-5%255D%2529?%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E039B%25239%253E044%255BHK%255D%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E039B%25239%253E044%255BHK%255D%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=039%255BBCDHISTUXYZ%255D%25239%253E039B%25239%253E044%255BHK%255D%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=039E%25239%253E021A%25239&l=041A%2528%252F%255B0-9%255D%255B0-5%255D%2529?%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=041A%2528%252F%255B0-9%255D%255B0-5%255D%2529?%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=041A%2528%252F%255B0-9%255D%255B0-5%255D%2529?%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=044G%25239&l=044%255BHK%255D%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=044%255BHK%255D%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=044%255BHK%255D%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529R%25239%253E%252802%255B289%255D%257C030%257C041%257C065%2529P%25239&l=044P%2528%252F0%255B1-9%255D%2529?%25239%253E%2528029%257C030%257C065%2529R%25239&l=045P%25239&l=07%255B01%255D%255BBDNP%255D%25239%253E%252802%255B89%255D%257C030%257C065%2529R%25239
HTTP/1.1|Host:etc.dnb.de|Connection:Keep-Alive|User-Agent:Apache-HttpClient/4.5.13
(Java/17.0.12)
Occurrences are searched by
root@prodchi0 ~ # bzcat ~apache/logs/forensic.log.20240814.prodchi0.bz2 | grep
'^.\{22\}|[+-]' -v -o
--
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 69264] Broken entries in forensic log (start missing)
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=69264
--- Comment #4 from Rainer Jung <ra...@kippdata.de> ---
For the sake of completeness: which Linux distribution and version are you
using?
Does the truncation happen whenever the line is longer than 4KB (even
reproducible for single requests without any additional load), or just for some
of them or only under high load?
Maybe it is a pipe buffer problem. So can you check, whether the problem only
happens when using piped logging, but not when using direct logging to file.
Yes, you will loose your added timestamp, but depending on reproducibility you
might be able to check on a test system.
I would hope, it happens only when using piped logging.
Then you could next check by using "cat" instead of your python script. This
would tell us, if python or the exact way how the read from the pipe is
relevant here.
Let us know your findings.
Thanks,
Rainer
--
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 69264] Broken entries in forensic log (start missing)
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=69264
--- Comment #5 from Guido Jäkel <G....@DNB.DE> ---
Dear Rainer, (nice to read you again!)
A) that's on Gentoo Linux
root@prodchi0 ~ # apache2 -V
Server version: Apache/2.4.61 (Unix)
Server built: Jul 16 2024 15:50:16
Server's Module Magic Number: 20120211:134
Server loaded: APR 1.7.4, APR-UTIL 1.6.3, PCRE 10.42 2022-12-11
Compiled using: APR 1.7.4, APR-UTIL 1.6.3, PCRE 10.42 2022-12-11
Architecture: 64-bit
Server MPM: worker
threaded: yes (fixed thread count)
forked: yes (variable process count)
root@prodchi0 ~ # /lib/libc.so.6
GNU C Library (Gentoo 2.38-r10 (patchset 10)) stable release version 2.38.
Copyright (C) 2023 Free Software Foundation, Inc.
This is free software; see the source for copying conditions.
There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A
PARTICULAR PURPOSE.
Compiled by GNU CC version 13.2.1 20230826.
libc ABIs: UNIQUE IFUNC ABSOLUTE
Minimum supported kernel: 3.2.0
For bug reporting instructions, please see:
<https://bugs.gentoo.org/>
root@prodchi0 ~ # uname -a
Linux prodchi0 6.6.13-gentoo #1 SMP PREEMPT_DYNAMIC Mon Jan 29 13:22:19 CET
2024 x86_64 Intel(R) Xeon(R) Gold 6348 CPU @ 2.60GHz GenuineIntel GNU/Linux
B) As stated in my first comment, I was wrong with "always 4K tail". It takes a
lot of time to investigate, e.g.
root@prodchi0 ~ # bzcat ~apache/logs/forensic.log.20240814.prodchi0.bz2 |
grep '^.\{22\}|[^+-]' -o
run for more than 2h and got 229 matches in the 100GB+ logfile of a day.
C) Of course, using 'cat' instead of the script is the obvious cross check. It
seems that one may use the tag ForensicLog more than once. But I discoverd this
in production, yet. And I will not change configuration on Friday ;)
D) Yes, there are unhurt request with bigger size in this second snippet:
root@prodchi0 ~ # cat forensic.log.20240814-003715+1s | grep '^.\{22\}|[+-].*'
| while read line; do printf "%4d %s\n" "$(echo -n "${line:23}" | wc -c)"
"${line:0:120}"; done | grep '^[^ ]'
4917 20240814-003715.000189|+ZrvgGxomNW9XyoUwnxNMeQAAAME|GET
/pica-record-tree-service/records/idn/1195408781?&l=039B%25239%2
4917 20240814-003715.008977|+ZrvgG8bPOhrfFHs-fLqyDwAAAWc|GET
/pica-record-tree-service/records/idn/1316313271?&l=039B%25239%2
4917 20240814-003715.014844|+ZrvgG5vvk1EExc8DKUceaAAAAIE|GET
/pica-record-tree-service/records/idn/1188016385?&l=039B%25239%2
4917 20240814-003715.018350|+ZrvgGxomNW9XyoUwnxNMfQAAAMM|GET
/pica-record-tree-service/records/idn/1316314073?&l=039B%25239%2
3889 20240814-003715.018897|+ZrvgG6_yvmQt7JfNhSyrLAAAABo|GET
/solr/zdb.cur/select?q=%2528%2528idn%253A%2522020587090%2522%252
4917 20240814-003715.019854|+ZrvgG6_yvmQt7JfNhSyrLgAAAAw|GET
/pica-record-tree-service/records/idn/1162987855?&l=039B%25239%2
4917 20240814-003715.076174|+ZrvgG8bPOhrfFHs-fLqyLAAAAWc|GET
/pica-record-tree-service/records/idn/1191012158?&l=039B%25239%2
4917 20240814-003715.099268|+ZrvgGxomNW9XyoUwnxNMkwAAAMM|GET
/pica-record-tree-service/records/idn/1316312852?&l=039B%25239%2
4917 20240814-003715.110062|+ZrvgGxomNW9XyoUwnxNMlwAAAOo|GET
/pica-record-tree-service/records/idn/1316313654?&l=039B%25239%2
4917 20240814-003715.126454|+ZrvgGxomNW9XyoUwnxNMpAAAAME|GET
/pica-record-tree-service/records/idn/1316314103?&l=039B%25239%2
4985 20240814-003715.171781|+ZrvgG5vvk1EExc8DKUceogAAAIE|GET
/pica-record-tree-service/records/idn/1331403707?&l=004E%25239&l
4917 20240814-003715.171823|+ZrvgG6_yvmQt7JfNhSyraAAAAAw|GET
/pica-record-tree-service/records/idn/1316313298?&l=039B%25239%2
4917 20240814-003715.174852|+ZrvgG5vvk1EExc8DKUcepAAAALY|GET
/pica-record-tree-service/records/idn/1316314618?&l=039B%25239%2
4917 20240814-003715.175468|+ZrvgGxomNW9XyoUwnxNMtgAAAMM|GET
/pica-record-tree-service/records/idn/1316311988?&l=039B%25239%2
4917 20240814-003715.266864|+ZrvgGxomNW9XyoUwnxNM1QAAAMM|GET
/pica-record-tree-service/records/idn/1316312895?&l=039B%25239%2
4917 20240814-003715.336546|+ZrvgG5vvk1EExc8DKUceuwAAALY|GET
/pica-record-tree-service/records/idn/1193920922?&l=039B%25239%2
4917 20240814-003715.336940|+ZrvgG6_yvmQt7JfNhSyrlwAAAAw|GET
/pica-record-tree-service/records/idn/1164568914?&l=039B%25239%2
4917 20240814-003715.337439|+ZrvgG8bPOhrfFHs-fLqyXAAAAWc|GET
/pica-record-tree-service/records/idn/1191818071?&l=039B%25239%2
4917 20240814-003715.337577|+ZrvgG5vvk1EExc8DKUcevAAAAIE|GET
/pica-record-tree-service/records/idn/1316313751?&l=039B%25239%2
4917 20240814-003715.367804|+ZrvgGxomNW9XyoUwnxNM4wAAAMM|GET
/pica-record-tree-service/records/idn/1316313328?&l=039B%25239%2
1131 20240814-003715.380396|+ZrvgG5vvk1EExc8DKUcexAAAAL4|GET
/solr/zdb.cur/select?q=%2528%2528zdb%253A40730-6%2529%2529+AND+%
4917 20240814-003715.402622|+ZrvgGxomNW9XyoUwnxNM5wAAAOo|GET
/pica-record-tree-service/records/idn/1190495406?&l=039B%25239%2
4917 20240814-003715.503091|+ZrvgG6_yvmQt7JfNhSyrqAAAABg|GET
/pica-record-tree-service/records/idn/1316313069?&l=039B%25239%2
4917 20240814-003715.503343|+ZrvgG4phZGR5Hqhtbq4NBgAAAEA|GET
/pica-record-tree-service/records/idn/1316314111?&l=039B%25239%2
4917 20240814-003715.503368|+ZrvgG5vvk1EExc8DKUceyAAAAIE|GET
/pica-record-tree-service/records/idn/1316314634?&l=039B%25239%2
4917 20240814-003715.503531|+ZrvgG5vvk1EExc8DKUceygAAALY|GET
/pica-record-tree-service/records/idn/1174980087?&l=039B%25239%2
4917 20240814-003715.503615|+ZrvgG6_yvmQt7JfNhSyrsQAAACQ|GET
/pica-record-tree-service/records/idn/1188101935?&l=039B%25239%2
4917 20240814-003715.504352|+ZrvgG8bPOhrfFHs-fLqydgAAAUM|GET
/pica-record-tree-service/records/idn/1316314952?&l=039B%25239%2
4124 20240814-003715.504822|+ZrvgGxomNW9XyoUwnxNM9QAAAME|GET
/pica-record-tree-service/records/idn/1182097413?&l=039B%25239%2
1172 20240814-003715.504886|+ZrvgG6_yvmQt7JfNhSyrwAAAABg|GET
/pica-record-tree-service/records/idn/1191012174?&l=039B%25239%2
4917 20240814-003715.557067|+ZrvgG6_yvmQt7JfNhSyr2QAAAAw|GET
/pica-record-tree-service/records/idn/1316313360?&l=039B%25239%2
4917 20240814-003715.559152|+ZrvgG5vvk1EExc8DKUce5gAAALY|GET
/pica-record-tree-service/records/idn/1316313778?&l=039B%25239%2
4917 20240814-003715.559169|+ZrvgG4phZGR5Hqhtbq4NGQAAAEA|GET
/pica-record-tree-service/records/idn/1316313077?&l=039B%25239%2
4917 20240814-003715.562256|+ZrvgG6_yvmQt7JfNhSyr3QAAACQ|GET
/pica-record-tree-service/records/idn/118758018X?&l=039B%25239%2
4917 20240814-003715.566267|+ZrvgG5vvk1EExc8DKUce6wAAAIE|GET
/pica-record-tree-service/records/idn/1316314642?&l=039B%25239%2
4917 20240814-003715.596460|+ZrvgGxomNW9XyoUwnxNNIAAAAOo|GET
/pica-record-tree-service/records/idn/1316314960?&l=039B%25239%2
4917 20240814-003715.605436|+ZrvgGxomNW9XyoUwnxNNKgAAAMM|GET
/pica-record-tree-service/records/idn/1316314316?&l=039B%25239%2
4917 20240814-003715.606380|+ZrvgG8bPOhrfFHs-fLqylgAAAUM|GET
/pica-record-tree-service/records/idn/1195408854?&l=039B%25239%2
4917 20240814-003715.665889|+ZrvgGxomNW9XyoUwnxNNMgAAAOo|GET
/pica-record-tree-service/records/idn/1194157254?&l=039B%25239%2
4917 20240814-003715.676628|+ZrvgGxomNW9XyoUwnxNNNgAAAMM|GET
/pica-record-tree-service/records/idn/1316313484?&l=039B%25239%2
4917 20240814-003715.679057|+ZrvgGxomNW9XyoUwnxNNOAAAAME|GET
/pica-record-tree-service/records/idn/1316315320?&l=039B%25239%2
4917 20240814-003715.679898|+ZrvgG5vvk1EExc8DKUce9wAAAIE|GET
/pica-record-tree-service/records/idn/1316313808?&l=039B%25239%2
1143 20240814-003715.692452|+ZrvgG6_yvmQt7JfNhSyr-gAAAB4|GET
/solr/zdb.cur/select?q=%2528%2528iss%253A%25220406-3317%2522%252
4917 20240814-003715.703431|+ZrvgG6_yvmQt7JfNhSyr_AAAACQ|GET
/pica-record-tree-service/records/idn/1191958957?&l=039B%25239%2
4917 20240814-003715.709873|+ZrvgG5vvk1EExc8DKUce-gAAALY|GET
/pica-record-tree-service/records/idn/1316313115?&l=039B%25239%2
4917 20240814-003715.731462|+ZrvgG8bPOhrfFHs-fLqyrQAAAUM|GET
/pica-record-tree-service/records/idn/1316314340?&l=039B%25239%2
4917 20240814-003715.788586|+ZrvgG5vvk1EExc8DKUcfDQAAALY|GET
/pica-record-tree-service/records/idn/131631538X?&l=039B%25239%2
4917 20240814-003715.794467|+ZrvgG8bPOhrfFHs-fLqyywAAAUM|GET
/pica-record-tree-service/records/idn/131631507X?&l=039B%25239%2
4917 20240814-003715.819418|+ZrvgGxomNW9XyoUwnxNNWAAAAOo|GET
/pica-record-tree-service/records/idn/1316314650?&l=039B%25239%2
4917 20240814-003715.823323|+ZrvgGxomNW9XyoUwnxNNWwAAAME|GET
/pica-record-tree-service/records/idn/1316313514?&l=039B%25239%2
4917 20240814-003715.823391|+ZrvgGxomNW9XyoUwnxNNXAAAAMM|GET
/pica-record-tree-service/records/idn/1316313891?&l=039B%25239%2
1139 20240814-003715.841709|+ZrvgG6_yvmQt7JfNhSysHwAAACk|GET
/solr/zdb.cur/select?q=%2528%2528all%253A%2522399-2%2522%2529%25
1117 20240814-003715.878720|+ZrvgG6_yvmQt7JfNhSysIwAAACU|GET
/solr/zdb.cur/select?q=%2528parallelEditionsOf%253A1235561704%25
4917 20240814-003715.893988|+ZrvgGxomNW9XyoUwnxNNbgAAAME|GET
/pica-record-tree-service/records/idn/1190508168?&l=039B%25239%2
4917 20240814-003715.896205|+ZrvgGxomNW9XyoUwnxNNcAAAAOo|GET
/pica-record-tree-service/records/idn/1191019845?&l=039B%25239%2
4917 20240814-003715.899004|+ZrvgGxomNW9XyoUwnxNNcwAAAMM|GET
/pica-record-tree-service/records/idn/1316315398?&l=039B%25239%2
4917 20240814-003715.899086|+ZrvgG8bPOhrfFHs-fLqy5QAAAUM|GET
/pica-record-tree-service/records/idn/1316315088?&l=039B%25239%2
4917 20240814-003715.930501|+ZrvgG5vvk1EExc8DKUcfLQAAALY|GET
/pica-record-tree-service/records/idn/1316315762?&l=039B%25239%2
4917 20240814-003715.948339|+ZrvgG6_yvmQt7JfNhSysNgAAACQ|GET
/pica-record-tree-service/records/idn/1316314677?&l=039B%25239%2
4917 20240814-003715.956818|+ZrvgG8bPOhrfFHs-fLqy6wAAAUM|GET
/pica-record-tree-service/records/idn/1316313603?&l=039B%25239%2
4917 20240814-003715.969492|+ZrvgGxomNW9XyoUwnxNNhgAAAMM|GET
/pica-record-tree-service/records/idn/1187714747?&l=039B%25239%2
4917 20240814-003715.989454|+ZrvgG6_yvmQt7JfNhSysQwAAAAw|GET
/pica-record-tree-service/records/idn/1316314359?&l=039B%25239%2
4917 20240814-003715.991755|+ZrvgG5vvk1EExc8DKUcfNgAAALY|GET
/pica-record-tree-service/records/idn/1316175936?&l=039B%25239%2
4652 20240814-003715.994138|+ZrvgG5vvk1EExc8DKUcfNwAAAIE|GET
/pica-record-tree-service/records/idn/1188164104?&l=039B%25239%2
--
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 69264] Broken entries in forensic log (start missing)
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=69264
--- Comment #27 from Guido Jäkel <G....@DNB.DE> ---
> But as you mention interleaved output Guido probably should find lines in his log that have a '+' or '-' plus id in the middle of a logline. Can these examples be found?
Yes:
root@evalchi0 /home/apache/logs # bzcat forensic.log.20240819.evalchi0.bz2 |
grep '.\{64\}[^|][+.]Z.\{64\}' -o | head -5
80019002000210022002300240025002600270028002900300031003200330034+ZsMPHepwt9kNnOLliNhz8gAAAoQ|GET
/server-status?462&00000001000200
80019002000210022002300240025002600270028002900300031003200330034+ZsMPHQNTtxIaN2SXchAmiwAAA4w|GET
/server-status?237&00000001000200
80019002000210022002300240025002600270028002900300031003200330034+ZsMPHbj-alsbBS_TBxfweAAAAws|GET
/server-status?292&00000001000200
80019002000210022002300240025002600270028002900300031003200330034+ZsMPHfJZyUlzOXi_bD539gAAAsk|GET
/server-status?142&00000001000200
80019002000210022002300240025002600270028002900300031003200330034+ZsMPHbj-alsbBS_TBxfwewAAAwo|GET
/server-status?205&00000001000200
There are hits with 2 or even more. The position difference of '+' is a
multiple of 4k -- q.e.d.
--
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 69264] Broken entries in forensic log (start missing)
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=69264
--- Comment #23 from Joe Orton <jo...@redhat.com> ---
I agree it should be evident somehow in the logs if interleaved writes are the
issue. I would guess the second read() call is showing it in the strace output
- it should be true that every read() call is on a "packet" boundary i.e.
starts with a + or -. (Right?)
read(0, "+ZsMivuUetIn_ZSVBVWzmeQAAAQo|GET"..., 131072) = 45786
...
read(0, "nt:Wget/1.21.4|Accept:*/*|Accept"..., 131072) = 16749
The pipe(7) man page has a good description of what is guaranteed under Linux:
https://man7.org/linux/man-pages/man7/pipe.7.html#DESCRIPTION
IMO mod_log_forensic should split lines longer than PIPE_BUF with some
continuation identifier + the ID.
--
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 69264] Broken entries in forensic log (start missing)
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=69264
--- Comment #12 from Guido Jäkel <G....@DNB.DE> ---
> [...] to do an strace at least on a cat as piped logger when you trigger the issue?
Yes. And it's very helpfull that strace will log the start of the transfer
buffer, therefore I may easy grep for the issue
root@evalchi0 ~ # strace -p $(pidof cat) |& grep '^read(0, "[^+-].*' -C 100
[...]
read(0, "+ZsMivsuSwNHur0hj7aodBQAAAN8|GET"..., 131072) = 4169
write(1, "+ZsMivsuSwNHur0hj7aodBQAAAN8|GET"..., 4169) = 4169
read(0, "-ZsMivsuSwNHur0hj7aodBQAAAN8\n", 131072) = 29
write(1, "-ZsMivsuSwNHur0hj7aodBQAAAN8\n", 29) = 29
read(0, "+ZsMivsuSwNHur0hj7aodBgAAAOA|GET"..., 131072) = 4169
write(1, "+ZsMivsuSwNHur0hj7aodBgAAAOA|GET"..., 4169) = 4169
read(0, "-ZsMivsuSwNHur0hj7aodBgAAAOA\n", 131072) = 29
write(1, "-ZsMivsuSwNHur0hj7aodBgAAAOA\n", 29) = 29
read(0, "+ZsMivgkXP1vN9VDpGpvjHAAAAYA|GET"..., 131072) = 4169
write(1, "+ZsMivgkXP1vN9VDpGpvjHAAAAYA|GET"..., 4169) = 4169
read(0, "-ZsMivgkXP1vN9VDpGpvjHAAAAYA\n", 131072) = 29
write(1, "-ZsMivgkXP1vN9VDpGpvjHAAAAYA\n", 29) = 29
read(0, "+ZsMivuf4wKS6QGLKaPMsYAAAALc|GET"..., 131072) = 4169
write(1, "+ZsMivuf4wKS6QGLKaPMsYAAAALc|GET"..., 4169) = 4169
read(0, "-ZsMivuf4wKS6QGLKaPMsYAAAALc\n", 131072) = 29
write(1, "-ZsMivuf4wKS6QGLKaPMsYAAAALc\n", 29) = 29
read(0, "+ZsMivkurIDDJT8JX5gLBPgAAAH4|GET"..., 131072) = 4169
write(1, "+ZsMivkurIDDJT8JX5gLBPgAAAH4|GET"..., 4169) = 4169
read(0, "-ZsMivkurIDDJT8JX5gLBPgAAAH4\n", 131072) = 29
write(1, "-ZsMivkurIDDJT8JX5gLBPgAAAH4\n", 29) = 29
read(0, "+ZsMivuUetIn_ZSVBVWzmeAAAAQk|GET"..., 131072) = 41690
write(1, "+ZsMivuUetIn_ZSVBVWzmeAAAAQk|GET"..., 41690) = 41690
read(0, "+ZsMivuUetIn_ZSVBVWzmeQAAAQo|GET"..., 131072) = 45786
write(1, "+ZsMivuUetIn_ZSVBVWzmeQAAAQo|GET"..., 45786) = 45786
read(0, "nt:Wget/1.21.4|Accept:*/*|Accept"..., 131072) = 16749
write(1, "nt:Wget/1.21.4|Accept:*/*|Accept"..., 16749) = 16749
read(0, "+ZsMivuUetIn_ZSVBVWzmiAAAARk|GET"..., 131072) = 8338
write(1, "+ZsMivuUetIn_ZSVBVWzmiAAAARk|GET"..., 8338) = 8338
read(0, "+ZsMivuUetIn_ZSVBVWzmigAAARs|GET"..., 131072) = 20845
write(1, "+ZsMivuUetIn_ZSVBVWzmigAAARs|GET"..., 20845) = 20845
read(0, "+ZsMivuUetIn_ZSVBVWzmjwAAASA|GET"..., 131072) = 4169
write(1, "+ZsMivuUetIn_ZSVBVWzmjwAAASA|GET"..., 4169) = 4169
read(0, "-ZsMivuUetIn_ZSVBVWzmiAAAARk\n-Zs"..., 131072) = 87
write(1, "-ZsMivuUetIn_ZSVBVWzmiAAAARk\n-Zs"..., 87) = 87
read(0, "-ZsMivuUetIn_ZSVBVWzmhAAAARg\n-Zs"..., 131072) = 232
write(1, "-ZsMivuUetIn_ZSVBVWzmhAAAARg\n-Zs"..., 232) = 232
read(0, "-ZsMivuUetIn_ZSVBVWzmgAAAARE\n-Zs"..., 131072) = 145
write(1, "-ZsMivuUetIn_ZSVBVWzmgAAAARE\n-Zs"..., 145) = 145
read(0, "-ZsMivuUetIn_ZSVBVWzmdgAAAQI\n-Zs"..., 131072) = 87
write(1, "-ZsMivuUetIn_ZSVBVWzmdgAAAQI\n-Zs"..., 87) = 87
read(0, "-ZsMivuUetIn_ZSVBVWzmeQAAAQo\n-Zs"..., 131072) = 87
write(1, "-ZsMivuUetIn_ZSVBVWzmeQAAAQo\n-Zs"..., 87) = 87
read(0, "-ZsMivuUetIn_ZSVBVWzmdAAAAQM\n", 131072) = 29
write(1, "-ZsMivuUetIn_ZSVBVWzmdAAAAQM\n", 29) = 29
read(0, "-ZsMivuUetIn_ZSVBVWzmewAAAQw\n", 131072) = 29
write(1, "-ZsMivuUetIn_ZSVBVWzmewAAAQw\n", 29) = 29
read(0, "-ZsMivuUetIn_ZSVBVWzmbwAAAQQ\n-Zs"..., 131072) = 87
write(1, "-ZsMivuUetIn_ZSVBVWzmbwAAAQQ\n-Zs"..., 87) = 87
read(0, "-ZsMivuUetIn_ZSVBVWzmfgAAARA\n-Zs"..., 131072) = 87
write(1, "-ZsMivuUetIn_ZSVBVWzmfgAAARA\n-Zs"..., 87) = 87
read(0, "-ZsMivuUetIn_ZSVBVWzmfAAAAQ0\n-Zs"..., 131072) = 87
write(1, "-ZsMivuUetIn_ZSVBVWzmfAAAAQ0\n-Zs"..., 87) = 87
read(0, "+ZsMivt0Q__bu8pdN0ojr1QAAADM|GET"..., 131072) = 4169
write(1, "+ZsMivt0Q__bu8pdN0ojr1QAAADM|GET"..., 4169) = 4169
[...]
--
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 69264] Broken entries in forensic log (start missing)
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=69264
--- Comment #30 from Joe Orton <jo...@redhat.com> ---
I agree that (A) makes most sense from my understanding of the module (I'm not
also proposing to implement it, sorry). I agree that changing the syntax is
necessary for reliability, though it could be done only for piped loggers since
it's likely that file-based write()s are atomic even for larger buffer sizes.
--
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 69264] Broken entries in forensic log (start missing)
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=69264
--- Comment #10 from Ruediger Pluem <rp...@apache.org> ---
I agree that my proposed patch will not help debugging as I missed the point
that the tail is always received.
apr_file_write isn't that complicated in our case as the file descriptor is not
buffered and blocking. This reduces the code mainly to
https://github.com/apache/apr/blob/b4197909d26042ece777727cc6152deeea75a3ab/file_io/unix/readwrite.c#L188-L190
Is it possible for you to do an strace at least on a cat as piped logger when
you trigger the issue?
--
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 69264] Broken entries in forensic log (start missing)
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=69264
--- Comment #13 from Guido Jäkel <G....@DNB.DE> ---
Do we see an overflow here between httpd and cat caused by the downstream
'log2rotate' that waits for file I/O?
* The usual transfer size of 4196 rises a lot just before the issue
* The forensic-raw.log holds a bunch of undamaged log lines more on the
transfer starting with '+ZsMivuUetIn_ZSVBVWzmeAAAAQk' and
'+ZsMivuUetIn_ZSVBVWzmeQAAAQo'
and the damaged one starting with 'nt:Wget/1.21.4|Accept:*/*|Accept'
--
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 69264] Broken entries in forensic log (start missing)
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=69264
--- Comment #17 from Guido Jäkel <G....@DNB.DE> ---
May some explain me the for my eyes strange code starting at
https://github.com/apache/apr/blob/b4197909d26042ece777727cc6152deeea75a3ab/file_io/unix/readwrite.c#L200,
please.
What's the intention of '*nbytes /= 2' in L207, what happens with the other
bytes if the loop exits?
--
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 69264] Broken entries in forensic log (start missing)
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=69264
--- Comment #7 from Guido Jäkel <G....@DNB.DE> ---
(In reply to Ruediger Pluem from comment #6)
> Maybe the following temporary patch can help support debugging:
Dear Ruediger,
thank you! I'll apply this ASAP; because of using Gentoo this should be easy
doing.
There's already the
ap_assert(rv == APR_SUCCESS);
What's the result of it on failure? I can't find any corresponding in the main
error log.
--
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 69264] Broken entries in forensic log (start missing)
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=69264
--- Comment #15 from Guido Jäkel <G....@DNB.DE> ---
It's corrupted, too
[...]
read(0, "+ZsMuqZeRzfxMz44o0excwQAAA1k|GET"..., 1048576) = 4169
write(1, "+ZsMuqZeRzfxMz44o0excwQAAA1k|GET"..., 4169) = 4169
read(0, "-ZsMuqZeRzfxMz44o0excwQAAA1k\n", 1048576) = 29
write(1, "-ZsMuqZeRzfxMz44o0excwQAAA1k\n", 29) = 29
read(0, "+ZsMuqZx6pEyxkml1DpbpFAAAA5k|GET"..., 1048576) = 4169
write(1, "+ZsMuqZx6pEyxkml1DpbpFAAAA5k|GET"..., 4169) = 4169
read(0, "-ZsMuqZx6pEyxkml1DpbpFAAAA5k\n+Zs"..., 1048576) = 37695
write(1, "-ZsMuqZx6pEyxkml1DpbpFAAAA5k\n+Zs"..., 37695) = 37695
read(0, "-ZsMuqQGG_YaD2MHykiSmugAAAto\n-Zs"..., 1048576) = 25246
write(1, "-ZsMuqQGG_YaD2MHykiSmugAAAto\n-Zs"..., 25246) = 25246
read(0, "-ZsMuqWwqRYkLwg241R89mQAAA9s\n-Zs"..., 1048576) = 33337
write(1, "-ZsMuqWwqRYkLwg241R89mQAAA9s\n-Zs"..., 33337) = 33337
read(0, "+ZsMuqZx6pEyxkml1DpbpGAAAA50|GET"..., 1048576) = 33584
write(1, "+ZsMuqZx6pEyxkml1DpbpGAAAA50|GET"..., 33584) = 33584
read(0, "+ZsMuqZeRzfxMz44o0excxgAAA14|GET"..., 1048576) = 33584
write(1, "+ZsMuqZeRzfxMz44o0excxgAAA14|GET"..., 33584) = 33584
read(0, "+ZsMuqQGG_YaD2MHykiSmwAAAAt8|GET"..., 1048576) = 29183
write(1, "+ZsMuqQGG_YaD2MHykiSmwAAAAt8|GET"..., 29183) = 29183
read(0, "+ZsMuqZx6pEyxkml1DpbpHAAAA6E|GET"..., 1048576) = 33352
write(1, "+ZsMuqZx6pEyxkml1DpbpHAAAA6E|GET"..., 33352) = 33352
read(0, "+ZsMuqWwqRYkLwg241R89oAAAA-I|GET"..., 1048576) = 33555
write(1, "+ZsMuqWwqRYkLwg241R89oAAAA-I|GET"..., 33555) = 33555
read(0, "-ZsMuqWwqRYkLwg241R89nwAAA-E\n-Zs"..., 1048576) = 33482
write(1, "-ZsMuqWwqRYkLwg241R89nwAAA-E\n-Zs"..., 33482) = 33482
read(0, "-ZsMuqZx6pEyxkml1DpbpHQAAA6I\n+Zs"..., 1048576) = 33482
write(1, "-ZsMuqZx6pEyxkml1DpbpHQAAA6I\n+Zs"..., 33482) = 33482
read(0, "-ZsMuqQ2mMIXa35O5-UK7cwAAAyQ\n+Zs"..., 1048576) = 29386
write(1, "-ZsMuqQ2mMIXa35O5-UK7cwAAAyQ\n+Zs"..., 29386) = 29386
read(0, "+ZsMuqSMzHNYEYri_EZ1atQAAAqg|GET"..., 1048576) = 33555
write(1, "+ZsMuqSMzHNYEYri_EZ1atQAAAqg|GET"..., 33555) = 33555
read(0, "-ZsMuqZx6pEyxkml1DpbpIgAAA6c\n+Zs"..., 1048576) = 21077
write(1, "-ZsMuqZx6pEyxkml1DpbpIgAAA6c\n+Zs"..., 21077) = 21077
read(0, "-ZsMuqWwqRYkLwg241R89pQAAA-U\n-Zs"..., 1048576) = 261
write(1, "-ZsMuqWwqRYkLwg241R89pQAAA-U\n-Zs"..., 261) = 261
read(0, "-ZsMuqWwqRYkLwg241R89pwAAA-k\n-Zs"..., 1048576) = 16734
write(1, "-ZsMuqWwqRYkLwg241R89pwAAA-k\n-Zs"..., 16734) = 16734
read(0, "-ZsMuqQGG_YaD2MHykiSmyQAAAuk\n+Zs"..., 1048576) = 4576
write(1, "-ZsMuqQGG_YaD2MHykiSmyQAAAuk\n+Zs"..., 4576) = 4576
read(0, "nt:Wget/1.21.4|Accept:*/*|Accept"..., 1048576) = 102
write(1, "nt:Wget/1.21.4|Accept:*/*|Accept"..., 102) = 102
read(0, "-ZsMuqZx6pEyxkml1DpbpJAAAA6o\n-Zs"..., 1048576) = 116
write(1, "-ZsMuqZx6pEyxkml1DpbpJAAAA6o\n-Zs"..., 116) = 116
read(0, "-ZsMuqSMzHNYEYri_EZ1atwAAAqk\n-Zs"..., 1048576) = 58
write(1, "-ZsMuqSMzHNYEYri_EZ1atwAAAqk\n-Zs"..., 58) = 58
read(0, "-ZsMuqQ2mMIXa35O5-UK7dAAAAyU\n", 1048576) = 29
write(1, "-ZsMuqQ2mMIXa35O5-UK7dAAAAyU\n", 29) = 29
read(0, "-ZsMuqQ2mMIXa35O5-UK7dQAAAyc\n+Zs"..., 1048576) = 4227[...]
--
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 69264] Broken entries in forensic log (start missing)
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=69264
--- Comment #16 from Guido Jäkel <G....@DNB.DE> ---
It also happens using a output file on a (4GB) tmpfs
ForensicLog "|/bin/sh -c \"cat > /var/tmp/portage/forensic-raw.log\""
root@evalchi0 /home/apache/logs # df -h /var/tmp/portage/
Filesystem Size Used Avail Use% Mounted on
portage-tmp 4.0G 628M 3.4G 16% /var/tmp/portage
--
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 69264] Broken entries in forensic log (start missing)
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=69264
--- Comment #18 from Joe Orton <jo...@redhat.com> ---
That change came from bug 20295
--
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 69264] Broken entries in forensic log (start missing)
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=69264
--- Comment #6 from Ruediger Pluem <rp...@apache.org> ---
Maybe the following temporary patch can help support debugging:
Index: modules/loggers/mod_log_forensic.c
===================================================================
--- modules/loggers/mod_log_forensic.c (revision 1919740)
+++ modules/loggers/mod_log_forensic.c (working copy)
@@ -186,6 +186,7 @@
const char *id;
hlog h;
apr_status_t rv;
+ apr_size_t bw;
if (!cfg->fd || r->prev) {
return DECLINED;
@@ -220,7 +221,12 @@
ap_assert(h.pos < h.end);
*h.pos++ = '\n';
- rv = apr_file_write_full(cfg->fd, h.log, h.count-1, NULL);
+ rv = apr_file_write_full(cfg->fd, h.log, h.count-1, &bw);
+ if (rv != APR_SUCCESS) {
+ ap_log_rerror(APLOG_MARK, APLOG_DEBUG, rv, r,
+ "Short write. Only wrote %" APR_SIZE_T_FMT
+ " instead of %" APR_SIZE_T_FMT ".", bw, h.count-1);
+ }
ap_assert(rv == APR_SUCCESS);
apr_table_setn(r->notes, "forensic-id", id);
@@ -237,6 +243,7 @@
char *s;
apr_size_t n;
apr_status_t rv;
+ apr_size_t bw;
if (!cfg->fd || id == NULL) {
return DECLINED;
@@ -244,7 +251,12 @@
s = apr_pstrcat(r->pool, "-", id, "\n", NULL);
n = strlen(s);
- rv = apr_file_write_full(cfg->fd, s, n, NULL);
+ rv = apr_file_write_full(cfg->fd, s, n, &bw);
+ if (rv != APR_SUCCESS) {
+ ap_log_rerror(APLOG_MARK, APLOG_DEBUG, rv, r,
+ "Short write. Only wrote %" APR_SIZE_T_FMT
+ " instead of %" APR_SIZE_T_FMT ".", bw, n);
+ }
ap_assert(rv == APR_SUCCESS);
return OK;
--
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 69264] Broken entries in forensic log (start missing)
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=69264
--- Comment #11 from Guido Jäkel <G....@DNB.DE> ---
Sorry, for an important typo: I was using
"/server-status?auto&<about 8000 chars>"
but I already reduce it with "success" and the triggering border seems to be
exactly 4k (+/-1, have cross-check it) to for the *complete* log line including
the uid an the other tags.
--
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