... which is not important enough for me to tackle it right now, in
particular because I really do not understand enough about how this code
works yet, e.g. which of the if() blocks can possibly happen in which
order. *cough* fsm? *cough*

This was already the behavior before #3468, but then the filtering was
moved to libvarnishapi to prevent varnishncsa from duplicating the logic
behind transaction collection.

Unfortunately, despite libvarnishapi's effort to not consider a client or
backend transaction without a Begin tag as a candidate, a transaction
missing one will get a synthetic Begin prior to dispatch.

Regardless, that would have only applied to vxid grouping so even if
varnishncsa was presented by default with only relevant transactions, it
could still see incomplete transactions in request grouping panic for
the same reason.

Fixes #3501

do someone a favor and reformat the VPI_vcl_fini() call.

Because ifp->fin basically gets output via "\t%s\n", this triggers my
OCD in a some other way ;), but I am not going down that rabbit hole
at this point...

We do not need to call trunc() to truncate a double into an integert.

Mark the intention for flexelint with a cast.

This change is based on the precondition that VRT_fail() should work
wherever we have a VRT_CTX and DTRT, see also previous.

on vcl_init {}
--------------

We already handled a "direct" VRT_fail() via a vmod function
correctly.  This commit adds a test.

Yet we can also VRT_fail() via a PRIV_TASK fini callback and did not
handle that case (triggered an assertion in VRT_fail()). Notice that
this case has worked in client / backend tasks for long and a test
case has been added with 746384b2 . It
has now gained relevance with 43d9e5fb

on vcl_fini {}
--------------

By design, vcl_fini {} must not fail, which is also why the only valid
return() value is "ok" (VCL_RET_OK).

Consequently, we had

	if (method && *ctx->handling && *ctx->handling != VCL_RET_OK) {
		assert(ev == VCL_EVENT_LOAD);

in vcl_send_event().

And then came VRT_fail().

If we wanted to sustain an assertion similar to the above, we would
need to require vmod authors to never call VRT_fail() from
VCL_MET_FINI - which would complicate code, be likely overlooked and
receive little to no test coverage.

So instead we now ignore errors during vcl_fini {} and emit a
VCL_error log line.

I considered the alternative to check for VCL_MET_FINI in VRT_fail(),
but decided to handle the exception where it applies, which is in
vcl_send_event().

I am aware that this part of the change may trigger some controversy
and I am open to discussing alternatives. If anything, we now avoid
unmotivated assertion failures triggered for the new tests in
v00051.vtc for the time being.

Ref 43d9e5fb :

PRIV_* fini methods need to leave (struct vrt_ctx).handling alone,
except that they might call VRT_fail(), see also
746384b2

Thus we add assertions that handling be either 0 or VCL_RET_FAIL
outside the FSM.

To be able to do so, we need to change VCL_RET_OK into 0 when
vcl_init{} has returned successfully.

The vcl_fini{} case is slightly more complicated:

By design, only "ok" (VCL_RET_OK) is allowed, but VRT_fail() also
added VCL_RET_FAIL, so we de-facto get a "fail" return if any vmod
code called VRT_fail().

Because PRIV_* handling happens from VCC generated code via
VGC_Discard(), we need to check and change (struct vrt_ctx).handling
right after calling vcl_fini{} / VGC_function_vcl_fini() from
VGC_Discard(). This is VPI_vcl_fini().

Implementation note:

I also considered void VPI_vcl_fini(VRT_CTX, vcl_func_f fini_sub),
having VPI_vcl_fini call the fini_sub, but that stirred up includes of
VPI where vcl.h is not included.

Though introduced for the purpose of failing upon rollback, they
actually just call VRT_fail() from the PRIV_* fini callback and thus
should be named accordingly.

Not sure where things went wrong on this...

Only if strtoll(3) stumbled upon a VNUM special character.

Fixes #3463

forgotten static declaration

The time_t t variable is not guaranteed to have a specific size, so
instead we use a dedicated long l variable. The explicit cast from
double is also restored, spotted by flexelint.

Refs #3499

The option was present in libvarnishapi but never exposed.

And remove [bcE]_opt handling entirely out of varnishncsa, relying on
libvarnishapi to do this filtering. As such we can consolidate the tag
management without backend marker fiddling.

This doesn't change the behavior of varnishncsa that already ignores ESI
sub-requests unless the -E option is specified. This is however breaking
the default behavior of other VSL processing tools that gained the -E
option, aligning with varnishncsa's behavior. Except varnishhist, that
gained the E filter in its -P argument instead of the -E option.

This allows to also not collect ESI transactions in VXID mode to further
reduce churn and reduce the risk for overruns in varnishncsa.

But paced, because they may repeat in a semi-tight loop.

For high-throughput scenarios we might be collecting irrelevant
transactions, especially sessions that are never buffered, and
drastically increase the risk of overruns with long-running
sessions (typically when varnishd is behind a load balancer or
a TLS terminator that we can entrust with high client connection
reuse).

The -b and -c options have an effect on the output, which is way
too late for such a setup. These options primarily work with the
MSB backend and client markers but that is not enough to rule out
sessions since they are marked as client transactions. The same
goes for incomplete transactions for which we are lacking a Begin
tag, that would still be ruled out at the output stage.

We also need to collect irrelevant transactions for the sake of
grouping, because even when we do not wish to output them we have
to maintain the hierarchy.

Therefore, we can identify candidate transactions early and not
waste memory footprint and churn keeping track of transactions
that would have no effect besides increasing the risk of overruns.

Otherwise the combination of -E and -b only outputs backend requests.

we take the chance of the breaking change in
681c1199 to also add a VRT_CTX
argument to vmod_priv_fini_f. This allows a vmod_priv fini function,
for example, access to the request or simpler and better logging
(because the task's vsl buffer can be used where otherwise only
unbuffered vsl was possible).

    Implementation:

The meat of this commit really only is the change to the
vmod_priv_fini_f typedef and VRT_priv_fini().

All other changes are either to bundled vmods or the straight forward
infrastructure to make available a ctx to VRT_priv_fini(), which, for
client and backend context, is called via VCL_TaskLeave().

Consequently, it made sense to also change the signature
Req_Rollback() and Bereq_Rollback().

Instead of triggering a WRONG() panic, we now fail the VCL when any vmod
function with PRIV_TOP argument(s) is present in a sub called from
outside client context.

Note that the VCL failure happens not when the vmod function with the
PRIV_TOP argument is called, but rather when the containing SUB is
called. This is because we prepare PRIV_TOP arguments in the function
preamble.

Fixes #3498

This is how 08b642d7 should have looked
like.

and add vtc code to avoid it from happening again.

The mentioned commit lead to resolve=NOW modify the shard's parameter
PRIV_TASK when only parameters on the stack should have been modified.

We will adjust this to use shard_param_task_r() in a follow-up

Spotted thanks to Coverity, ref CID 1472212

Propagate upwards any workspace allocation failure of the
recursive shard_param_task_l() case.

We use shard_param_task_{r,l} on (struct sharddir *) and (struct
vmod_directors_shard_param *), so the id parameter is (const void *).
Yet we still want to make sure that we always retrieve the intended
PRIV_TASK, and we can by simply asserting that the vcl_name attribute
matches.

Note that a simple pointer comparison is sufficient here because,
unltimately, the PRIV_TASK vcl_name is always that of a vmod object,
assigned by the constructor.

This brings back the "who" parameter from
9ea2f29f, but used differently.

When a VUT is slow enough, it might very well be overrun while it is
scanning logs. For our built-in VUTs like varnishncsa or varnishlog
this can happen if writing the output can block waiting for IO ops
or when the output is piped to a slow consumer.

There's only one call site for vtx_dispatch() and it guarantees that len
is greater than zero.

Allow the user to log the request time in milliseconds through the new
format specifier: %{ms}T .
Signed-off-by: Asad Sajjad Ahmed <asadsa@varnish-software.com>

7da412fa at work

This removes logging from xid 0 and makes clearer what is happening