title: Why are kernel log messages in the syslog file (or those redirected to terminal) exactly one 'message' behind?
body: <p>I wrote a simple hello-world module on Ubuntu 10.04 machine. When loading and unloading the module, printk should log messages from the following hello_world and bye_world functions.</p>
  
  <pre><code>static int hello_world()
  {
          printk(KERN_INFO "Hello, beautiful world");
          return 0;
  }
  
  static void bye_world()
  {
          printk(KERN_INFO "Good-bye kernel uncle");
  }
  
  module_init(hello_world);
  module_exit(bye_world);
  </code></pre>
  
  <p>However, when actually inserting and removing the hello.ko module, I see that the message printed on the terminal (I redirected it to the current terminal) is exactly one message behind.</p>
  
  <blockquote>
  <pre><code># rmmod hello.ko
  # Jul  8 16:34:02 panchavati kernel: [64599.954113] Hello, beautiful world
  
  # insmod hello.ko
  # Jul  8 16:34:57 panchavati kernel: [65456.367422] Good-bye kernel uncle
  </code></pre>
  </blockquote>
  
  <p>From dmesg output, I can see the next message entry (corresponding to insmod) has been already logged, just that it is not being printed yet.</p>
  
  <blockquote>
  <pre><code>chanakya@panchavati:~$ dmesg | tail -2
  [65456.367422] Good-bye kernel uncle
  [65511.198299] Hello, beautiful world
  </code></pre>
  </blockquote>
  
  <p>The entry <code>[65511.198299]</code> is there in the kernel log, but only the previous entry <code>[65456.367422] Good-bye kernel uncle</code> was printed. Why is it so?</p>
  
  <p>I earlier thought that <a href="http://linux.die.net/man/8/syslogd" rel="nofollow">'-' specifier</a> used in /etc/syslog.conf might have to do something with this (it prevents synchronization after every write), but removing it didn't work either.</p>