Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

v1d: Log client write error #4042

Draft
wants to merge 3 commits into
base: master
Choose a base branch
from
Draft

v1d: Log client write error #4042

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
c434148
vsl_tags: New DeliveryError tag for VDPs
dridi Jan 29, 2024
3233bd2
v1f: Log backend write error as a DeliveryError
dridi Jan 29, 2024
3d6fd2f
v1d: Log delivery errors
dridi Jan 29, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
5 changes: 4 additions & 1 deletion bin/varnishd/http1/cache_http1_deliver.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -142,6 +142,9 @@ V1D_Deliver(struct req *req, struct boc *boc, int sendbody)

if (sc == SC_NULL && err && req->sp->fd >= 0)
sc = SC_REM_CLOSE;
if (sc != SC_NULL)
if (sc != SC_NULL) {
VSLb(req->vsl, SLT_DeliveryError, "resp: \"%s\" %d \"%s\"",
sc->desc, errno, VAS_errtxt(errno));
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

See 10f1e5c and #4047

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Req_Fail(req, sc);
}
}
5 changes: 2 additions & 3 deletions bin/varnishd/http1/cache_http1_fetch.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -154,9 +154,8 @@ V1F_SendReq(struct worker *wrk, struct busyobj *bo, uint64_t *ctr_hdrbytes,

CHECK_OBJ_NOTNULL(sc, STREAM_CLOSE_MAGIC);
if (sc != SC_NULL) {
VSLb(bo->vsl, SLT_FetchError,
"backend write error: %d (%s) (%s)",
errno, VAS_errtxt(errno), sc->desc);
VSLb(bo->vsl, SLT_DeliveryError, "bereq: \"%s\" %d \"%s\"",
sc->desc, errno, VAS_errtxt(errno));
dridi marked this conversation as resolved.
Show resolved Hide resolved
VSLb_ts_busyobj(bo, "Bereq", W_TIM_real(wrk));
htc->doclose = sc;
return (-1);
Expand Down
14 changes: 10 additions & 4 deletions bin/varnishtest/tests/r03189.vtc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -14,10 +14,14 @@ server s1 {
chunkedlen 0
} -start

varnish v1 \
-arg "-p idle_send_timeout=.1" \
-arg "-p send_timeout=.8" \
-vcl+backend { } -start
varnish v1 -cliok "param.set idle_send_timeout .1"
varnish v1 -cliok "param.set send_timeout .8"
varnish v1 -vcl+backend { } -start

logexpect l1 -v v1 {
expect * * DeliveryError {resp: "Error transaction" \d+ ".*"}
expect 0 = Timestamp "Resp:"
} -start

client c1 {
txreq
Expand All @@ -26,3 +30,5 @@ client c1 {
barrier b sync
expect_close
} -run

logexpect l1 -wait
11 changes: 11 additions & 0 deletions include/tbl/vsl_tags.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -691,6 +691,17 @@ SLTM(VdpAcct, 0, "Deliver filter accounting",
NODEF_NOTICE
)

SLTM(DeliveryError, 0, "Error while delivering an HTTP message.",
"Logs the error message of a failed delivery operation.\n\n"
nigoroll marked this conversation as resolved.
Show resolved Hide resolved
"The format is::\n\n"
"\t%s: \"%s\" %d \"%s\"\n"
"\t| | | |\n"
"\t| | | +- Detailed error message\n"
"\t| | +------ Error Number (errno)\n"
"\t| +----------- Why the stream closed\n"
"\t+----------------- \"bereq\" or \"resp\"\n"
"\n"
)

#undef NOSUP_NOTICE
#undef NODEF_NOTICE
Expand Down