From 343cdd9bb4488c4f0c632583af8bb4bdae0a32dc Mon Sep 17 00:00:00 2001 From: Yann Ylavic Date: Wed, 1 Apr 2020 22:56:44 +0000 Subject: [PATCH] core: add r->flushed flag and set it when the response is sent. By setting EOR->r->flushed in the core output filter, allow one to determine at log_transaction hook time whether the request has been fully flushed through the network, or not (network issue, filter error, n-th pipelined resposne...). Introduce the ap_bucket_eor_request() helper to get the request bound to an EOR bucket, and uses it in ap_core_output_filter() to mark the EOR's request just before destroying it, after all the previous buckets have been sent. While at it, rename the request_rec* member of struct ap_bucket_eor from "data" to "r", which makes the code clearer (not to be confused with b->data). Finally, add CustomLog format %F, showing "F" or "-" depending on r->flushed, for admins to figure out for each request. git-svn-id: https://svn.apache.org/repos/asf/httpd/httpd/trunk@1876017 13f79535-47bb-0310-9956-ffa450edef68 --- include/ap_mmn.h | 3 ++- include/http_request.h | 7 +++++++ include/httpd.h | 5 +++++ modules/loggers/mod_log_config.c | 5 +++++ server/core_filters.c | 16 ++++++++++++++++ server/eor_bucket.c | 15 +++++++++++---- server/util_filter.c | 11 ----------- 7 files changed, 46 insertions(+), 16 deletions(-) diff --git a/include/ap_mmn.h b/include/ap_mmn.h index 7636683a5b..30c156fbfa 100644 --- a/include/ap_mmn.h +++ b/include/ap_mmn.h @@ -624,6 +624,7 @@ * 20200217.0 (2.5.1-dev) Add and use ap_method_mask_t type * 20200331.0 (2.5.1-dev) Remove ap_request_core_filter() and * ap_request_core_filter_handle. + * 20200331.1 (2.5.1-dev) Add flushed:1 to request_rec */ #define MODULE_MAGIC_COOKIE 0x41503235UL /* "AP25" */ @@ -631,7 +632,7 @@ #ifndef MODULE_MAGIC_NUMBER_MAJOR #define MODULE_MAGIC_NUMBER_MAJOR 20200331 #endif -#define MODULE_MAGIC_NUMBER_MINOR 0 /* 0...n */ +#define MODULE_MAGIC_NUMBER_MINOR 1 /* 0...n */ /** * Determine if the server's current MODULE_MAGIC_NUMBER is at least a diff --git a/include/http_request.h b/include/http_request.h index 4259e8a652..11ddbaf9b6 100644 --- a/include/http_request.h +++ b/include/http_request.h @@ -624,6 +624,13 @@ AP_DECLARE(apr_bucket *) ap_bucket_eor_make(apr_bucket *b, request_rec *r); AP_DECLARE(apr_bucket *) ap_bucket_eor_create(apr_bucket_alloc_t *list, request_rec *r); +/** + * Get the request bound to an End Of Request (EOR) bucket. + * @param b The EOR bucket + * @return Its associated request + */ +AP_DECLARE(request_rec *) ap_bucket_eor_request(apr_bucket *b); + /** * Can be used within any handler to determine if any authentication * is required for the current request. Note that if used with an diff --git a/include/httpd.h b/include/httpd.h index 88c71c0c22..c3a81ba446 100644 --- a/include/httpd.h +++ b/include/httpd.h @@ -1092,6 +1092,11 @@ struct request_rec { * Always use ap_request_tainted() to check taint. */ int taint; + /** Whether the response has been flushed through the network, + * relevant at ap_run_log_transaction() time only. + * TODO: compact elsewhere + */ + unsigned int flushed:1; }; /** diff --git a/modules/loggers/mod_log_config.c b/modules/loggers/mod_log_config.c index 6f9201d609..d85e39322d 100644 --- a/modules/loggers/mod_log_config.c +++ b/modules/loggers/mod_log_config.c @@ -416,6 +416,10 @@ static const char *log_request_method(request_rec *r, char *a) { return ap_escape_logitem(r->pool, r->method); } +static const char *log_request_flushed(request_rec *r, char *a) +{ + return (r->flushed) ? "F" : "-"; +} static const char *log_log_id(request_rec *r, char *a) { if (a && !strcmp(a, "c")) { @@ -1854,6 +1858,7 @@ static int log_pre_config(apr_pool_t *p, apr_pool_t *plog, apr_pool_t *ptemp) log_pfn_register(p, "H", log_request_protocol, 0); log_pfn_register(p, "m", log_request_method, 0); log_pfn_register(p, "q", log_request_query, 0); + log_pfn_register(p, "F", log_request_flushed, 1); log_pfn_register(p, "X", log_connection_status, 0); log_pfn_register(p, "C", log_cookie, 0); log_pfn_register(p, "k", log_requests_on_connection, 0); diff --git a/server/core_filters.c b/server/core_filters.c index bb02b207fa..d9085e83ab 100644 --- a/server/core_filters.c +++ b/server/core_filters.c @@ -559,6 +559,14 @@ static apr_status_t send_brigade_nonblocking(apr_socket_t *s, * brigade in order. */ if (!nvec) { + if (AP_BUCKET_IS_EOR(bucket)) { + /* Mark the request as flushed since all its + * buckets (preceding this EOR) have been sent. + */ + request_rec *r = ap_bucket_eor_request(bucket); + ap_assert(r != NULL); + r->flushed = 1; + } apr_bucket_delete(bucket); } continue; @@ -643,6 +651,14 @@ static apr_status_t writev_nonblocking(apr_socket_t *s, for (i = offset; i < nvec; ) { apr_bucket *bucket = APR_BRIGADE_FIRST(bb); if (!bucket->length) { + if (AP_BUCKET_IS_EOR(bucket)) { + /* Mark the request as flushed since all its + * buckets (preceding this EOR) have been sent. + */ + request_rec *r = ap_bucket_eor_request(bucket); + ap_assert(r != NULL); + r->flushed = 1; + } apr_bucket_delete(bucket); } else if (n >= vec[i].iov_len) { diff --git a/server/eor_bucket.c b/server/eor_bucket.c index ecb809ca77..d8156de776 100644 --- a/server/eor_bucket.c +++ b/server/eor_bucket.c @@ -21,7 +21,7 @@ typedef struct { apr_bucket_refcount refcount; - request_rec *data; + request_rec *r; } ap_bucket_eor; static apr_status_t eor_bucket_cleanup(void *data) @@ -58,7 +58,7 @@ AP_DECLARE(apr_bucket *) ap_bucket_eor_make(apr_bucket *b, request_rec *r) ap_bucket_eor *h; h = apr_bucket_alloc(sizeof(*h), b->list); - h->data = r; + h->r = r; b = apr_bucket_shared_make(b, h, 0, 0); b->type = &ap_bucket_type_eor; @@ -85,17 +85,24 @@ AP_DECLARE(apr_bucket *) ap_bucket_eor_create(apr_bucket_alloc_t *list, * We need to use a pre-cleanup here because a module may create a * sub-pool which is still needed during the log_transaction hook. */ - apr_pool_pre_cleanup_register(r->pool, &h->data, eor_bucket_cleanup); + apr_pool_pre_cleanup_register(r->pool, &h->r, eor_bucket_cleanup); } return b; } +AP_DECLARE(request_rec *) ap_bucket_eor_request(apr_bucket *b) +{ + ap_bucket_eor *h = b->data; + AP_DEBUG_ASSERT(AP_BUCKET_IS_EOR(b)); + return h->r; +} + static void eor_bucket_destroy(void *data) { ap_bucket_eor *h = data; if (apr_bucket_shared_destroy(h)) { - request_rec *r = h->data; + request_rec *r = h->r; if (r) { /* eor_bucket_cleanup will be called when the pool gets destroyed */ apr_pool_destroy(r->pool); diff --git a/server/util_filter.c b/server/util_filter.c index 8f34a8771c..136237a601 100644 --- a/server/util_filter.c +++ b/server/util_filter.c @@ -1017,17 +1017,6 @@ AP_DECLARE(apr_status_t) ap_filter_setaside_brigade(ap_filter_t *f, * * XXX: Should we cleanup all previous c->output_filters' setaside * brigades? - * - * XXX: For each EOR we potentially destroy here, there is a - * request handler/module which "thought" everything went well - * on the output filters side, and returned OK. Should we mark - * something in each EOR's request_rec (e.g. r->aborted) for - * the log_transaction hooks to know at least? - * Or alternatively (and possibly more robustly) have the - * ap_core_output_filter() set r->flushed when it sees an EOR - * up to which it sent everything (before destroying it)? - * Anyway we can't set c->aborted here, because close_notify - * for instance can/should still be sent out. */ AP_DEBUG_ASSERT(rv != APR_SUCCESS); f->c->keepalive = AP_CONN_CLOSE;