v1d: Log client write error #4042

dridi · 2024-01-18T21:06:12Z

Some scenarios like hitting send_timeout because of a dripping write leaves no clue that an error occurred from the client request logs alone.

This introduces a client counterpart for:

FetchError backend write error: %d (%s) (%s)

Refs 49e44e3

dridi · 2024-01-22T14:54:35Z

Bugwash:

add SLT_DeliveryError
use it for "backend write error"
introduce "client write error"
collect feedback from production

nigoroll · 2024-01-22T14:58:16Z

bugwash:

The error is in the session VSL, but due to the impracticality of -g session, it is not particularly useful
SLT_Error is not a particularly good tag for this, because it is currently used for internal errors which can usually be addressed with VCL or changing parameters
we have FetchError, should add a DeliveryError tag and then use the former consistently for VFPs, and the latter for VDPs

dridi · 2024-01-22T15:03:53Z

SLT_Error is not a particularly good tag for this, because it is currently used for internal errors which can usually be addressed with VCL or changing parameters

nitpick: this can be addressed with send_timeout for that case, but point taken, there is nothing we can do when the client disconnects.

This is not quite a counterpart of FetchError that is used in more contexts than just a VFP.

This is not going through a VDP, but it eventually will. Refs varnishcache#4035

dridi · 2024-01-29T12:36:16Z

I'd like to cover this during bugwash today, before we send this to production.

include/tbl/vsl_tags.h

nigoroll · 2024-01-29T15:21:26Z

bin/varnishd/http1/cache_http1_deliver.c

-	if (sc != SC_NULL)
+	if (sc != SC_NULL) {
+		VSLb(req->vsl, SLT_DeliveryError, "resp: \"%s\" %d \"%s\"",
+		    sc->desc, errno, VAS_errtxt(errno));


I think we should use sc->name as with SessClose and add the long descriptions from include/tbl/sess_close.h to the documentation. Reason: name is shorter, less likely to change for editorial reasons and easier to parse (does not contain spaces). We should then also remove the quotes.

See 10f1e5c and #4047

I think we should use sc->name as with SessClose and add the long descriptions from include/tbl/sess_close.h

I'm all for logging the names, but against including the descriptions in the manual. "See other section" ought to be enough.

We should then also remove the quotes.

Once we switch to the name, that goes without saying :)

See 10f1e5c

I think we should instead add a section dedicated to session/stream close reasons in the manual and add some codegen to generate the RST from the sess_close.h table. Then all the tags that print a name can refer to that section and we avoid manual sync.

If you don't, I will.

That if statement should be based on whether sc is an error instead of not null.

I am happy with all your answers. In particular, moving the session close reasons to a separate docs section makes sense once they are no longer "owned" by SessClose.

I'm having second thoughts on the tag format and I'm wondering whether we should make it free form like FetchError so that any VDP could use DeliveryError to log errors?

That does not change my plans to address SessClose et al to use the name over the description and add a manual section.

How about the prefix (resp here) can be replaced by a VDP name and then the format is custom?

I thought about doing that, but I think I would rather keep the VDP prefix informal. The current "backend write error" prefix is very informal and unusual (and yet query-able) and should be improved, but generally it should be possible to issue DeliveryError logs outside of a VDP too, as long as it is related to delivery? Like FetchError today.

bugwash: It seems we actually agree on the alternative format <vdpname>: <error message free form>

bin/varnishd/http1/cache_http1_fetch.c

Motivated by #4042

this is for consistency, to simplify parsing and to reduce the amount of data logged with VSL. Motivated by varnishcache#4042

daghf · 2024-02-02T12:15:37Z

bionic failure,

cache/cache_expire.c: In function 'exp_inbox':
cache/cache_expire.c:282:61: error: format '%ld' expects argument of type 'long int', but argument 6 has type 'VCL_INT {aka long long int}' [-Werror=format=]
   VSLb(&ep->vsl, SLT_ExpKill, "EXP_Removed x=%ju t=%.0f h=%ld",
                                                           ~~^
                                                           %lld
cache/cache_expire.c:284:7:
       oc->hits);
       ~~~~~~~~                                               
cache/cache_expire.c: In function 'exp_expire':
cache/cache_expire.c:360:61: error: format '%ld' expects argument of type 'long int', but argument 6 has type 'VCL_INT {aka long long int}' [-Werror=format=]
   VSLb(&ep->vsl, SLT_ExpKill, "EXP_Expired x=%ju t=%.0f h=%ld",
                                                           ~~^
                                                           %lld
cache/cache_expire.c:362:7:
       oc->hits);
       ~~~~~~~~                                               
  CC       cache/varnishd-cache_fetch_proc.o
cache/cache_expire.c: At top level:
cc1: error: unrecognized command line option '-Wno-nullability-completeness' [-Werror]
cc1: error: unrecognized command line option '-Wno-missing-variable-declarations' [-Werror]
cc1: error: unrecognized command line option '-Wno-system-headers-Wno-thread-safety' [-Werror]
cc1: all warnings being treated as errors

Instead of adding hoops to the documentation, in particular to keep it in sync, improve the only location where we emit HTC status logs. We could also consider replacing the HTC enum with a struct, similar to what we did in other places. The struct symbols would be named after the UPPER name from the table, have a name and description fields, possibly replace the error number with a simple is_err field. Capturing the long description like this is less intrusive. Refs #4042

bsdphk · 2024-02-19T14:40:34Z

goes after march-15 release

nigoroll · 2024-02-19T14:41:18Z

during bugwash, @bsdphk brought up the question if this could affect vsl clients, and while it does not look like it, git grep suggests that we should change some other places where FetchError is referred.

bsdphk · 2024-02-19T14:51:24Z

after march15 release

this is for consistency, to simplify parsing and to reduce the amount of data logged with VSL. Motivated by #4042

dridi added b=enhancement r=trunk labels Jan 18, 2024

dridi force-pushed the drip_log branch 2 times, most recently from c0f6e31 to a6d962b Compare January 19, 2024 08:06

dridi changed the title ~~req_fsm: Log session error before Resp timestamp~~ v1d: Log client write error Jan 19, 2024

dridi added 3 commits January 29, 2024 13:25

vsl_tags: New DeliveryError tag for VDPs

c434148

This is not quite a counterpart of FetchError that is used in more contexts than just a VFP.

v1f: Log backend write error as a DeliveryError

3233bd2

This is not going through a VDP, but it eventually will. Refs varnishcache#4035

v1d: Log delivery errors

3d6fd2f

dridi force-pushed the drip_log branch from a6d962b to 3d6fd2f Compare January 29, 2024 12:35

dridi added the a=Bugwash Today label Jan 29, 2024

nigoroll reviewed Jan 29, 2024

View reviewed changes

include/tbl/vsl_tags.h Show resolved Hide resolved

nigoroll requested changes Jan 29, 2024

View reviewed changes

nigoroll added a commit that referenced this pull request Jan 29, 2024

Add SessClose reasons to documentation

10f1e5c

Motivated by #4042

nigoroll added a commit to nigoroll/varnish-cache that referenced this pull request Jan 29, 2024

For BackendClose, also log the short tag as with SessClose

cb46256

this is for consistency, to simplify parsing and to reduce the amount of data logged with VSL. Motivated by varnishcache#4042

nigoroll mentioned this pull request Jan 29, 2024

For BackendClose, also log the short tag as with SessClose #4047

Merged

dridi marked this pull request as draft January 29, 2024 17:00

bsdphk removed the a=Bugwash Today label Feb 19, 2024

nigoroll added a commit that referenced this pull request Mar 1, 2024

For BackendClose, also log the short tag as with SessClose

a73e6a5

this is for consistency, to simplify parsing and to reduce the amount of data logged with VSL. Motivated by #4042

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

v1d: Log client write error #4042

v1d: Log client write error #4042

dridi commented Jan 18, 2024

dridi commented Jan 22, 2024

nigoroll commented Jan 22, 2024

dridi commented Jan 22, 2024

dridi commented Jan 29, 2024

nigoroll Jan 29, 2024

nigoroll Jan 29, 2024

dridi Jan 29, 2024

dridi Jan 29, 2024

nigoroll Jan 29, 2024

dridi Jan 31, 2024

nigoroll Jan 31, 2024

dridi Jan 31, 2024

nigoroll Feb 12, 2024

daghf commented Feb 2, 2024

bsdphk commented Feb 19, 2024

nigoroll commented Feb 19, 2024

bsdphk commented Feb 19, 2024

v1d: Log client write error #4042

Are you sure you want to change the base?

v1d: Log client write error #4042

Conversation

dridi commented Jan 18, 2024

dridi commented Jan 22, 2024

nigoroll commented Jan 22, 2024

dridi commented Jan 22, 2024

dridi commented Jan 29, 2024

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

daghf commented Feb 2, 2024

bsdphk commented Feb 19, 2024

nigoroll commented Feb 19, 2024

bsdphk commented Feb 19, 2024