From c185bc4656d732074842b69a1be5e174f743db2f Mon Sep 17 00:00:00 2001 From: Willy Tarreau Date: Fri, 29 Sep 2023 08:17:49 +0200 Subject: [PATCH] MEDIUM: stream: now provide full stream dumps in case of loops When a stream is caught looping, we produce some output to help figure its internal state explaining why it's looping. The problem is that this debug output is quite old and the info it provides are quite insufficient to debug a modern process, and since such bugs happen only once or twice a year the situation doesn't improve. On the other hand the output of "show sess all" is extremely detailed and kept up to date with code evolutions since it's a heavily used debugging tool. This commit replaces the call to the totally outdated stream_dump() with a call to strm_dump_to_buffer(), and removes the filters dump since they are already emitted there, and it now produces much more exploitable output: [ALERT] (5936) : A bogus STREAM [0x7fa8dc02f660] is spinning at 5653514 calls per second and refuses to die, aborting now! Please report this error to developers: 0x7fa8dc02f660: [28/Sep/2023:09:53:08.811818] id=2 proto=tcpv4 source=127.0.0.1:58306 flags=0xc4a, conn_retries=0, conn_exp= conn_et=0x000 srv_conn=0x133f220, pend_pos=(nil) waiting=0 epoch=0x1 frontend=public (id=2 mode=http), listener=? (id=1) addr=127.0.0.1:4080 backend=public (id=2 mode=http) addr=127.0.0.1:61932 server=s1 (id=1) addr=127.0.0.1:7443 task=0x7fa8dc02fa40 (state=0x01 nice=0 calls=5749559 rate=5653514 exp=3s tid=1(1/1) age=1s) txn=0x7fa8dc02fbf0 flags=0x3000 meth=1 status=-1 req.st=MSG_DONE rsp.st=MSG_RPBEFORE req.f=0x4c rsp.f=0x00 scf=0x7fa8dc02f5f0 flags=0x00000482 state=EST endp=CONN,0x7fa8dc02b4b0,0x05004001 sub=1 rex=58s wex= h1s=0x7fa8dc02b4b0 h1s.flg=0x100010 .sd.flg=0x5004001 .req.state=MSG_DONE .res.state=MSG_RPBEFORE .meth=GET status=0 .sd.flg=0x05004001 .sc.flg=0x00000482 .sc.app=0x7fa8dc02f660 .subs=0x7fa8dc02f608(ev=1 tl=0x7fa8dc02fae0 tl.calls=0 tl.ctx=0x7fa8dc02f5f0 tl.fct=sc_conn_io_cb) h1c=0x7fa8dc0272d0 h1c.flg=0x0 .sub=0 .ibuf=0@(nil)+0/0 .obuf=0@(nil)+0/0 .task=0x7fa8dc0273f0 .exp= co0=0x7fa8dc027040 ctrl=tcpv4 xprt=RAW mux=H1 data=STRM target=LISTENER:0x12840c0 flags=0x00000300 fd=32 fd.state=20 updt=0 fd.tmask=0x2 scb=0x7fa8dc02fb30 flags=0x00001411 state=EST endp=CONN,0x7fa8dc0300c0,0x05000001 sub=1 rex=58s wex= h1s=0x7fa8dc0300c0 h1s.flg=0x4010 .sd.flg=0x5000001 .req.state=MSG_DONE .res.state=MSG_RPBEFORE .meth=GET status=0 .sd.flg=0x05000001 .sc.flg=0x00001411 .sc.app=0x7fa8dc02f660 .subs=0x7fa8dc02fb48(ev=1 tl=0x7fa8dc02feb0 tl.calls=2 tl.ctx=0x7fa8dc02fb30 tl.fct=sc_conn_io_cb) h1c=0x7fa8dc02ff00 h1c.flg=0x80000000 .sub=1 .ibuf=0@(nil)+0/0 .obuf=0@(nil)+0/0 .task=0x7fa8dc030020 .exp= co1=0x7fa8dc02fcd0 ctrl=tcpv4 xprt=RAW mux=H1 data=STRM target=SERVER:0x133f220 flags=0x10000300 fd=33 fd.state=10421 updt=0 fd.tmask=0x2 req=0x7fa8dc02f680 (f=0x1840000 an=0x8000 pipe=0 tofwd=0 total=79) an_exp= buf=0x7fa8dc02f688 data=(nil) o=0 p=0 i=0 size=0 htx=0xc18f60 flags=0x0 size=0 data=0 used=0 wrap=NO extra=0 res=0x7fa8dc02f6d0 (f=0x80000000 an=0x1400000 pipe=0 tofwd=0 total=0) an_exp= buf=0x7fa8dc02f6d8 data=(nil) o=0 p=0 i=0 size=0 htx=0xc18f60 flags=0x0 size=0 data=0 used=0 wrap=NO extra=0 call trace(10): | 0x59f2b7 [0f 0b 0f 1f 80 00 00 00]: stream_dump_and_crash+0x1f7/0x2bf | 0x5a0d71 [e9 af e6 ff ff ba 40 00]: process_stream+0x19f1/0x3a56 | 0x68d7bb [49 89 c7 4d 85 ff 74 77]: run_tasks_from_lists+0x3ab/0x924 | 0x68e0b4 [29 44 24 14 8b 4c 24 14]: process_runnable_tasks+0x374/0x6d6 | 0x656f67 [83 3d f2 75 84 00 01 0f]: run_poll_loop+0x127/0x5a8 | 0x6575d7 [48 8b 1d 42 50 5c 00 48]: main+0x1b22f7 | 0x7fa8e0f35e45 [64 48 89 04 25 30 06 00]: libpthread:+0x7e45 | 0x7fa8e0e5a4af [48 89 c7 b8 3c 00 00 00]: libc:clone+0x3f/0x5a Note that the output is subject to the global anon key so that IPs and object names can be anonymized if required. It could make sense to backport this and the few related previous patches next time such an issue is reported. --- include/haproxy/stream.h | 1 + src/stream.c | 19 ++++--------------- 2 files changed, 5 insertions(+), 15 deletions(-) diff --git a/include/haproxy/stream.h b/include/haproxy/stream.h index 55a77bd39d..8bb4e5cf86 100644 --- a/include/haproxy/stream.h +++ b/include/haproxy/stream.h @@ -68,6 +68,7 @@ int stream_set_http_mode(struct stream *s, const struct mux_proto_list *mux_prot void stream_shutdown(struct stream *stream, int why); void stream_dump(struct buffer *buf, const struct stream *s, const char *pfx); void stream_dump_and_crash(enum obj_type *obj, int rate); +void strm_dump_to_buffer(struct buffer *buf, const struct stream *strm, const char *pfx, uint32_t anon_key); struct ist stream_generate_unique_id(struct stream *strm, struct list *format); diff --git a/src/stream.c b/src/stream.c index dedb2286d8..db633014a9 100644 --- a/src/stream.c +++ b/src/stream.c @@ -2880,7 +2880,7 @@ void stream_dump(struct buffer *buf, const struct stream *s, const char *pfx) */ void stream_dump_and_crash(enum obj_type *obj, int rate) { - const struct stream *s; + struct stream *s; char *msg = NULL; const void *ptr; @@ -2896,19 +2896,8 @@ void stream_dump_and_crash(enum obj_type *obj, int rate) } chunk_reset(&trash); - stream_dump(&trash, s, " "); - - chunk_appendf(&trash, " filters={"); - if (HAS_FILTERS(s)) { - struct filter *filter; - - list_for_each_entry(filter, &s->strm_flt.filters, list) { - if (filter->list.p != &s->strm_flt.filters) - chunk_appendf(&trash, ", "); - chunk_appendf(&trash, "%p=\"%s\"", filter, FLT_ID(filter)); - } - } - chunk_appendf(&trash, "}"); + chunk_printf(&trash, " "); + strm_dump_to_buffer(&trash, s, " ", HA_ATOMIC_LOAD(&global.anon_key)); if (ptr != s) { // that's an appctx const struct appctx *appctx = ptr; @@ -3245,7 +3234,7 @@ struct show_sess_ctx { * stream at once. Each new output line will be prefixed with if non-null, * which is used to preserve indenting. */ -static void strm_dump_to_buffer(struct buffer *buf, const struct stream *strm, const char *pfx, uint32_t anon_key) +void strm_dump_to_buffer(struct buffer *buf, const struct stream *strm, const char *pfx, uint32_t anon_key) { struct stconn *scf, *scb; struct tm tm;