Apache httpd 소스 파헤치기 16: 로그 — 접근 로그와 오류 로그, 그리고 연재를 마치며

이 글에서 다루는 것

"Apache httpd 소스 파헤치기" 연재의 열여섯 번째이자 마지막 글입니다. 15편에서는 mod_ssl이 연결에 TLS를 끼워 넣는 자리를 봤습니다. 이번에는 요청 하나가 끝나고 남는 흔적, 곧 로그를 봅니다. httpd.conf에서 늘 보던 ErrorLog, LogLevel, LogFormat, CustomLog 네 줄이 소스의 어디에 있는지 따라가고, 글 끝의 "연재를 마치며"에서 16편 전체를 정리합니다.

답하려는 질문은 네 가지입니다.

• 모듈이 ap_log_rerror()를 부르면 그 한 줄이 파일에 쓰이기까지 무슨 일이 일어나고, LogLevel warn mod_ssl:trace3처럼 모듈마다 레벨을 다르게 거는 것은 어떻게 가능한가
• ErrorLogFormat과 LogFormat의 %h %{Host}i %>s 같은 문자열은 어떻게 처리되는가
• 접근 로그 한 줄은 정확히 언제 쓰이는가
• CustomLog "|rotatelogs ..."처럼 프로그램으로 로그를 넘기면, 그 프로그램이 죽었을 때 어떻게 되는가

글에 나오는 줄 번호는 모두 이 커밋 기준입니다. 같은 커밋의 소스를 받고 예제용 도커 이미지를 만드는 방법은 1편에 있습니다.

server/log.c는 1,961줄, mod_log_config.c는 1,992줄입니다. 이 글은 처음 보는 사람이 따라올 수 있는 큰 줄기만 골랐습니다. 빼놓은 것은 글 끝의 "이 글에서 뺀 것"에 이름과 위치만 적어 두었습니다.

먼저 알아 둘 말

오류 로그(error log)와 접근 로그(access log)는 이름이 비슷하지만 완전히 다른 두 장치입니다. 오류 로그는 서버와 모듈이 "이런 일이 있었다"고 그때그때 남기는 메시지이고, 기본 설정에서 logs/error_log에 쌓입니다. 접근 로그는 요청 하나가 끝날 때마다 한 줄씩 남는 기록이고 logs/access_log에 쌓입니다. 앞의 것은 코어(server/log.c)가, 뒤의 것은 mod_log_config라는 모듈이 맡습니다.

로그 레벨은 메시지의 무게입니다. httpd에는 emerg(가장 심각)부터 alert, crit, error, warn, notice, info, debug, 그리고 trace1~trace8(가장 자세함)까지 16단계가 있고 소스에서는 0부터 15까지의 숫자입니다(include/http_log.h 64–79행, syslog가 있는 시스템에서는 syslog의 값을 그대로 씁니다 — 43–58행). LogLevel warn은 "숫자가 warn(4)보다 큰, 곧 더 자세한 메시지는 버린다"는 뜻입니다.

매크로는 컴파일 전에 글자 그대로 바꿔 끼워지는 이름입니다. __FILE__과 __LINE__은 C 컴파일러가 미리 정해 둔 매크로로, 그것이 쓰인 소스 파일의 이름과 줄 번호로 바뀝니다. 매크로와 함수 포인터는 2편에서 자세히 봤습니다.

module_index 는 모듈마다 붙는 번호입니다. 서버는 모듈 설정을 void * 배열에 모아 두고 이 번호를 칸 번호로 씁니다(2편, 7편). 이 글에서는 같은 번호가 "모듈별 로그 레벨" 배열의 칸 번호로도 쓰이는 것을 봅니다.

훅(hook)은 코어가 "이 시점에 등록된 함수들을 불러 주겠다"고 열어 둔 자리입니다. 모두를 차례로 부르는 방식이 RUN_ALL, 처음 맡겠다는 쪽에서 멈추는 방식이 RUN_FIRST입니다(6편). 접근 로그는 log_transaction이라는 RUN_ALL 훅에서 남습니다.

파이프 로그(piped log)는 로그를 파일 대신 다른 프로그램의 표준 입력으로 흘려 보내는 방식입니다. 설정에서 파일 이름 자리에 |로 시작하는 명령을 적으면 됩니다. 로그 파일을 날짜별로 나누는 rotatelogs가 대표적인 상대 프로그램입니다.

1. 설정 네 줄과 소스의 자리

먼저 지도를 펼쳐 두겠습니다. 설정 파일에서 보던 로그 관련 디렉티브가 어디서 처리되는지입니다.

ErrorLog와 ErrorLogFormat은 코어의 디렉티브 표에 있습니다(server/core.c 4854–4858행). LogLevel도 마찬가지입니다(4881–4882행). 반면 LogFormat과 CustomLog는 mod_log_config의 디렉티브 표에 있습니다(mod_log_config.c 1452–1466행). 그래서 오류 로그는 어떤 모듈을 싣든 늘 있지만, 접근 로그는 LoadModule log_config_module ...이 없으면 남지 않습니다. 빌드 스크립트의 설명에도 "이 모듈 없이는 요청을 로그로 남길 수 없다"고 적혀 있습니다(modules/loggers/config.m4 47행).

로그 파일을 여는 때는 5편에서 본 기동 순서의 open_logs 훅입니다. 코어는 자기 함수 ap_open_logs()를 이 훅의 맨 앞(APR_HOOK_REALLY_FIRST)에 걸어 두고(server/core.c 6167행), mod_log_config는 같은 훅의 가운데에 접근 로그를 여는 함수를 겁니다(mod_log_config.c 1967행). 그래서 오류 로그가 접근 로그보다 먼저 열립니다.

위 표와 문단을 한 장으로 모았습니다. 노란 칸이 코어, 파란 칸이 mod_log_config 이고, 초록 칸은 open_logs 훅에서 불리는 순서입니다.

2. ap_log_rerror() 한 줄 — 매크로가 먼저 거른다

모듈에서 오류 로그를 남기는 코드는 거의 언제나 이런 모양입니다.

/* 이 글을 위해 쓴 예시입니다 (httpd 의 소스가 아닙니다) */
ap_log_rerror(APLOG_MARK, APLOG_WARNING, 0, r, "something happened: %s", detail);

r는 지금 요청의 request_rec이고, 그 뒤는 printf와 같은 형식 문자열과 인자입니다. 요청이 없는 자리에서는 ap_log_error()(서버 server_rec를 넘김), 연결만 있는 자리에서는 ap_log_cerror()(conn_rec를 넘김)를 씁니다. 세 함수는 받는 구조체만 다르고 결국 같은 함수 log_error_core()에 닿습니다(server/log.c 1326–1402행).

APLOG_MARK는 인자 세 개입니다

맨 앞의 APLOG_MARK는 인자 하나처럼 보이지만 매크로입니다.

#define APLOG_MARK     __FILE__,__LINE__,APLOG_MODULE_INDEX

include/http_log.h 283행

쉼표까지 통째로 바뀌므로 컴파일러가 보는 호출은 ap_log_rerror("mod_foo.c", 42, 모듈번호, APLOG_WARNING, ...)입니다. 부르는 쪽은 한 단어만 적었는데 어느 파일 몇 번째 줄의 어느 모듈에서 남긴 메시지인지가 함께 넘어갑니다. LogLevel debug에서 오류 로그에 mod_logdemo.c(22):처럼 파일과 줄이 찍히는 것이 이 두 값입니다. 세 번째 값 APLOG_MODULE_INDEX는 3절에서 봅니다.

ap_log_rerror도 매크로입니다

ap_log_rerror라는 이름도 함수가 아니라 매크로입니다. C99 이상의 컴파일러에서는 이렇게 정의됩니다.

#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 446–455행

...와 __VA_ARGS__는 "인자 개수가 정해지지 않은 매크로"를 만드는 C99 문법입니다. 매크로를 두 번 거치는 것은 주석대로 APLOG_MARK를 먼저 세 개의 인자로 펼치기 위해서이고, do { ... } while(0)은 여러 줄짜리 매크로를 문장 하나처럼 쓰게 하는 C의 관용구입니다.

핵심은 가운데 if입니다. 진짜 함수 ap_log_rerror_()(끝에 밑줄)를 부르기 전에 레벨부터 확인합니다. 레벨 검사 매크로는 이렇습니다.

#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 195–198행

notice보다 무겁거나 같은 메시지는 무조건 통과하고, 그보다 자세한 메시지는 설정된 레벨과 비교합니다. 서버를 LogLevel warn으로 돌리면 모듈 곳곳의 trace·debug 호출은 이 if 하나에서 끝나고, 형식 문자열을 채우는 일도, 함수 호출도 일어나지 않습니다. 로그 호출이 소스 곳곳에 박혀 있어도 평소에 느려지지 않는 이유입니다.

빨간 칸이 대부분의 trace·debug 호출이 끝나는 곳입니다. 초록 칸까지 가는 것은 걸러지지 않은 메시지뿐입니다.

log_error_core()가 하는 일

통과한 메시지는 log_error_core()로 갑니다(server/log.c 1082–1309행). 이 함수는 레벨을 한 번 더 확인합니다.

        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 1134–1144행

두 번 보는 까닭은 매크로 쪽 검사가 없는 경우가 있어서입니다. C99가 아닌 컴파일러에서는 위 매크로가 그냥 ap_log_rerror_로 바뀌어(#else 쪽) 검사 없이 곧바로 함수가 불립니다. 이 검사를 지나면 기록할 곳(파일 s->error_log 또는 프로바이더)을 고르고, ErrorLogFormat이 있으면 그 모양으로, 없으면 기본 모양으로 한 줄을 만들어 씁니다(1290행). 마지막에는 error_log 훅을 불러 다른 모듈에게도 메시지를 알려 줍니다(1304행).

ap_log_rerror_()에는 덤이 하나 있습니다. 레벨에 APLOG_TOCLIENT를 섞어 부르면 warn 이상의 메시지를 r->notes의 "error-notes"에 HTML 이스케이프해서 넣어 둡니다(1350–1377행). 오류 페이지를 만드는 쪽이 원하면 이 글을 보여 줄 수 있게 해 두는 것입니다.

AH로 시작하는 번호

오류 로그에서 AH00558:, AH00106: 같은 번호를 본 적이 있을 것입니다. 이것도 매크로입니다.

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

include/http_log.h 117행

#n은 매크로 인자를 문자열로 바꾸는 C 문법이고, C에서 나란히 놓인 문자열은 하나로 붙습니다. 그래서 ap_log_error(APLOG_MARK, ..., APLOGNO(00558) "Could not reliably ...")는 형식 문자열 "AH00558: Could not reliably ..."이 됩니다. 번호를 매기는 규칙은 docs/log-message-tags/README에 있습니다(1–21행). 같은 메시지라도 남기는 자리가 다르면 다른 번호를 주고, 지운 번호는 다시 쓰지 않으며, 브랜치가 달라도 같은 번호를 씁니다. 다음에 쓸 번호는 next-number 파일에 있고, 이 커밋에서는 10654입니다. 검색 엔진에서 번호로 찾으면 그 메시지 이야기만 나오게 하려는 장치라고 README에 적혀 있습니다.

헷갈리기 쉬운 곳

• notice는 레벨로 끌 수 없습니다. 위 두 검사 모두 notice를 예외로 둡니다(매크로는 <= APLOG_NOTICE면 통과, log_error_core()는 != APLOG_NOTICE일 때만 비교). LogLevel crit으로 두어도 시작·종료 때의 notice 줄이 남는 것은 이 때문입니다. 3절 예제의 3번에서 직접 봅니다.
• 걸러진 호출의 인자는 계산되지 않습니다. 매크로가 if로 감싸므로, ap_log_rerror(APLOG_MARK, APLOG_TRACE5, 0, r, "%s", 비싼_함수())에서 비싼_함수()는 레벨이 낮으면 아예 불리지 않습니다. 반대로 인자에 부수 효과(예: 값을 바꾸는 함수)를 넣으면 레벨에 따라 동작이 달라집니다. (C99 매크로 경로에서의 이야기입니다.)
• 형식 문자열에 네트워크에서 온 값을 넣으면 안 됩니다. 헤더 주석이 대문자로 경고합니다. 요청 URI나 헤더 값을 형식 문자열 자리에 그대로 넣지 말고 "%s"로 받으라는 것입니다(include/http_log.h 321–329행). printf 계열 함수는 문자열 속 %를 지시어로 읽기 때문입니다.

3. 모듈마다 다른 LogLevel — module_index 한 칸

LogLevel warn ssl:trace3처럼 적으면 서버 전체는 warn인데 mod_ssl만 trace3까지 남깁니다. 메시지가 어느 모듈에서 왔는지 알아야 가능한 일이고, 그 정보가 APLOG_MARK의 세 번째 값 APLOG_MODULE_INDEX입니다.

파일마다 숨은 변수 하나

http_log.h에는 이런 선언이 있습니다.

static int * const aplog_module_index;

include/http_log.h 148행

static이 붙은 전역 변수는 그 소스 파일 안에서만 보이는 변수입니다. http_log.h를 포함하는 .c 파일마다 자기만의 aplog_module_index가 하나씩 생기고, 초기값을 주지 않았으니 C 규칙에 따라 NULL입니다. 그리고 APLOG_MODULE_INDEX는 이 변수를 들여다봅니다.

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

include/http_log.h 168–169행

NULL이면 APLOG_NO_MODULE, 곧 -1입니다(129행). 이 변수에 값을 넣는 것이 APLOG_USE_MODULE 매크로이고, 모듈을 선언할 때 쓰는 AP_DECLARE_MODULE이 그것을 대신 불러 줍니다.

#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 456–469행

##는 매크로 인자를 다른 낱말에 이어 붙이는 문법이라, APLOG_USE_MODULE(ssl)은 ssl_module의 module_index 필드를 가리키는 포인터를 이 파일의 aplog_module_index에 넣습니다. 값이 아니라 주소를 넣는 이유는 module_index가 컴파일 때는 정해지지 않고 서버가 모듈을 싣는 순간에 매겨지기 때문입니다(6편). 포인터로 들고 있다가 로그를 남기는 순간에 읽으면 그때의 번호가 나옵니다.

같은 번호로 모듈 이름도 찾습니다. 모듈을 실을 때 ssl_module에서 _module을 떼어 낸 짧은 이름을 ap_module_short_names[module_index]에 적어 두고(server/config.c 606–615행), 오류 로그의 [ssl:warn]에서 앞쪽 ssl이 여기서 나옵니다.

레벨을 찾는 두 단계

번호가 있으면 레벨은 이렇게 찾습니다.

#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 618–626행

첫째, 어느 설정을 볼지 고릅니다. 요청에 붙은 설정(r->log)이 있으면 그것, 없으면 연결에 붙은 설정, 그것도 없으면 가상 호스트의 설정입니다. 둘째, 그 설정 안에서 이 모듈의 칸을 봅니다. 설정 구조체 ap_logconf는 필드가 둘뿐입니다 — 모두에게 걸린 level과, 모듈 수만큼의 칸이 있는 signed char 배열 module_levels(include/httpd.h 1391–1397행). 칸에 0 이상의 값이 있으면 그 모듈만의 레벨, 칸이 비어 있거나(음수) 모듈 번호가 -1이면 모두의 레벨을 씁니다.

노란 칸이 실제로 레벨 값이 들어 있는 곳입니다. module_levels는 7편의 모듈별 설정 배열과 같은 방식, 곧 module_index를 칸 번호로 쓰는 배열입니다.

설정 쪽은 update_loglevel()이 채웁니다(server/core.c 3559–3606행). 인자에 :이 없으면(LogLevel warn) level을 바꾸고 모든 모듈 칸을 비웁니다. :이 있으면(logdemo:trace3) 앞쪽 이름으로 모듈을 찾고 — 없으면 뒤에 _module을 붙여 한 번 더 찾습니다 — ap_set_module_loglevel()로 그 모듈 칸에만 값을 적습니다(server/config.c 1572–1586행). LogLevel이 <Directory>나 <Location> 안에 있으면 디렉터리 설정에 따로 ap_logconf를 만들고(3608–3627행), 10편에서 본 location walk가 끝난 뒤 그것이 r->log에 걸립니다(server/request.c 176–182행).

예제 1: 모듈별 LogLevel

이 예제는 기준 커밋(e4af30fe6d)을 그대로 빌드한 httpd 2.5.1-dev로 도커 컨테이너(Ubuntu 24.04)에서 실행했습니다. 예제 폴더는 ex/u16-error-log입니다.

요청 하나에서 여섯 레벨의 메시지를 하나씩 남기는 핸들러를 만들고, 일부러 APLOG_USE_MODULE이 없는 파일을 하나 섞었습니다.

/* 이 글을 위해 쓴 예제입니다 (httpd 의 소스가 아닙니다) */
#include "httpd.h"
#include "http_config.h"
#include "http_protocol.h"
#include "http_log.h"

/* AP_DECLARE_MODULE 을 쓰면 APLOG_USE_MODULE(logdemo) 가 함께 펼쳐진다(여기서는 직접 적었다) —
 * 이 파일의 APLOG_MARK 는 logdemo_module.module_index 를 넘기게 된다 */
module AP_MODULE_DECLARE_DATA logdemo_module;
APLOG_USE_MODULE(logdemo);

void logdemo_helper(request_rec *r);   /* logdemo_helper.c — APLOG_USE_MODULE 이 없는 파일 */

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

    /* 같은 요청에서 단계별로 하나씩 남긴다 — 어느 것이 실제로 찍히는지는 LogLevel 이 정한다 */
    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 와 모듈 선언은 생략 ... */

/* 이 글을 위해 쓴 예제입니다 (httpd 의 소스가 아닙니다) */
#include "httpd.h"
#include "http_log.h"

/* 이 파일에는 APLOG_USE_MODULE 이 없다 — APLOG_MARK 의 module_index 는 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로 두 파일을 모듈 하나로 묶고, LogLevel만 바꿔 가며 요청을 하나씩 보냈습니다. 서버 시작·종료 줄은 빼고 실었고, 시각·PID·포트는 실행마다 다릅니다.

=== 1) 기본: 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) 모듈별: 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) 모듈을 crit 로 낮춰도 notice 는 남는다
    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

읽을 거리가 네 가지 있습니다.

1. 2번에서 logdemo만 자세해졌습니다. 같은 요청 안에서 helper 파일의 info 메시지는 여전히 빠졌습니다. 그 파일의 모듈 번호는 -1이어서 module_levels의 칸을 보지 않고 모두의 레벨(warn)을 따랐기 때문입니다.
2. helper의 줄은 [:warn]으로 찍혔습니다. 모듈 이름 자리가 비었습니다. ap_find_module_short_name(-1)이 NULL을 돌려주고(server/config.c 823–828행), 기본 모양을 만드는 함수는 NULL이면 아무것도 쓰지 않습니다(server/log.c 507–514행). 모듈을 여러 .c 파일로 나눌 때 파일마다 APLOG_USE_MODULE을 적어야 하는 이유가 이것입니다.
3. 3번에서 notice는 살아남았습니다. 모듈 레벨을 crit으로 낮췄는데도 그렇습니다. 2절의 "notice는 끌 수 없다"입니다.
4. 파일과 줄 번호는 debug 이상에서만 나옵니다. 2번의 trace3·debug 줄에만 mod_logdemo.c(21):가 있습니다. 기본 모양을 만드는 do_errorlog_default()가 info->level >= APLOG_DEBUG일 때만 넣기 때문입니다(server/log.c 946–952행). 상태 코드를 넘긴 error 줄에는 (2)No such file or directory:처럼 APR 오류 문장이 붙습니다.

헷갈리기 쉬운 곳

• LogLevelOverride는 trunk에만 있습니다. 그림의 "연결의 설정"(c->log)을 채우는 디렉티브로, 특정 클라이언트 IP에서 온 연결만 레벨을 바꿉니다(server/core.c 4883–4884행). 2.4.x 브랜치의 server/core.c에는 이 디렉티브가 없습니다.
• 오류 로그를 아직 열기 전의 메시지는 다른 기준을 씁니다. 서버 구조체 없이(s == NULL) 남긴 메시지는 기동 중 표준 오류로 가고, 이때는 모듈별 레벨이 아니라 ap_default_loglevel(기본값 warn)과 비교합니다(server/log.c 1109–1131행).

4. ErrorLogFormat — 문자열이 함수 포인터 배열이 된다

ErrorLogFormat을 적지 않으면 오류 로그는 위 예제처럼 [시각] [모듈:레벨] [pid ...] ... 모양입니다. 이 모양은 do_errorlog_default()에 C 코드로 박혀 있습니다(server/log.c 907–1001행). ErrorLogFormat을 적으면 그 문자열이 항목 배열로 바뀌어 대신 쓰입니다.

글자 하나에 함수 하나

코어는 시작할 때 % 뒤에 올 글자마다 그 값을 만드는 함수를 해시 표에 등록합니다.

    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 885–900행

등록 함수는 글자를 열쇠로 함수 포인터를 errorlog_hash에 넣을 뿐입니다(server/core.c 4680–4689행). 함수들은 모두 같은 모양 int fn(const ap_errorlog_info *info, const char *arg, char *buf, int buflen) — 정보 묶음과 {} 안의 인자를 받아 버퍼에 글자를 쓰고 쓴 길이를 돌려줍니다(include/http_core.h 978–979행). 등록 함수가 AP_DECLARE로 공개되어 있으니 다른 모듈도 자기 글자를 더할 수 있습니다.

설정을 읽을 때 한 번 해석한다

ErrorLogFormat 디렉티브를 만나면 parse_errorlog_string()이 문자열을 앞에서부터 잘라 항목을 하나씩 배열에 넣습니다(server/core.c 4539–4587행). 항목 하나를 해석하는 parse_errorlog_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 4515–4533행

% 다음 글자로 해시를 찾아 그 함수 포인터를 항목의 func에 적습니다. 못 찾으면 설정 오류입니다. %M(메시지 본문)만 함수가 없는 특별한 항목입니다. 이 앞쪽 switch에서는 {...}를 인자로, +·-를 플래그로, 숫자를 "이 레벨 이상일 때만" 조건으로 받아 둡니다(4488–4514행). % 가 아닌 일반 글자는 "그 글자를 그대로 내놓는 함수"(log_constant_item)를 가진 항목이 됩니다(4393–4398행). 그래서 결과는 전부 같은 모양의 항목 배열입니다.

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 1006–1015행

메시지마다 배열을 돈다

메시지가 올 때마다 do_errorlog_format()은 이 배열을 처음부터 끝까지 돌며 함수를 부릅니다. 가운데 부분입니다.

        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 1042–1069행

(*item->func)(...)가 함수 포인터 호출입니다. 형식 문자열을 다시 해석하지 않고 미리 만든 배열의 함수만 차례로 부릅니다. 함수가 아무것도 쓰지 않으면(길이 0) 세 갈래로 나뉩니다 — +가 붙은 항목이면 줄 전체를 버리고, -가 붙었으면 -를 쓰고, 둘 다 아니면 그 필드(앞의 공백이나 % 부터 다음 필드 전까지)를 통째로 지웁니다. ErrorLogFormat "... %E: %M"에서 오류 상태가 없을 때 : 까지 함께 사라지는 것이 이 마지막 갈래입니다.

배열은 일부만 그렸습니다. 아래 예제 2의 설정이고, 맨 아래 세 갈래가 그 출력에서 보이는 차이입니다.

예제 2: ErrorLogFormat 바꾸기

같은 모듈(ex/u16-error-log)로 4번과 5번을 돌렸습니다. 4번 설정은 시각을 시:분:초로 줄이고, 모듈 이름이 없으면 -를 쓰고(%-m), 요청 ID(%L)를 넣고, 파일·줄(%F)은 레벨 7(debug) 이상에서만, 오류 상태(%E)는 있을 때만 쓰게 했습니다. 두 번째 줄 ErrorLogFormat request ...는 요청마다 한 번, 그 요청의 첫 메시지 앞에 찍히는 줄입니다.

=== 4) 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) 잘못된 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):는 debug 줄에만 있습니다. %7F의 7이 min_loglevel이 되어 info(6) 이하에서는 필드가 지워졌습니다.
• (2)No such file or directory:는 상태를 넘긴 error 줄에만 있습니다. 나머지 줄에서는 %E가 길이 0이라 : 까지 필드째 사라졌습니다.
• helper 줄의 모듈 이름은 이번에는 -입니다. %-m의 - 플래그입니다.
• 맨 위 줄은 요청 단위 줄입니다. 요청 ID Zs6r4/wKg2U(실행마다 다릅니다)가 아래 메시지들과 같아서 여러 요청이 섞인 로그에서도 묶어 볼 수 있습니다. 이 ID는 log_error_core()가 그 요청의 첫 메시지를 남길 때 generate_log_id 훅으로 만듭니다(add_log_id() 호출, server/log.c 1175행).
• 5번의 두 오류는 parse_errorlog_item()의 해시 찾기 실패, 그리고 parse_errorlog_string()의 "주 형식에는 %M이 있어야 한다" 검사입니다(server/core.c 4581–4584행). 둘 다 httpd -t에서 잡히므로 서버를 띄우기 전에 알 수 있습니다.

5. 접근 로그 — mod_log_config의 항목 함수 표

접근 로그도 구조가 거의 같습니다. 이번에는 코어가 아니라 mod_log_config가, 글자마다 함수를 등록하는 일부터 합니다.

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개 ... */

modules/loggers/mod_log_config.c 1855–1866행 (목록 전체는 1862–1902행)

등록 함수를 직접 부르지 않고 APR_RETRIEVE_OPTIONAL_FN으로 꺼내 부르는 것이 눈에 띕니다. optional function은 "이 이름의 함수가 있으면 주소를 달라"고 APR에 묻는 장치로(6편에서 맛만 봤습니다), mod_log_config는 이 등록 함수를 자기 register_hooks에서 optional function으로 내놓습니다(1976–1979행). 다른 모듈도 같은 방법으로 주소를 얻어 자기 글자를 더합니다. 예를 들어 %I·%O(주고받은 바이트 수)는 mod_logio가 이렇게 더하는 글자입니다(modules/loggers/mod_logio.c 209–215행).

항목 함수의 모양은 오류 로그보다 단순합니다. 요청과 {} 안의 인자를 받아 문자열을 돌려줍니다(mod_log_config.h 36행). %{Host}i의 함수는 한 줄짜리입니다.

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 474–477행

요청 헤더 표에서 a(여기서는 "Host")를 찾아 로그에 안전하게 이스케이프해서 돌려줍니다. 헤더 값에 줄바꿈 같은 글자를 넣어 로그 줄을 위조하지 못하게 하려는 것입니다.

LogFormat 문자열 → log_format_item 배열

LogFormat이나 CustomLog의 형식 문자열은 parse_log_string()이 항목 배열로 바꿉니다. 항목 하나는 이렇습니다.

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 289–295행

func와 arg는 오류 로그와 같고, 나머지 셋이 접근 로그만의 것입니다. conditions는 %400,404{User-Agent}i의 400,404처럼 "응답 상태가 이 중 하나일 때만" 조건이고, condition_sense는 앞에 !를 붙여 뒤집은 것입니다. want_orig는 아래 "헷갈리기 쉬운 곳"에서 봅니다. 해석 함수의 끝부분입니다.

        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 1079–1104행

4절의 오류 로그 해석과 같은 모양입니다. 다른 점은 %^ti처럼 ^로 시작하는 세 글자 이름(트레일러 헤더)을 먼저 찾아본다는 것 정도입니다. 그리고 parse_log_string()은 문자열을 다 해석한 뒤 줄바꿈을 내놓는 항목을 하나 더 붙입니다(1110–1125행). 그래서 LogFormat에 줄바꿈을 적지 않아도 한 줄씩 끊깁니다.

%가 아닌 글자 덩어리도 "그 글자를 그대로 돌려주는 함수"를 가진 항목이 됩니다. 그래서 배열 전체가 같은 모양입니다.

2편에서 C에는 클래스가 없는 대신 함수 포인터를 담은 구조체로 "같은 모양, 다른 동작"을 만든다고 했습니다. 버킷 종류가 그랬고 훅이 그랬습니다. 로그 형식은 그 생각을 가장 작게 보여 주는 예입니다. 설정을 읽을 때 문자열을 한 번 해석해 함수 포인터 배열로 바꿔 두면, 요청마다 하는 일은 배열을 돌며 함수를 부르는 것뿐입니다.

요청마다: 배열을 돌고 한 번에 쓴다

요청이 끝나면 config_log_transaction()이 그 배열을 돕니다.

    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 1217–1234행

항목마다 나온 문자열 조각을 strs[]에 모으고 길이를 더해 둔 뒤, 쓰기 함수(log_writer)에 넘깁니다. 기본 쓰기 함수는 조각을 버퍼 하나에 이어 붙여 apr_file_write_full()로 한 번에 씁니다. 주석에 이유가 있습니다 — 파이프에 쓸 때 PIPE_BUF 이하의 write()는 한 번에 들어가지만(원자적), 조각을 여러 개 넘기는 writev()는 그렇다는 보장이 없어서입니다(1669–1716행). 여러 자식 프로세스가 같은 파이프에 동시에 써도 줄이 섞이지 않게 하려는 것입니다.

process_item()은 조건을 확인한 다음 함수 포인터를 부르기만 합니다.

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

mod_log_config.c 1159–1160행

함수가 NULL을 돌려주면 -가 찍힙니다. 접근 로그에서 값이 없는 칸이 늘 -인 이유입니다.

헷갈리기 쉬운 곳

• %s와 %>s는 다를 수 있습니다. 위 코드의 orig는 내부 리다이렉트(10편)가 일어나기 전의 첫 요청, r은 마지막 요청입니다. want_orig가 참이면 orig를 넘깁니다. %s는 등록할 때 기본값이 1(원래 요청)이고(1891행), >를 붙이면 want_orig = 0(마지막 요청)이 됩니다(1045–1048행). ErrorDocument로 내부 리다이렉트된 요청에서 실제로 나간 상태를 보려면 %>s를 씁니다. 기본 httpd.conf의 common·combined 형식이 %>s를 쓰는 것도 그래서입니다.
• LogFormat "..." 이름은 그 자리에서 배열을 만들지 않습니다. 이름을 붙인 형식은 문법만 검사하고 문자열을 표에 적어 둡니다(1332–1355행). CustomLog 파일 이름의 이름을 실제 배열로 바꾸는 것은 로그를 여는 open_logs 때입니다(1487–1545행). 그래서 CustomLog가 LogFormat보다 위에 적혀 있어도 이름을 찾습니다.
• %D는 "응답이 다 나간 뒤 로그를 쓰는 순간까지"입니다. %D의 끝 시각은 그 요청에서 처음 이 값을 계산할 때의 현재 시각이고(663–676행, 813–817행), 시작 시각은 ap_read_request()가 요청을 읽기 시작하기 직전에 적어 둔 r->request_time입니다(server/protocol.c 1323행). 로그가 언제 쓰이는지는 6절에서 봅니다.

예제 3: 직접 만든 LogFormat

ex/u16-access-log에서 형식을 하나 만들어 요청 세 개를 보냈습니다. 두 번째 요청은 Host 헤더를 바꾸고 쿼리 문자열을 붙였고, 세 번째는 없는 파일입니다.

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) 직접 만든 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) 잘못된 LogFormat
AH00526: Syntax error on line 15 of /tmp/bad.conf:
Unrecognized LogFormat directive %Z

시각과 D= 값은 실행마다 다릅니다. ua=는 상태가 400이나 404일 때만 찍히고 200에서는 -입니다. process_item()의 조건 검사가 걸러 낸 것입니다. 쿼리가 없을 때 q= 뒤가 -가 아니라 빈칸인 것은 %q의 함수가 NULL이 아니라 빈 문자열을 돌려주기 때문입니다(437–442행).

6. 접근 로그는 언제 쓰이나 — log_transaction 훅과 EOR 버킷

mod_log_config는 log_transaction 훅에 multi_log_transaction()을 겁니다(1968행). 이 함수는 CustomLog 줄마다 config_log_transaction()을 부릅니다(1249–1286행). 훅 자체는 RUN_ALL입니다(server/protocol.c 2556–2557행). 로그를 남기는 모듈이 여럿이어도 모두 불립니다.

그러면 이 훅은 언제 불릴까요? 핸들러가 return OK를 하는 순간이 아닙니다. 10편에서 요청 처리의 끝에 EOR(End Of Request) 버킷을 흘려 보낸다고 했습니다(modules/http/http_request.c 344–349행). 그 버킷이 답입니다.

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 27–46행

이 함수는 EOR 버킷을 만들 때 요청 풀의 pre-cleanup으로 등록됩니다(88행). 일의 순서는 이렇습니다. 출력 필터를 지나 코어 출력 필터가 응답 바이트를 소켓에 다 쓰면 EOR 버킷이 지워지고, 지워지는 버킷은 요청 풀을 없앱니다(100–112행). 풀이 없어지기 직전에 pre-cleanup이 돌면서 로그 훅이 불립니다. 4편에서 본 "풀에 정리 함수를 걸어 두면 풀이 사라질 때 불린다"를, 요청이 끝나는 시점을 알아내는 데 쓴 것입니다. 일반 cleanup이 아니라 pre-cleanup인 이유는 주석대로, 로그 훅이 아직 쓸 수 있어야 하는 하위 풀들이 먼저 지워지지 않게 하려는 것입니다(85–86행).

노란 칸이 4편의 풀과 cleanup입니다. 로그를 쓰는 동안에는 request_rec가 아직 살아 있습니다.

그래서 접근 로그는 응답을 클라이언트에게 다 보낸 뒤에 쓰이고, %D는 응답을 보내는 데 걸린 시간까지 포함합니다. 로그를 쓰는 데 시간이 걸려도 그 요청의 응답은 이미 나간 뒤입니다. 다만 그동안 그 작업 스레드는 다음 일을 받지 못하므로, 스코어보드에는 그 사이 상태가 SERVER_BUSY_LOG(mod_status 화면의 L — modules/generators/mod_status.c 1012행)로 적힙니다(위 코드의 ap_update_child_status, 스코어보드는 8편).

이 훅을 부르는 곳은 하나 더 있습니다. 요청을 읽다가 시간이 초과된 경우, 그것이 연결의 첫 요청이면 ap_read_request()가 직접 부릅니다(server/protocol.c 1404–1409행). 이때는 EOR 버킷을 만들 응답이 없기 때문입니다.

7. 파이프 로그 — 로그 프로그램이 죽으면 다시 띄운다

CustomLog "|/opt/httpd/bin/rotatelogs ..."처럼 파일 이름 자리에 |로 시작하는 명령을 적으면, httpd는 그 프로그램을 띄우고 파이프로 로그를 흘려 보냅니다. 접근 로그 쪽 입구는 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 1910–1928행

기본값이 APR_PROGRAM_ENV, 곧 셸 없이 프로그램을 직접 실행한다는 점이 중요합니다. 명령 문자열을 공백으로 잘라 인자 배열을 만들고 첫 낱말을 실행합니다. | 다음에 $를 붙여야 /bin/sh -c로 셸을 거칩니다(APR threadproc/unix/proc.c 503–508행).

ap_open_piped_log_ex()는 파이프를 만들고 piped_log_spawn()으로 프로그램을 띄웁니다(1846–1871행). 띄운 직후 이 프로세스를 APR에 등록합니다.

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

server/log.c 1757–1758행

"다른 자식"(other child)은 APR이 제공하는 장치로, "MPM이 관리하는 작업 프로세스는 아니지만 내가 띄운 자식 프로세스"를 등록해 두는 목록입니다. 등록할 때 함수 포인터 piped_log_maintenance를 함께 넘깁니다. MPM 부모 프로세스는 자식이 죽을 때마다 waitpid()로 알아채는데, 죽은 프로세스가 작업 프로세스가 아니면 apr_proc_other_child_alert()에 물어봅니다(server/mpm/event/event.c 3550–3554행, prefork·worker도 같은 자리가 있습니다). APR은 등록 목록에서 PID가 같은 것을 찾아 그 함수 포인터를 부릅니다(APR misc/unix/otherchild.c 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 1779–1802행

서버가 멈추는 중이 아니면 AH00106을 남기고 같은 파이프에 프로그램을 다시 띄웁니다. 파이프 자체는 부모가 계속 들고 있으므로 자식 프로세스들은 아무것도 모른 채 같은 write_fd에 계속 씁니다. 소스는 이것을 "reliable piped logs"라고 부르고, APR에 다른 자식 기능이 있을 때만 켭니다(include/ap_config.h 209–212행).

노란 칸의 파이프는 그대로 두고 오른쪽 아래의 프로그램만 갈아 끼웁니다.

예제 4: 파이프 로그와 rotatelogs

ex/u16-piped-log입니다. 프로세스 번호와 pid= 값은 실행마다 다릅니다.

=== 1) CustomLog "|/bin/cat >> /tmp/piped.log" (셸 없이 실행)
/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" ($ = 셸로 실행)
--- 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) 로그 프로그램을 죽이면
--- 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. 셸 없이 실행하면 >>가 그냥 인자입니다. 처음에 흔히 적을 법한 "|/bin/cat >> /tmp/piped.log"는 동작하지 않았습니다. cat이 >>와 /tmp/piped.log를 읽을 파일 이름으로 받아 "없는 파일"이라며 곧 끝났고, httpd는 그때마다 AH00106을 남기고 다시 띄웠습니다. 이 실행에서는 몇 초 사이에 세 번이었고, 횟수는 실행마다 다릅니다. 프로그램이 곧바로 죽는 설정이면 이렇게 되풀이됩니다.
2. $를 붙이자 셸(/bin/sh -c)이 리디렉션을 처리했습니다. 로그 프로그램(117)의 부모가 httpd 부모 프로세스(115)이고, 요청을 처리한 것은 daemon 사용자의 자식(pid=120)입니다. 자식이 쓴 줄이 부모가 띄운 프로그램에 닿았습니다. 로그 프로그램이 root로 도는 것도 볼 수 있습니다 — 부모가 띄우기 때문입니다.
3. 로그 프로그램을 kill -9로 죽이자 AH00106이 남고 새 프로세스(214, 215)가 같은 부모 밑에 떴습니다. 그 뒤의 요청도 같은 파일에 이어서 쓰였습니다.

다음은 rotatelogs입니다. 일부러 아주 작게(100바이트) 잡고 -n 3으로 파일 세 개를 돌려 쓰게 했습니다.

=== 4a) 상대 경로 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 — 100바이트를 넘으면 새 파일, 파일은 3개를 돌려 쓴다
    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는 실제로 막혔던 곳입니다. ServerRoot /opt/httpd이니 bin/rotatelogs면 될 줄 알았는데 AH00104로 시작조차 하지 못했습니다. piped_log_spawn()이 자식의 작업 디렉터리를 ServerRoot로 지정하기는 합니다(apr_procattr_dir_set, 1725–1726행). 하지만 APR은 프로세스를 만들기 전에 부모 쪽에서 access(progname, X_OK)로 실행 파일을 확인하고, 이 검사는 부모의 현재 디렉터리 기준입니다. 소스 주석도 이 실행 방식에서는 "호출하는 쪽이 전체 경로를 넘겨야 한다"고 적어 두었습니다(APR threadproc/unix/proc.c 364–385행). 절대 경로로 바꾸자 4번처럼 동작했습니다.

rotatelogs는 httpd와 따로 도는 작은 C 프로그램입니다(support/rotatelogs.c). 본체는 표준 입력을 읽어 현재 파일에 쓰는 무한 반복이고, 읽을 때마다 checkRotate()로 "크기를 넘었나, 시간이 지났나"를 본 뒤 필요하면 doRotate()로 새 파일을 엽니다(733–805행, 234–269행). 크기 비교가 current_size > config->sRotation이므로 한 줄(약 53바이트)을 쓴 파일은 아직 100바이트 이하이고, 두 줄을 쓰면 넘어서 다음 줄은 새 파일로 갑니다. -n 3이면 이름이 access_log → .1 → .2 → 다시 access_log(비우고 씀)로 돕니다(428–437행). 그래서 1·2번째 요청은 7·8번째가 덮어써 사라졌습니다. httpd는 파일을 닫거나 다시 열 필요 없이 같은 파이프에 계속 쓸 뿐이고, 파일을 나누는 일은 전부 바깥 프로그램이 합니다.

헷갈리기 쉬운 곳: ErrorLog 쪽 파이프는 다시 띄우지 않습니다

ErrorLog "|..."도 파이프 로그이지만 다른 길로 열립니다. open_error_log()는 ap_open_piped_log()가 아니라 log_child()를 부르고(server/log.c 337행), log_child()는 프로세스를 띄워 풀에 적어 둘 뿐 "다른 자식"으로 등록하지 않습니다(258–307행). 예제의 5번이 이것을 확인합니다.

=== 5) ErrorLog 쪽 파이프는 다시 띄우지 않는다
    349 root     /bin/sh -c /bin/cat >> /tmp/err_piped.log
--- after kill:
(no error-log process)
server still answers: 200

오류 로그 프로그램을 죽이고 7초를 기다려도 새로 뜨지 않았습니다. 서버는 계속 응답했지만, 그 뒤의 오류 로그는 갈 곳이 없습니다. 오류 로그를 파이프로 보낼 때는 그 프로그램이 죽지 않게 하는 것이 운영하는 쪽의 몫이라는 뜻입니다. (재시작 때 로그를 다시 열면서 새로 띄워지는지는 이 글에서 확인하지 않았습니다.)

8. 헷갈리기 쉬운 곳: 이 커밋의 BufferedLogs는 줄을 잃습니다

BufferedLogs On은 접근 로그를 줄마다 쓰지 않고 PIPE_BUF 크기의 버퍼(218–222행)에 모았다가 한꺼번에 쓰게 하는 디렉티브입니다(설명 문자열에 "experimental"이라고 적혀 있습니다 — 1463–1464행). 버퍼에 남은 것은 자식 프로세스가 끝날 때 풀의 cleanup(flush_all_logs())으로 씁니다(1604–1642행). 그래서 "요청 직후에는 0줄, 서버를 멈추면 쓰인다"를 보여 주려고 예제를 만들었는데, 결과가 달랐습니다.

=== 3) BufferedLogs On — 요청 직후와 종료 뒤의 줄 수
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)

멈춘 뒤에도 0줄입니다. strace로 httpd의 write()를 지켜보니, 종료할 때 버퍼를 쓰긴 하는데 말이 안 되는 파일 디스크립터 번호(실행마다 다른 큰 수로, 음수로 찍힐 때도 양수로 찍힐 때도 있습니다)에 쓰다가 EBADF로 실패했습니다. 크기로 보아 80바이트와 31바이트는 요청 세 개의 줄을 두 자식 프로세스가 나눠 들고 있던 것입니다(두 줄 45+35바이트, 한 줄 31바이트). 나뉘는 모양은 실행마다 다릅니다.

원인은 소스에서 보입니다. 버퍼 구조체는 파일을 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 257–262행

그런데 그 handle에 넣는 값은 ap_default_log_writer_init()의 반환값이고(1796행), trunk에서 이 함수는 파일이 아니라 파일을 감싼 다른 구조체를 돌려줍니다.

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

mod_log_config.c 321–324행 (반환하는 자리는 1740–1746행과 1785–1788행)

flush_log()는 이것을 apr_file_t *로 믿고 apr_file_write_full(buf->handle, ...)을 부르므로(1163–1170행), APR은 default_log_writer를 파일 구조체로 읽습니다. APR 1.7.2의 Unix용 apr_file_t는 풀 포인터 다음에 디스크립터 번호 filedes가 오므로(APR include/arch/unix/apr_arch_file_io.h 93–95행), 64비트 기계에서는 default_log_writer의 두 번째 필드인 포인터 log_writer 값의 아래 32비트가 디스크립터 번호로 읽힙니다. 위 출력의 번호를 16진수로 바꾸면(-1920009896 → 0x8d8ef958) 같은 줄의 버퍼 주소(0x7f068d8ee928)와 아래 자리가 비슷한 것도 이와 맞습니다. void *가 어떤 타입이든 받아 주는 대신 컴파일러가 실수를 잡아 주지 못한다는 2편의 "단점" 그대로입니다. 이 구조체는 접근 로그를 오류 로그 프로바이더(syslog 등)로도 보낼 수 있게 한 trunk의 변경(커밋 438584b106, "mod_log_config: Allow using ErrorLog providers for CustomLog")에서 생겼습니다. 2.4.x 브랜치의 ap_default_log_writer_init()은 apr_file_t *를 그대로 돌려주므로 이 어긋남이 없습니다(2.4.x에서 예제를 돌려 보지는 않았습니다). 이 커밋으로 빌드했다면 BufferedLogs On을 쓰지 않는 것이 안전합니다.

바이트 자리는 두 구조체의 정의(mod_log_config.c 321–324행, APR apr_arch_file_io.h 93–95행)에서 64비트 기준으로 계산했고, 숫자는 위 strace 출력 그대로입니다.

이 글에서 뺀 것

• 오류 로그 프로바이더: trunk에서는 ErrorLog syslog:...가 error_log_writer라는 프로바이더 그룹을 거칩니다(set_errorlog(), server/core.c 4589–4636행). syslog와 journald는 각각 modules/loggers/mod_syslog.c, mod_journald.c에 있습니다. 2.4.x 브랜치에서는 syslog가 server/log.c 안에 직접 들어 있습니다.
• ErrorLogFormat connection: 연결마다 한 번 찍히는 줄(server/core.c 4649–4660행).
• error_log 훅의 사용자와 generate_log_id 훅의 기본 구현(core_generate_log_id(), server/log.c 815–864행).
• 바이트를 16진수로 덤프하는 ap_log_rdata() 계열(1453–1525행).
• 조건부 접근 로그 CustomLog ... env= / expr=(mod_log_config.c 1358–1404행), 가상 호스트에도 강제로 물려 주는 GlobalLog(1406–1431행).
• 다른 로그 모듈: mod_logio(%I·%O), mod_log_forensic, trunk의 mod_log_json(모두 modules/loggers/).
• PID 파일: ap_log_pid()·ap_remove_pid()도 server/log.c에 있습니다(1563–1647행).

정리

연재를 마치며

이 글로 1편의 지도에 적어 둔 16편을 모두 썼습니다. 연재의 글 전체입니다.

요청 하나의 길, 다시 한 번

1편에서 그린 그림을 다시 봅니다. 이제는 칸마다 소스의 이름이 떠오를 것입니다.

1편의 그림입니다. 이 글은 맨 아래 칸이었습니다.

httpd -k start로 시작한 main()은 설정을 두 번 읽고(5편), 디렉티브 표로 httpd.conf를 구조체로 바꾸고(7편), 모듈들의 훅을 정렬해 둔 뒤(6편) MPM에게 일을 넘깁니다(8편). MPM의 작업 스레드가 연결을 받으면 요청 줄과 헤더를 읽어 request_rec를 만들고(9편), 훅 단계를 지나며 URL을 파일과 핸들러로 바꾸고 권한을 판정합니다(10·13편). 핸들러는 버킷에 응답을 담아(12편) 필터 사슬로 흘려 보내고(11편), 프록시나 TLS가 있으면 그 사이에 끼어듭니다(14·15편). 응답 끝의 EOR 버킷이 지워지며 요청 풀이 사라질 때(4편) 접근 로그가 남습니다(이 글).

16편을 지나며 되풀이해 나온 것은 세 가지였습니다. 풀은 메모리뿐 아니라 "언제 끝나는가"를 알려 주는 장치였고(요청 로그도, 파이프 로그 프로세스 정리도 풀의 cleanup이었습니다). 함수 포인터 표는 버킷 종류, 훅, 디렉티브 표, 프로바이더, 그리고 이 글의 로그 형식까지 모든 확장 지점의 모양이었습니다. module_index 는 설정 배열의 칸이자 로그 레벨 배열의 칸이었습니다. 이 셋을 알면 처음 보는 모듈의 소스도 어디부터 볼지 짐작할 수 있습니다.

Spring 연재와 비교하면

이 블로그는 앞서 Spring 소스 파헤치기를 27편으로 읽었습니다. 두 연재는 같은 질문 — "남의 코드를 어떻게 끼워 넣게 만들었나" — 에 다른 언어로 답한 것을 보여 줍니다.

• 끼어드는 자리. Spring은 인터페이스와 BeanPostProcessor(Spring 6편), 그리고 프록시로 끼어들게 합니다. httpd는 훅과 함수 포인터 표로 같은 일을 합니다. Spring이 객체를 감싸 동작을 더한다면, httpd는 정해 둔 시점에 등록된 함수를 부릅니다.
• 요청의 길. Spring 21편의 DispatcherServlet은 핸들러 매핑 목록에 차례로 물어 처음 답하는 쪽을 씁니다. httpd의 RUN_FIRST 훅과 같은 발상입니다. 요청이 끝난 뒤 불리는 HandlerInterceptor.afterCompletion()(Spring 23편)은 이 글의 log_transaction 훅과 자리가 닮았습니다.
• 수명. Spring은 가비지 컬렉터에 메모리를 맡기고 컨테이너가 빈의 생명주기를 관리합니다. httpd는 풀로 수명을 묶고, 메모리 해제와 "끝났다는 신호"를 같은 장치로 처리합니다.
• 안전과 대가. Spring은 타입이 맞지 않으면 컴파일러나 시작 시점에 알려 주는 일이 많습니다. httpd는 void *와 매크로로 가볍고 빠르지만, 8절의 BufferedLogs처럼 타입이 어긋나도 컴파일이 되고 실행 중에 조용히 틀립니다. 어느 쪽이 낫다기보다 무엇을 얻고 무엇을 내주었는지의 차이입니다.

다음에 읽을 것

이 블로그의 오픈소스 읽기는 Spring, Apache httpd에 이어 Tomcat, nginx, MariaDB, Gradle, Kafka 순서로 이어졌습니다. Tomcat 연재는 Tomcat 소스 파헤치기 1편부터 읽을 수 있습니다. Tomcat은 httpd처럼 웹 서버이면서 Spring이 올라가는 서블릿 컨테이너이기도 해서, 두 연재 사이에 다리를 놓는 자리입니다. C로 짠 또 하나의 웹 서버를 같은 방식으로 읽은 nginx 소스 파헤치기는 이 연재의 풀·훅·필터를 nginx 쪽과 나란히 놓고 비교합니다.

• 1편: AI와 함께 소스를 읽는 방법과 분석 지도
• 2편: C로 짠 서버를 읽기 전에 — 구조체, 함수 포인터, 매크로
• Spring 1편: AI와 함께 소스를 읽는 방법과 분석 지도