Digging into Apache httpd's Source 16: Logging — Access Logs, Error Logs, and Wrapping Up the Series

What this post covers

This is the sixteenth and final post in the "Digging into Apache httpd's Source" series. Part 15 looked at where mod_ssl slips TLS into a connection. This time we look at the trace a request leaves behind once it is done: the logs. We follow the four lines you always see in httpd.conf — ErrorLog, LogLevel, LogFormat, CustomLog — into the source, and in "Wrapping up the series" at the end we look back over all 16 posts.

There are four questions to answer.

• When a module calls ap_log_rerror(), what happens before that line lands in a file — and how can LogLevel warn mod_ssl:trace3 give one module its own level?
• How are strings like ErrorLogFormat or the %h %{Host}i %>s of a LogFormat handled?
• Exactly when is an access log line written?
• With CustomLog "|rotatelogs ...", logs go to another program. What happens if that program dies?

Every line number in this post refers to that commit. Part 1 explains how to get the source at the same commit and build the Docker image used for the examples.

server/log.c is 1,961 lines and mod_log_config.c is 1,992. This post keeps only the main thread that someone seeing the code for the first time can follow. What was left out is listed by name and location at the end, under "What this post leaves out".

Words to know first

The error log and the access log sound alike but are two completely separate mechanisms. The error log holds messages the server and its modules write whenever something happens; with the default configuration it piles up in logs/error_log. The access log gets exactly one line each time a request finishes, in logs/access_log. The first is handled by the core (server/log.c), the second by a module called mod_log_config.

A log level is how serious a message is. httpd has 16 levels, from emerg (most serious) through alert, crit, error, warn, notice, info, debug, and on to trace1–trace8 (most detailed). In the source they are the numbers 0 to 15 (include/http_log.h lines 64–79; on systems with syslog the syslog values are reused — lines 43–58). LogLevel warn means "throw away any message whose number is larger than warn (4), that is, more detailed".

A macro is a name that gets replaced, letter for letter, before compilation. __FILE__ and __LINE__ are macros predefined by every C compiler; they turn into the name of the source file and the line number where they appear. Macros and function pointers were covered in Part 2.

module_index is the number each module gets. The server keeps module configurations in a void * array and uses this number as the slot number (Part 2, Part 7). In this post we will see the same number used as the slot in a "per-module log level" array.

A hook is a point the core leaves open, saying "at this moment I will call the functions registered here". Calling all of them in turn is RUN_ALL; stopping at the first one that takes the job is RUN_FIRST (Part 6). The access log is written from a RUN_ALL hook called log_transaction.

A piped log sends log lines to the standard input of another program instead of a file. In the config you write a command starting with | where the file name would go. rotatelogs, which splits logs into dated files, is the usual partner program.

1. Four config lines and where they live in the source

First, the map: where each logging directive from the config file is handled.

ErrorLog and ErrorLogFormat are in the core's directive table (server/core.c lines 4854–4858), and so is LogLevel (lines 4881–4882). LogFormat and CustomLog, on the other hand, are in mod_log_config's directive table (mod_log_config.c lines 1452–1466). So the error log is always there whatever modules you load, but without LoadModule log_config_module ... there is no access log. The build script's description even says "You won't be able to log requests to the server without this module" (modules/loggers/config.m4 line 47).

The logs are opened in the open_logs hook of the startup sequence from Part 5. The core hangs its own ap_open_logs() at the very front of that hook (APR_HOOK_REALLY_FIRST, server/core.c line 6167), while mod_log_config hangs the function that opens access logs in the middle of the same hook (mod_log_config.c line 1967). So the error log is opened before the access logs.

The table and paragraph above in one picture. The yellow box is the core, the blue box is mod_log_config, and the green boxes are the order of calls in the open_logs hook.

2. One ap_log_rerror() call — the macro filters first

The code a module uses to write to the error log almost always looks like this.

/* An example written for this post (not httpd source) */
ap_log_rerror(APLOG_MARK, APLOG_WARNING, 0, r, "something happened: %s", detail);

r is the current request's request_rec, and the rest is a format string and arguments just like printf. Where there is no request you use ap_log_error() (passing the server_rec), and where there is only a connection you use ap_log_cerror() (passing the conn_rec). The three differ only in which struct they take; they all end up in the same function, log_error_core() (server/log.c lines 1326–1402).

APLOG_MARK is three arguments

The APLOG_MARK at the front looks like one argument, but it is a macro.

#define APLOG_MARK     __FILE__,__LINE__,APLOG_MODULE_INDEX

include/http_log.h line 283

Because the commas are replaced too, the compiler actually sees ap_log_rerror("mod_foo.c", 42, module_number, APLOG_WARNING, ...). The caller wrote a single word, yet which file, which line and which module the message came from all travel along. When LogLevel debug prints a file and line like mod_logdemo.c(22): in the error log, those are the first two values. The third, APLOG_MODULE_INDEX, is the subject of section 3.

ap_log_rerror is a macro too

The name ap_log_rerror itself is not a function but a macro. With a C99 or newer compiler it is defined like this.

#ifdef AP_HAVE_C99
/* need additional step to expand APLOG_MARK first */
#define ap_log_rerror(...) ap_log_rerror__(__VA_ARGS__)
#define ap_log_rerror__(file, line, mi, level, status, r, ...)              \
    do { if (APLOG_R_MODULE_IS_LEVEL(r, mi, level))                         \
             ap_log_rerror_(file, line, mi, level, status, r, __VA_ARGS__); \
    } while(0)
#else
#define ap_log_rerror ap_log_rerror_
#endif

include/http_log.h lines 446–455

... and __VA_ARGS__ are the C99 syntax for a macro with a variable number of arguments. The macro goes through two steps, as the comment says, so that APLOG_MARK is expanded into its three arguments first. do { ... } while(0) is a C idiom that lets a multi-line macro be used like a single statement.

The key part is the if in the middle. The level is checked before the real function ap_log_rerror_() (with the trailing underscore) is ever called. The level-check macro is this.

#define APLOG_R_MODULE_IS_LEVEL(r,module_index,level)            \
          ( (((level)&APLOG_LEVELMASK) <= APLOG_NOTICE) ||       \
            (ap_get_request_module_loglevel(r, module_index)     \
             >= ((level)&APLOG_LEVELMASK) ) )

include/http_log.h lines 195–198

Anything at notice or more serious always passes; anything more detailed is compared against the configured level. Run the server with LogLevel warn and all the trace and debug calls scattered across the modules end at this one if — no format string is filled in and no function is called. That is why log calls all over the source cost almost nothing in normal operation.

The red box is where most trace and debug calls end. Only messages that are not filtered out reach the green boxes.

What log_error_core() does

A message that passes goes to log_error_core() (server/log.c lines 1082–1309). This function checks the level once more.

        int configured_level = r ? ap_get_request_module_loglevel(r, module_index)        :
                               c ? ap_get_conn_server_module_loglevel(c, s, module_index) :
                                   ap_get_server_module_loglevel(s, module_index);
        /*
         * If we are doing normal logging, don't log messages that are
         * above the module's log level unless it is a startup/shutdown notice
         */
        if ((level_and_mask != APLOG_NOTICE)
            && (level_and_mask > configured_level)) {
            return;
        }

server/log.c lines 1134–1144

It checks twice because the macro's check is not always there. With a compiler that is not C99, the macro above simply becomes ap_log_rerror_ (the #else branch) and the function is called straight away with no check. After this check, the function picks the target (the file s->error_log or a provider), builds the line in the ErrorLogFormat layout if there is one or the default layout if not, and writes it (line 1290). Finally it calls the error_log hook so other modules can see the message too (line 1304).

ap_log_rerror_() has one extra. If you mix APLOG_TOCLIENT into the level, a message at warn or above is HTML-escaped and stored in r->notes under "error-notes" (lines 1350–1377). Whatever builds the error page can show that text if it wants to.

The numbers that start with AH

You have probably seen numbers like AH00558: or AH00106: in an error log. They come from a macro too.

#define APLOGNO(n)              "AH" #n ": "

include/http_log.h line 117

#n is C syntax that turns a macro argument into a string, and in C, string literals placed side by side are joined into one. So ap_log_error(APLOG_MARK, ..., APLOGNO(00558) "Could not reliably ...") gets the format string "AH00558: Could not reliably ...". The numbering rules are in docs/log-message-tags/README (lines 1–21): the same message logged from two different places gets two different numbers, removed numbers are never reused, and the same numbers are used across branches. The next free number is kept in the next-number file; at this commit it is 10654. The README says the point is that searching for the number on a search engine finds discussions of that message.

Easy to get wrong

• notice cannot be switched off by level. Both checks above make an exception for notice (the macro passes anything <= APLOG_NOTICE, and log_error_core() only compares when the level is != APLOG_NOTICE). That is why the notice lines at startup and shutdown still appear under LogLevel crit. We see it for ourselves in run 3 of the example in section 3.
• Arguments of a filtered call are not evaluated. Because the macro wraps the call in an if, in ap_log_rerror(APLOG_MARK, APLOG_TRACE5, 0, r, "%s", expensive_function()) the expensive_function() is never called when the level is too low. Conversely, if you put an argument with a side effect (say, a function that changes a value) in there, behaviour changes with the log level. (This is about the C99 macro path.)
• Never put data from the network into the format string. The header comment warns about this in capitals: do not put the request URI or header values in the format string position; pass them through "%s" (include/http_log.h lines 321–329). printf-style functions read any % inside the string as a directive.

3. A different LogLevel per module — one slot at module_index

Write LogLevel warn ssl:trace3 and the server as a whole stays at warn while mod_ssl alone logs down to trace3. That only works if the server knows which module a message came from, and that information is the third value of APLOG_MARK, APLOG_MODULE_INDEX.

A hidden variable in every file

http_log.h contains this declaration.

static int * const aplog_module_index;

include/http_log.h line 148

A global variable marked static is visible only inside that one source file. Every .c file that includes http_log.h gets its own aplog_module_index, and since it has no initial value, C's rules make it NULL. APLOG_MODULE_INDEX then looks at this variable.

#define APLOG_MODULE_INDEX  \
    (aplog_module_index ? *aplog_module_index : APLOG_NO_MODULE)

include/http_log.h lines 168–169

If it is NULL, the result is APLOG_NO_MODULE, that is -1 (line 129). The macro that puts a value in this variable is APLOG_USE_MODULE, and AP_DECLARE_MODULE, which you use to declare a module, calls it for you.

#define APLOG_USE_MODULE(foo) \
    extern module AP_MODULE_DECLARE_DATA foo##_module;                  \
    AP_MAYBE_UNUSED(static int * const aplog_module_index) = &(foo##_module.module_index)

/* ... */
#define AP_DECLARE_MODULE(foo) \
    APLOG_USE_MODULE(foo);                         \
    module AP_MODULE_DECLARE_DATA foo##_module

include/http_config.h lines 456–469

## glues a macro argument onto another word, so APLOG_USE_MODULE(ssl) stores in this file's aplog_module_index a pointer to the module_index field of ssl_module. It stores the address rather than the value because module_index is not known at compile time; it is assigned when the server loads the module (Part 6). Holding a pointer and reading through it at logging time gives whatever number was assigned.

The same number also finds the module's name. When a module is loaded, the short name — ssl_module with _module cut off — is stored in ap_module_short_names[module_index] (server/config.c lines 606–615). The ssl in an error log's [ssl:warn] comes from there.

Finding the level in two steps

With the number in hand, the level is looked up like this.

#define ap_get_request_logconf(r)                  \
    ((r)->log             ? (r)->log             : \
     (r)->connection->log ? (r)->connection->log : \
     &(r)->server->log)

#define ap_get_module_loglevel(l,i)                                     \
    (((i) < 0 || (l)->module_levels == NULL || (l)->module_levels[i] < 0) ?  \
     (l)->level :                                                         \
     (l)->module_levels[i])

include/http_config.h lines 618–626

First, choose which settings to look at: the settings attached to the request (r->log) if there are any, otherwise the ones attached to the connection, otherwise the virtual host's. Second, look at this module's slot in those settings. The settings struct ap_logconf has only two fields: level, which applies to everyone, and module_levels, a signed char array with one slot per module (include/httpd.h lines 1391–1397). If the slot holds 0 or more, that is the module's own level; if the slot is empty (negative) or the module number is -1, the level for everyone is used.

The yellow boxes are where the level values actually live. module_levels works the same way as the per-module config array from Part 7: an array that uses module_index as its slot number.

The settings side is filled in by update_loglevel() (server/core.c lines 3559–3606). If the argument has no : (LogLevel warn), it changes level and clears every module slot. If it has one (logdemo:trace3), it looks up the module by the name before the colon — trying again with _module appended if needed — and writes the value into that module's slot only, via ap_set_module_loglevel() (server/config.c lines 1572–1586). If LogLevel sits inside <Directory> or <Location>, a separate ap_logconf is made in the directory config (lines 3608–3627), and after the location walk from Part 10 it is attached to r->log (server/request.c lines 176–182).

Example 1: LogLevel per module

These examples were run with httpd 2.5.1-dev built unchanged from the reference commit (e4af30fe6d), in a Docker container (Ubuntu 24.04). The example folder is ex/u16-error-log.

I wrote a handler that logs one message at each of six levels for a single request, and deliberately added a second file without APLOG_USE_MODULE.

/* An example written for this post (not httpd source) */
#include "httpd.h"
#include "http_config.h"
#include "http_protocol.h"
#include "http_log.h"

/* AP_DECLARE_MODULE would expand APLOG_USE_MODULE(logdemo) for us —
 * this file's APLOG_MARK passes logdemo_module.module_index */
module AP_MODULE_DECLARE_DATA logdemo_module;
APLOG_USE_MODULE(logdemo);

void logdemo_helper(request_rec *r);   /* logdemo_helper.c — a file without APLOG_USE_MODULE */

static int logdemo_handler(request_rec *r)
{
    if (strcmp(r->handler, "logdemo")) {
        return DECLINED;
    }

    /* one message per level in the same request — LogLevel decides which ones actually appear */
    ap_log_rerror(APLOG_MARK, APLOG_TRACE3, 0, r, "trace3 message");
    ap_log_rerror(APLOG_MARK, APLOG_DEBUG,  0, r, "debug message");
    ap_log_rerror(APLOG_MARK, APLOG_INFO,   0, r, "info message");
    ap_log_rerror(APLOG_MARK, APLOG_NOTICE, 0, r, "notice message");
    ap_log_rerror(APLOG_MARK, APLOG_WARNING, 0, r, "warn message");
    ap_log_rerror(APLOG_MARK, APLOG_ERR, APR_ENOENT, r, "error message with status");

    logdemo_helper(r);

    ap_set_content_type(r, "text/plain");
    ap_rputs("logged\n", r);
    return OK;
}

/* ... register_hooks and the module declaration are omitted ... */

/* An example written for this post (not httpd source) */
#include "httpd.h"
#include "http_log.h"

/* no APLOG_USE_MODULE in this file — APLOG_MARK's module_index is APLOG_NO_MODULE (-1) */
void logdemo_helper(request_rec *r)
{
    ap_log_rerror(APLOG_MARK, APLOG_INFO,    0, r, "helper: info message");
    ap_log_rerror(APLOG_MARK, APLOG_WARNING, 0, r, "helper: warn message");
}

apxs -c mod_logdemo.c logdemo_helper.c builds both files into one module; then I sent one request per LogLevel setting. Server start and stop lines are left out, and timestamps, PIDs and ports differ on every run. (The === heading lines are printed by the example script in Korean; they are translated here. Everything else is the real output.)

=== 1) default: LogLevel warn
    LogLevel warn
[Sat Oct 24 12:03:43.627250 2026] [logdemo:notice] [pid 206:tid 215] [client 127.0.0.1:53466] notice message
[Sat Oct 24 12:03:43.627316 2026] [logdemo:warn] [pid 206:tid 215] [client 127.0.0.1:53466] warn message
[Sat Oct 24 12:03:43.627321 2026] [logdemo:error] [pid 206:tid 215] (2)No such file or directory: [client 127.0.0.1:53466] error message with status
[Sat Oct 24 12:03:43.627330 2026] [:warn] [pid 206:tid 215] [client 127.0.0.1:53466] helper: warn message

=== 2) per module: LogLevel warn logdemo:trace3
    LogLevel warn logdemo:trace3
[Sat Oct 24 12:03:43.941425 2026] [logdemo:trace3] [pid 299:tid 307] mod_logdemo.c(21): [client 127.0.0.1:50078] trace3 message
[Sat Oct 24 12:03:43.941514 2026] [logdemo:debug] [pid 299:tid 307] mod_logdemo.c(22): [client 127.0.0.1:50078] debug message
[Sat Oct 24 12:03:43.941519 2026] [logdemo:info] [pid 299:tid 307] [client 127.0.0.1:50078] info message
[Sat Oct 24 12:03:43.941522 2026] [logdemo:notice] [pid 299:tid 307] [client 127.0.0.1:50078] notice message
[Sat Oct 24 12:03:43.941526 2026] [logdemo:warn] [pid 299:tid 307] [client 127.0.0.1:50078] warn message
[Sat Oct 24 12:03:43.941529 2026] [logdemo:error] [pid 299:tid 307] (2)No such file or directory: [client 127.0.0.1:50078] error message with status
[Sat Oct 24 12:03:43.941538 2026] [:warn] [pid 299:tid 307] [client 127.0.0.1:50078] helper: warn message

=== 3) notice survives even with the module lowered to crit
    LogLevel warn logdemo:crit
[Sat Oct 24 12:03:46.016690 2026] [logdemo:notice] [pid 393:tid 418] [client 127.0.0.1:50086] notice message
[Sat Oct 24 12:03:46.016778 2026] [:warn] [pid 393:tid 418] [client 127.0.0.1:50086] helper: warn message

There are four things to read here.

1. In run 2 only logdemo became more detailed. In the same request, the helper file's info message was still dropped. That file's module number is -1, so it never looks at a module_levels slot and follows the level for everyone (warn).
2. The helper's lines are printed as [:warn]. The module name is empty. ap_find_module_short_name(-1) returns NULL (server/config.c lines 823–828), and the function that builds the default layout writes nothing for NULL (server/log.c lines 507–514). This is why a module split across several .c files needs APLOG_USE_MODULE in every file.
3. In run 3 notice survived, even though the module's level was lowered to crit. This is "notice cannot be switched off" from section 2.
4. File and line appear only at debug and above. Only the trace3 and debug lines in run 2 carry mod_logdemo.c(21):. do_errorlog_default(), which builds the default layout, only adds them when info->level >= APLOG_DEBUG (server/log.c lines 946–952). The error line, which was given a status code, carries the APR error text (2)No such file or directory:.

Easy to get wrong

• LogLevelOverride exists only in trunk. It is the directive that fills the "per-connection setting" (c->log) in the figure, changing the level only for connections from given client IPs (server/core.c lines 4883–4884). The 2.4.x branch's server/core.c does not have it.
• Messages from before the error log is open use a different rule. A message logged without a server struct (s == NULL) goes to standard error during startup, and is compared not with any per-module level but with ap_default_loglevel (default warn) (server/log.c lines 1109–1131).

4. ErrorLogFormat — a string becomes an array of function pointers

Without ErrorLogFormat, error log lines look like the example above: [time] [module:level] [pid ...] .... That layout is hard-coded in C in do_errorlog_default() (server/log.c lines 907–1001). With ErrorLogFormat, the string is turned into an array of items that is used instead.

One function per letter

At startup the core registers, in a hash table, a function for each letter that can follow %. Each function produces that letter's value.

    ap_register_errorlog_handler(p, "a", log_remote_address, 0);
    ap_register_errorlog_handler(p, "A", log_local_address, 0);
    ap_register_errorlog_handler(p, "e", log_env_var, 0);
    ap_register_errorlog_handler(p, "E", log_apr_status, 0);
    ap_register_errorlog_handler(p, "F", log_file_line, 0);
    ap_register_errorlog_handler(p, "i", log_header, 0);
    ap_register_errorlog_handler(p, "k", log_keepalives, 0);
    ap_register_errorlog_handler(p, "l", log_loglevel, 0);
    ap_register_errorlog_handler(p, "L", log_log_id, 0);
    ap_register_errorlog_handler(p, "m", log_module_name, 0);
    ap_register_errorlog_handler(p, "n", log_note, 0);
    ap_register_errorlog_handler(p, "P", log_pid, 0);
    ap_register_errorlog_handler(p, "t", log_ctime, 0);
    ap_register_errorlog_handler(p, "T", log_tid, 0);
    ap_register_errorlog_handler(p, "v", log_virtual_host, 0);
    ap_register_errorlog_handler(p, "V", log_server_name, 0);

server/log.c lines 885–900

The registration function just puts a function pointer into errorlog_hash with the letter as the key (server/core.c lines 4680–4689). The functions all share one shape, int fn(const ap_errorlog_info *info, const char *arg, char *buf, int buflen): they take a bundle of information and the argument from {}, write characters into the buffer, and return how many they wrote (include/http_core.h lines 978–979). Because the registration function is public (AP_DECLARE), other modules can add letters of their own.

Parsed once, while reading the config

When the ErrorLogFormat directive is read, parse_errorlog_string() cuts the string from the front and pushes the items into an array one by one (server/core.c lines 4539–4587). This is the end of parse_errorlog_item(), which parses one item.

        case 'M':
            it->func = NULL;
            it->flags |= AP_ERRORLOG_FLAG_MESSAGE;
            *sa = ++s;
            return NULL;
        default:
            handler = (ap_errorlog_handler *)apr_hash_get(errorlog_hash, s, 1);
            if (!handler) {
                char dummy[2];

                dummy[0] = *s;
                dummy[1] = '\0';
                return apr_pstrcat(p, "Unrecognized error log format directive %",
                               dummy, NULL);
            }
            it->func = handler->func;
            *sa = ++s;
            return NULL;
        }

server/core.c lines 4515–4533

It looks up the letter after % in the hash and stores that function pointer in the item's func. If it is not found, that is a config error. %M (the message itself) is the one special item without a function. The switch cases before this collect {...} as the argument, + and - as flags, and a number as an "only at this level or more detailed" condition (lines 4488–4514). Plain characters that are not % become an item whose function "returns that text as is" (log_constant_item, lines 4393–4398). So the result is an array of items that all have the same shape.

typedef struct {
    /** ap_errorlog_handler function */
    ap_errorlog_handler_fn_t *func;
    /** argument passed to item in {} */
    const char *arg;
    /** a combination of the AP_ERRORLOG_* flags */
    unsigned int flags;
    /** only log item if the message's log level is higher than this */
    unsigned int min_loglevel;
} ap_errorlog_format_item;

include/http_core.h lines 1006–1015

Walking the array for each message

For each message, do_errorlog_format() walks this array from start to end and calls the functions. Here is the middle part.

        else if (skipping) {
            continue;
        }
        else if (info->level != -1 && (int)item->min_loglevel > info->level) {
            len = field_start;
            skipping = 1;
        }
        else {
            int item_len = (*item->func)(info, item->arg, buf + len,
                                         buflen - len);
            if (!item_len) {
                if (item->flags & AP_ERRORLOG_FLAG_REQUIRED) {
                    /* required item is empty. skip whole line */
                    buf[0] = '\0';
                    return 0;
                }
                else if (item->flags & AP_ERRORLOG_FLAG_NULL_AS_HYPHEN) {
                    buf[len++] = '-';
                }
                else {
                    len = field_start;
                    skipping = 1;
                }
            }
            else {
                len += item_len;
            }
        }

server/log.c lines 1042–1069

(*item->func)(...) is the function pointer call. The format string is never parsed again; only the functions in the prepared array are called in turn. When a function writes nothing (length 0) there are three branches: an item flagged + throws away the whole line, an item flagged - writes -, and otherwise the whole field (from the preceding space or % up to the next field) is erased. That last branch is why, in ErrorLogFormat "... %E: %M", the : disappears along with %E when there is no error status.

Only part of the array is drawn. It is the config of example 2 below, and the three branches at the bottom are the differences visible in its output.

Example 2: changing ErrorLogFormat

Runs 4 and 5 used the same module (ex/u16-error-log). Run 4's format shortens the time to hours:minutes:seconds, writes - when there is no module name (%-m), adds the request ID (%L), shows file and line (%F) only at level 7 (debug) or more detailed, and shows the error status (%E) only when there is one. The second line, ErrorLogFormat request ..., is printed once per request, before that request's first message.

=== 4) changing ErrorLogFormat
    LogLevel warn logdemo:debug
    ErrorLogFormat "[%{%H:%M:%S}t] [%-m:%l] [%L] %7F: %E: %M% , ua=%{User-Agent}i"
    ErrorLogFormat request "[%L] --- request %{X-Req-Tag}i from %a"
[Zs6r4/wKg2U] --- request demo-1 from 127.0.0.1:50088
[12:03:48] [logdemo:debug] [Zs6r4/wKg2U] mod_logdemo.c(22): debug message, ua=curl/8.5.0
[12:03:48] [logdemo:info] [Zs6r4/wKg2U] info message, ua=curl/8.5.0
[12:03:48] [logdemo:notice] [Zs6r4/wKg2U] notice message, ua=curl/8.5.0
[12:03:48] [logdemo:warn] [Zs6r4/wKg2U] warn message, ua=curl/8.5.0
[12:03:48] [logdemo:error] [Zs6r4/wKg2U] (2)No such file or directory: error message with status, ua=curl/8.5.0
[12:03:48] [-:warn] [Zs6r4/wKg2U] helper: warn message, ua=curl/8.5.0

=== 5) an invalid ErrorLogFormat
AH00526: Syntax error on line 15 of /tmp/bad.conf:
Unrecognized error log format directive %Q
AH00526: Syntax error on line 15 of /tmp/bad2.conf:
main ErrorLogFormat must contain message format string '%M'

• mod_logdemo.c(22): appears only on the debug line. The 7 in %7F became min_loglevel, so the field was erased at info (6) and below.
• (2)No such file or directory: appears only on the error line that was given a status. On the other lines %E had length 0, so the field went away together with its : .
• This time the helper line's module name is -. That is the - flag in %-m.
• The top line is the per-request line. Its request ID Zs6r4/wKg2U (different on every run) matches the messages below it, so they can be grouped even in a log where many requests are interleaved. log_error_core() creates this ID through the generate_log_id hook when it writes the request's first message (the add_log_id() call, server/log.c line 1175).
• The two errors in run 5 are the failed hash lookup in parse_errorlog_item() and the "the main format must contain %M" check in parse_errorlog_string() (server/core.c lines 4581–4584). Both are caught by httpd -t, so you find out before starting the server.

5. The access log — mod_log_config's table of item functions

The access log has almost the same structure. This time it is mod_log_config, not the core, that starts by registering a function for each letter.

static int log_pre_config(apr_pool_t *p, apr_pool_t *plog, apr_pool_t *ptemp)
{
    static APR_OPTIONAL_FN_TYPE(ap_register_log_handler) *log_pfn_register;

    log_pfn_register = APR_RETRIEVE_OPTIONAL_FN(ap_register_log_handler);

    if (log_pfn_register) {
        log_pfn_register(p, "h", log_remote_host, 0);
        log_pfn_register(p, "a", log_remote_address, 0 );
        log_pfn_register(p, "A", log_local_address, 0 );
        log_pfn_register(p, "l", log_remote_logname, 0);
        log_pfn_register(p, "u", log_remote_user, 0);
        /* ... %t %f %b %B %i %o ... 35 in all ... */

modules/loggers/mod_log_config.c lines 1855–1866 (the full list is at lines 1862–1902)

Notice that the registration function is not called directly but fetched with APR_RETRIEVE_OPTIONAL_FN. An optional function is a way of asking APR "if a function by this name exists, give me its address" (we only had a taste of it in Part 6). mod_log_config publishes this registration function as an optional function in its own register_hooks (lines 1976–1979), and other modules get its address the same way to add letters of their own. For example, %I and %O (bytes received and sent) are letters that mod_logio adds like this (modules/loggers/mod_logio.c lines 209–215).

The item functions are simpler than the error log's. They take the request and the {} argument and return a string (mod_log_config.h line 36). The function for %{Host}i is a one-liner.

static const char *log_header_in(request_rec *r, char *a)
{
    return ap_escape_logitem(r->pool, apr_table_get(r->headers_in, a));
}

mod_log_config.c lines 474–477

It looks up a (here "Host") in the request headers and returns it escaped for safe logging. The escaping stops someone from forging log lines by putting characters like newlines in a header value.

LogFormat string → array of log_format_item

The format string of a LogFormat or CustomLog is turned into an array of items by parse_log_string(). One item looks like this.

typedef struct {
    ap_log_handler_fn_t *func;
    char *arg;
    int condition_sense;
    int want_orig;
    apr_array_header_t *conditions;
} log_format_item;

mod_log_config.c lines 289–295

func and arg are the same as in the error log; the other three are specific to the access log. conditions holds a "only when the response status is one of these" condition, like the 400,404 in %400,404{User-Agent}i, and condition_sense is that condition flipped with a leading !. want_orig is explained under "Easy to get wrong" below. Here is the end of the parsing function.

        default:
            /* check for '^' + two character format first */
            if (*s == '^' && *(s+1) && *(s+2)) { 
                handler = (ap_log_handler *)apr_hash_get(log_hash, s, 3); 
                if (handler) { 
                   s += 3;
                }
            }
            if (!handler) {  
                handler = (ap_log_handler *)apr_hash_get(log_hash, s++, 1);  
            }
            if (!handler) {
                char dummy[2];

                dummy[0] = s[-1];
                dummy[1] = '\0';
                return apr_pstrcat(p, "Unrecognized LogFormat directive %",
                               dummy, NULL);
            }
            it->func = handler->func;
            if (it->want_orig == -1) {
                it->want_orig = handler->want_orig_default;
            }
            *sa = s;
            return NULL;
        }

mod_log_config.c lines 1079–1104

It has the same shape as the error log parser in section 4. The main difference is that it first tries three-character names starting with ^, such as %^ti (trailer headers). And once parse_log_string() has parsed the whole string, it appends one more item that outputs a newline (lines 1110–1125). That is why lines break even though no LogFormat contains a newline.

Even runs of plain text that are not % become items with a "return this text as is" function. That is why the whole array has one shape.

Part 2 said that C has no classes, so it builds "same shape, different behaviour" out of structs that hold function pointers. Bucket types worked that way, and so did hooks. Log formats are the smallest example of the idea. Parse the string once while reading the config and turn it into an array of function pointers; after that, all each request has to do is walk the array and call the functions.

For each request: walk the array, write once

When a request ends, config_log_transaction() walks that array.

    format = cls->format ? cls->format : default_format;

    strs = apr_palloc(r->pool, sizeof(char *) * (format->nelts));
    strl = apr_palloc(r->pool, sizeof(int) * (format->nelts));
    items = (log_format_item *) format->elts;

    orig = r;
    while (orig->prev) {
        orig = orig->prev;
    }
    while (r->next) {
        r = r->next;
    }

    for (i = 0; i < format->nelts; ++i) {
        strs[i] = process_item(r, orig, &items[i]);
        len += strl[i] = strlen(strs[i]);
    }

mod_log_config.c lines 1217–1234

It collects each item's string piece in strs[], adds up the lengths, and hands everything to the writer function (log_writer). The default writer copies the pieces into one buffer and writes it with apr_file_write_full() in one go. The comment gives the reason: on a pipe, a write() of up to PIPE_BUF bytes goes in as one piece (atomically), but writev(), which hands over several pieces, has no such guarantee (lines 1669–1716). It keeps lines from getting mixed when several child processes write to the same pipe at once.

process_item() checks the conditions and then just calls the function pointer.

    cp = (*item->func) (item->want_orig ? orig : r, item->arg);
    return cp ? cp : "-";

mod_log_config.c lines 1159–1160

If the function returns NULL, a - is printed. That is why empty fields in an access log are always -.

Easy to get wrong

• %s and %>s can differ. In the code above, orig is the first request, before any internal redirect (Part 10), and r is the last one. When want_orig is true, orig is passed. %s is registered with a default of 1 (the original request) (line 1891), and adding > sets want_orig = 0 (the last request) (lines 1045–1048). To see the status that was actually sent for a request internally redirected by ErrorDocument, use %>s. That is also why the default httpd.conf's common and combined formats use %>s.
• LogFormat "..." name does not build the array on the spot. A named format is only syntax-checked and its string stored in a table (lines 1332–1355). The name in CustomLog file name is turned into a real array at open_logs time, when the logs are opened (lines 1487–1545). So the name is found even when CustomLog is written above the LogFormat.
• %D runs "until the moment the log is written, after the response has gone out". The end time for %D is the current time when this value is first computed for the request (lines 663–676, lines 813–817); the start time is r->request_time, which ap_read_request() records just before it starts reading the request (server/protocol.c line 1323). When the log is written is the subject of section 6.

Example 3: a custom LogFormat

In ex/u16-access-log I defined a format and sent three requests. The second changes the Host header and adds a query string; the third asks for a file that does not exist.

LogFormat "%h [%{%H:%M:%S}t] \"%r\" %>s %b host=%{Host}i D=%Dus T=%{ms}Tms q=%q ua=%400,404{User-Agent}i" mine
CustomLog /tmp/access_log mine

=== 1) a custom LogFormat
127.0.0.1 [12:03:42] "GET / HTTP/1.1" 200 6 host=127.0.0.1:8080 D=401us T=0ms q= ua=-
127.0.0.1 [12:03:42] "GET /index.html?a=1 HTTP/1.1" 200 6 host=example.test D=275us T=0ms q=?a=1 ua=-
127.0.0.1 [12:03:42] "GET /nope HTTP/1.1" 404 236 host=127.0.0.1:8080 D=249us T=0ms q= ua=curl/8.5.0

=== 2) an invalid LogFormat
AH00526: Syntax error on line 15 of /tmp/bad.conf:
Unrecognized LogFormat directive %Z

The time and the D= values differ on every run. ua= is filled in only when the status is 400 or 404, and is - for 200 — the condition check in process_item() filtered it. When there is no query, q= is followed by nothing rather than -, because %q's function returns an empty string, not NULL (lines 437–442).

6. When is the access log written? — the log_transaction hook and the EOR bucket

mod_log_config hangs multi_log_transaction() on the log_transaction hook (line 1968). That function calls config_log_transaction() once for each CustomLog line (lines 1249–1286). The hook itself is RUN_ALL (server/protocol.c lines 2556–2557), so every logging module gets called.

So when does this hook run? Not the moment the handler does return OK. Part 10 said that at the end of request processing an EOR (End Of Request) bucket is sent down (modules/http/http_request.c lines 344–349). That bucket is the answer.

static apr_status_t eor_bucket_cleanup(void *data)
{
    request_rec **rp = data;

    if (*rp) {
        request_rec *r = *rp;
        /*
         * If eor_bucket_destroy is called after us, this prevents
         * eor_bucket_destroy from trying to destroy the pool again.
         */
        *rp = NULL;
        /* Update child status and log the transaction */
        ap_update_child_status(r->connection->sbh, SERVER_BUSY_LOG, r);
        ap_run_log_transaction(r);
        if (ap_extended_status) {
            ap_increment_counts(r->connection->sbh, r);
        }
    }
    return APR_SUCCESS;
}

server/eor_bucket.c lines 27–46

This function is registered as a pre-cleanup of the request pool when the EOR bucket is created (line 88). The order of events is this. After the output filters, once the core output filter has written all of the response bytes to the socket, the EOR bucket is destroyed, and the bucket being destroyed destroys the request pool (lines 100–112). Just before the pool goes away, the pre-cleanup runs and calls the log hook. This takes the idea from Part 4 — "hang a cleanup function on a pool and it is called when the pool goes away" — and uses it to find out when a request has ended. It is a pre-cleanup rather than a normal cleanup because, as the comment says, sub-pools that the log hook may still need must not be destroyed first (lines 85–86).

The yellow boxes are the pool and the cleanup from Part 4. The request_rec is still alive while the log is being written.

So the access log is written after the whole response has been sent to the client, and %D includes the time spent sending it. Even if writing the log takes a while, that request's response is already out. That worker thread cannot take new work in the meantime, though, so the scoreboard records it as SERVER_BUSY_LOG during that time (the ap_update_child_status in the code above; it is the L on the mod_status page — modules/generators/mod_status.c line 1012; the scoreboard is in Part 8).

There is one more place that calls this hook. If reading a request times out and it was the connection's first request, ap_read_request() calls it directly (server/protocol.c lines 1404–1409), because in that case there is no response to put an EOR bucket on.

7. Piped logs — if the log program dies, it is started again

Write a command starting with | in place of a file name, as in CustomLog "|/opt/httpd/bin/rotatelogs ...", and httpd starts that program and streams the log to it through a pipe. On the access log side the entry point is ap_open_piped_log().

AP_DECLARE(piped_log *) ap_open_piped_log(apr_pool_t *p,
                                          const char *program)
{
    apr_cmdtype_e cmdtype = APR_PROGRAM_ENV;

    /* In 2.4 favor PROGRAM_ENV, accept "||prog" syntax for compatibility
     * and "|$cmd" to override the default.
     * Any 2.2 backport would continue to favor SHELLCMD_ENV so there
     * accept "||prog" to override, and "|$cmd" to ease conversion.
     */
    if (*program == '|')
        ++program;
    if (*program == '$') {
        cmdtype = APR_SHELLCMD_ENV;
        ++program;
    }

    return ap_open_piped_log_ex(p, program, cmdtype);
}

server/log.c lines 1910–1928

What matters is that the default is APR_PROGRAM_ENV, which means the program is run directly, without a shell. The command string is split on spaces into an argument array and the first word is executed. Only with a $ after the | does it go through a shell, /bin/sh -c (APR threadproc/unix/proc.c lines 503–508).

ap_open_piped_log_ex() creates a pipe and starts the program with piped_log_spawn() (lines 1846–1871). Right after starting it, it registers the process with APR.

            apr_proc_other_child_register(procnew, piped_log_maintenance, pl,
                                          pl->write_fd, pl->p);

server/log.c lines 1757–1758

The "other child" facility in APR is a list for registering "a child process I started that is not one of the worker processes the MPM manages". Registration comes with a function pointer, here piped_log_maintenance. The MPM parent process notices with waitpid() whenever a child dies, and if the dead process is not a worker, it asks apr_proc_other_child_alert() (server/mpm/event/event.c lines 3550–3554; prefork and worker have the same spot). APR finds the entry with the same PID in its list and calls that function pointer (APR misc/unix/otherchild.c lines 103–119).

    switch (reason) {
    case APR_OC_REASON_DEATH:
    case APR_OC_REASON_LOST:
        pl->pid = NULL; /* in case we don't get it going again, this
                         * tells other logic not to try to kill it
                         */
        apr_proc_other_child_unregister(pl);
        rv = ap_mpm_query(AP_MPMQ_MPM_STATE, &mpm_state);
        if (rv != APR_SUCCESS) {
            /* ... AH00105 ... */
        }
        else if (mpm_state != AP_MPMQ_STOPPING) {
            ap_log_error(APLOG_MARK, APLOG_STARTUP, 0, NULL, APLOGNO(00106)
                         "piped log program '%s' failed unexpectedly",
                         pl->program);
            if ((rv = piped_log_spawn(pl)) != APR_SUCCESS) {
                /* ... AH00107 ... */

server/log.c lines 1779–1802

Unless the server is shutting down, it logs AH00106 and starts the program again on the same pipe. The parent keeps holding the pipe itself, so the child processes notice nothing and keep writing to the same write_fd. The source calls this "reliable piped logs" and turns it on only when APR has the other-child facility (include/ap_config.h lines 209–212).

The pipe in the yellow box stays put; only the program at the bottom right is replaced.

Example 4: piped logs and rotatelogs

This is ex/u16-piped-log. Process numbers and pid= values differ on every run. (As before, the === headings are translated from the script's Korean.)

=== 1) CustomLog "|/bin/cat >> /tmp/piped.log" (run without a shell)
/bin/cat: '>>': No such file or directory
/bin/cat: /tmp/piped.log: No such file or directory
AH00106 (respawned) count: 3
AH00106: piped log program '/bin/cat >> /tmp/piped.log' failed unexpectedly
ls: cannot access '/tmp/piped.log': No such file or directory

=== 2) CustomLog "|$/bin/cat >> /tmp/piped.log" ($ = run through a shell)
--- processes:
    PID    PPID USER     COMMAND
    115       1 root     httpd -f /tmp/p2.conf -k start
    117     115 root     /bin/sh -c /bin/cat >> /tmp/piped.log
    118     115 daemon   httpd -f /tmp/p2.conf -k start
    119     115 daemon   httpd -f /tmp/p2.conf -k start
    120     115 daemon   httpd -f /tmp/p2.conf -k start
    126     117 root     /bin/cat
--- /tmp/piped.log:
127.0.0.1 "GET /index.html HTTP/1.1" 200 pid=120

=== 3) when the log program is killed
--- error_log:
AH00106: piped log program '/bin/cat >> /tmp/piped.log' failed unexpectedly
--- processes:
    PID    PPID USER     COMMAND
    115       1 root     httpd -f /tmp/p2.conf -k start
    118     115 daemon   httpd -f /tmp/p2.conf -k start
    119     115 daemon   httpd -f /tmp/p2.conf -k start
    120     115 daemon   httpd -f /tmp/p2.conf -k start
    214     115 root     /bin/sh -c /bin/cat >> /tmp/piped.log
    215     214 root     /bin/cat
--- /tmp/piped.log:
127.0.0.1 "GET /index.html HTTP/1.1" 200 pid=120
127.0.0.1 "GET /index.html HTTP/1.1" 200 pid=120

1. Without a shell, >> is just an argument. The natural first attempt, "|/bin/cat >> /tmp/piped.log", did not work. cat took >> and /tmp/piped.log as file names to read, said "no such file" and exited at once, and httpd logged AH00106 and started it again each time. In this run that happened three times within a few seconds; the count differs between runs. With a program that dies immediately, this repeats.
2. With $, the shell (/bin/sh -c) handled the redirection. The log program's (117) parent is the httpd parent process (115), while the request was handled by a child running as the daemon user (pid=120). The line the child wrote reached the program the parent started. You can also see the log program running as root, because the parent starts it.
3. After killing the log program with kill -9, AH00106 was logged and new processes (214, 215) appeared under the same parent. Later requests kept being written to the same file.

Next is rotatelogs. I deliberately made the size tiny (100 bytes) and used -n 3 to cycle through three files.

=== 4a) a relative path, bin/rotatelogs
(2)No such file or directory: AH00104: unable to start piped log program 'bin/rotatelogs -n 3 /tmp/rot/access_log 100B'

=== 4) rotatelogs — a new file after 100 bytes, three files used in turn
    236 root     /opt/httpd/bin/rotatelogs -n 3 /tmp/rot/access_log 100B
--- /tmp/rot/access_log
127.0.0.1 "GET /index.html?n=7 HTTP/1.1" 200 pid=238
127.0.0.1 "GET /index.html?n=8 HTTP/1.1" 200 pid=239
--- /tmp/rot/access_log.1
127.0.0.1 "GET /index.html?n=3 HTTP/1.1" 200 pid=239
127.0.0.1 "GET /index.html?n=4 HTTP/1.1" 200 pid=239
--- /tmp/rot/access_log.2
127.0.0.1 "GET /index.html?n=5 HTTP/1.1" 200 pid=239
127.0.0.1 "GET /index.html?n=6 HTTP/1.1" 200 pid=239

4a is where I actually got stuck. With ServerRoot /opt/httpd, I expected bin/rotatelogs to work, but it failed to start with AH00104. piped_log_spawn() does set the child's working directory to ServerRoot (apr_procattr_dir_set, lines 1725–1726). But APR checks the executable with access(progname, X_OK) in the parent, before creating the process, and that check is relative to the parent's current directory. The source comment says that with this way of running programs "caller must pass full path" (APR threadproc/unix/proc.c lines 364–385). With an absolute path it worked, as in run 4.

rotatelogs is a small C program that runs separately from httpd (support/rotatelogs.c). Its core is an endless loop that reads standard input and writes it to the current file; after each read, checkRotate() asks "is the file too big, or has the time passed?", and if so doRotate() opens a new file (lines 733–805, lines 234–269). The size test is current_size > config->sRotation, so a file with one line (about 53 bytes) is still at or under 100 bytes; after two lines it is over, and the next line goes into a new file. With -n 3 the names cycle access_log → .1 → .2 → back to access_log (emptied first) (lines 428–437). That is why requests 1 and 2 were lost, overwritten by 7 and 8. httpd never closes or reopens anything; it just keeps writing to the same pipe, and all the file splitting is done by the outside program.

Easy to get wrong: a piped ErrorLog is not restarted

ErrorLog "|..." is also a piped log, but it is opened by a different route. open_error_log() calls log_child(), not ap_open_piped_log() (server/log.c line 337), and log_child() just starts the process and notes it in the pool; it does not register it as an "other child" (lines 258–307). Run 5 of the example confirms this.

=== 5) a piped ErrorLog is not started again
    349 root     /bin/sh -c /bin/cat >> /tmp/err_piped.log
--- after kill:
(no error-log process)
server still answers: 200

After killing the error log program and waiting seven seconds, no new one appeared. The server kept answering, but any error log written after that has nowhere to go. When you pipe the error log, keeping that program alive is up to whoever runs the server. (Whether it is started again when a restart reopens the logs was not checked for this post.)

8. Easy to get wrong: BufferedLogs loses lines at this commit

BufferedLogs On makes the access log collect lines in a buffer of PIPE_BUF bytes (lines 218–222) and write them in bulk instead of one by one (its description string says "experimental" — lines 1463–1464). Whatever is left in the buffer is written by a pool cleanup (flush_all_logs()) when the child process exits (lines 1604–1642). I wrote an example to show "zero lines right after the requests, written when the server stops", but the result was different.

=== 3) BufferedLogs On — line count right after the requests and after stopping
requests done, lines in access_log: 0
after stop,    lines in access_log: 0
--- write() calls that failed (strace):
write(-1920009896, 0x7f068d8ee928, 80) = -1 EBADF (Bad file descriptor)
write(-1920009896, 0x7f068d8ee928, 31) = -1 EBADF (Bad file descriptor)

Zero lines even after stopping. Watching httpd's write() calls with strace showed that the buffer is written at shutdown, but to a file descriptor number that makes no sense (a huge number that differs on every run — sometimes it shows up negative, sometimes positive), and it fails with EBADF. Judging by the sizes, 80 bytes and 31 bytes are the lines of the three requests split between two child processes (two lines of 45+35 bytes and one of 31 bytes). How they are split differs between runs.

The cause is visible in the source. The buffer struct holds the file as an apr_file_t *.

typedef struct {
    apr_file_t *handle;
    apr_size_t outcnt;
    char outbuf[LOG_BUFSIZE];
    apr_anylock_t mutex;
} buffered_log;

mod_log_config.c lines 257–262

But the value stored in handle is the return value of ap_default_log_writer_init() (line 1796), and in trunk that function returns not a file but a different struct that wraps the file.

typedef struct {
    enum default_log_writer_type type;
    void *log_writer;
} default_log_writer;

mod_log_config.c lines 321–324 (where it is returned: lines 1740–1746 and lines 1785–1788)

flush_log() trusts it to be an apr_file_t * and calls apr_file_write_full(buf->handle, ...) (lines 1163–1170), so APR reads the default_log_writer as a file struct. In APR 1.7.2 the Unix apr_file_t has the descriptor number filedes right after a pool pointer (APR include/arch/unix/apr_arch_file_io.h lines 93–95), so on a 64-bit machine the lower 32 bits of the pointer in default_log_writer's second field, log_writer, are read as the descriptor number. Converting the number in the output above to hex (-1920009896 → 0x8d8ef958) gives low digits close to the buffer address on the same line (0x7f068d8ee928), which fits this. It is exactly the "downside" from Part 2: void * accepts anything, and in exchange the compiler cannot catch the mistake. This struct came from the trunk change that lets the access log go to error log providers such as syslog (commit 438584b106, "mod_log_config: Allow using ErrorLog providers for CustomLog"). In the 2.4.x branch, ap_default_log_writer_init() returns the apr_file_t * itself, so the mismatch does not exist there (I did not run the example on 2.4.x). If you build this commit, it is safer not to use BufferedLogs On.

Byte positions were worked out for 64-bit from the two struct definitions (mod_log_config.c lines 321–324, APR apr_arch_file_io.h lines 93–95); the numbers are exactly the strace output above.

What this post leaves out

• Error log providers: in trunk, ErrorLog syslog:... goes through a provider group called error_log_writer (set_errorlog(), server/core.c lines 4589–4636). syslog and journald live in modules/loggers/mod_syslog.c and mod_journald.c. In the 2.4.x branch, syslog is built directly into server/log.c.
• ErrorLogFormat connection: a line printed once per connection (server/core.c lines 4649–4660).
• Users of the error_log hook, and the default implementation of the generate_log_id hook (core_generate_log_id(), server/log.c lines 815–864).
• The ap_log_rdata() family, which dumps bytes as hex (lines 1453–1525).
• Conditional access logging with CustomLog ... env= / expr= (mod_log_config.c lines 1358–1404), and GlobalLog, which forces virtual hosts to inherit a log (lines 1406–1431).
• Other logging modules: mod_logio (%I, %O), mod_log_forensic, and trunk's mod_log_json (all in modules/loggers/).
• PID files: ap_log_pid() and ap_remove_pid() are also in server/log.c (lines 1563–1647).

Summary

Wrapping up the series

With this post, all 16 parts from the map in Part 1 are written. Here is the whole series.

The path of one request, one more time

Here is the figure from Part 1 again. By now, a source name should come to mind for every box.

The figure from Part 1. This post was the bottom box.

main(), started by httpd -k start, reads the config twice (Part 5), turns httpd.conf into structs through directive tables (Part 7), sorts the modules' hooks (Part 6), and hands the work to the MPM (Part 8). When an MPM worker thread takes a connection, it reads the request line and headers into a request_rec (Part 9), passes through the hook phases that turn the URL into a file and a handler and decide access (Parts 10 and 13). The handler puts the response in buckets (Part 12) and sends them down the filter chain (Part 11), with a proxy or TLS slotting in along the way when present (Parts 14 and 15). When the EOR bucket at the end of the response is destroyed and the request pool goes away (Part 4), the access log is written (this post).

Three things kept coming back across the 16 parts. Pools were not only about memory but also a way of knowing "when is this over" (the request log and the cleanup of piped log processes were both pool cleanups). Tables of function pointers were the shape of every extension point: bucket types, hooks, directive tables, providers, and in this post the log formats. module_index was the slot in the config array and also the slot in the log level array. Knowing these three, you can make a good guess at where to start reading a module you have never seen.

Compared with the Spring series

This blog previously read Spring's source over 27 parts. The two series show two languages answering the same question: "how do you let other people's code plug in?"

• Where code plugs in. Spring lets you plug in through interfaces, BeanPostProcessor (Spring Part 6) and proxies. httpd does the same with hooks and tables of function pointers. Where Spring wraps an object to add behaviour, httpd calls the registered functions at a fixed moment.
• The path of a request. Spring Part 21's DispatcherServlet asks its list of handler mappings in turn and uses the first that answers — the same idea as httpd's RUN_FIRST hooks. HandlerInterceptor.afterCompletion(), called after a request is finished (Spring Part 23), sits in a similar place to this post's log_transaction hook.
• Lifetimes. Spring leaves memory to the garbage collector and lets the container manage bean lifecycles. httpd ties lifetimes to pools and uses the same mechanism both to free memory and to signal "this is finished".
• Safety and its price. Spring often tells you about a type mismatch at compile time or at startup. httpd is light and fast with void * and macros, but as with BufferedLogs in section 8, a type mismatch still compiles and silently goes wrong at run time. It is less a question of which is better than of what each one gained and what it gave up.

What this blog reads next

The open-source reading on this blog continues, after Spring and Apache httpd, with Tomcat, then nginx, MariaDB, Gradle and Kafka. The Tomcat series starts at Digging into Tomcat's Source 1. Tomcat is a web server like httpd and also the servlet container Spring runs on, so it sits right between the two series. Digging into nginx's Source reads another web server written in C the same way, and sets this series' pools, hooks and filters side by side with nginx's.

• Part 1: How I Read It with AI, and the Map
• Part 2: Before Reading a Server Written in C — Structs, Function Pointers, Macros
• Spring Part 1: How I Read It with AI, and the Map