varnish-bugs at varnish-cache
Jul 22, 2013, 8:02 AM
Post #1 of 1
(43 views)
Permalink
|
|
#1330: VSL_Dispatch parameters 'fd' and 'spec' intermittently called with uninitialized values
|
|
#1330: VSL_Dispatch parameters 'fd' and 'spec' intermittently called with
uninitialized values
-------------------+------------------------
Reporter: geoff | Type: defect
Status: new | Priority: high
Milestone: | Component: varnishlog
Version: 3.0.3 | Severity: major
Keywords: |
-------------------+------------------------
I've set 'component' to 'varnishlog', but it's actually about the logging
API.
I'm using the VSL_Dispatch callback in two tools to read from the log, and
for both of them, it's intermittently called with the argument fd ==
((unsigned) -1) and/or spec == 0, although the log entry unquestionably
belongs to a client or backend transaction (because the tag is something
like TxHeader or RxURL, and the content of the log payload is clearly
correct for the tag).
As a reminder: fd is the number that appears in the leftmost column of
varnishlog, and spec is reflected in varnishlog's 'c'/'b'/'-' column. spec
has the value VSL_S_CLIENT or VSL_S_BACKEND for the 'c' or 'b' cases.
To reproduce the error, it seems to be enough to let varnishd and a log-
reading tool run until one or the other value appears. varnishlog itself
frequently shows '-' in the 'c'/'b' column, although it's clearly either a
client or backend entry; but varnishlog simply passes over calls in which
fd > 65535 (and hence may be suppressing entries when fd is not set
correctly).
A number of things suggest to me that a memory barrier is lacking,
somewhere between writing these two values to the SHM log and reading
them, although I haven't been able to prove it by adding one of the V*MB()
calls to the code.
I've tried forcing core dumps when either of the two uninitialized values
are seen in VSL_Dispatch, but then when I read the core dump afterward,
the correct values are there. Also, when I use varnishlog -w to save SHM
contents to file, the correct values appear in the saved log although the
VSL_Dispatch call of another process saw the uninitialized value(s) for
the same entries. In both cases, the data in memory is evidently fresh by
the time it is written to file, but not when read for the call to
VSL_Dispatch.
And the problem appears to happen less often when Varnish is under a
heavier load. My guess is that under high load, the varnishd process,
writing to the SHM log, is consistently further ahead in the log than the
VSL reading process, so when the VSL reader "catches up", log contents
have had time to become fresh. But when the load is low, the VSL reader
accesses a location in the SHM log very soon after it has been written,
and thus is more likely to encounter stale data.
One of our two tools cannot work correctly unless the fd parameter has a
correct value, and it's seeing the uninitialized values on the order of
tens of thousands of times a day on a live site (in beta, so that the load
is still low). So the impact is fairly severe (not to mention the
information that users of varnishlog are presumably not seeing).
--
Ticket URL: <https://www.varnish-cache.org/trac/ticket/1330>
Varnish <https://varnish-cache.org/>
The Varnish HTTP Accelerator
_______________________________________________
varnish-bugs mailing list
varnish-bugs [at] varnish-cache
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-bugs
|
