From b747d7f3c38ca2424e301f99b33bd528a44049d9 Mon Sep 17 00:00:00 2001
From: Stefan Fritsch <sf@apache.org>
Date: Sun, 4 Aug 2013 18:21:24 +0000
Subject: [PATCH] add high trace level log messages for debugging buffering and
 write completion

git-svn-id: https://svn.apache.org/repos/asf/httpd/httpd/trunk@1510295 13f79535-47bb-0310-9956-ffa450edef68
---
 modules/ssl/ssl_engine_io.c |  4 ++++
 server/core_filters.c       | 40 ++++++++++++++++++++++++++++++++++---
 2 files changed, 41 insertions(+), 3 deletions(-)

diff --git a/modules/ssl/ssl_engine_io.c b/modules/ssl/ssl_engine_io.c
index 18bc48503a..dc7731edff 100644
--- a/modules/ssl/ssl_engine_io.c
+++ b/modules/ssl/ssl_engine_io.c
@@ -788,6 +788,8 @@ static apr_status_t ssl_filter_write(ap_filter_t *f,
              */
             outctx->c->cs->sense = CONN_SENSE_WANT_READ;
             outctx->rc = APR_EAGAIN;
+            ap_log_cerror(APLOG_MARK, APLOG_TRACE6, 0, outctx->c,
+                          "Want read during nonblocking write");
         }
         else if (ssl_err == SSL_ERROR_SYSCALL) {
             ap_log_cerror(APLOG_MARK, APLOG_INFO, outctx->rc, c, APLOGNO(01993)
@@ -1953,6 +1955,8 @@ void ssl_io_filter_init(conn_rec *c, request_rec *r, SSL *ssl)
     /* write is non blocking for the benefit of async mpm */
     if (c->cs) {
         BIO_set_nbio(filter_ctx->pbioWrite, 1);
+        ap_log_cerror(APLOG_MARK, APLOG_TRACE6, 0, c,
+                      "Enabling non-blocking writes");
     }
 
     ssl_io_input_add_filter(filter_ctx, c, r, ssl);
diff --git a/server/core_filters.c b/server/core_filters.c
index fb826c3cfa..e5588afbb1 100644
--- a/server/core_filters.c
+++ b/server/core_filters.c
@@ -379,6 +379,7 @@ apr_status_t ap_core_output_filter(ap_filter_t *f, apr_bucket_brigade *new_bb)
     apr_size_t bytes_in_brigade, non_file_bytes_in_brigade;
     int eor_buckets_in_brigade, morphing_bucket_in_brigade;
     apr_status_t rv;
+    int loglevel = ap_get_conn_module_loglevel(c, APLOG_MODULE_INDEX);
 
     /* Fail quickly if the connection has already been aborted. */
     if (c->aborted) {
@@ -515,7 +516,7 @@ apr_status_t ap_core_output_filter(ap_filter_t *f, apr_bucket_brigade *new_bb)
             || eor_buckets_in_brigade > MAX_REQUESTS_IN_PIPELINE) {
             /* this segment of the brigade MUST be sent before returning. */
 
-            if (APLOGctrace6(c)) {
+            if (loglevel >= APLOG_TRACE6) {
                 char *reason = APR_BUCKET_IS_FLUSH(bucket) ?
                                "FLUSH bucket" :
                                (non_file_bytes_in_brigade >= THRESHOLD_MAX_BUFFER) ?
@@ -523,8 +524,17 @@ apr_status_t ap_core_output_filter(ap_filter_t *f, apr_bucket_brigade *new_bb)
                                morphing_bucket_in_brigade ? "morphing bucket" :
                                "MAX_REQUESTS_IN_PIPELINE";
                 ap_log_cerror(APLOG_MARK, APLOG_TRACE6, 0, c,
-                              "core_output_filter: flushing because of %s",
-                              reason);
+                              "will flush because of %s", reason);
+                ap_log_cerror(APLOG_MARK, APLOG_TRACE8, 0, c,
+                              "seen in brigade%s: bytes: %" APR_SIZE_T_FMT
+                              ", non-file bytes: %" APR_SIZE_T_FMT ", eor "
+                              "buckets: %d, morphing buckets: %d",
+                              flush_upto == NULL ? " so far"
+                                                 : " since last flush point",
+                              bytes_in_brigade,
+                              non_file_bytes_in_brigade,
+                              eor_buckets_in_brigade,
+                              morphing_bucket_in_brigade);
             }
             /*
              * Defer the actual blocking write to avoid doing many writes.
@@ -541,6 +551,10 @@ apr_status_t ap_core_output_filter(ap_filter_t *f, apr_bucket_brigade *new_bb)
     if (flush_upto != NULL) {
         ctx->tmp_flush_bb = apr_brigade_split_ex(bb, flush_upto,
                                                  ctx->tmp_flush_bb);
+        if (loglevel >= APLOG_TRACE8) {
+                ap_log_cerror(APLOG_MARK, APLOG_TRACE8, 0, c,
+                              "flushing now");
+        }
         rv = send_brigade_blocking(net->client_socket, bb,
                                    &(ctx->bytes_written), c);
         if (rv != APR_SUCCESS) {
@@ -550,9 +564,23 @@ apr_status_t ap_core_output_filter(ap_filter_t *f, apr_bucket_brigade *new_bb)
             c->aborted = 1;
             return rv;
         }
+        if (loglevel >= APLOG_TRACE8) {
+                ap_log_cerror(APLOG_MARK, APLOG_TRACE8, 0, c,
+                              "total bytes written: %" APR_SIZE_T_FMT,
+                              ctx->bytes_written);
+        }
         APR_BRIGADE_CONCAT(bb, ctx->tmp_flush_bb);
     }
 
+    if (loglevel >= APLOG_TRACE8) {
+        ap_log_cerror(APLOG_MARK, APLOG_TRACE8, 0, c,
+                      "brigade contains: bytes: %" APR_SIZE_T_FMT
+                      ", non-file bytes: %" APR_SIZE_T_FMT
+                      ", eor buckets: %d, morphing buckets: %d",
+                      bytes_in_brigade, non_file_bytes_in_brigade,
+                      eor_buckets_in_brigade, morphing_bucket_in_brigade);
+    }
+
     if (bytes_in_brigade >= THRESHOLD_MIN_WRITE) {
         rv = send_brigade_nonblocking(net->client_socket, bb,
                                       &(ctx->bytes_written), c);
@@ -563,6 +591,12 @@ apr_status_t ap_core_output_filter(ap_filter_t *f, apr_bucket_brigade *new_bb)
             c->aborted = 1;
             return rv;
         }
+        if (loglevel >= APLOG_TRACE8) {
+                ap_log_cerror(APLOG_MARK, APLOG_TRACE8, 0, c,
+                              "tried nonblocking write, total bytes "
+                              "written: %" APR_SIZE_T_FMT,
+                              ctx->bytes_written);
+        }
     }
 
     setaside_remaining_output(f, ctx, bb, c);