For obvious reasons it's impossible to use the sd_journal
C API from kernel to do structured logging. However, there are mechanisms for passing key=value pairs as extra data for log messages.
The standard way of reporting/logging from kernel is the printk()
function. As its name suggests, it's very similar to the well-known printf()
function from libc, but it has some specialties related to the fact that it's actually being used in kernel (address) space.
Actually, printk
is a whole family of functions varying in the number and types of arguments and the way variadic arguments are passed. The most important way for our case is:
int printk_emit(int facility, int level,
const char *dict, size_t dictlen,
const char *fmt, ...);
facility
and level
are the common logging parameters just like the ones passed to the syslog()
function. fmt
and the variadic arguments are like the respective ones for printf()/printk()
functions. Finally, the most important ones for our case are dict
and dictlen
. The latter one of course just specifies the length of the former one. And that's needed, because the dict
is a dictionary of key=value pairs that are separated by \0
-bytes.
Here's a trivial example of a kernel module using the structured logging:
MODULE_LICENSE("GPL");
MODULE_AUTHOR("Vratislav Podzimek");
MODULE_DESCRIPTION("Testing structured logging from kernel");
static int __init strl_test_init(void)
{
printk_emit (0, LOGLEVEL_INFO, "TEST=test\0TEST2=test2", 22, "Module loaded");
return 0; // Non-zero return means that the module couldn't be loaded.
}
static void __exit strl_test_cleanup(void)
{
printk(KERN_INFO "Cleaning up module.\n");
}
module_init(strl_test_init);
module_exit(strl_test_cleanup);
and this is how the respective journal entries look like (in the JSON format):
{
"__CURSOR" : "s=7ab355e44efe46b38bc5db3bbaffa43e;i=2ecd4;b=b5cef4a829854151af7c0ee85b5a8ee3;m=119ce5d32c;t=554bd1bacd5a4;x=3cd94eca28194703",
"__REALTIME_TIMESTAMP" : "1500546073417124",
"__MONOTONIC_TIMESTAMP" : "75646751532",
"_BOOT_ID" : "b5cef4a829854151af7c0ee85b5a8ee3",
"PRIORITY" : "6",
"_MACHINE_ID" : "a128b9a3c70b44e6898984060de3a76f",
"_HOSTNAME" : "localhost.localdomain",
"_TRANSPORT" : "kernel",
"SYSLOG_FACILITY" : "0",
"SYSLOG_IDENTIFIER" : "kernel",
"_KERNEL_TEST" : "test",
"MESSAGE" : "Module loaded",
"_KERNEL_TEST2" : "test2",
"_SOURCE_MONOTONIC_TIMESTAMP" : "75638333296"
}
{
"__CURSOR" : "s=7ab355e44efe46b38bc5db3bbaffa43e;i=2ecde;b=b5cef4a829854151af7c0ee85b5a8ee3;m=119ce5f85f;t=554bd1bacfad7;x=b7727152b8156bca",
"__REALTIME_TIMESTAMP" : "1500546073426647",
"__MONOTONIC_TIMESTAMP" : "75646761055",
"_BOOT_ID" : "b5cef4a829854151af7c0ee85b5a8ee3",
"PRIORITY" : "6",
"_MACHINE_ID" : "a128b9a3c70b44e6898984060de3a76f",
"_HOSTNAME" : "localhost.localdomain",
"_TRANSPORT" : "kernel",
"SYSLOG_FACILITY" : "0",
"SYSLOG_IDENTIFIER" : "kernel",
"MESSAGE" : "Cleaning up module.",
"_SOURCE_MONOTONIC_TIMESTAMP" : "75638343612"
}
It can be seen that the entries come from kernel and that the TEST
and TEST2
items are stored as _KERNEL_TEST
and _KERNEL_TEST2
. This is a transformation that always happens for items coming from kernel. At the same time, keys coming from user-space cannot start with the _KERNEL
prefix. That's how authenticity of the data coming from kernel is ensured.
That means that any standard items/keys we specify for storage events/actions reporting will have to be supported both in their kernel-space and user-space forms, i.e. with the _KERNEL_
prefix and without it respectively.
Looks good to me. So, based on our discussion from earlier today, the next step is to decide on a (universal) set of keys to use. Once that is done, we will probably want a kernel function/macro that builds the dict from the standard data structures used to represent block devices.