Is there a way to create kernel log messages via Python?

Discussion in 'Python' started by J, Oct 16, 2012.

  1. J

    J Guest

    Hi...

    I have a bit of code that does the following:

    uses the syslog module to inject a LOG_INFO message into the syslog on
    my linux machine
    runs a suspend/resume cycle
    uses the syslog module to inkect a LOG_INFO message marking the end of test.

    Then I parse everything between the start and stop markers for certain
    items that the Linux kernel logs during a suspend and resume cycle.

    But my "resume complete" timing is not as accurate as it could be.
    The problem with doing it this way is that while I can find definite
    kernel messages that mark various points in the suspend/resume cycle,
    the final message when the kernel is done resuming is NOT the point I
    actually want to mark.

    Instead, the end point I want is the time of the ending marker itself,
    as this happens after certain other things are done such as resumption
    of networking services.

    Here's the problem. I can't just use syslog timestamps. The reason
    is that the syslog timestamps are only indicative of when messages are
    written to syslog via syslogd. The kernel timestamps are different.
    For example, the following bits of log are taken from the time the
    test starts until the end of the "going to sleep" kernel messages.
    First, note that there's a 5 second difference between the START
    marker and the first kernel message. Next, look at the kernel
    timestamps. The total real time to suspend starts at 421320.380947
    and ends at 421322.386355, around 2 seconds later, where the log
    messages themselves all state that the events occurred at the same
    time.

    Oct 15 10:24:19 klaatu sleep_test: ---SLEEP TEST START 1350296656---
    Oct 15 10:25:24 klaatu kernel: [421320.380947] PM: Syncing filesystems ... done.
    Oct 15 10:25:24 klaatu kernel: [421320.391282] PM: Preparing system
    for mem sleep
    [SNIP]
    Oct 15 10:25:24 klaatu kernel: [421322.282943] Broke affinity for irq 23
    Oct 15 10:25:24 klaatu kernel: [421322.386355] CPU 7 is now offline

    So, what I REALLY want is to inject my start/stop markers into klogd
    rather than syslogd. This will, I hope, give my markers kernel
    timestamps rather than syslog timestamps which are not as accurate.

    So does anyone know of a way to do this? Unfortunately, I've tried
    some searching but google doesn't like the term klog, and most of the
    hits involved injecting code or other things that are not related at
    all.

    Or, if there's a better way to get accurate timestamps, what would that be?
     
    J, Oct 16, 2012
    #1
    1. Advertising

  2. J

    Marco Nawijn Guest

    On Tuesday, October 16, 2012 5:43:28 AM UTC+2, J wrote:
    > Hi...
    >
    >
    >
    > I have a bit of code that does the following:
    >
    >
    >
    > uses the syslog module to inject a LOG_INFO message into the syslog on
    >
    > my linux machine
    >
    > runs a suspend/resume cycle
    >
    > uses the syslog module to inkect a LOG_INFO message marking the end of test.
    >
    >
    >
    > Then I parse everything between the start and stop markers for certain
    >
    > items that the Linux kernel logs during a suspend and resume cycle.
    >
    >
    >
    > But my "resume complete" timing is not as accurate as it could be.
    >
    > The problem with doing it this way is that while I can find definite
    >
    > kernel messages that mark various points in the suspend/resume cycle,
    >
    > the final message when the kernel is done resuming is NOT the point I
    >
    > actually want to mark.
    >
    >
    >
    > Instead, the end point I want is the time of the ending marker itself,
    >
    > as this happens after certain other things are done such as resumption
    >
    > of networking services.
    >
    >
    >
    > Here's the problem. I can't just use syslog timestamps. The reason
    >
    > is that the syslog timestamps are only indicative of when messages are
    >
    > written to syslog via syslogd. The kernel timestamps are different.
    >
    > For example, the following bits of log are taken from the time the
    >
    > test starts until the end of the "going to sleep" kernel messages.
    >
    > First, note that there's a 5 second difference between the START
    >
    > marker and the first kernel message. Next, look at the kernel
    >
    > timestamps. The total real time to suspend starts at 421320.380947
    >
    > and ends at 421322.386355, around 2 seconds later, where the log
    >
    > messages themselves all state that the events occurred at the same
    >
    > time.
    >
    >
    >
    > Oct 15 10:24:19 klaatu sleep_test: ---SLEEP TEST START 1350296656---
    >
    > Oct 15 10:25:24 klaatu kernel: [421320.380947] PM: Syncing filesystems ... done.
    >
    > Oct 15 10:25:24 klaatu kernel: [421320.391282] PM: Preparing system
    >
    > for mem sleep
    >
    > [SNIP]
    >
    > Oct 15 10:25:24 klaatu kernel: [421322.282943] Broke affinity for irq 23
    >
    > Oct 15 10:25:24 klaatu kernel: [421322.386355] CPU 7 is now offline
    >
    >
    >
    > So, what I REALLY want is to inject my start/stop markers into klogd
    >
    > rather than syslogd. This will, I hope, give my markers kernel
    >
    > timestamps rather than syslog timestamps which are not as accurate.
    >
    >
    >
    > So does anyone know of a way to do this? Unfortunately, I've tried
    >
    > some searching but google doesn't like the term klog, and most of the
    >
    > hits involved injecting code or other things that are not related at
    >
    > all.
    >
    >
    >
    > Or, if there's a better way to get accurate timestamps, what would that be?


    Hi,

    I cannot be of too much help here, but is there a userspace/kernel C-interface that could be used. If so, you might be able to use the Python ctypes module to create messages at the correct moments

    Regards,
    Marco
     
    Marco Nawijn, Oct 16, 2012
    #2
    1. Advertising

  3. J

    Marco Nawijn Guest

    On Tuesday, October 16, 2012 5:43:28 AM UTC+2, J wrote:
    > Hi...
    >
    >
    >
    > I have a bit of code that does the following:
    >
    >
    >
    > uses the syslog module to inject a LOG_INFO message into the syslog on
    >
    > my linux machine
    >
    > runs a suspend/resume cycle
    >
    > uses the syslog module to inkect a LOG_INFO message marking the end of test.
    >
    >
    >
    > Then I parse everything between the start and stop markers for certain
    >
    > items that the Linux kernel logs during a suspend and resume cycle.
    >
    >
    >
    > But my "resume complete" timing is not as accurate as it could be.
    >
    > The problem with doing it this way is that while I can find definite
    >
    > kernel messages that mark various points in the suspend/resume cycle,
    >
    > the final message when the kernel is done resuming is NOT the point I
    >
    > actually want to mark.
    >
    >
    >
    > Instead, the end point I want is the time of the ending marker itself,
    >
    > as this happens after certain other things are done such as resumption
    >
    > of networking services.
    >
    >
    >
    > Here's the problem. I can't just use syslog timestamps. The reason
    >
    > is that the syslog timestamps are only indicative of when messages are
    >
    > written to syslog via syslogd. The kernel timestamps are different.
    >
    > For example, the following bits of log are taken from the time the
    >
    > test starts until the end of the "going to sleep" kernel messages.
    >
    > First, note that there's a 5 second difference between the START
    >
    > marker and the first kernel message. Next, look at the kernel
    >
    > timestamps. The total real time to suspend starts at 421320.380947
    >
    > and ends at 421322.386355, around 2 seconds later, where the log
    >
    > messages themselves all state that the events occurred at the same
    >
    > time.
    >
    >
    >
    > Oct 15 10:24:19 klaatu sleep_test: ---SLEEP TEST START 1350296656---
    >
    > Oct 15 10:25:24 klaatu kernel: [421320.380947] PM: Syncing filesystems ... done.
    >
    > Oct 15 10:25:24 klaatu kernel: [421320.391282] PM: Preparing system
    >
    > for mem sleep
    >
    > [SNIP]
    >
    > Oct 15 10:25:24 klaatu kernel: [421322.282943] Broke affinity for irq 23
    >
    > Oct 15 10:25:24 klaatu kernel: [421322.386355] CPU 7 is now offline
    >
    >
    >
    > So, what I REALLY want is to inject my start/stop markers into klogd
    >
    > rather than syslogd. This will, I hope, give my markers kernel
    >
    > timestamps rather than syslog timestamps which are not as accurate.
    >
    >
    >
    > So does anyone know of a way to do this? Unfortunately, I've tried
    >
    > some searching but google doesn't like the term klog, and most of the
    >
    > hits involved injecting code or other things that are not related at
    >
    > all.
    >
    >
    >
    > Or, if there's a better way to get accurate timestamps, what would that be?


    Hi,

    I cannot be of too much help here, but is there a userspace/kernel C-interface that could be used. If so, you might be able to use the Python ctypes module to create messages at the correct moments

    Regards,
    Marco
     
    Marco Nawijn, Oct 16, 2012
    #3
  4. J

    Jerry Peters Guest

    J <> wrote:
    > Hi...
    >
    > I have a bit of code that does the following:
    >
    > uses the syslog module to inject a LOG_INFO message into the syslog on
    > my linux machine
    > runs a suspend/resume cycle
    > uses the syslog module to inkect a LOG_INFO message marking the end of test.
    >
    > Then I parse everything between the start and stop markers for certain
    > items that the Linux kernel logs during a suspend and resume cycle.
    >
    > But my "resume complete" timing is not as accurate as it could be.
    > The problem with doing it this way is that while I can find definite
    > kernel messages that mark various points in the suspend/resume cycle,
    > the final message when the kernel is done resuming is NOT the point I
    > actually want to mark.
    >
    > Instead, the end point I want is the time of the ending marker itself,
    > as this happens after certain other things are done such as resumption
    > of networking services.
    >
    > Here's the problem. I can't just use syslog timestamps. The reason
    > is that the syslog timestamps are only indicative of when messages are
    > written to syslog via syslogd. The kernel timestamps are different.
    > For example, the following bits of log are taken from the time the
    > test starts until the end of the "going to sleep" kernel messages.
    > First, note that there's a 5 second difference between the START
    > marker and the first kernel message. Next, look at the kernel
    > timestamps. The total real time to suspend starts at 421320.380947
    > and ends at 421322.386355, around 2 seconds later, where the log
    > messages themselves all state that the events occurred at the same
    > time.
    >
    > Oct 15 10:24:19 klaatu sleep_test: ---SLEEP TEST START 1350296656---
    > Oct 15 10:25:24 klaatu kernel: [421320.380947] PM: Syncing filesystems ... done.
    > Oct 15 10:25:24 klaatu kernel: [421320.391282] PM: Preparing system
    > for mem sleep
    > [SNIP]
    > Oct 15 10:25:24 klaatu kernel: [421322.282943] Broke affinity for irq 23
    > Oct 15 10:25:24 klaatu kernel: [421322.386355] CPU 7 is now offline
    >
    > So, what I REALLY want is to inject my start/stop markers into klogd
    > rather than syslogd. This will, I hope, give my markers kernel
    > timestamps rather than syslog timestamps which are not as accurate.
    >
    > So does anyone know of a way to do this? Unfortunately, I've tried
    > some searching but google doesn't like the term klog, and most of the
    > hits involved injecting code or other things that are not related at
    > all.
    >
    > Or, if there's a better way to get accurate timestamps, what would that be?



    Take a look at /dev/kmsg, I *believe* it's the way various boot
    logging programs inject application type messages into the kernel boot
    up message stream.

    Jerry
     
    Jerry Peters, Oct 16, 2012
    #4
  5. On 16/10/2012 04:43, J wrote:
    > Hi...
    >

    <snip>
    >
    > So, what I REALLY want is to inject my start/stop markers into klogd
    > rather than syslogd. This will, I hope, give my markers kernel
    > timestamps rather than syslog timestamps which are not as accurate.
    >
    > So does anyone know of a way to do this? Unfortunately, I've tried
    > some searching but google doesn't like the term klog, and most of the
    > hits involved injecting code or other things that are not related at
    > all.
    >
    > Or, if there's a better way to get accurate timestamps, what would that be?
    >


    It is very easy (about 40 lines of C) to write a kernel module which
    opens up an easy interface to use.

    I wrote a kernel module (unimaginatively called uklog, for user-klog)
    which exports /proc/printk/{alert thru debug}. With this in place, any
    (root, although this can be changed) userspace process can issue
    messages into the kernel by opening the relevant file and writing to it.

    Sadly, this is not useful on any system which is not your own, and is
    also unlikely to be accepted upstream (although it is fantastically
    useful for micro-vms with no root filesystems, where the kernel log is
    the only form of logging, and the serial console is the only useful
    method of communication.)

    ~Andrew
     
    Andrew Cooper, Oct 17, 2012
    #5
    1. Advertising

Want to reply to this thread or ask your own question?

It takes just 2 minutes to sign up (and it's free!). Just click the sign up button to choose a username and then you can ask your own questions on the forum.
Similar Threads
  1. Brian Donovan

    Replacing python: in syslog log messages

    Brian Donovan, Sep 5, 2003, in forum: Python
    Replies:
    1
    Views:
    396
    Jp Calderone
    Sep 6, 2003
  2. yogesh
    Replies:
    3
    Views:
    590
    Kenny McCormack
    Feb 12, 2006
  3. Replies:
    3
    Views:
    178
  4. Leena Jethwa

    Create a log-in & log-out page

    Leena Jethwa, May 1, 2009, in forum: Ruby
    Replies:
    2
    Views:
    102
    Mike Stephens
    May 1, 2009
  5. Lars Gierth
    Replies:
    6
    Views:
    226
    David Masover
    Mar 20, 2010
Loading...

Share This Page