システムログはカーネルが出力するログです。これは printk()およびその下位のvprintk()をコールすることで行っています。printk()とvprintk()は引数が可変かどうかの違いです。このログはコンソールデバイスに表示されますが、dmesgコマンドおよびcat /proc/kmsgで仮想端末に表示することも可能です。表示形式に違いはあるものの、この2つの表示方法は、ログを保持しているカーネルバッファーから読み取っています。（syslogシステムコールを呼び出しているだけなのですが。）なお/proc/kmsgの内容が、実際のシステムログとして保持している内容そのものとなっています。

上の２つのログ表示方法の機能的な違いは、dmesgコマンドは全ログを表示し、cat /proc/kmsgでは本コマンド表示した以降のログを表示することにあります。実はcat /proc/kmsgで表示するとコマンドプロンプトに戻ってきません。

[root@dhcppc4 kitamura]# cat /proc/kmsg
<6>eth0: link up
<7>eth0: no IPv6 routers present
^C                           <- CTR+Cでコマンドプロンプトへ
[root@dhcppc4 kitamura]# cat /proc/kmsg
^C                  　　　    <- CTR+Cでコマンドプロンプトへ

[root@dhcppc4 kitamura]# dmesg
Initializing cgroup subsys cpuset
Initializing cgroup subsys cpu
Linux version 2.6.32.26-175.fc12.i686 (mockbuild@x86-17.phx2.fedoraproject.org) (gcc versi
 :
 :
eth0: link up
eth0: no IPv6 routers present

実はこの疑問が今回の内容について調査した動機だったのですが、シスログバッファprintk()というものが、どのような物かをまとめた後、上記の内容について次回アップしたいと思っています。

printk()はva_start()で可変変数をva_list argsに整形」して、そのままvprintk()をコールするだけです。

asmlinkage int printk(const char *fmt, ...)
{
       va_list args;
       int r;

       va_start(args, fmt);
       r = vprintk(fmt, args);
       va_end(args);

       return r;
}

vprintk()がシスログの実処理となります。boot_delay_msec()はsystem_stateがSYSTEM_BOOTINGすなわち、ブート時ログメッセージがさあっと流れないようにウエイトします。これはjiffiesタイマーをループすることでウエイトします。（カーネルが立ち上がってないのでsleep()を使うことはできません。と解釈していますが・・・）

if (unlikely(printk_cpu == this_cpu))の条件文は、以降のvprintk処理でエラーが発生し、そこからprintkが呼ばれた場合の処理です。処理ではロックを取得したりしていますので、デッドロックを引き起こします。そのためこのようなケースの場合(本処理内から本処理が呼ばれた。)、スタティック変数recursion_bug = 1として、一旦本処理を抜けます。そして本来処理していたvprintk()の流れの中で、先のエラーの処理をしようとしています。

それがif (recursion_bug)の処理です。recursion_bug_msgメッセージをまず、printk_buf[]に設定しています。printk_buf[]はラインバッファみたいなもので、vprintk()処理毎のバッファで、シスログバッファとは違います。そして、本来のシスログメッセージをprintk_buf[]に設定します。

for (p = printk_buf; *p; p++)で、シスログメッセージをシスログバッファーに設定します。その関数はemit_log_char()です。

if (new_text_line)で新規行です。new_text_lineの初期値は1で、改行毎に1に設定されています。そして新規行なら、先頭の表示として<エラーレベル>を表示します。もしシスログにエラーレベルがないならcurrent_log_level(default_message_loglevel)をエラーレベルとしています。

if (printk_time)はコンパイルオプションCONFIG_PRINTK_TIMEの時、1に設定されます。この場合この時のタイムスタンプを挿入しています。この整形されたログメッセージは1文字づつemit_log_char()で、シスログバッファーに設定されることになり、ループを抜けてrelease_console_sem()でコンソールデバイスに表示されることになります。

static const char recursion_bug_msg [] =
               KERN_CRIT "BUG: recent printk recursion!\n";
static int recursion_bug;
       static int new_text_line = 1;
static char printk_buf[1024];

asmlinkage int vprintk(const char *fmt, va_list args)
{
       int printed_len = 0;
       int current_log_level = default_message_loglevel;
       unsigned long flags;
       int this_cpu;
       char *p;

       boot_delay_msec();

       preempt_disable();
       raw_local_irq_save(flags);
       this_cpu = smp_processor_id();

       if (unlikely(printk_cpu == this_cpu)) {
               if (!oops_in_progress) {
                       recursion_bug = 1;
                       goto out_restore_irqs;
               }
               zap_locks();
       }

       lockdep_off();
       spin_lock(&logbuf_lock);
       printk_cpu = this_cpu;

       if (recursion_bug) {
               recursion_bug = 0;
               strcpy(printk_buf, recursion_bug_msg);
               printed_len = sizeof(recursion_bug_msg);
       }

       printed_len += vscnprintf(printk_buf + printed_len,
                                 sizeof(printk_buf) - printed_len, fmt, args);


       for (p = printk_buf; *p; p++) {
               if (new_text_line) {
                       if (p[0] == '<' && p[1] >= '0' && p[1] <= '7' &&
                           p[2] == '>') {
                               current_log_level = p[1] - '0';
                               p += 3;
                               printed_len -= 3;
                       }

                       emit_log_char('<');
                       emit_log_char(current_log_level + '0');
                       emit_log_char('>');
                       printed_len += 3;
                       new_text_line = 0;

                       if (printk_time) {
                               /* Follow the token with the time */
                               char tbuf[50], *tp;
                               unsigned tlen;
                               unsigned long long t;
                               unsigned long nanosec_rem;

                               t = cpu_clock(printk_cpu);
                               nanosec_rem = do_div(t, 1000000000);
                               tlen = sprintf(tbuf, "[%5lu.%06lu] ",
                                               (unsigned long) t,
                                               nanosec_rem / 1000);

                               for (tp = tbuf; tp < tbuf + tlen; tp++)
                                       emit_log_char(*tp);
                               printed_len += tlen;
                       }

                       if (!*p)
                               break;
               }

               emit_log_char(*p);
               if (*p == '\n')
                       new_text_line = 1;
       }

       if (acquire_console_semaphore_for_printk(this_cpu))
               release_console_sem();

       lockdep_on();
out_restore_irqs:
       raw_local_irq_restore(flags);

       preempt_enable();
       return printed_len;
}

シスログバッファ(リングバッファ)と言うべきものは、log_buf[]となります。ビット演算でうまくリングバッファの処理をしています。（力技プログラマの私としては、コロンブスの卵でした。）処理そのものはいたって常識的な内容です。log_startはリングバッファの開始位置で、log_endはリングバッファの終了位置、そしてlogged_charsはリングバッファに設定されたバイト数です。なおcon_startはコンソールに表示する時に参照されます。

#define LOG_BUF_MASK (log_buf_len-1)
#define LOG_BUF(idx) (log_buf[(idx) & LOG_BUF_MASK])

static char __log_buf[__LOG_BUF_LEN];
static char *log_buf = __log_buf;
static int log_buf_len = __LOG_BUF_LEN;

static void emit_log_char(char c)
{
       LOG_BUF(log_end) = c;
       log_end++;
       if (log_end - log_start > log_buf_len)
               log_start = log_end - log_buf_len;
       if (log_end - con_start > log_buf_len)
               con_start = log_end - log_buf_len;
       if (logged_chars < log_buf_len)
               logged_chars++;
}