= mlog = 작성할 프로그램이 시작한 후 금방 끝나거나 빠른 시간내에 여러번 실행하는 것이라면, 버그가 발생했을 때 디버깅하기 쉽습니다. 왜냐하면, 버그가 발생한 원인을 빨리 알 수 있기 때문입니다. 또는 원인을 모른다 하더라도 어떤 상황에 버그가 발생했는지 파악하기가 쉽습니다. 그러나 네트워킹 서버처럼 일단 실행한 다음 오래도록 실행하는 도중 버그가 발생한다면, 원인을 알아내기도 힘들 뿐더러, 어떤 상황에 버그가 발생했는지 알아내기가 매우 힘듭니다. 따라서 이러한 프로그램일 경우에는 프로그램 동작 과정을 파일이나 기타 방법을 통해 기록해 둘 필요가 있습니다. 이런 기록을 보통 log라고 하는데, 여기에서는 프로그램에서 쉽게 쓸 수 있는 로그 관련 기능을 만들어 보도록 하겠습니다. 먼저, 우리가 만들 로그 기능이 가져야 할 것들은 크게 다음과 같이 생각할 수 있습니다: 1. 로그를 원하지 않을 경우, 로그 기능을 쉽게 끌 수 있어야 한다. 2. 로그 정보를 지정한 파일에 기록할 수 있어야 한다. 3. 로그 정보를 필요하다면 syslog(3) 인터페이스를 통해서 시스템 로거(logger)에 보낼 수 있어야 한다. 첫째, 로그 기능은 [xassert]()와는 다릅니다. [xassert]는 디버깅할 때가 아니면, 마치 [xassert]()를 쓰지 않은 것처럼 어떠한 기계어 코드를 만들어 내지 않아야 합니다. 로그 기능은 이와는 달리 항상 그 기능을 수행하여야 합니다. 다만 원하지 않을 경우에는 아무런 일도 하지 않을 수 있는 것입니다. 둘째, 로그 정보는 필요에 따라서 지정한 파일에 기록할 수 있어야 합니다. 이 파일은 항상 동적으로 변경될 수 있으며, 정확한 기록 시점을 위해 파일 처리에 버퍼를 사용하지 말아야 합니다. 우리는 표준 라이브러리에서 제공하는 스트림 입출력(정확히 FILE *를 통하여)을 써서 파일로 기록하게 만들겠습니다. FILE *를 쓸 것이므로 상황에 따라 stdout이나 stderr를 통하여 표준 출력이나 표준 에러 출력으로 출력할 수도 있을 것입니다. 세째, 시스템 로거(logger)인 syslog로 메시지를 출력하는 기능도 있으면 나중에 대몬(daemon)과 같은 서버 프로그램을 만든다면 매우 쓸모있을 것 같습니다. 단지 syslog가 모든 시스템에서 지원하는 기능은 아니기 때문에 상황에 따라 쓸 수 있도록 조건부 컴파일을 지원해야 할 것입니다. 대개의 경우, 경험상, 항상 로그 메시지를 출력할 때보다는 어떤 조건에 따라서 로그 메시지를 출력할 것인지 아닌지 결정하고 상황에 따라서 로그 메시지를 출력하는 경우가 많았습니다. 따라서 우리가 사용자들에게 제공할 인터페이스는 어떤 조건 x가 참일 경우에 printf(3)와 같은 형식으로 메시지를 출력할 수 있는 것입니다. 결국 다음과 같은 인터페이스를 지니게 됩니다: {{{#!vim c int message_logger(condition, const char *format, ...); }}} 두번째 이후의 인자는 [xassert]()와 같기 때문에 더 이상 설명할 필요는 없을 것이라고 생각합니다. 이제 첫번째 인자에 대해서 좀 더 생각해 봅시다. 우리가 사용자에게 제공하는 것은 어떤 수식(expression)이 참이냐, 거짓이냐 하는 것을 묻기 위한 것입니다. 만약 위의 함수에서 ‘condition’이 int 타입이라고 가정해 봅시다. 이 경우 다음과 같이 명령을 내린다면 컴파일러에 따라서는 타입 변환(type conversion)에 따른 경고를 출력할 수도 있습니다: {{{#!vim c message_logger(3.2, "some log message"); }}} 따라서 condition을 어떤 특정한 타입의 파라메터로 쓰기에는 무리가 있습니다. 생각해본 결과, [xassert]()처럼 매크로로 쓰면 쉽게 해결될 것 같습니다. 그래서 다음과 같이 만들어보았습니다: {{{#!vim c #define MLOG(condition, ...) ((condition) ? mlog(__VA_ARGS__) : 0) }}} 즉, 위와 같이 하면 ‘condition’에 특별한 타입을 지정한 것이 아니기 때문에 컴파일러가 경고를 주는 경우는 없을 것 같습니다. 여기에서 mlog()는 단순히 printf(3)와 같은 파라메터를 받습니다. == Stream Buffer == mlog() 함수는 조금 이따가 만들어 보기로 하고, 이 모듈이 제공해야 할 것들을 좀 더 생각해 보기로 합시다. 일단 사용자가 특별히 지정하지 않았다면 로그는 지정한 스트림으로 출력되게 합시다. 이렇게 하기 위하여, 다음과 같이 로그용 스트림을 가지고 있는 게 좋을 것 같습니다: {{{#!vim c static FILE *mlog_stream; }}} 그래서 ‘mlog_stream’이 널(null)인 경우에 로그를 출력하지 않도록 만들 것입니다. 그리고 이 ‘mlog_stream’에 스트림을 지정할 수 있는 함수와 지정된 스트림을 얻어 낼 수 있는 함수를 다음과 같이 만들었습니다: {{{#!vim c FILE * mlog_get_stream(void) { return mlog_stream; } int mlog_set_stream(FILE *fp) { fflush(fp); if (setvbuf(fp, 0, _IONBF, 0) != 0) return -1; mlog_stream = fp; return 0; } }}} mlog_get_stream()은 설명할 필요도 없는 간단한 함수입니다. mlog_set_stream()의 경우, setvbuf(3)를 부르는 것을 빼놓고는 단순히 ‘mlog_stream’에 주어진 인자를 대입하는 함수입니다. 여기에서 setvbuf()가 하는 일은 주어진 스트림에 대한 내부 버퍼를 설정하는 것입니다. 여러분은 표준 입력 스트림, ‘stdin’과 표준 출력 스트림 ‘stdout’, 그리고 표준 에러 출력 스트림인 ‘stderr’를 이미 알고 있을 것입니다. 그런데 ‘stdout’과 ‘stderr’의 차이점을 모르는 분도 있기 때문에 잠깐 그 차이점에 대해 다루겠습니다. 스트림 타입, 정확히 말해 FILE * 타입으로 연결된 파일은 표준 C 라이브러리가 내부적으로 버퍼를 가지고 있습니다. 따라서 여러분이 fprintf(3), fputs(3), fputc(3), 또는 fwrite(3) 등으로 파일에 쓴다(write) 하더라도 바로 써지지 않을 수 있습니다. 대개의 경우, 어느 크기까지는 버퍼에 쓰게 되고, 이 버퍼가 다 차거나 또는 어떤 특수한 상황이 발생할 경우, 실제 파일에 쓰게 됩니다. 특별히 지정하지 않은 한, ‘stdout’과 ‘stderr’는 똑같이 터미널의 출력으로 지정되어 있지만, ‘stdout’의 경우, 버퍼링(buffering)을 하지만, ‘stderr’는 버퍼링을 하지 않고 바로 출력하게 됩니다. 아까 버퍼가 다 차지 않아도 어떤 특수한 상황이 발생하면 실제 파일에 쓴다고 했습니다. 보통은 newline 문자인 ‘\n’을 출력하면 버퍼의 내용을 출력하게 됩니다. 다음 프로그램을 실행하면 그 차이를 쉽게 알 수 있습니다: {{{#!vim c #include int main(void) { fprintf(stdout, "hello"); fprintf(stderr, "hi"); fprintf(stdout, ", world!\n"); return 0; } }}} 위 프로그램(tmp.c)을 제 시스템에서 컴파일하고 실행한 결과는 다음과 같습니다: {{{ $ gcc tmp.c $ ./a.out hihello, world! $ _ }}} 출력은 “hello”를 먼저 했지만, ‘stdout’으로 출력되어 버퍼에 대기해 있는 상태입니다. 이 때 버퍼링되지 않는 ‘stderr’로 “hi”를 출력하면 바로 출력되고, 다음으로 ‘stdout’으로 “, world!\n”를 출력하면, 아까 대기하고 있던 “hello”와 함께 출력되어, 실제 터미널로는 “hihello, world!”가 출력됩니다. == syslog(3) Interface == syslog1는 시스템 로그 메시지를 기록하는 인터페이스입니다. 일반적으로 시스템에는 syslogd(8) 데몬 프로세스가 존재하며, 모든 syslog 로그들을 모아, 지정한 곳에 출력 또는 저장하게 됩니다. 따라서 syslog(3)으로 출력한다는 것은 결국 syslogd(8)에 메시지를 보내고, syslogd(8) 프로세스가 정해진 규칙에 따라 로그를 처리합니다. syslogd(8)로 메시지를 보내기 위해, 대개의 시스템에서는 아래 함수들을 제공합니다: {{{#!vim c #include void openlog(const char *ident, int option, int facility); void syslog(int priority, const char *format, ...); void closelog(void); #include void vsyslog(int priority, const char *format, va_list ap); }}} 일단 syslog(3)는 printf(3)와 비슷한 인터페이스를 제공하며, 마지막 vsyslog(3)의 경우, vprintf(3)와 유사한 인터페이스를 제공합니다. 시스템에 따라서 vsyslog(3)를 제공하지 않는 경우도 있습니다. 일단 syslog(3)로 메시지를 출력하기 전에 openlog(3)를 불러서 초기화해야 하며, 모든 로그를 다 출력한 후에는 closelog(3)로 종료합니다. 자세한 사항은 매뉴얼 페이지를 참고하기 바랍니다. == mlog() == 다시 본론으로 돌아와서, 이제 mlog()를 만들어 보겠습니다. 먼저, mlog()의 출력은 다음 꼴로 출력될 것입니다: {{{시간: 프로그램이름 [PID]: 메시지}}} 시간을 출력하기 위해, 우리는 time(2), localtime(3), strftime(3)을 쓰려고 합니다. 프로그램 이름은 전역 변수 ‘program_name’에 저장되어 있다고 가정하겠습니다. 프로세스 id(pid)는 getpid(2)를 써서 얻으려고 합니다. 시간을 얻어내는 함수는 다음과 같이 만들겠습니다: {{{#!vim c static const char *current_time(void); }}} mlog()는 스트림과 syslog(3) 인터페이스 둘 중 하나로 출력을 하기 때문에, 어느 쪽으로 출력을 할 지 정책(policy)을 결정해야 합니다. 다음과 같이 using_stream()을 만들어서 이 함수가 참을 리턴하면 스트림으로 출력하도록 하겠습니다. {{{#!vim c static int using_stream(void); }}} 위 두 함수를 이미 만들었다고 가정하고, syslog(3) 인터페이스도 초기화되어 있다고 가정하고, mlog()를 만들어 봅시다. 어차피 printf(3)와 비슷한 일을 하기 때문에, 앞에서 만든 ASSERT()와 매우 비슷합니다. 먼저 전체 mlog()의 뼈대는 다음과 같습니다: {{{#!vim c void mlog(const char *format, ...) { if (using_stream()) { /* 스트림으로 출력 */ } else { /* syslog로 출력 */ } } }}} 이 절의 앞에서 우리는 이미 로그의 포맷을 정했습니다. syslogd(8)는 알아서 메시지를 포맷시켜 주므로, 우리는 스트림으로 출력할 경우에만 포맷해주면 됩니다. 따라서 위 뼈대에서 using_stream()이 참인 경우에 다음과 같은 코드를 실행합니다. {{{#!vim c va_list ap; fprintf(mlog_stream, "%s: %s[%d]: ", current_time(), program_name, (int)getpid()); va_start(ap, format); vfprintf(mlog_stream, format, ap); va_end(ap); fputc('\n', mlog_stream); }}} syslogd(8)로 메시지를 보낼 경우 (즉, using_stream()이 거짓을 리턴할 경우)를 생각해 봅시다. 먼저 vsyslog()가 제공되지 않는다면, 우리는 mlog()의 가변 인자 부분을 syslog(3)로 전해줄 방법이 없습니다. 따라서 하나의 버퍼를 만들어서 여기에다 로그 메시지를 포매팅하여 저장한 다음, 이 버퍼를 syslog(3)에 전달해야 합니다. 이를 위해서 우리는 버퍼를 준비해야 하며, 버퍼에 포매팅한 메시지를 저장하기 위해서 vsnprintf(3)를 써야 합니다. {{{#!vim c #define MLOG_BUFFER_MAX 1024 static char mlog_buffer[MLOG_BUFFER_MAX]; }}} 또한 vsyslog()가 제공되지 않는 경우와 제공되는 경우를 구별하기 위해, 우리는 HAVE_VSYSLOG라는 매크로를 두고 제공되는 경우에만 이 매크로를 정의할 것입니다. 그 결과 실제 코드 부분은 다음과 같습니다: {{{#!vim c int ret; va_list ap; #ifdef HAVE_VSYSLOG vsyslog(LOG_INFO | LOG_USER, format, ap); #else va_start(ap, format); ret = vsnprintf(mlog_buffer, MLOG_BUFFER_MAX, format, ap); va_end(ap); if (ret >= MLOG_BUFFER_MAX || ret < 0) mlog_buffer[MLOG_BUFFER_MAX - 1] = '\0'; syslog(LOG_INFO | LOG_USER, "%s", mlog_buffer); #endif /* HAVE_VSYSLOG */ }}} vsprintf(3)를 쓰지 않고, 조금 더 복잡한 vsnprintf(3)를 쓴 이유는 간단합니다. 주어진 버퍼, mlog_buffer가 오버플로우가 일어날 경우 발생할 수 있는 오동작을 막기 위해서입니다. 위 코드에서 va_end()를 부른 다음의 ‘if’는 이 오버플로우가 일어났는지 검사하는 부분입니다. 즉, vsnprintf()의 리턴값이 양수이고, MLOG_BUFFER_MAX보다 작으면, mlog_buffer에 에러없이 포매팅되었다고 할 수 있습니다. 일단 메시지가 mlog_buffer에 저장되었으면, syslog(3)로 보냅니다. HAVE_VSYSLOG가 정의된 경우데는 간단하게 vsyslog()를 통해 메시지를 전달합니다. mlog()에 대한 완전한 코드는 다음과 같습니다: {{{#!vim c #define MLOG_BUFFER_MAX 1024 static char mlog_buffer[MLOG_BUFFER_MAX]; void mlog(const char *format, ...) { va_list ap; int ret; if (using_stream()) { fprintf(mlog_stream, "%s: %s[%d]: ", current_time(), program_name, (int)getpid()); va_start(ap, format); vfprintf(mlog_stream, format, ap); va_end(ap); fputc('\n', mlog_stream); } else { #ifdef HAVE_VSYSLOG vsyslog(LOG_INFO | LOG_USER, format, ap); #else va_start(ap, format); ret = vsnprintf(mlog_buffer, MLOG_BUFFER_MAX, format, ap); va_end(ap); if (ret >= MLOG_BUFFER_MAX || ret < 0) mlog_buffer[MLOG_BUFFER_MAX - 1] = '\0'; syslog(LOG_INFO | LOG_USER, "%s", mlog_buffer); #endif /* HAVE_VSYSLOG */ } } }}} ---- == mlog.h == {{{#!vim c /* $Id: mlog,v 1.6 2008/04/10 09:26:22 kss Exp kss $ */ /* * stream/syslog logger module * Copyright (C) 2003, 2004 Seong-Kook Shin */ #ifndef MLOG_H_ #define MLOG_H_ #include #ifdef HAVE_CONFIG_H # include #endif /* This indirect writing of extern "C" { ... } makes Emacs happy */ #ifndef BEGIN_C_DECLS # ifdef __cplusplus # define BEGIN_C_DECLS extern "C" { # define END_C_DECLS } # else # define BEGIN_C_DECLS # define END_C_DECLS # endif #endif /* BEGIN_C_DECLS */ BEGIN_C_DECLS #define MLOG_BUFFER_MAX 4096 /* You should define PROGRAM_NAME somewhere in your code. */ extern const char *program_name; /* Set the stream for logging. * Returns zero on success, otherwise returns -1 */ extern int mlog_set_stream(FILE *fp); /* Get the stream for logging. */ extern FILE *mlog_get_stream(void); extern void mlog(const char *format, ...); #define MLOG(expr, ...) do { if (expr) mlog(__VA_ARGS__); } while (0) END_C_DECLS }}} ---- == mlog.c == {{{#!vim c #include #include #include #include #define TIME_BUF_MAX 32 static FILE *mlog_stream = 0; static int syslog_opened = 0; #ifndef HAVE_VSYSLOG static char mlog_buffer[MLOG_BUFFER_MAX]; #endif static int using_stream(void) { if (mlog_stream) return 1; if (!syslog_opened) { openlog(program_name, LOG_CONS | LOG_NOWAIT | LOG_PID, LOG_USER); atexit(closelog); syslog_opened = 1; } return 0; } int mlog_set_stream(FILE *fp) { fflush(fp); if (setvbuf(fp, 0, _IONBF, 0) != 0) { /* Warning: cannot empty the stream buffer. */ return -1; } mlog_stream = fp; return 0; } FILE * mlog_get_stream(void) { return mlog_stream; } static const char * current_time() { struct tm *tmptr; time_t t; static char buf[TIME_BUF_MAX]; int ret; t = time(0); tmptr = localtime(&t); ret = strftime(buf, TIME_BUF_MAX, "%b %d %H:%M:%S", tmptr); if (ret == TIME_BUF_MAX || ret == 0) return 0; return buf; } void mlog(const char *format, ...) { va_list ap; int ret; if (using_stream()) { fprintf(mlog_stream, "%s: %s[%d]: ", current_time(), program_name, (int)getpid()); va_start(ap, format); vfprintf(mlog_stream, format, ap); va_end(ap); fputc('\n', mlog_stream); } else { #ifdef HAVE_VSYSLOG vsyslog(LOG_INFO | LOG_USER, format, ap); #else va_start(ap, format); ret = vsnprintf(mlog_buffer, MLOG_BUFFER_MAX, format, ap); va_end(ap); if (ret >= MLOG_BUFFER_MAX || ret < 0) mlog_buffer[MLOG_BUFFER_MAX - 1] = '\0'; syslog(LOG_INFO | LOG_USER, "%s", mlog_buffer); #endif /* HAVE_VSYSLOG */ } } #ifdef MLOG_TEST const char *program_name = "mlog"; int main(int argc, char *argv[]) { FILE *fp; char buf[10]; fp = fopen(argv[1], "a"); if (!fp) return -1; mlog_set_stream(fp); MLOG(1, "hello, %s", "world"); gets(buf); MLOG(1, "hello, %s", "world"); gets(buf); MLOG(1, "hello, %s", "world"); gets(buf); fclose(fp); return 0; } #endif /* MLOG_TEST */ }}} ---- Please see CCodeSnippets == TODO ==