[Varnish] #1330: VSL_Dispatch parameters 'fd' and 'spec' intermittently called with uninitialized values

[Varnish]

#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