]> git.ipfire.org Git - thirdparty/haproxy.git/log
thirdparty/haproxy.git
2 years agoOPTIM: hpack-huff: reduce the cache footprint of the huffman decoder
Willy Tarreau [Tue, 20 Sep 2022 05:27:15 +0000 (07:27 +0200)] 
OPTIM: hpack-huff: reduce the cache footprint of the huffman decoder

Some tables are currently used to decode bit blocks and lengths. We do
see such lookups in perf top. We have 4 512-byte tables and one 64-byte
one. Looking closer, the second half of the table (length) has so few
variations that most of the time it will be computed in a single "if",
and never more than 3. This alone allows to cut the tables in half. In
addition, one table (bits 15-11) is only 32-element long, while another
one (bits 11-4) starts at 0x60, so we can merge the two as they do not
overlap, and further save size. We're now down to 4 256-entries tables.

This is visible in h3 and h2 where the max request rate is slightly higher
(e.g. +1.6% for h2). The huff_dec() function got slightly larger but the
overall code size shrunk:

  $ nm --size haproxy-before | grep huff_dec
  000000000000029e T huff_dec
  $ nm --size haproxy-after | grep huff_dec
  0000000000000345 T huff_dec
  $ size haproxy-before haproxy-after
     text    data     bss     dec     hex filename
  7591126  569268 2761348 10921742         a6a70e haproxy-before
  7591082  568180 2761348 10920610         a6a2a2 haproxy-after

2 years agoMINOR: httpclient: enabled the use of SNI presets
Miroslav Zagorac [Mon, 19 Sep 2022 10:20:29 +0000 (12:20 +0200)] 
MINOR: httpclient: enabled the use of SNI presets

This commit allows setting SNI outside http_client.c code.

2 years agoCLEANUP: httpclient: deleted unused variables
Miroslav Zagorac [Mon, 19 Sep 2022 10:18:53 +0000 (12:18 +0200)] 
CLEANUP: httpclient: deleted unused variables

The locally defined static variables 'httpclient_srv_raw' and
'httpclient_srv_ssl' are not used anywhere in the source code,
except that they are set in the httpclient_precheck() function.

2 years agoBUG/MEDIUM: mux-quic: fix nb_hreq decrement
Amaury Denoyelle [Mon, 19 Sep 2022 09:58:24 +0000 (11:58 +0200)] 
BUG/MEDIUM: mux-quic: fix nb_hreq decrement

nb_hreq is a counter on qcc for active HTTP requests. It is incremented
for each qcs where a full HTTP request was received. It is decremented
when the stream is closed locally :
- on HTTP response fully transmitted
- on stream reset

A bug will occur if a stream is resetted without having processed a full
HTTP request. nb_hreq will be decremented whereas it was not
incremented. This will lead to a crash when building with
DEBUG_STRICT=2. If BUG_ON_HOT are not active, nb_hreq counter will wrap
which may break the timeout logic for the connection.

This bug was triggered on haproxy.org. It can be reproduced by
simulating the reception of a STOP_SENDING frame instead of a STREAM one
by patching qc_handle_strm_frm() :

+       if (quic_stream_is_bidi(strm_frm->id))
+               qcc_recv_stop_sending(qc->qcc, strm_frm->id, 0);
+       //ret = qcc_recv(qc->qcc, strm_frm->id, strm_frm->len,
+       //               strm_frm->offset.key, strm_frm->fin,
+       //               (char *)strm_frm->data);

To fix this bug, a qcs is now flagged with a new QC_SF_HREQ_RECV. This
is set when the full HTTP request is received. When the stream is closed
locally, nb_hreq will be decremented only if this flag was set.

This must be backported up to 2.6.

2 years ago[RELEASE] Released version 2.7-dev6 v2.7-dev6
Willy Tarreau [Sat, 17 Sep 2022 10:24:53 +0000 (12:24 +0200)] 
[RELEASE] Released version 2.7-dev6

Released version 2.7-dev6 with the following main changes :
    - MINOR: Revert part of clarifying samples support per os commit
    - BUILD: makefile: enable crypt(3) for NetBSD
    - BUG/MINOR: quic: Retransmitted frames marked as acknowledged
    - BUG/MINOR: quic: Possible crash with "tls-ticket-keys" on QUIC bind lines
    - MINOR: http-check: Remove support for headers/body in "option httpchk" version
    - BUG/MINOR: h1: Support headers case adjustment for TCP proxies
    - BUG/MINOR: quic: Possible crash when verifying certificates
    - BUILD: quic: add some ifdef around the SSL_ERROR_* for libressl
    - BUILD: ssl: fix ssl_sock_switchtx_cbk when no client_hello_cb
    - BUILD: quic: temporarly ignore chacha20_poly1305 for libressl
    - BUILD: quic: enable early data only with >= openssl 1.1.1
    - BUILD: ssl: fix the ifdef mess in ssl_sock_initial_ctx
    - BUILD: quic: fix the #ifdef in ssl_quic_initial_ctx()
    - MINOR: quic: add QUIC support when no client_hello_cb
    - MINOR: quic: Add traces about sent or resent TX frames
    - MINOR: quic: No TRACE_LEAVE() in retrieve_qc_conn_from_cid()
    - BUG/MINOR: quic: Wrong connection ID to thread ID association
    - BUG/MINOR: task: always reset a new tasklet's call date
    - BUG/MINOR: task: make task_instant_wakeup() work on a task not a tasklet
    - MINOR: task: permanently enable latency measurement on tasklets
    - CLEANUP: task: rename ->call_date to ->wake_date
    - BUG/MINOR: sched: properly account for the CPU time of dying tasks
    - MINOR: sched: store the current profile entry in the thread context
    - BUG/MINOR: stream/sched: take into account CPU profiling for the last call
    - MINOR: tasks: do not keep cpu and latency times in struct task
    - MINOR: tools: add generic pointer hashing functions
    - CLEANUP: activity: make memprof use the generic ptr_hash() function
    - CLEANUP: activity: make taskprof use ptr_hash()
    - MINOR: debug: add struct ha_caller to describe a calling location
    - CLEANUP: debug: use struct ha_caller for memstat
    - DEBUG: task: define a series of wakeup types for tasks and tasklets
    - DEBUG: task: use struct ha_caller instead of arrays of file:line
    - DEBUG: applet: instrument appctx_wakeup() to log the caller's location
    - DEBUG: task: simplify the caller recording in DEBUG_TASK
    - CLEANUP: task: move tid and wake_date into the common part
    - CLEANUP: sched: remove duplicate code in run_tasks_from_list()
    - CLEANUP: activity: make the number of sched activity entries more configurable
    - DEBUG: resolvers: unstatify process_resolvers() to make it appear in profiling
    - DEBUG: quic: export the few task handlers that often appear in task dumps
    - MEDIUM: tasks/activity: combine the called function with the caller
    - MINOR: tasks/activity: improve the caller-callee activity hash
    - MINOR: activity/cli: support aggregating task profiling outputs
    - MINOR: activity/cli: support sorting task profiling by total CPU time
    - BUG/MINOR: signals/poller: set the poller timeout to 0 when there are signals
    - BUG/MINOR: quic: Speed up the handshake completion only one time
    - BUG/MINOR: quic: Trace fix about packet number space information.
    - BUG/MINOR: h3: Crash when h3 trace verbosity is "minimal"
    - MINOR: h3: Add the quic_conn object to h3 traces
    - MINOR: h3: Missing connection argument for a TRACE_LEAVE() argument
    - MINOR: h3: Send the h3 settings with others streams (requests)
    - MINOR: dev/udp: Apply the corruption to both directions
    - BUILD: udp-perturb: Add a make target for udp-perturb tool
    - BUG/MINOR: signals/poller: ensure wakeup from signals
    - CI: cirrus-ci: bump FreeBSD image to 13-1
    - DEV: flags: fix usage message to reflect available options
    - DEV: flags: add missing CO_FL_FDLESS connection flag
    - MINOR: flags: add a new file to host flag dumping macros
    - MINOR: flags: implement a macro used to dump enums inside masks
    - MINOR: flags/channel: use flag dumping for channel flags and analysers
    - MINOR: flags/connection: use flag dumping for connection flags
    - MINOR: flags/stconn: use flag dumping for stconn and sedesc flags
    - MINOR: flags/stream: use flag dumping for stream error type
    - MINOR: flags/stream: use flag dumping for stream flags
    - MINOR: flags/task: use flag dumping for task state
    - MINOR: flags/http_ana: use flag dumping for txn flags
    - DEV: flags: remove the now unused SHOW_FLAG() definition
    - DEV: flags: remove the now useless intermediary functions
    - MINOR: flags/htx: use flag dumping to show htx and start-line flags
    - MINOR: flags/http_ana: use flag dumping to show http msg states
    - BUG/MEDIUM: proxy: ensure pause_proxy() and resume_proxy() own PROXY_LOCK
    - MINOR: listener: small API change
    - MINOR: proxy/listener: support for additional PAUSED state
    - BUG/MINOR: stats: fixing stat shows disabled frontend status as 'OPEN'
    - BUILD: flags: fix build warning in some macros used by show_flags
    - BUILD: flags: fix the fallback macros for missing stdio
    - CLEANUP: pollers: remove dead code in the polling loop
    - BUG/MINOR: mux-h1: Increment open_streams counter when H1 stream is created
    - REGTESTS: healthcheckmail: Relax matching on the healthcheck log message
    - CLEANUP: listener: function comment typo in stop_listener()
    - BUG/MINOR: listener: null pointer dereference suspected by coverity
    - MINOR: flags/fd: decode FD flags states
    - REORG: mux-h2: extract flags and enums into mux_h2-t.h
    - MINOR: flags/mux-h2: decode H2C and H2S flags
    - REGTESTS: log: test the log-forward feature
    - BUG/MEDIUM: sink: bad init sequence on tcp sink from a ring.
    - REGTESTS: ssl/log: test the log-forward with SSL
    - MEDIUM: httpclient: httpclient_create_proxy() creates a proxy for httpclient
    - MEDIUM: httpclient: allow to use another proxy
    - DOC: fix TOC in starter guide for subsection 3.3.8. Statistics
    - MINOR: httpclient: export httpclient_create_proxy()
    - MEDIUM: quic: separate path for rx and tx with set_encryption_secrets
    - BUG/MEDIUM: mux-quic: fix crash on early app-ops release
    - REORG: mux-h1: extract flags and enums into mux_h1-t.h
    - MINOR: flags/mux-h1: decode H1C and H1S flags
    - CLEANUP: mux-quic: remove stconn usage in h3/hq
    - BUG/MINOR: mux-quic: do not remotely close stream too early
    - CLEANUP: exclude udp-perturb with .gitignore
    - BUG/MEDIUM: server: segv when adding server with hostname from CLI
    - CLEANUP: quic,ssl: fix tiny typos in C comments
    - BUG/MEDIUM: captures: free() an error capture out of the proxy lock
    - BUILD: fd: fix a build warning on the DWCAS
    - MINOR: anon: add new macros and functions to anonymize contents
    - MINOR: anon: store the anonymizing key in the global structure
    - MINOR: anon: store the anonymizing key in the CLI's appctx
    - MINOR: cli: anonymize commands 'show sess' and 'show sess all'
    - MINOR: cli: anonymize 'show servers state' and 'show servers conn'
    - MINOR: config: add command-line -dC to dump the configuration file
    - SCRIPTS: announce-release: update some URLs to https

2 years agoSCRIPTS: announce-release: update some URLs to https
Willy Tarreau [Sat, 17 Sep 2022 10:17:07 +0000 (12:17 +0200)] 
SCRIPTS: announce-release: update some URLs to https

Some components like Discourse were already redirecting to https. Other
ones like docs and git are covered by the certificate, and finally
switching the advertised scheme for www should increase the ratio of
H2 and H3 in the stats (resp 8.9 and 1.9%) and possibly help spot new
issues.

2 years agoMINOR: config: add command-line -dC to dump the configuration file
Erwan Le Goas [Wed, 14 Sep 2022 15:51:55 +0000 (17:51 +0200)] 
MINOR: config: add command-line -dC to dump the configuration file

This commit adds a new command line option -dC to dump the configuration
file. An optional key may be appended to -dC in order to produce an
anonymized dump using this key. The anonymizing process uses the same
algorithm as the CLI so that the same key will produce the same hashes
for the same identifiers. This way an admin may share an anonymized
extract of a configuration to match against live dumps. Note that key 0
will not anonymize the output. However, in any case, the configuration
is dumped after tokenizing, thus comments are lost.

2 years agoMINOR: cli: anonymize 'show servers state' and 'show servers conn'
Erwan Le Goas [Wed, 14 Sep 2022 15:48:55 +0000 (17:48 +0200)] 
MINOR: cli: anonymize 'show servers state' and 'show servers conn'

Modify proxy.c in order to anonymize the following confidential data on
commands 'show servers state' and 'show servers conn':
  - proxy name
  - server name
  - server address

2 years agoMINOR: cli: anonymize commands 'show sess' and 'show sess all'
Erwan Le Goas [Wed, 14 Sep 2022 15:45:41 +0000 (17:45 +0200)] 
MINOR: cli: anonymize commands 'show sess' and 'show sess all'

Modify stream.c in order to hash the following confidential data if the
anonymized mode is enabled:
  - configuration elements such as frontend/backend/server names
  - IP addresses

2 years agoMINOR: anon: store the anonymizing key in the CLI's appctx
Erwan Le Goas [Wed, 14 Sep 2022 15:24:22 +0000 (17:24 +0200)] 
MINOR: anon: store the anonymizing key in the CLI's appctx

In order to allow users to dump internal states using a specific key
without changing the global one, we're introducing a key in the CLI's
appctx. This key is preloaded from the global one when "set anon on"
is used (and if none exists, a random one is assigned). And the key
can optionally be assigned manually for the whole CLI session.

A "show anon" command was also added to show the anon state, and the
current key if the users has sufficient permissions. In addition, a
"debug dev hash" command was added to test the feature.

2 years agoMINOR: anon: store the anonymizing key in the global structure
Erwan Le Goas [Wed, 14 Sep 2022 15:24:22 +0000 (17:24 +0200)] 
MINOR: anon: store the anonymizing key in the global structure

Add a uint32_t key in global to hash words with it. A new CLI command
'set global-key <key>' was added to change the global anonymizing key.
The global may also be set in the configuration using the global
"anonkey" directive. For now this key is not used.

2 years agoMINOR: anon: add new macros and functions to anonymize contents
Erwan Le Goas [Wed, 14 Sep 2022 15:40:24 +0000 (17:40 +0200)] 
MINOR: anon: add new macros and functions to anonymize contents

These macros and functions will be used to anonymize strings by producing
a short hash. This will allow to match config elements against dump elements
without revealing the original data. This will later be used to anonymize
configuration parts and CLI commands output. For now only string, identifiers
and addresses are supported, but the model is easily extensible.

2 years agoBUILD: fd: fix a build warning on the DWCAS
Willy Tarreau [Sat, 17 Sep 2022 09:15:29 +0000 (11:15 +0200)] 
BUILD: fd: fix a build warning on the DWCAS

Ilya reported in issue #1816 a build warning on armhf (promoted to error
here since -Werror):

  src/fd.c: In function fd_rm_from_fd_list:
  src/fd.c:209:87: error: passing argument 3 of __ha_cas_dw discards volatile qualifier from pointer target type [-Werror=discarded-array-qualifiers]
    209 |    unlikely(!_HA_ATOMIC_DWCAS(((long *)&fdtab[fd].update), (uint32_t *)&cur_list.u32, &next_list.u32))
        |                                                                                       ^~~~~~~~~~~~~~

This happens only on such an architecture because the DWCAS requires the
pointer not the value, and gcc seems to be needlessly picky about reading
a const from a volatile! This may safely be backported to older versions.

2 years agoBUG/MEDIUM: captures: free() an error capture out of the proxy lock
Willy Tarreau [Sat, 17 Sep 2022 09:07:19 +0000 (11:07 +0200)] 
BUG/MEDIUM: captures: free() an error capture out of the proxy lock

Ed Hein reported in github issue #1856 some occasional watchdog panics
in 2.4.18 showing extreme contention on the proxy's lock while the libc
was in malloc()/free(). One cause of this problem is that we call free()
under the proxy's lock in proxy_capture_error(), which makes no sense
since if we can free the object under the lock after it's been detached,
we can also free it after releasing the lock (since it's not referenced
anymore).

This should be backported to all relevant versions, likely all
supported ones.

2 years agoCLEANUP: quic,ssl: fix tiny typos in C comments
cui fliter [Mon, 29 Aug 2022 06:42:57 +0000 (14:42 +0800)] 
CLEANUP: quic,ssl: fix tiny typos in C comments

This fixes 4 tiny and harmless typos in mux_quic.c, quic_tls.c and
ssl_sock.c. Originally sent via GitHub PR #1843.

Signed-off-by: cui fliter <imcusg@gmail.com>
[Tim: Rephrased the commit message]
[wt: further complete the commit message]

2 years agoBUG/MEDIUM: server: segv when adding server with hostname from CLI
Aurelien DARRAGON [Fri, 16 Sep 2022 12:27:53 +0000 (14:27 +0200)] 
BUG/MEDIUM: server: segv when adding server with hostname from CLI

When calling 'add server' with a hostname from the cli (runtime),
str2sa_range() does not resolve hostname because it is purposely
called without PA_O_RESOLVE flag.

This leads to 'srv->addr_node.key' being NULL. According to Willy it
is fine behavior, as long as we handle it properly, and is already
handled like this in srv_set_addr_desc().

This patch fixes GH #1865 by adding an extra check before inserting
'srv->addr_node' into 'be->used_server_addr'. Insertion and removal
will be skipped if 'addr_node.key' is NULL.

It must be backported to 2.6 and 2.5 only.

2 years agoCLEANUP: exclude udp-perturb with .gitignore
Amaury Denoyelle [Fri, 16 Sep 2022 13:44:57 +0000 (15:44 +0200)] 
CLEANUP: exclude udp-perturb with .gitignore

udp-perturb is a tool which can be used as a UDP gateway. It can be used
to reorder, remove or corrupt datagrams. It is compiled in dev/
directory and added to .gitignore to not clutter git status output.

2 years agoBUG/MINOR: mux-quic: do not remotely close stream too early
Amaury Denoyelle [Fri, 16 Sep 2022 11:30:59 +0000 (13:30 +0200)] 
BUG/MINOR: mux-quic: do not remotely close stream too early

A stream is considered as remotely closed once we have received all the
data with the FIN bit set.

The condition to close the stream was wrong. In particular, if we
receive an empty STREAM frame with FIN bit set, this would have close
the stream even if we do not have yet received all the data. The
condition is now adjusted to ensure that Rx buffer contains all the data
up to the stream final size.

In most cases, this bug is harmless. However, if compiled with
DEBUG_STRICT=2, a BUG_ON_HOT crash would have been triggered if close is
done too early. This was most notably the case sometimes on interop test
suite with quinn or kwik clients. This can also be artificially
reproduced by simulating reception of an empty STREAM frame with FIN bit
set in qc_handle_strm_frm() :

+       if (strm_frm->fin) {
+               qcc_recv(qc->qcc, strm_frm->id, 0,
+                        strm_frm->len, strm_frm->fin,
+                        (char *)strm_frm->data);
+       }
        ret = qcc_recv(qc->qcc, strm_frm->id, strm_frm->len,
                       strm_frm->offset.key, strm_frm->fin,
                       (char *)strm_frm->data);

This must be backported up to 2.6.

2 years agoCLEANUP: mux-quic: remove stconn usage in h3/hq
Amaury Denoyelle [Thu, 15 Sep 2022 09:22:32 +0000 (11:22 +0200)] 
CLEANUP: mux-quic: remove stconn usage in h3/hq

Small cleanup on snd_buf for application protocol layer.
* do not export h3_snd_buf
* replace stconn by a qcs argument. This is better as h3/hq-interop only
  uses the qcs instance.

This should be backported up to 2.6.

2 years agoMINOR: flags/mux-h1: decode H1C and H1S flags
Christopher Faulet [Thu, 15 Sep 2022 08:54:36 +0000 (10:54 +0200)] 
MINOR: flags/mux-h1: decode H1C and H1S flags

The new functions h1c_show_flags() and h1s_show_flags() decode the flags
state into a string, and are used by dev/flags:

$ /dev/flags/flags h1c 0x2200
h1c->flags = H1C_F_ST_READY | H1C_F_ST_ATTACHED

./dev/flags/flags h1s 0x190
h1s->flags = H1S_F_BODYLESS_RESP | H1S_F_NOT_FIRST | H1S_F_WANT_KAL

2 years agoREORG: mux-h1: extract flags and enums into mux_h1-t.h
Christopher Faulet [Thu, 15 Sep 2022 08:51:26 +0000 (10:51 +0200)] 
REORG: mux-h1: extract flags and enums into mux_h1-t.h

The same was performed for the H2 multiplexer. H1C and H1S flags are moved
in a dedicated header file. It will be mainly used to be able to decode
mux-h1 flags from the flags utility.

In this patch, we only move the flags to mux_h1-t.h.

2 years agoBUG/MEDIUM: mux-quic: fix crash on early app-ops release
Amaury Denoyelle [Wed, 14 Sep 2022 14:23:47 +0000 (16:23 +0200)] 
BUG/MEDIUM: mux-quic: fix crash on early app-ops release

H3 SETTINGS emission has recently been delayed. The idea is to send it
with the first STREAM to reduce sendto syscall invocation. This was
implemented in the following patch :
  3dd79d378c86b3ebf60e029f518add5f1ed54815
  MINOR: h3: Send the h3 settings with others streams (requests)

This patch works fine under nominal conditions. However, it will cause a
crash if a HTTP/3 connection is released before having sent any data,
for example when receiving an invalid first request. In this case,
qc_release will first free qcc.app_ops HTTP/3 application protocol layer
via release callback. Then qc_send is called to emit any closing frames
built by app_ops release invocation. However, in qc_send, as no data has
been sent, it will try to complete application layer protocol
intialization, with a SETTINGS emission for HTTP/3. Thus, qcc.app_ops is
reused, which is invalid as it has been just freed. This will cause a
crash with h3_finalize in the call stack.

This bug can be reproduced artificially by generating incomplete HTTP/3
requests. This will in time trigger http-request timeout without any
data send. This is done by editing qc_handle_strm_frm function.

-       ret = qcc_recv(qc->qcc, strm_frm->id, strm_frm->len,
+       ret = qcc_recv(qc->qcc, strm_frm->id, strm_frm->len - 1,
                       strm_frm->offset.key, strm_frm->fin,
                       (char *)strm_frm->data);

To fix this, application layer closing API has been adjusted to be done
in two-steps. A new shutdown callback is implemented : it is used by the
HTTP/3 layer to generate GOAWAY frame in qc_release prologue.
Application layer context qcc.app_ops is then freed later in qc_release
via the release operation which is now only used to liberate app layer
ressources. This fixes the problem as the intermediary qc_send
invocation will be able to reuse app_ops before it is freed.

This patch fixes the crash, but it would be better to adjust H3 SETTINGS
emission in case of early connection closing : in this case, there is no
need to send it. This should be implemented in a future patch.

This should fix the crash recently experienced by Tristan in github
issue #1801.

This must be backported up to 2.6.

2 years agoMEDIUM: quic: separate path for rx and tx with set_encryption_secrets
William Lallemand [Wed, 14 Sep 2022 15:54:05 +0000 (17:54 +0200)] 
MEDIUM: quic: separate path for rx and tx with set_encryption_secrets

With quicTLS the set_encruption_secrets callback is always called with
the read_secret and the write_secret.

However this is not the case with libreSSL, which uses the
set_read_secret()/set_write_secret() mecanism. It still provides the
set_encryption_secrets() callback, which is called with a NULL
parameter for the write_secret during the read, and for the read_secret
during the write.

The exchange key was not designed in haproxy to be called separately for
read and write, so this patch allow calls with read or write key to
NULL.

2 years agoMINOR: httpclient: export httpclient_create_proxy()
William Lallemand [Wed, 14 Sep 2022 12:34:39 +0000 (14:34 +0200)] 
MINOR: httpclient: export httpclient_create_proxy()

Export httpclient_create_proxy() in http_client.h

2 years agoDOC: fix TOC in starter guide for subsection 3.3.8. Statistics
Mathias Weiersmueller [Sat, 10 Sep 2022 17:45:51 +0000 (19:45 +0200)] 
DOC: fix TOC in starter guide for subsection 3.3.8. Statistics

This subsection has been moved from 3.4.9 to 3.3.8 somewhere along
2.4, but the TOC has not been updated - resulting in a invalid
anchor in the HTML version.

Needs to be backported to 2.4+

2 years agoMEDIUM: httpclient: allow to use another proxy
William Lallemand [Mon, 12 Sep 2022 15:39:04 +0000 (17:39 +0200)] 
MEDIUM: httpclient: allow to use another proxy

httpclient_new_from_proxy() is a variant of httpclient_new() which
allows to create the requests from a different proxy.

The proxy and its 2 servers are now stored in the httpclient structure.

The proxy must have been created with httpclient_create_proxy() to be
used.

The httpclient_postcheck() callback will finish the initialization of
all proxies created with PR_CAP_HTTPCLIENT.

2 years agoMEDIUM: httpclient: httpclient_create_proxy() creates a proxy for httpclient
William Lallemand [Mon, 12 Sep 2022 14:46:35 +0000 (16:46 +0200)] 
MEDIUM: httpclient: httpclient_create_proxy() creates a proxy for httpclient

httpclient_create_proxy() is a function which creates a proxy that could
be used for the httpclient. It will allocate a proxy, a raw server and
an ssl server.

This patch moves most of the code from httpclient_precheck() into a
generic function httpclient_create_proxy().

The proxy will have the PR_CAP_HTTPCLIENT capability.

This could be used for specifics httpclient instances that needs
different proxy settings.

2 years agoREGTESTS: ssl/log: test the log-forward with SSL
William Lallemand [Tue, 13 Sep 2022 10:41:29 +0000 (12:41 +0200)] 
REGTESTS: ssl/log: test the log-forward with SSL

Test the log-forward section with an SSL server and an SSL bind.

Must be backported as far as 2.3.

2 years agoBUG/MEDIUM: sink: bad init sequence on tcp sink from a ring.
Emeric Brun [Tue, 13 Sep 2022 14:16:30 +0000 (16:16 +0200)] 
BUG/MEDIUM: sink: bad init sequence on tcp sink from a ring.

The init of tcp sink, particularly for SSL, was done
too early in the code, during parsing, and this can cause
a crash specially if nbthread was not configured.

This was detected by William using ASAN on a new regtest
on log forward.

This patch adds the 'struct proxy' created for a sink
to a list and this list is now submitted to the same init
code than the main proxies list or the log_forward's proxies
list. Doing this, we are assured to use the right init sequence.
It also removes the ini code for ssl from post section parsing.

This patch should be backported as far as v2.2

Note: this fix uses 'goto' labels created by commit
'BUG/MAJOR: log-forward: Fix log-forward proxies not fully initialized'
but this code didn't exist before v2.3 so this patch needs to be
adapted for v2.2.

2 years agoREGTESTS: log: test the log-forward feature
William Lallemand [Tue, 13 Sep 2022 08:34:36 +0000 (10:34 +0200)] 
REGTESTS: log: test the log-forward feature

This reg-test test the log-forward feature by chaining a UDP and a TCP
log-forwarder.

It could be backported as far as 2.3.

2 years agoMINOR: flags/mux-h2: decode H2C and H2S flags
Willy Tarreau [Mon, 12 Sep 2022 17:20:23 +0000 (19:20 +0200)] 
MINOR: flags/mux-h2: decode H2C and H2S flags

The new functions h2c_show_flags() and h2s_show_flags() decode the flags
state into a string, and are used by dev/flags:

  $ ./dev/flags/flags h2c 0x0600
  h2c->flags = H2_CF_DEM_IN_PROGRESS | H2_CF_DEM_SHORT_READ

  $ ./dev/flags/flags h2s 0x7003
  h2s->flags = H2_SF_HEADERS_RCVD | H2_SF_OUTGOING_DATA | H2_SF_HEADERS_SENT \
             | H2_SF_ES_SENT | H2_SF_ES_RCVD

2 years agoREORG: mux-h2: extract flags and enums into mux_h2-t.h
Willy Tarreau [Mon, 12 Sep 2022 17:07:51 +0000 (19:07 +0200)] 
REORG: mux-h2: extract flags and enums into mux_h2-t.h

Originally in 1.8 we wanted to have an independent mux that could possibly
be disabled and would not impose dependencies on the outside. Everything
would fit into a single C file and that was fine.

Nowadays muxes are unavoidable, and not being able to easily inspect them
from outside is sometimes a bit of a pain. In particular, the flags utility
still cannot be used to decode their flags.

As a first step towards this, this patch moves the flags and enums to
mux_h2-t.h, as well as the two state decoding inline functions. It also
dropped the H2_SS_*_BIT defines that nobody uses. The mux_h2.c file remains
the only one to include that for now.

2 years agoMINOR: flags/fd: decode FD flags states
Willy Tarreau [Mon, 12 Sep 2022 16:53:06 +0000 (18:53 +0200)] 
MINOR: flags/fd: decode FD flags states

The new function is fd_show_flags() and it reports known FD flags:

  $ ./dev/flags/flags fd 0x000121
  fd->flags = FD_POLL_IN | FD_EV_READY_W | FD_EV_ACTIVE_R

2 years agoBUG/MINOR: listener: null pointer dereference suspected by coverity
Aurelien DARRAGON [Mon, 12 Sep 2022 07:26:21 +0000 (09:26 +0200)] 
BUG/MINOR: listener: null pointer dereference suspected by coverity

Please refer to GH #1859 for more info.
Coverity suspected improper proxy pointer handling.
Without the fix it is considered safe for the moment, but it might not
be the case in the future as we want to keep the ability to have
isolated listeners.

Making sure stop_listener(), pause_listener(), resume_listener()
and listener_release() functions make proper use
of px pointer in that context.

No need for backport except if multi-connection protocols (ie:FTP)
were to be backported as well.

2 years agoCLEANUP: listener: function comment typo in stop_listener()
Aurelien DARRAGON [Sun, 11 Sep 2022 14:19:49 +0000 (16:19 +0200)] 
CLEANUP: listener: function comment typo in stop_listener()

A minor typo related to stop_listener() function comment
was introduced in 0013288.

This makes stop_listener() function comment easier to read.

2 years agoREGTESTS: healthcheckmail: Relax matching on the healthcheck log message
Christopher Faulet [Mon, 12 Sep 2022 07:58:47 +0000 (09:58 +0200)] 
REGTESTS: healthcheckmail: Relax matching on the healthcheck log message

Depending on the timing, the conneciton on lisrv listener may be fully
accepted before any reject. Thus, instead of getting a socket error, an
invalid L7 response is reported. There is no reason to be strick on the
error type. Any failure is good here, because we just want to test the
email-alert feature.

This patch should fix issue #1857. It may be backported as far as 2.2.

2 years agoBUG/MINOR: mux-h1: Increment open_streams counter when H1 stream is created
Christopher Faulet [Mon, 12 Sep 2022 05:46:11 +0000 (07:46 +0200)] 
BUG/MINOR: mux-h1: Increment open_streams counter when H1 stream is created

Since this counter was added, it was incremented at the wrong place for
client streams. It was incremented when the stream-connector (formely the
conn-stream) was created while it should be done when the H1 stream is
created. Thus, on parsing error, on H1>H2 upgrades or TCP>H1 upgrades, the
counter is not incremented. However, it is always decremented when the H1
stream is destroyed.

On bakcned side, there is no issue.

This patch must be backported to 2.6.

2 years agoCLEANUP: pollers: remove dead code in the polling loop
Willy Tarreau [Mon, 12 Sep 2022 07:35:44 +0000 (09:35 +0200)] 
CLEANUP: pollers: remove dead code in the polling loop

As reported by Ilya and Coverity in issue #1858, since recent commit
eea152ee6 ("BUG/MINOR: signals/poller: ensure wakeup from signals")
which removed the test for the global signal flag from the pollers'
loop, the remaining "wake" flag doesn't need to be tested since it
already participates to zeroing the wait_time and will be caught
on the previous line.

Let's just remove that test now.

2 years agoBUILD: flags: fix the fallback macros for missing stdio
Willy Tarreau [Fri, 9 Sep 2022 15:46:45 +0000 (17:46 +0200)] 
BUILD: flags: fix the fallback macros for missing stdio

The fallback macros for when stdio is not there didn't have the "..."
and were causing build issues on platforms with stricter dependencies
between includes.

2 years agoBUILD: flags: fix build warning in some macros used by show_flags
Willy Tarreau [Fri, 9 Sep 2022 15:35:05 +0000 (17:35 +0200)] 
BUILD: flags: fix build warning in some macros used by show_flags

Some gcc versions seem to be upset by the use of enums as booleans,
so OK, let's cast all of them as uint, that's no big deal.

2 years agoBUG/MINOR: stats: fixing stat shows disabled frontend status as 'OPEN'
Aurelien DARRAGON [Fri, 9 Sep 2022 13:58:57 +0000 (15:58 +0200)] 
BUG/MINOR: stats: fixing stat shows disabled frontend status as 'OPEN'

This patch adresses the issue #1626.

Adding support for PR_FL_PAUSED flag in the function stats_fill_fe_stats().
The command 'show stat' now properly reports a disabled frontend
using "PAUSED" state label.

This patch depends on the following commits:
  - 7d00077fd5 "BUG/MEDIUM: proxy: ensure pause_proxy()
  and resume_proxy() own PROXY_LOCK".
  - 001328873c "MINOR: listener: small API change"
  - d46f437de6 "MINOR: proxy/listener: support for additional PAUSED state"

It should be backported to 2.6, 2.5 and 2.4

2 years agoMINOR: proxy/listener: support for additional PAUSED state
Aurelien DARRAGON [Fri, 9 Sep 2022 13:51:37 +0000 (15:51 +0200)] 
MINOR: proxy/listener: support for additional PAUSED state

This patch is a prerequisite for #1626.
Adding PAUSED state to the list of available proxy states.
The flag is set when the proxy is paused at runtime (pause_listener()).
It is cleared when the proxy is resumed (resume_listener()).

It should be backported to 2.6, 2.5 and 2.4

2 years agoMINOR: listener: small API change
Aurelien DARRAGON [Fri, 9 Sep 2022 13:32:57 +0000 (15:32 +0200)] 
MINOR: listener: small API change

A minor API change was performed in listener(.c/.h) to restore consistency
between stop_listener() and (resume/pause)_listener() functions.

LISTENER_LOCK was never locked prior to calling stop_listener():
lli variable hint is thus not useful anymore.

Added PROXY_LOCK locking in (resume/pause)_listener() functions
with related lpx variable hint (prerequisite for #1626).

It should be backported to 2.6, 2.5 and 2.4

2 years agoBUG/MEDIUM: proxy: ensure pause_proxy() and resume_proxy() own PROXY_LOCK
Aurelien DARRAGON [Thu, 8 Sep 2022 12:35:35 +0000 (14:35 +0200)] 
BUG/MEDIUM: proxy: ensure pause_proxy() and resume_proxy() own PROXY_LOCK

There was a race involving hlua_proxy_* functions
and some proxy management functions.

pause_proxy() and resume_proxy() can be used directly from lua code,
but that could lead to some race as lua code didn't make sure PROXY_LOCK
was owned before calling the proxy functions.

This patch makes sure it won't happen again elsewhere in the code
by locking PROXY_LOCK directly in resume and pause proxy functions
so that it's not the caller's responsibility anymore.
(based on stop_proxy() behavior that was already safe prior to the patch)

This should be backported to stable series.
Note that the API will likely differ < 2.4

2 years agoMINOR: flags/http_ana: use flag dumping to show http msg states
Willy Tarreau [Fri, 9 Sep 2022 15:18:57 +0000 (17:18 +0200)] 
MINOR: flags/http_ana: use flag dumping to show http msg states

The function is hmsg_show_flags(). It shows the HTTP_MSGF_* flags.

2 years agoMINOR: flags/htx: use flag dumping to show htx and start-line flags
Willy Tarreau [Fri, 9 Sep 2022 14:59:29 +0000 (16:59 +0200)] 
MINOR: flags/htx: use flag dumping to show htx and start-line flags

The function are respectively htx_show_flags() and hsl_show_flags().

2 years agoDEV: flags: remove the now useless intermediary functions
Willy Tarreau [Fri, 9 Sep 2022 14:47:43 +0000 (16:47 +0200)] 
DEV: flags: remove the now useless intermediary functions

There's no more point keeping functions that are just wrappers around
other ones, let's directly call them from the main entry point. It helps
visually control the mapping between output formats and their definition
and doesn't require to invent long names. For a bit more readability, the
tmpbuf and its size adopted slightly shorter names.

2 years agoDEV: flags: remove the now unused SHOW_FLAG() definition
Willy Tarreau [Fri, 9 Sep 2022 14:36:37 +0000 (16:36 +0200)] 
DEV: flags: remove the now unused SHOW_FLAG() definition

All dump functions were converted, no need to use this macro anymore.

2 years agoMINOR: flags/http_ana: use flag dumping for txn flags
Willy Tarreau [Fri, 9 Sep 2022 14:31:37 +0000 (16:31 +0200)] 
MINOR: flags/http_ana: use flag dumping for txn flags

The new function is txn_show_flags(). It dumps the TXN flags
as well as the client and server cookie types.

2 years agoMINOR: flags/task: use flag dumping for task state
Willy Tarreau [Fri, 9 Sep 2022 14:19:33 +0000 (16:19 +0200)] 
MINOR: flags/task: use flag dumping for task state

The new function is task_show_state().

2 years agoMINOR: flags/stream: use flag dumping for stream flags
Willy Tarreau [Fri, 9 Sep 2022 14:10:40 +0000 (16:10 +0200)] 
MINOR: flags/stream: use flag dumping for stream flags

The new function is strm_show_flags(). It dumps the stream flags
as well as the err type under SF_ERR_MASK and the final state under
SF_FINST_MASK.

2 years agoMINOR: flags/stream: use flag dumping for stream error type
Willy Tarreau [Fri, 9 Sep 2022 13:38:30 +0000 (15:38 +0200)] 
MINOR: flags/stream: use flag dumping for stream error type

The new function is strm_et_show_flags(). Only the error type is
handled at the moment, as a bit more complex logic is needed to
mix the values and enums present in some fields.

2 years agoMINOR: flags/stconn: use flag dumping for stconn and sedesc flags
Willy Tarreau [Fri, 9 Sep 2022 13:26:38 +0000 (15:26 +0200)] 
MINOR: flags/stconn: use flag dumping for stconn and sedesc flags

The two new functions are se_show_flags() and sc_show_flags().
Maybe something could be done for SC_ST_* values but as it's a
small enum, a simple switch/case should work fine.

2 years agoMINOR: flags/connection: use flag dumping for connection flags
Willy Tarreau [Fri, 9 Sep 2022 13:04:32 +0000 (15:04 +0200)] 
MINOR: flags/connection: use flag dumping for connection flags

The new function is conn_show_flags(), it only deals with flags. Nothing
is planned for connection error types at the moment.

2 years agoMINOR: flags/channel: use flag dumping for channel flags and analysers
Willy Tarreau [Fri, 9 Sep 2022 12:51:57 +0000 (14:51 +0200)] 
MINOR: flags/channel: use flag dumping for channel flags and analysers

The two new functions are chn_show_analysers() and chn_show_flags().
They work on an existing buffer so one was declared in flags.c for this
purpose. File flags.c does not have to know about channel flags anymore.

2 years agoMINOR: flags: implement a macro used to dump enums inside masks
Willy Tarreau [Fri, 9 Sep 2022 14:05:10 +0000 (16:05 +0200)] 
MINOR: flags: implement a macro used to dump enums inside masks

Some of our flags have enums inside a mask. The new macro __APPEND_ENUM
is able to deal with that by comparing the flag's value against an exact
one under the mask. One needs to take care of eliminating the zero value
though, otherwise delimiters will not always be properly placed (e.g. if
some flags were dumped before and what remains is exactly zero). The
bits of the mask are cleared only upon exact matches.

2 years agoMINOR: flags: add a new file to host flag dumping macros
Willy Tarreau [Fri, 9 Sep 2022 12:34:12 +0000 (14:34 +0200)] 
MINOR: flags: add a new file to host flag dumping macros

The "flags" utility is useful but painful to maintain up to date. This
commit aims at providing a low-maintenance solution to keep flags up to
date, by proposing some macros that build a string from a set of flags
in a way that requires the least possible verbosity.

The idea will be to add an inline function dedicated to this just after
the flags declaration, and enumerate the flags one is interested in, and
that function will fill a string based on them.

Placing this inside the type files allows both haproxy and external tools
like "flags" to use it, but comes with a few constraints. First, the
files will be slightly less readable if these functions are huge, so they
need to stay as compact as possible. Second, the function will need
anprintf() and we don't want to include stdio.h in type files as it
proved to be particularly heavy and to cause definition headaches in
the past.

As such the file here only contains a macro enclosed in #ifdef EOF (that
is defined in stdio), and provides an alternate empty one when no stdio
is defined. This way it's the caller that has to include stdio first or
it won't get anything back, and in practice the locations relying on
this always have it.

The macro has to be used in 3 steps:
  - prologue: dumps 0 and exits if the value is zero
  - flags: the macro can be recursively called and it will push the
    flag from bottom to top so that they appear in the same order as
    today without requiring to be declared the other way around
  - epilogue: dump remaining flags that were not identified

The macro was arranged so that a single character can be used with no
other argument to declare all flags at once. Example:

  #define _(n, ...) __APPEND_FLAG(buf, len, del, flg, n, #n, __VA_ARGS__)
     _(0);
     _(X_FLAG1, _(X_FLAG2, _(X_FLAG3, _(X_FLAG4))));
     _(~0);
  #undef _

Existing files will have to be updated to rely on it, and more files
could come soon.

2 years agoDEV: flags: add missing CO_FL_FDLESS connection flag
Willy Tarreau [Fri, 9 Sep 2022 12:46:15 +0000 (14:46 +0200)] 
DEV: flags: add missing CO_FL_FDLESS connection flag

This was added in 2.6 by commit c78a9698e ("MINOR: connection: add a new
flag CO_FL_FDLESS on fd-less connections") but forgotten in flags.c.
This must be backported to 2.6.

2 years agoDEV: flags: fix usage message to reflect available options
Willy Tarreau [Fri, 9 Sep 2022 12:16:49 +0000 (14:16 +0200)] 
DEV: flags: fix usage message to reflect available options

The proposed decoding options were not updated after the changes in 2.6,
let's fix that by taking the names from the existing declaration. This
should be backported to 2.6.

2 years agoCI: cirrus-ci: bump FreeBSD image to 13-1
Ilya Shipitsin [Thu, 8 Sep 2022 16:45:16 +0000 (21:45 +0500)] 
CI: cirrus-ci: bump FreeBSD image to 13-1

we use FreeBSD binary packages that we rebuilt for FreeBSD-13.1

Newer FreeBSD version for package zstd:
To ignore this error set IGNORE_OSVERSION=yes
- package: 1301000
- running kernel: 1300139

2 years agoBUG/MINOR: signals/poller: ensure wakeup from signals
Matthias Wirth [Fri, 9 Sep 2022 08:21:00 +0000 (10:21 +0200)] 
BUG/MINOR: signals/poller: ensure wakeup from signals

Add self-wake in signal_handler() to fix a race condition with a signal
coming in between checking signal_queue_len and entering polling sleep.

The changes in commit 43c891dda ("BUG/MINOR: signals/poller: set the
poller timeout to 0 when there are signals") were insufficient.

Move the signal_queue_len check from the poll implementations to
run_poll_loop() to keep that logic in one place.

The poll loops are terminated either by the parameter wake being set or
wake up due to a write to their poller_wr_pipe by wake_thread() in
signal_handler().

This fixes issue #1841.

Must be backported in every stable version.

2 years agoBUILD: udp-perturb: Add a make target for udp-perturb tool
Frédéric Lécaille [Thu, 8 Sep 2022 18:47:28 +0000 (20:47 +0200)] 
BUILD: udp-perturb: Add a make target for udp-perturb tool

This is only to rely on make to build this tool.

2 years agoMINOR: dev/udp: Apply the corruption to both directions
Frédéric Lécaille [Thu, 8 Sep 2022 18:38:59 +0000 (20:38 +0200)] 
MINOR: dev/udp: Apply the corruption to both directions

Harden the UDP datagram corruption applying it on both sides. This approaches
the conditions of some tests run by the QUIC interop runner developed by
Marten Seeman.

2 years agoMINOR: h3: Send the h3 settings with others streams (requests)
Frédéric Lécaille [Thu, 8 Sep 2022 15:53:36 +0000 (17:53 +0200)] 
MINOR: h3: Send the h3 settings with others streams (requests)

This is the ->finalize application callback which prepares the unidirectional STREAM
frames for h3 settings and wakeup the mux I/O handler to send them. As haproxy is
at the same time always waiting for the client request, this makes haproxy
call sendto() to send only about 20 bytes of stream data. Furthermore in case
of heavy loss, this give less chances to short h3 requests to succeed.

Drawback: as at this time the mux sends its streams by their IDs ascending order
the stream 0 is always embedded before the unidirectional stream 3 for h3 settings.
Nevertheless, as these settings may be lost and received after other h3 request
streams, this is permitted by the RFC.

Perhaps there is a better way to do. This will have to be checked with Amaury.

Must be backported to 2.6.

2 years agoMINOR: h3: Missing connection argument for a TRACE_LEAVE() argument
Frédéric Lécaille [Thu, 8 Sep 2022 14:04:55 +0000 (16:04 +0200)] 
MINOR: h3: Missing connection argument for a TRACE_LEAVE() argument

This should help in debbuging issues to be able to associate this trace to a
QUIC connection.

Must be backported to 2.6.

2 years agoMINOR: h3: Add the quic_conn object to h3 traces
Frédéric Lécaille [Thu, 8 Sep 2022 14:03:13 +0000 (16:03 +0200)] 
MINOR: h3: Add the quic_conn object to h3 traces

This is very useful to associate h3 traces to a QUIC connection when debugging.

Must be backported to 2.6.

2 years agoBUG/MINOR: h3: Crash when h3 trace verbosity is "minimal"
Frédéric Lécaille [Thu, 8 Sep 2022 13:49:37 +0000 (15:49 +0200)] 
BUG/MINOR: h3: Crash when h3 trace verbosity is "minimal"

This was due to a missing check in h3_trace() about the first argument
presence (connection) and h3_parse_settings_frm() which calls TRACE_LEAVE()
without any argument. Then this argument was dereferenced.

Must be backported to 2.6

2 years agoBUG/MINOR: quic: Trace fix about packet number space information.
Frédéric Lécaille [Thu, 8 Sep 2022 07:52:14 +0000 (09:52 +0200)] 
BUG/MINOR: quic: Trace fix about packet number space information.

<qc> variable was confused with <qel>. The consequence was that it was
always the same packet number space which was displayed: the first one (or
the Initial packet number space).

Must be backported to 2.6.

2 years agoBUG/MINOR: quic: Speed up the handshake completion only one time
Frédéric Lécaille [Wed, 7 Sep 2022 15:34:18 +0000 (17:34 +0200)] 
BUG/MINOR: quic: Speed up the handshake completion only one time

It is possible to speed up the handshake completion but only one time
by connection as mentionned in RFC 9002 "6.2.3. Speeding up Handshake Completion".
Add a flag to prevent this process to be run several times
(see https://www.rfc-editor.org/rfc/rfc9002#name-speeding-up-handshake-compl).

Must be backported to 2.6.

2 years agoBUG/MINOR: signals/poller: set the poller timeout to 0 when there are signals
William Lallemand [Thu, 8 Sep 2022 15:46:31 +0000 (17:46 +0200)] 
BUG/MINOR: signals/poller: set the poller timeout to 0 when there are signals

When receiving a signal before entering the poller, and without any
activity in the process, the poller will be entered with a timeout
calculated without checking the signals.

Since commit 4f59d3 ("MINOR: time: increase the minimum wakeup interval
to 60s") the issue is much more visible because it could be stuck for
60s.

When in mworker mode, if a worker quits and the SIGCHLD signal deliver
at the right time to the master, this one could be stuck for the time of
the timeout.

This should fix issue #1841

Must be backported in every stable version.

2 years agoMINOR: activity/cli: support sorting task profiling by total CPU time
Willy Tarreau [Thu, 8 Sep 2022 14:38:10 +0000 (16:38 +0200)] 
MINOR: activity/cli: support sorting task profiling by total CPU time

The new "bytime" sorting criterion uses the reported CPU time instead of
the usage. This is convenient to spot tasks that are mostly reponsible
for the CPU usage in a running process. It supports both the detailed
and the aggregated format. The output looks like this:

> show profiling tasks bytime
Tasks activity:
  function                      calls   cpu_tot   cpu_avg   lat_tot   lat_avg
  qc_io_cb                     117739   1.961m    999.1us   37.45s    318.1us <- h3_snd_buf@src/h3.c:1084 tasklet_wakeup
  process_stream              7376273   1.384m    11.26us   1.013h    494.2us <- stream_new@src/stream.c:563 task_wakeup
  process_stream              8104400   1.133m    8.389us   1.130h    502.0us <- sc_notify@src/stconn.c:1209 task_wakeup
  qc_io_cb                      43280   45.76s    1.057ms   13.95s    322.3us <- qc_stream_desc_ack@src/quic_stream.c:128 tasklet_wakeup
  h1_io_cb                   11025715   24.82s    2.251us   5.406m    29.42us <- sock_conn_iocb@src/sock.c:869 tasklet_wakeup
  quic_conn_app_io_cb          312861   23.86s    76.27us   2.373s    7.584us <- qc_lstnr_pkt_rcv@src/xprt_quic.c:6184 tasklet_wakeup_after
  qc_io_cb                      37063   12.65s    341.4us   6.409s    172.9us <- qc_treat_acked_tx_frm@src/xprt_quic.c:1695 tasklet_wakeup
  h1_io_cb                    4783520   11.79s    2.463us   1.419h    1.068ms <- conn_subscribe@src/connection.c:732 tasklet_wakeup
  sc_conn_io_cb              12269693   11.51s    938.0ns   2.117h    621.2us <- sc_app_chk_rcv_conn@src/stconn.c:762 tasklet_wakeup
  sc_conn_io_cb               6479006   10.94s    1.689us   7.984m    73.93us <- h1_wake_stream_for_recv@src/mux_h1.c:2600 tasklet_wakeup
  qc_io_cb                      12011   10.72s    892.5us   2.120s    176.5us <- qcc_release_remote_stream@src/mux_quic.c:1200 tasklet_wakeup
  h2_io_cb                     246423   6.225s    25.26us   56.52s    229.4us <- h2_snd_buf@src/mux_h2.c:6712 tasklet_wakeup
  h2_io_cb                     137744   6.076s    44.11us   16.59s    120.4us <- sock_conn_iocb@src/sock.c:869 tasklet_wakeup
  quic_lstnr_dghdlr            323575   3.062s    9.462us   3.424m    634.9us <- quic_lstnr_dgram_dispatch@src/quic_sock.c:255 tasklet_wakeup
  sc_conn_io_cb               1206939   1.616s    1.338us   27.62m    1.373ms <- qcs_notify_send@src/mux_quic.c:529 tasklet_wakeup
  h2_io_cb                     212370   251.2ms   1.182us   6.476s    30.49us <- h2c_restart_reading@src/mux_h2.c:856 tasklet_wakeup
  h1_io_cb                      44109   197.0ms   4.466us   31.89s    723.0us <- h1_takeover@src/mux_h1.c:4085 tasklet_wakeup
  quic_conn_app_io_cb            3029   87.59ms   28.92us   999.0ms   329.8us <- qc_process_timer@src/xprt_quic.c:4635 tasklet_wakeup
  task_run_applet                  40   35.77ms   894.3us   4.407ms   110.2us <- sc_applet_create@src/stconn.c:489 appctx_wakeup
  task_run_applet                  18   27.36ms   1.520ms   19.56us   1.086us <- sc_app_chk_snd_applet@src/stconn.c:996 appctx_wakeup
  sc_conn_io_cb                  2186   11.76ms   5.377us   963.0ms   440.5us <- h1_wake_stream_for_send@src/mux_h1.c:2610 tasklet_wakeup
  qc_io_cb                          8   9.880ms   1.235ms   5.871ms   733.9us <- qcs_consume@src/mux_quic.c:800 tasklet_wakeup
  quic_conn_io_cb                   4   5.951ms   1.488ms   38.85us   9.713us <- qc_lstnr_pkt_rcv@src/xprt_quic.c:6184 tasklet_wakeup_after
  qc_io_cb                        101   4.975ms   49.26us   13.91ms   137.8us <- qc_process_timer@src/xprt_quic.c:4602 tasklet_wakeup
  h1_io_cb                       2186   1.809ms   827.0ns   720.2ms   329.5us <- sock_conn_iocb@src/sock.c:849 tasklet_wakeup
  qc_process_timer               3031   1.735ms   572.0ns   1.153s    380.3us <- wake_expired_tasks@src/task.c:344 task_wakeup
  accept_queue_process            359   1.362ms   3.793us   80.32ms   223.7us <- listener_accept@src/listener.c:1099 tasklet_wakeup
  quic_conn_app_io_cb               2   921.1us   460.6us   203.1us   101.5us <- qc_xprt_start@src/xprt_quic.c:7122 tasklet_wakeup
  h1_timeout_task                2618   526.8us   201.0ns   1.121s    428.4us <- h1_release@src/mux_h1.c:1087 task_wakeup
  process_resolvers               316   283.3us   896.0ns   14.96ms   47.33us <- wake_expired_tasks@src/task.c:429 task_drop_running
  sc_conn_io_cb                   420   235.6us   560.0ns   116.7ms   277.8us <- h2s_notify_recv@src/mux_h2.c:1298 tasklet_wakeup
  qc_idle_timer_task                1   225.5us   225.5us   506.0ns   506.0ns <- wake_expired_tasks@src/task.c:344 task_wakeup
  accept_queue_process             36   153.0us   4.250us   5.834ms   162.1us <- accept_queue_process@src/listener.c:165 tasklet_wakeup
  sc_conn_io_cb                    18   54.05us   3.003us   11.50us   638.0ns <- sock_conn_iocb@src/sock.c:869 tasklet_wakeup
  h2_io_cb                          6   38.88us   6.480us   2.089ms   348.2us <- h2_do_shutw@src/mux_h2.c:4656 tasklet_wakeup
  srv_cleanup_idle_conns           54   37.72us   698.0ns   14.21ms   263.1us <- wake_expired_tasks@src/task.c:429 task_drop_running
  sc_conn_io_cb                    50   32.86us   657.0ns   28.83ms   576.5us <- qcs_notify_recv@src/mux_quic.c:519 tasklet_wakeup
  qc_io_cb                          2   30.25us   15.12us   6.093us   3.046us <- qc_init@src/mux_quic.c:2057 tasklet_wakeup
  srv_cleanup_toremove_conns        1   27.16us   27.16us   905.6us   905.6us <- srv_cleanup_idle_conns@src/server.c:5948 task_wakeup
  task_run_applet                  39   19.61us   502.0ns   818.7us   20.99us <- run_tasks_from_lists@src/task.c:652 task_drop_running
  quic_accept_run                   2   15.46us   7.727us   305.5us   152.8us <- quic_accept_push_qc@src/quic_sock.c:458 tasklet_wakeup
  h2_timeout_task                  32   12.91us   403.0ns   4.207ms   131.5us <- h2_release@src/mux_h2.c:1191 task_wakeup
  quic_conn_app_io_cb               1   9.645us   9.645us   1.445us   1.445us <- qc_process_timer@src/xprt_quic.c:4589 tasklet_wakeup

> show profiling tasks bytime aggr
Tasks activity:
  function                      calls   cpu_tot   cpu_avg   lat_tot   lat_avg
  qc_io_cb                     212301   3.147m    889.5us   1.009m    285.2us
  process_stream             15503573   2.519m    9.747us   2.148h    498.7us
  h1_io_cb                   15916733   36.95s    2.321us   1.535h    347.1us
  quic_conn_app_io_cb          318845   24.21s    75.92us   3.410s    10.70us
  sc_conn_io_cb              20037058   24.19s    1.207us   2.737h    491.8us
  h2_io_cb                     596543   12.55s    21.04us   1.326m    133.4us
  quic_lstnr_dghdlr            326624   3.094s    9.473us   3.462m    635.9us
  task_run_applet                 100   64.43ms   644.3us   5.285ms   52.85us
  quic_conn_io_cb                   4   5.951ms   1.488ms   38.85us   9.713us
  qc_process_timer               3061   1.750ms   571.0ns   1.162s    379.5us
  accept_queue_process            396   1.521ms   3.840us   86.16ms   217.6us
  h1_timeout_task                2618   526.8us   201.0ns   1.121s    428.4us
  process_resolvers               319   286.0us   896.0ns   16.82ms   52.73us
  qc_idle_timer_task                1   225.5us   225.5us   506.0ns   506.0ns
  srv_cleanup_idle_conns           54   37.72us   698.0ns   14.21ms   263.1us
  srv_cleanup_toremove_conns        1   27.16us   27.16us   905.6us   905.6us
  quic_accept_run                   2   15.46us   7.727us   305.5us   152.8us
  h2_timeout_task                  32   12.91us   403.0ns   4.207ms   131.5us

2 years agoMINOR: activity/cli: support aggregating task profiling outputs
Willy Tarreau [Thu, 8 Sep 2022 14:05:57 +0000 (16:05 +0200)] 
MINOR: activity/cli: support aggregating task profiling outputs

By default we now dump stats between caller and callee, but by
specifying "aggr" on the command line, stats get aggregated by
callee again as it used to be before the feature was available.
It may sometimes be helpful when comparing total call counts,
though that's about all.

2 years agoMINOR: tasks/activity: improve the caller-callee activity hash
Willy Tarreau [Wed, 7 Sep 2022 16:54:30 +0000 (18:54 +0200)] 
MINOR: tasks/activity: improve the caller-callee activity hash

The previous dump already showed that the "other" category was getting
a few entries. Let's proceed like for the memory profiling, by scanning
a limited range of adjacent slots to find a spare one (16 max). That's
pretty fast since close and likely prefetched and the comparison is
cheap. The new dump now shows up to 45 entries below without "other":

Now:
Tasks activity:
  function                      calls   cpu_tot   cpu_avg   lat_tot   lat_avg
  task_run_applet                  22   34.56ms   1.571ms   1.145ms   52.04us <- sc_applet_create@src/stconn.c:489 appctx_wakeup
  task_run_applet                  21   11.11us   529.0ns   2.590ms   123.3us <- run_tasks_from_lists@src/task.c:652 task_drop_running
  task_run_applet                   5   7.715ms   1.543ms   2.186us   437.0ns <- sc_app_chk_snd_applet@src/stconn.c:996 appctx_wakeup
  accept_queue_process            345   3.129ms   9.068us   72.84ms   211.1us <- listener_accept@src/listener.c:1099 tasklet_wakeup
  accept_queue_process             32   113.0us   3.529us   3.070ms   95.94us <- accept_queue_process@src/listener.c:165 tasklet_wakeup
  sc_conn_io_cb               5026032   3.037s    604.0ns   17.47m    208.5us <- sc_app_chk_rcv_conn@src/stconn.c:762 tasklet_wakeup
  sc_conn_io_cb               4361192   7.626s    1.748us   3.179m    43.74us <- h1_wake_stream_for_recv@src/mux_h1.c:2600 tasklet_wakeup
  sc_conn_io_cb                178293   275.4ms   1.544us   2.740m    922.0us <- qcs_notify_send@src/mux_quic.c:529 tasklet_wakeup
  sc_conn_io_cb                  2561   15.84ms   6.185us   1.036s    404.4us <- h1_wake_stream_for_send@src/mux_h1.c:2610 tasklet_wakeup
  sc_conn_io_cb                   453   261.4us   577.0ns   86.79ms   191.6us <- h2s_notify_recv@src/mux_h2.c:1298 tasklet_wakeup
  sc_conn_io_cb                    89   50.05us   562.0ns   100.7ms   1.131ms <- qcs_notify_recv@src/mux_quic.c:519 tasklet_wakeup
  sc_conn_io_cb                     8   19.04us   2.379us   472.5us   59.06us <- sock_conn_iocb@src/sock.c:869 tasklet_wakeup
  process_resolvers                50   57.50us   1.149us   1.116ms   22.32us <- wake_expired_tasks@src/task.c:429 task_drop_running
  srv_cleanup_idle_conns            8   5.669us   708.0ns   216.6us   27.08us <- wake_expired_tasks@src/task.c:429 task_drop_running
  process_stream              4599847   48.79s    10.61us   16.92m    220.7us <- sc_notify@src/stconn.c:1209 task_wakeup
  process_stream              4530081   52.82s    11.66us   14.92m    197.6us <- stream_new@src/stream.c:563 task_wakeup
  process_stream                   15   201.7us   13.45us   31.58ms   2.105ms <- sc_app_chk_snd_conn@src/stconn.c:857 task_wakeup
  h1_io_cb                    7861205   18.22s    2.317us   2.408m    18.38us <- sock_conn_iocb@src/sock.c:869 tasklet_wakeup
  h1_io_cb                     474763   1.379s    2.905us   6.578m    831.4us <- conn_subscribe@src/connection.c:732 tasklet_wakeup
  h1_io_cb                      34830   38.64ms   1.109us   18.85s    541.2us <- h1_takeover@src/mux_h1.c:4085 tasklet_wakeup
  h1_io_cb                       2561   2.150ms   839.0ns   674.4ms   263.3us <- sock_conn_iocb@src/sock.c:849 tasklet_wakeup
  h1_timeout_task                2634   588.5us   223.0ns   890.5ms   338.1us <- h1_release@src/mux_h1.c:1087 task_wakeup
  h2_timeout_task                  16   7.519us   469.0ns   1.146ms   71.63us <- h2_release@src/mux_h2.c:1191 task_wakeup
  h2_io_cb                      99601   2.212s    22.21us   19.33s    194.1us <- h2_snd_buf@src/mux_h2.c:6712 tasklet_wakeup
  h2_io_cb                      79777   146.6ms   1.837us   3.529s    44.24us <- h2c_restart_reading@src/mux_h2.c:856 tasklet_wakeup
  h2_io_cb                      60698   2.259s    37.21us   4.704s    77.50us <- sock_conn_iocb@src/sock.c:869 tasklet_wakeup
  h2_io_cb                          5   36.90us   7.380us   2.045ms   409.0us <- h2_do_shutw@src/mux_h2.c:4656 tasklet_wakeup
  qc_io_cb                      26595   8.007s    301.1us   4.261s    160.2us <- qc_treat_acked_tx_frm@src/xprt_quic.c:1695 tasklet_wakeup
  qc_io_cb                       7921   5.284s    667.1us   2.171s    274.1us <- qc_stream_desc_ack@src/quic_stream.c:128 tasklet_wakeup
  qc_io_cb                       6229   5.851s    939.3us   1.856s    297.9us <- h3_snd_buf@src/h3.c:1084 tasklet_wakeup
  qc_io_cb                        994   699.1ms   703.3us   174.9ms   176.0us <- qcc_release_remote_stream@src/mux_quic.c:1200 tasklet_wakeup
  qc_io_cb                         65   9.883ms   152.0us   13.33ms   205.1us <- qc_process_timer@src/xprt_quic.c:4602 tasklet_wakeup
  qc_io_cb                          1   293.5us   293.5us   105.9us   105.9us <- qcs_consume@src/mux_quic.c:800 tasklet_wakeup
  qc_io_cb                          1   10.87us   10.87us   3.307us   3.307us <- qc_init@src/mux_quic.c:2057 tasklet_wakeup
  quic_conn_io_cb                   2   2.531ms   1.265ms   2.839us   1.419us <- qc_lstnr_pkt_rcv@src/xprt_quic.c:6184 tasklet_wakeup_after
  quic_conn_app_io_cb           61392   2.620s    42.67us   268.0ms   4.365us <- qc_lstnr_pkt_rcv@src/xprt_quic.c:6184 tasklet_wakeup_after
  quic_conn_app_io_cb             408   10.56ms   25.88us   124.0ms   303.8us <- qc_process_timer@src/xprt_quic.c:4635 tasklet_wakeup
  quic_conn_app_io_cb               2   15.61us   7.806us   103.2us   51.59us <- qc_process_timer@src/xprt_quic.c:4589 tasklet_wakeup
  quic_conn_app_io_cb               1   410.6us   410.6us   11.52us   11.52us <- qc_xprt_start@src/xprt_quic.c:7122 tasklet_wakeup
  quic_lstnr_dghdlr             62716   409.2ms   6.523us   21.81s    347.8us <- quic_lstnr_dgram_dispatch@src/quic_sock.c:255 tasklet_wakeup
  qc_process_timer                410   245.4us   598.0ns   238.5ms   581.7us <- wake_expired_tasks@src/task.c:344 task_wakeup
  quic_accept_run                   1   7.711us   7.711us   82.28us   82.28us <- quic_accept_push_qc@src/quic_sock.c:458 tasklet_wakeup

2 years agoMEDIUM: tasks/activity: combine the called function with the caller
Willy Tarreau [Wed, 7 Sep 2022 16:37:47 +0000 (18:37 +0200)] 
MEDIUM: tasks/activity: combine the called function with the caller

Now instead of getting aggregate stats per called function, we have
them per function AND per call place. The "byaddr" sort considers
the function pointer first, then the call count, so that dominant
callers of a given callee are instantly spotted. This allows to get
sorted outputs like this:

Tasks activity:
  function                      calls   cpu_tot   cpu_avg   lat_tot   lat_avg
  h1_io_cb                   17357952   40.91s    2.357us   4.849m    16.76us <- sock_conn_iocb@src/sock.c:869 tasklet_wakeup
  sc_conn_io_cb              10357182   6.297s    607.0ns   27.93m    161.8us <- sc_app_chk_rcv_conn@src/stconn.c:762 tasklet_wakeup
  process_stream              9891131   1.809m    10.97us   53.61m    325.2us <- sc_notify@src/stconn.c:1209 task_wakeup
  process_stream              9823934   1.887m    11.52us   48.31m    295.1us <- stream_new@src/stream.c:563 task_wakeup
  sc_conn_io_cb               9347863   16.59s    1.774us   6.143m    39.43us <- h1_wake_stream_for_recv@src/mux_h1.c:2600 tasklet_wakeup
  h1_io_cb                     501344   1.848s    3.686us   6.544m    783.2us <- conn_subscribe@src/connection.c:732 tasklet_wakeup
  sc_conn_io_cb                239717   492.3ms   2.053us   3.213m    804.3us <- qcs_notify_send@src/mux_quic.c:529 tasklet_wakeup
  h2_io_cb                     173019   4.204s    24.30us   40.95s    236.7us <- h2_snd_buf@src/mux_h2.c:6712 tasklet_wakeup
  h2_io_cb                     149487   424.3ms   2.838us   14.63s    97.87us <- h2c_restart_reading@src/mux_h2.c:856 tasklet_wakeup
  other                        101893   4.626s    45.40us   14.84s    145.7us
  quic_lstnr_dghdlr             94389   614.0ms   6.504us   30.54s    323.6us <- quic_lstnr_dgram_dispatch@src/quic_sock.c:255 tasklet_wakeup
  quic_conn_app_io_cb           92205   3.735s    40.51us   390.9ms   4.239us <- qc_lstnr_pkt_rcv@src/xprt_quic.c:6184 tasklet_wakeup_after
  qc_io_cb                      50355   19.01s    377.5us   10.65s    211.4us <- qc_treat_acked_tx_frm@src/xprt_quic.c:1695 tasklet_wakeup
  h1_io_cb                      44427   155.0ms   3.489us   21.50s    484.0us <- h1_takeover@src/mux_h1.c:4085 tasklet_wakeup
  qc_io_cb                       9018   4.924s    546.0us   3.084s    342.0us <- qc_stream_desc_ack@src/quic_stream.c:128 tasklet_wakeup
  h1_timeout_task                3236   1.172ms   362.0ns   1.119s    345.9us <- h1_release@src/mux_h1.c:1087 task_wakeup
  h1_io_cb                       2804   7.974ms   2.843us   1.980s    706.0us <- sock_conn_iocb@src/sock.c:849 tasklet_wakeup
  sc_conn_io_cb                  2804   33.44ms   11.92us   2.597s    926.2us <- h1_wake_stream_for_send@src/mux_h1.c:2610 tasklet_wakeup
  qc_io_cb                       2623   2.669s    1.017ms   1.347s    513.5us <- h3_snd_buf@src/h3.c:1084 tasklet_wakeup
  qc_process_timer                662   526.4us   795.0ns   1.081s    1.633ms <- wake_expired_tasks@src/task.c:344 task_wakeup
  quic_conn_app_io_cb             648   12.62ms   19.47us   225.7ms   348.2us <- qc_process_timer@src/xprt_quic.c:4635 tasklet_wakeup
  accept_queue_process            286   1.571ms   5.494us   72.55ms   253.7us <- listener_accept@src/listener.c:1099 tasklet_wakeup
  process_resolvers               176   157.8us   896.0ns   7.835ms   44.52us <- wake_expired_tasks@src/task.c:429 task_drop_running
  qc_io_cb                        167   10.71ms   64.12us   32.47ms   194.4us <- qc_process_timer@src/xprt_quic.c:4602 tasklet_wakeup
  sc_conn_io_cb                   123   80.05us   650.0ns   50.35ms   409.4us <- qcs_notify_recv@src/mux_quic.c:519 tasklet_wakeup
  h2_timeout_task                  32   30.69us   958.0ns   9.038ms   282.4us <- h2_release@src/mux_h2.c:1191 task_wakeup
  task_run_applet                  24   33.79ms   1.408ms   5.838ms   243.3us <- sc_applet_create@src/stconn.c:489 appctx_wakeup
  accept_queue_process             17   56.34us   3.314us   7.505ms   441.5us <- accept_queue_process@src/listener.c:165 tasklet_wakeup
  srv_cleanup_toremove_conns       16   1.133ms   70.81us   5.685ms   355.3us <- srv_cleanup_idle_conns@src/server.c:5948 task_wakeup
  srv_cleanup_idle_conns           16   74.57us   4.660us   2.797ms   174.8us <- wake_expired_tasks@src/task.c:429 task_drop_running
  quic_conn_app_io_cb              12   786.9us   65.58us   2.042ms   170.1us <- qc_process_timer@src/xprt_quic.c:4589 tasklet_wakeup
  sc_conn_io_cb                     9   20.55us   2.283us   2.475ms   275.0us <- sock_conn_iocb@src/sock.c:869 tasklet_wakeup
  h2_io_cb                          8   34.12us   4.265us   1.784ms   223.0us <- h2_do_shutw@src/mux_h2.c:4656 tasklet_wakeup
  task_run_applet                   4   6.615ms   1.654ms   2.306us   576.0ns <- sc_app_chk_snd_applet@src/stconn.c:996 appctx_wakeup
  quic_conn_io_cb                   4   4.278ms   1.069ms   6.469us   1.617us <- qc_lstnr_pkt_rcv@src/xprt_quic.c:6184 tasklet_wakeup_after
  qc_io_cb                          2   20.81us   10.40us   4.943us   2.471us <- qc_init@src/mux_quic.c:2057 tasklet_wakeup
  quic_conn_app_io_cb               2   752.9us   376.4us   63.97us   31.99us <- qc_xprt_start@src/xprt_quic.c:7122 tasklet_wakeup
  quic_accept_run                   2   13.84us   6.920us   172.8us   86.42us <- quic_accept_push_qc@src/quic_sock.c:458 tasklet_wakeup
  qc_idle_timer_task                2   295.0us   147.5us   8.761us   4.380us <- wake_expired_tasks@src/task.c:344 task_wakeup
  qc_io_cb                          1   867.1us   867.1us   812.8us   812.8us <- qcs_consume@src/mux_quic.c:800 tasklet_wakeup

... and calls sorted by address like this:

Tasks activity:
  function                      calls   cpu_tot   cpu_avg   lat_tot   lat_avg
  task_run_applet                  23   32.73ms   1.423ms   5.837ms   253.8us <- sc_applet_create@src/stconn.c:489 appctx_wakeup
  task_run_applet                   4   6.615ms   1.654ms   2.306us   576.0ns <- sc_app_chk_snd_applet@src/stconn.c:996 appctx_wakeup
  accept_queue_process            285   1.566ms   5.495us   72.49ms   254.3us <- listener_accept@src/listener.c:1099 tasklet_wakeup
  accept_queue_process             17   56.34us   3.314us   7.505ms   441.5us <- accept_queue_process@src/listener.c:165 tasklet_wakeup
  sc_conn_io_cb              10357182   6.297s    607.0ns   27.93m    161.8us <- sc_app_chk_rcv_conn@src/stconn.c:762 tasklet_wakeup
  sc_conn_io_cb               9347863   16.59s    1.774us   6.143m    39.43us <- h1_wake_stream_for_recv@src/mux_h1.c:2600 tasklet_wakeup
  sc_conn_io_cb                239717   492.3ms   2.053us   3.213m    804.3us <- qcs_notify_send@src/mux_quic.c:529 tasklet_wakeup
  sc_conn_io_cb                  2804   33.44ms   11.92us   2.597s    926.2us <- h1_wake_stream_for_send@src/mux_h1.c:2610 tasklet_wakeup
  sc_conn_io_cb                   123   80.05us   650.0ns   50.35ms   409.4us <- qcs_notify_recv@src/mux_quic.c:519 tasklet_wakeup
  sc_conn_io_cb                     9   20.55us   2.283us   2.475ms   275.0us <- sock_conn_iocb@src/sock.c:869 tasklet_wakeup
  process_resolvers               159   145.9us   917.0ns   7.823ms   49.20us <- wake_expired_tasks@src/task.c:429 task_drop_running
  srv_cleanup_idle_conns           16   74.57us   4.660us   2.797ms   174.8us <- wake_expired_tasks@src/task.c:429 task_drop_running
  srv_cleanup_toremove_conns       16   1.133ms   70.81us   5.685ms   355.3us <- srv_cleanup_idle_conns@src/server.c:5948 task_wakeup
  process_stream              9891130   1.809m    10.97us   53.61m    325.2us <- sc_notify@src/stconn.c:1209 task_wakeup
  process_stream              9823933   1.887m    11.52us   48.31m    295.1us <- stream_new@src/stream.c:563 task_wakeup
  h1_io_cb                   17357952   40.91s    2.357us   4.849m    16.76us <- sock_conn_iocb@src/sock.c:869 tasklet_wakeup
  h1_io_cb                     501344   1.848s    3.686us   6.544m    783.2us <- conn_subscribe@src/connection.c:732 tasklet_wakeup
  h1_io_cb                      44427   155.0ms   3.489us   21.50s    484.0us <- h1_takeover@src/mux_h1.c:4085 tasklet_wakeup
  h1_io_cb                       2804   7.974ms   2.843us   1.980s    706.0us <- sock_conn_iocb@src/sock.c:849 tasklet_wakeup
  h1_timeout_task                3236   1.172ms   362.0ns   1.119s    345.9us <- h1_release@src/mux_h1.c:1087 task_wakeup
  h2_timeout_task                  32   30.69us   958.0ns   9.038ms   282.4us <- h2_release@src/mux_h2.c:1191 task_wakeup
  h2_io_cb                     173019   4.204s    24.30us   40.95s    236.7us <- h2_snd_buf@src/mux_h2.c:6712 tasklet_wakeup
  h2_io_cb                     149487   424.3ms   2.838us   14.63s    97.87us <- h2c_restart_reading@src/mux_h2.c:856 tasklet_wakeup
  h2_io_cb                          8   34.12us   4.265us   1.784ms   223.0us <- h2_do_shutw@src/mux_h2.c:4656 tasklet_wakeup
  qc_io_cb                      50355   19.01s    377.5us   10.65s    211.4us <- qc_treat_acked_tx_frm@src/xprt_quic.c:1695 tasklet_wakeup
  qc_io_cb                       9018   4.924s    546.0us   3.084s    342.0us <- qc_stream_desc_ack@src/quic_stream.c:128 tasklet_wakeup
  qc_io_cb                       2623   2.669s    1.017ms   1.347s    513.5us <- h3_snd_buf@src/h3.c:1084 tasklet_wakeup
  qc_io_cb                        167   10.71ms   64.12us   32.47ms   194.4us <- qc_process_timer@src/xprt_quic.c:4602 tasklet_wakeup
  qc_io_cb                          2   20.81us   10.40us   4.943us   2.471us <- qc_init@src/mux_quic.c:2057 tasklet_wakeup
  qc_io_cb                          1   867.1us   867.1us   812.8us   812.8us <- qcs_consume@src/mux_quic.c:800 tasklet_wakeup
  qc_idle_timer_task                2   295.0us   147.5us   8.761us   4.380us <- wake_expired_tasks@src/task.c:344 task_wakeup
  quic_conn_io_cb                   4   4.278ms   1.069ms   6.469us   1.617us <- qc_lstnr_pkt_rcv@src/xprt_quic.c:6184 tasklet_wakeup_after
  quic_conn_app_io_cb           92205   3.735s    40.51us   390.9ms   4.239us <- qc_lstnr_pkt_rcv@src/xprt_quic.c:6184 tasklet_wakeup_after
  quic_conn_app_io_cb             648   12.62ms   19.47us   225.7ms   348.2us <- qc_process_timer@src/xprt_quic.c:4635 tasklet_wakeup
  quic_conn_app_io_cb              12   786.9us   65.58us   2.042ms   170.1us <- qc_process_timer@src/xprt_quic.c:4589 tasklet_wakeup
  quic_conn_app_io_cb               2   752.9us   376.4us   63.97us   31.99us <- qc_xprt_start@src/xprt_quic.c:7122 tasklet_wakeup
  quic_lstnr_dghdlr             94389   614.0ms   6.504us   30.54s    323.6us <- quic_lstnr_dgram_dispatch@src/quic_sock.c:255 tasklet_wakeup
  qc_process_timer                662   526.4us   795.0ns   1.081s    1.633ms <- wake_expired_tasks@src/task.c:344 task_wakeup
  quic_accept_run                   2   13.84us   6.920us   172.8us   86.42us <- quic_accept_push_qc@src/quic_sock.c:458 tasklet_wakeup
  other                        101892   4.626s    45.40us   14.84s    145.7us

It already becomes visible that some tasks have different very costs
depending where they're called (e.g. process_stream). The method used
to wake them up is also shown. Applets are handled specially and shown
as appctx_wakeup.

2 years agoDEBUG: quic: export the few task handlers that often appear in task dumps
Willy Tarreau [Thu, 8 Sep 2022 13:12:59 +0000 (15:12 +0200)] 
DEBUG: quic: export the few task handlers that often appear in task dumps

The following task/tasklet handlers often appear in "show profiling tasks"
but were not resolved since static:

 qc_io_cb, quic_conn_app_io_cb, process_timer,
 quic_accept_run, qc_idle_timer_task

This commit simply exports them so they can be resolved now. "process_timer"
which was a bit too generic and renamed to qc_process_timer.

2 years agoDEBUG: resolvers: unstatify process_resolvers() to make it appear in profiling
Willy Tarreau [Thu, 8 Sep 2022 13:07:13 +0000 (15:07 +0200)] 
DEBUG: resolvers: unstatify process_resolvers() to make it appear in profiling

The function appears like this in "show profiling tasks", so let's export
it:

  function       calls  cpu_tot  cpu_avg  lat_tot  lat_avg
  main+0x1463f0     92  77.28us  839.0ns  2.018ms  21.93us <- wake_expired_tasks@src/task.c:429 task_drop_running

2 years agoCLEANUP: activity: make the number of sched activity entries more configurable
Willy Tarreau [Wed, 7 Sep 2022 16:49:55 +0000 (18:49 +0200)] 
CLEANUP: activity: make the number of sched activity entries more configurable

This removes all the hard-coded 8-bit and 256 entries to use a pair of
macros instead so that we can more easily experiment with larger table
sizes if needed.

2 years agoCLEANUP: sched: remove duplicate code in run_tasks_from_list()
Willy Tarreau [Wed, 7 Sep 2022 15:06:16 +0000 (17:06 +0200)] 
CLEANUP: sched: remove duplicate code in run_tasks_from_list()

Now that ->wake_date is common to tasks and tasklets, we don't need
anymore to carry a duplicate control block to read and update it for
tasks and tasklets. And given that this code was present early in the
if/else fork between tasks and tasklets, taking it out of the block
allows to move the task part into a more visible "else" branch that
also allows to factor the epilogue that resets th_ctx->current and
updates profile_entry->cpu_time, which also used to be duplicated.

Overall, doing just that saved 253 bytes in the function, or ~1/6,
which is not bad considering that it's on a hot path. And the code
got much ore readable.

2 years agoCLEANUP: task: move tid and wake_date into the common part
Willy Tarreau [Wed, 7 Sep 2022 14:43:01 +0000 (16:43 +0200)] 
CLEANUP: task: move tid and wake_date into the common part

There used to be one tid for tasklets and a thread_mask for tasks. Since
2.7, both tasks and tasklets now use a tid (albeit with a very slight
semantic difference for the negative value), to in order to limit code
duplication and to ease debugging it makes sense to move tid into the
common part. One limitation is that it will leave a hole in the structure,
but we now have the wake_date that is always present and can move there as
well to plug the hole.

This results in something overall pretty clean (and cleaner than before),
with the low-level stuff (state,tid,process,context) appearing first, then
the caller stuff (caller,wake_date,calls,debug) next, and finally the
type-specific stuff (rq/wq/expire/nice).

2 years agoDEBUG: task: simplify the caller recording in DEBUG_TASK
Willy Tarreau [Tue, 6 Sep 2022 09:11:47 +0000 (11:11 +0200)] 
DEBUG: task: simplify the caller recording in DEBUG_TASK

Instead of storing an index that's swapped at every call, let's use the
two pointers as a shifting history. Now we have a permanent "caller"
field that records the last caller, and an optional prev_caller in the
debug section enabled by DEBUG_TASK that keeps a copy of the previous
caller one. This way, not only it's much easier to follow what's
happening during debugging, but it saves 8 bytes in the struct task in
debug mode and still keeps it under 2 cache lines in nominal mode, and
this will finally be usable everywhere and later in profiling.

The caller_idx was also used as a hint that the entry was freed, in order
to detect wakeup-after-free. This was changed by setting caller to -1
instead and preserving its value in caller[1].

Finally, the operations were made atomic. That's not critical but since
it's used for debugging and race conditions represent a significant part
of the issues in multi-threaded mode, it seems wise to at least eliminate
some possible factors of faulty analysis.

2 years agoDEBUG: applet: instrument appctx_wakeup() to log the caller's location
Willy Tarreau [Tue, 6 Sep 2022 12:45:55 +0000 (14:45 +0200)] 
DEBUG: applet: instrument appctx_wakeup() to log the caller's location

appctx_wakeup() relies on task_wakeup(), but since it calls it from a
function, the calling place is always appctx_wakeup() itself, which is
not very useful.

Let's turn it to a macro so that we can log the location of the caller
instead. As an example, the cli_io_handler() which used to be seen as
this:

  (gdb) p *appctx->t.debug.caller[0]
  $10 = {
    func = 0x9ffb78 <__func__.37996> "appctx_wakeup",
    file = 0x9b336a "include/haproxy/applet.h",
    line = 110,
    what = 1 '\001',
    arg8 = 0 '\000',
    arg32 = 0
  }

Now shows the more useful:

  (gdb) p *appctx->t.debug.caller[0]
  $6 = {
    func = 0x9ffe80 <__func__.38641> "sc_app_chk_snd_applet",
    file = 0xa00320 "src/stconn.c",
    line = 996,
    what = 6 '\006',
    arg8 = 0 '\000',
    arg32 = 0
  }

2 years agoDEBUG: task: use struct ha_caller instead of arrays of file:line
Willy Tarreau [Tue, 6 Sep 2022 08:25:49 +0000 (10:25 +0200)] 
DEBUG: task: use struct ha_caller instead of arrays of file:line

This reduces the task struct by 8 bytes, reduces the code size a little
bit by simplifying the calling convention (one argument dropped), and
as a bonus provides the function name in the caller.

2 years agoDEBUG: task: define a series of wakeup types for tasks and tasklets
Willy Tarreau [Tue, 6 Sep 2022 13:01:55 +0000 (15:01 +0200)] 
DEBUG: task: define a series of wakeup types for tasks and tasklets

The WAKEUP_* values will be used to report how a task/tasklet was woken
up, and task_wakeup_type_str() wlil report the associated function name.

2 years agoCLEANUP: debug: use struct ha_caller for memstat
Willy Tarreau [Tue, 6 Sep 2022 06:05:59 +0000 (08:05 +0200)] 
CLEANUP: debug: use struct ha_caller for memstat

The memstats code currently defines its own file/function/line number,
type and extra pointer. We don't need to keep them separate and we can
easily replace them all with just a struct ha_caller. Note that the
extra pointer could be converted to a pool ID stored into arg8 or
arg32 and be dropped as well, but this would first require to define
IDs for pools (which we currently do not have).

2 years agoMINOR: debug: add struct ha_caller to describe a calling location
Willy Tarreau [Tue, 6 Sep 2022 05:55:44 +0000 (07:55 +0200)] 
MINOR: debug: add struct ha_caller to describe a calling location

The purpose of this structure is to assemble all constant parts of a
generic calling point for a specific event. These ones are created by
the compiler as a static const element outside of the code path, so
they cost nothing in terms of CPU, and a pointer to that descriptor
can be passed to the place that needs it. This is very similar to what
is being done for the mem_stat stuff.

This will be useful to simplify and improve DEBUG_TASK.

2 years agoCLEANUP: activity: make taskprof use ptr_hash()
Willy Tarreau [Wed, 7 Sep 2022 09:27:25 +0000 (11:27 +0200)] 
CLEANUP: activity: make taskprof use ptr_hash()

There's no more point using a different hash function here, xxh64 is
of course better distributed but we really don't care so let's unify
the code.

2 years agoCLEANUP: activity: make memprof use the generic ptr_hash() function
Willy Tarreau [Wed, 7 Sep 2022 09:20:01 +0000 (11:20 +0200)] 
CLEANUP: activity: make memprof use the generic ptr_hash() function

There's no need to keep a local version of that function anymore.

2 years agoMINOR: tools: add generic pointer hashing functions
Willy Tarreau [Wed, 7 Sep 2022 08:56:03 +0000 (10:56 +0200)] 
MINOR: tools: add generic pointer hashing functions

There are a few places where it's convenient to hash a pointer to compute
a statistics bucket. Here we're basically reusing the hash that was used
by memory profiling with a minor update that the multiplier was corrected
to be prime and stand by its promise to have equal numbers of 1 and 0,
and that 32-bit platforms won't lose range anymore.

A two-pointer variant was also added.

2 years agoMINOR: tasks: do not keep cpu and latency times in struct task
Willy Tarreau [Wed, 7 Sep 2022 07:17:45 +0000 (09:17 +0200)] 
MINOR: tasks: do not keep cpu and latency times in struct task

It was a mistake to put these two fields in the struct task. This
was added in 1.9 via commit 9efd7456e ("MEDIUM: tasks: collect per-task
CPU time and latency"). These fields are used solely by streams in
order to report the measurements via the lat_ns* and cpu_ns* sample
fetch functions when task profiling is enabled. For the rest of the
tasks, this is pure CPU waste when profiling is enabled, and memory
waste 100% of the time, as the point where these latencies and usages
are measured is in the profiling array.

Let's move the fields to the stream instead, and have process_stream()
retrieve the relevant info from the thread's context.

The struct task is now back to 120 bytes, i.e. almost two cache lines,
with 32 bit still available.

2 years agoBUG/MINOR: stream/sched: take into account CPU profiling for the last call
Willy Tarreau [Wed, 7 Sep 2022 14:17:49 +0000 (16:17 +0200)] 
BUG/MINOR: stream/sched: take into account CPU profiling for the last call

When task profiling is enabled, the reported CPU time for short requests
and responses (e.g. redirect) is always zero in the logs, because
process_stream() is only called once and the CPU time is measured after
it returns. This is particuarly annoying when dealing with denies and in
general anything that deals with parasitic traffic because it can be
difficult to figure where the CPU is spent.

The solution taken in this patch consists in having process_stream()
update the cpu time itself before logging and quitting. It's very simple.
It will not take into account the time taken to produce the log nor
freeing the stream, but that's marginal compared to always logging zero.
The task's wake_date is also reset so that the scheduler doesn't have to
perform these operations again. This is dependent on the following patch:

   MINOR: sched: store the current profile entry in the thread context

It should be backported to 2.6 as it does help for troubleshooting.

2 years agoMINOR: sched: store the current profile entry in the thread context
Willy Tarreau [Wed, 7 Sep 2022 14:16:39 +0000 (16:16 +0200)] 
MINOR: sched: store the current profile entry in the thread context

The profile entry that corresponds to the current task/tasklet being
profiled is now stored into the thread's context. This will allow it
to be accessed from the tasks themselves. This is needed for an upcoming
fix.

2 years agoBUG/MINOR: sched: properly account for the CPU time of dying tasks
Willy Tarreau [Wed, 7 Sep 2022 13:11:25 +0000 (15:11 +0200)] 
BUG/MINOR: sched: properly account for the CPU time of dying tasks

When task profiling is enabled, the scheduler can measure and report
the cumulated time spent in each task and their respective latencies. But
this was wrong for tasks with few wakeups as well as for self-waking ones,
because the call date needed to measure how long it takes to process the
task is retrieved in the task itself (->wake_date was turned to the call
date), and we could face two conditions:
  - a new wakeup while the task is executing would reset the ->wake_date
    field before returning and make abnormally low values being reported;
    that was likely the case for taskèrun_applet for self-waking applets;

  - when the task dies, NULL is returned and the call date couldn't be
    retrieved, so that CPU time was not being accounted for. This was
    particularly visible with process_stream() which is usually called
    only twice per request, and whose time was systematically halved.

The cleanest solution here is to keep in mind that the scheduler already
uses quite a bit of local context in th_ctx, and place the intermediary
values there so that they cannot vanish. The wake_date has to be reset
immediately once read, and only its copy is used along the function. Note
that this must be done both for tasks and tasklet, and that until recently
tasklets were also able to report wrong values due to their sole dependency
on TH_FL_TASK_PROFILING between tests.

One nice benefit for future improvements is that such information will now
be available from the task without having to be stored into the task itself
anymore.

Since the tasklet part was computed on wrapping 32-bit arithmetics and
the task one was on 64-bit, the values were now consistently moved to
32-bit as it's already largely sufficient (4s spent in a task is more
than twice what the watchdog would tolerate). Some further cleanups might
be necessary, but the patch aimed at staying minimal.

Task profiling output after 1 million HTTP request previously looked like
this:

  Tasks activity:
    function                      calls   cpu_tot   cpu_avg   lat_tot   lat_avg
    h1_io_cb                    2012338   4.850s    2.410us   12.91s    6.417us
    process_stream              2000136   9.594s    4.796us   34.26s    17.13us
    sc_conn_io_cb               2000135   1.973s    986.0ns   30.24s    15.12us
    h1_timeout_task                 137      -         -      2.649ms   19.34us
    accept_queue_process             49   152.3us   3.107us   321.7yr   6.564yr
    main+0x146430                     7   5.250us   750.0ns   25.92us   3.702us
    srv_cleanup_idle_conns            1   559.0ns   559.0ns   918.0ns   918.0ns
    task_run_applet                   1      -         -      2.162us   2.162us

  Now it looks like this:
  Tasks activity:
    function                      calls   cpu_tot   cpu_avg   lat_tot   lat_avg
    h1_io_cb                    2014194   4.794s    2.380us   13.75s    6.826us
    process_stream              2000151   20.01s    10.00us   36.04s    18.02us
    sc_conn_io_cb               2000148   2.167s    1.083us   32.27s    16.13us
    h1_timeout_task                 198   54.24us   273.0ns   3.487ms   17.61us
    accept_queue_process             52   158.3us   3.044us   409.9us   7.882us
    main+0x1466e0                    18   16.77us   931.0ns   63.98us   3.554us
    srv_cleanup_toremove_conns        8   282.1us   35.26us   546.8us   68.35us
    srv_cleanup_idle_conns            3   149.2us   49.73us   8.131us   2.710us
    task_run_applet                   3   268.1us   89.38us   11.61us   3.871us

Note the two-fold difference on process_stream().

This feature is essentially used for debugging so it has extremely limited
impact. However it's used quite a bit more in bug reports and it would be
desirable that at least 2.6 gets this fix backported. It depends on at least
these two previous patches which will then also have to be backported:

     MINOR: task: permanently enable latency measurement on tasklets
     CLEANUP: task: rename ->call_date to ->wake_date

2 years agoCLEANUP: task: rename ->call_date to ->wake_date
Willy Tarreau [Wed, 7 Sep 2022 12:49:50 +0000 (14:49 +0200)] 
CLEANUP: task: rename ->call_date to ->wake_date

This field is misnamed because its real and important content is the
date the task was woken up, not the date it was called. It temporarily
holds the call date during execution but this remains confusing. In
fact before the latency measurements were possible it was indeed a call
date. Thus is will now be called wake_date.

This change is necessary because a subsequent fix will require the
introduction of the real call date in the thread ctx.

2 years agoMINOR: task: permanently enable latency measurement on tasklets
Willy Tarreau [Tue, 6 Sep 2022 17:17:45 +0000 (19:17 +0200)] 
MINOR: task: permanently enable latency measurement on tasklets

When tasklet latency measurement was enabled in 2.4 with commit b2285de04
("MINOR: tasks: also compute the tasklet latency when DEBUG_TASK is set"),
the feature was conditionned on DEBUG_TASK because the field would add 8
bytes to the struct tasklet.

This approach was not a very good idea because the struct ends on an int
anyway thus it does finish with a 32-bit hole regardless of the presence
of this field. What is true however is that adding it turned a 64-byte
struct to 72-byte when caller debugging is enabled.

This patch revisits this with a minor change. Now only the lowest 32
bits of the call date are stored, so they always fit in the remaining
hole, and this allows to remove the dependency on DEBUG_TASK. With
debugging off, we're now seeing a 48-byte struct, and with debugging
on it's exactly 64 bytes, thus still exactly one cache line. 32 bits
allow a latency of 4 seconds on a tasklet, which already indicates a
completely dead process, so there's no point storing the upper bits at
all. And even in the event it would happen once in a while, the lost
upper bits do not really add any value to the debug reports. Also, now
one tasklet wakeup every 4 billion will not be sampled due to the test
on the value itself. Similarly we just don't care, it's statistics and
the measurements are not 9-digit accurate anyway.

2 years agoBUG/MINOR: task: make task_instant_wakeup() work on a task not a tasklet
Willy Tarreau [Tue, 6 Sep 2022 14:31:30 +0000 (16:31 +0200)] 
BUG/MINOR: task: make task_instant_wakeup() work on a task not a tasklet

There's a subtle (harmless) bug in task_instant_wakeup(). As it uses
some tasklet code instead of some task code, the debug part also acts
on the tasklet equivalent, and the call_date is only set when DEBUG_TASK
is set instead of inconditionally like with tasks. As such, without this
debugging macro, call dates are not updated for tasks woken this way.

There isn't any impact yet because this function was introduced in 2.6 to
solve certain classes of issues and is not used yet, and in the worst case
it would only affect the reported latency time.

This may be backported to 2.6 in case a future fix would depend on it but
currently will not fix existing code.

2 years agoBUG/MINOR: task: always reset a new tasklet's call date
Willy Tarreau [Tue, 6 Sep 2022 17:06:52 +0000 (19:06 +0200)] 
BUG/MINOR: task: always reset a new tasklet's call date

The tasklet's call date was not reset, so if profiling was enabled while
some tasklets were in the run queue, their initial random value could be
used to preload a bogus initial latency value into the task profiling bin.
Let's just zero the initial value.

This should be backported to 2.4 as it was brought with initial commit
b2285de04 ("MINOR: tasks: also compute the tasklet latency when DEBUG_TASK
is set"). The impact is very low though.

2 years agoBUG/MINOR: quic: Wrong connection ID to thread ID association
Frédéric Lécaille [Wed, 7 Sep 2022 13:06:52 +0000 (15:06 +0200)] 
BUG/MINOR: quic: Wrong connection ID to thread ID association

To work, quic_pin_cid_to_tid() must set cid[0] to a value with <target_id>
as <global.nbthread> modulo. For each integer n, (n - (n % m)) + d has always
d as modulo m (with d < m).

So, this statement seemed correct:

     cid[0] = cid[0] - (cid[0] % global.nbthread) + target_tid;

except when n wraps or when another modulo is applied to the addition result.
Here, for 8bit modulo arithmetic, if m does not divides 256, this cannot
works for values which wraps when we increment them by d.
For instance n=255 m=3 and d=1 the formula result is 0 (should be d).

To fix this, we first limit c[0] to 255 - <target_id> to prevent c[0] from wrapping.

Thank you to @esb for having reported this issue in GH #1855.

Must be backported to 2.6

2 years agoMINOR: quic: No TRACE_LEAVE() in retrieve_qc_conn_from_cid()
Frédéric Lécaille [Wed, 7 Sep 2022 10:15:43 +0000 (12:15 +0200)] 
MINOR: quic: No TRACE_LEAVE() in retrieve_qc_conn_from_cid()

This macro was confused with TRACE_ENTER().

Should be backported to 2.6.

2 years agoMINOR: quic: Add traces about sent or resent TX frames
Frédéric Lécaille [Fri, 2 Sep 2022 20:16:10 +0000 (22:16 +0200)] 
MINOR: quic: Add traces about sent or resent TX frames

Very useful to help in debugging issues, especially during retransmissions.

Should be backported to 2.6

2 years agoMINOR: quic: add QUIC support when no client_hello_cb
William Lallemand [Wed, 7 Sep 2022 09:21:34 +0000 (11:21 +0200)] 
MINOR: quic: add QUIC support when no client_hello_cb

Add QUIC support to the ssl_sock_switchctx_cbk() variant used only when
no client_hello_cb is available.

This could be used with libreSSL implementation of QUIC for example.
It also works with quictls when HAVE_SSL_CLIENT_HELLO_CB is removed from
openss-compat.h