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

[J]

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?

 

[Marco Nawijn]

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]

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

 

[Jerry Peters]

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

 

[Andrew Cooper]

Hi...

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