I messaggi del kernel

di Alessandro Rubini

Questo articolo spiega come il kernel gestisce i messaggi
stampati dalla funzione printk e come questi raggiungono la console
e lo spazio utente.


Una delle operazioni più semplici che vengono effettuate dal codice in
spazio kernel è la stampa di messaggi tramite la funzione
_printk_. In questo articolo vengono descritti i meccanismi del kernel
associati alla stampa di messaggi, come appaiono in Linux-2.6.2.

* I livelli di priorità

Ogni messaggio del kernel viene associato ad un livello di priorità,
come avviene per gli altri messaggi di sistema e come descritto dalla
pagina di manuale _syslog(3)_.

A differenza di quanto accade con _syslog(3)_, la priorità associata
ai messaggi di _printk_ non viene passata come argomento alla funzione
ma viene inserita come stringa all'inizio del messaggio stesso:
viene rappresentata da un numero compreso tra 1 e 8, racchiuso
tra parentesi ad angolo (minore e maggiore). Il file ==<linux/kernel.h>==
definisce nomi simbolici per queste stringhe, come indicato nel
riquadro 2. Normalmente, perciò, un messaggio del kernel viene
generato chiamando _printk_ nel modo seguente:

	 printk(KERN_INFO "modulo: messaggio\n");

Si noti l'assenza della virgola tra ==KERN_ERROR== e il messaggio vero
e proprio, in quanto ==KERN_ERROR== è a sua volta una stringa, che il
compilatore concatena alla stringa seguente per formare un'unica
stringa come primo parametro per _printk_. La funzione _printk_ prende
un numero variabile di argomenti dopo la prima stringa, esattamente
come _printf_ nello spazio utente, ma non gestisce argomenti in
virgola mobile, in quanto in spazio kernel la virgola mobile
non si usa.

I messaggi del kernel, come tutti i messaggi ben formati, sono righe
di testo: ogni messaggio generalmente inizia in una nuova riga e
termina con un carattere di andata a capo. La gestione delle priorità
dei messaggi dipende da questa divisione in righe più di quanto ci si
possa aspettare: la funzione _printk_ (in ==kernel/printk.c==) si
aspetta di trovare un'indicazione di priorità dopo ogni carattere di
andata a capo (e non, come ci si potrebbe aspettare, all'inizio della
stringa che riceve come primo parametro).  Se una riga non specifica
la priorità, _printk_ usa il valore predefinito in vigore in quel
momento.


* /proc/sys/kernel/printk

Il comportamento di _printk_, come la maggior parte dei comportamenti
del sistema, è configurabile per poter essere adattato, ove
possibile, alle necessità dell'utente.

Nel caso specifico i valori configurabili sono 4 numeri interi e il meccanismo
usato è _sysctl_. I valori esportati tramite _sysctl_ sono accessibili
tramite una chiamata di sistema (_sysctl(2)_), uno strumento a linea
di comando (_sysctl(8)_) e file ASCII ospitati in _/proc/sys_; in questa
sede ci limiteremo ad usare il file _/proc/sys/kernel/printk_.

I 4 parametri configurabili sono associati a 4 variabili definite ed
usate da ==kernel/printk.c==: "console_loglevel" (il livello al di
sotto del quale i messaggi vengono visualizzati in console),
"default_message_loglevel" (il livello predefinito per le righe di
messaggio che non specificano una priorità),
"minimum_console_loglevel" (il livello minimo consentito per la stampa
dei messaggi in console), "default_console_loglevel" (il livello usato
dal comando "enable printk to console" di _syslog(2)_).

Il primo parametro viene usato abbastanza frequentemente: il valore
predefinito (7) specifica che tutti i messaggi tranne quelli di debug
devono essere visualizzati in console; assegnando 8 al parametro si
abilita la stampa in console anche dei messaggi di debug; assegnando 1
si disabilitano tutti i messaggi tranne che quelli di emergenza.  È
raro, invece, dover cambiare parametri successivi al primo.

Per la comodita` dell'utente, anche quando un file di _sysctl_ contiene
piu` valori e` consentito scrivere solo una parte dei parametri, se
non si intende modificarli tutti.. Per esempio:

	\# cat /proc/sys/kernel/printk
	7       4       1       7
	\# echo 8 > /proc/syste/kernel/printk
	\# cat /proc/sys/kernel/printk
	8       4       1       7

Mentre i 4 valori appena descritti sono disponibili da molti anni e il
loro comportamento è immutato rispetto alle precedenti versioni del
kernel, Linux-2.6 aggiunge un nuovo tipo di funzionalità: la
possibilità di limitare la cadenza di generazione di certi messaggi.
La funzione _printk\_ratelimit_, sempre parte di ==kernel/printk.c==,
ritorna un valore booleano che dice al chiamante se la soglia attuale
sulla frequenza dei messaggi permette o meno di invocare _printk_.

La funzione viene utilizzata nel modo seguente:

	if (printk\_ratelimit())
		printk( ... );

I due parametri per limitare la cadenza dei messaggi sono l'intervallo di
tempo, in secondi, tra due messaggi consecutivi
(_/proc/sys/kernel/printk\_ratelimit_) e il numero di messaggi
consecutivi che vengono accettati prima di procedere con la limitazione
(_/proc/sys/kernel/printk\_ratelimit\_burst_).  I valori predefiniti sono
5 secondi e 10 messaggi; vedremo più avanti un esempio pratico di
come funziona la limitazione di cadenza dei messaggi.


* La stampa in console

Alla console, come accennato, vengono inviati tutti i messaggi di
livello pari o inferiore a "console_loglevel", predefinito a 7.  È
però possibile modificare il valore predefinito tramite la linea di
comando del kernel, per scegliere un comportamento diverso fin
dall'avvio del sistema, prima cioè di aver modo di usare _sysctl_. La
parola ==debug==, se presente sulla linea di comando, abilita anche i
messaggi di debug; la parola ==quiet==, se presente, disabilita tutti
i messaggi meno importanti dei messaggi di attenzione (KERN_WARNING).

La scelta del livello di stampa in console può sembrare un dettaglio
puramente estetico, ma in realtà non è così.  La "console", che
normalmente nelle macchine da tavolo moderne è associata allo schermo
di testo e diviene invisibile verso la fine della procedura di avvio,
quando parte automaticamente l'ambiente grafico, è in realtà un
dispositivo più complesso e variegato di quello che può sembrare: può
essere associata alla scheda video della macchina ma anche alla porta
seriale o alla stampante sulla porta parallela. O a tutte e tre le
cose insieme. Oppure a qualche altra diavoleria non convenzionale il
cui driver si è presentato al kernel come un driver di console; per
esempio in un caso mi è capitato di usare come console di sistema 4
led osservati da una telecamera, su una macchina particolarmente
povera di periferiche.

La console, in effetti, è uno strumento di diagnostica fondamentale
per il programmatore, in particolare nei casi in cui un errore nel
proprio codice in spazio kernel porta ad un blocco totale del
sistema.  Per permettere la consegna dei messaggi di diagnostica in
ogni situazione, la stampa dei messaggi in console è sincrona: la
funzione _printk_ non ritorna al chiamante finchè non ha consegnato
il messaggio a tutti i driver di console attivi; i driver di console,
da parte loro, non ritornano finchè non hanno trasmesso il messaggio
al dispositivo fisico, senza fare uso di interruzioni hardware (che
potrebbero essere disabilitate nel contesto da cui _printk_ è stata
chiamata).

La consegna di un messaggio su console seriale a 9600 bit per secondo,
perciò, ritarda il sistema di circa 1 millisecondo per ogni
carattere, la consegna su stampante un tempo ancora più lungo, la
console "4 led" mi richiedeva circa 0.3 secondi per carattere, una
console "morse" su altoparlante impiega in media un secondo per carattere.

Poter modificare il livello minimo di messaggi da stampare durante il
funzionamento del sistema è perciò un requisito importante per
evitare inutili rallentamenti del sistema ma essere comunque in grado
di raccogliere le informazioni quando necessario.

La natura sincrona della stampa in console associata alla possibilità
di usare dispositivi lenti per la trasmissione dei messaggi è quello
che ha suggerito di implementare il limite nel numero di messaggi
descritto in precedenza. Il meccanismo della limitazione di cadenza,
==printk\_ratelimit()==, deve essere usato in particolare nei casi in
cui un programma applicativo non privilegiato può volontariamente
indurre il kernel a stampare un messaggio; in tale situazione, se non
è stata prevista la limitazione nella cadenza dei messaggi, qualunque
utente del sistema può sferrare un attacco di negazione di servizio
("denial of service") obbligando il kernel a spendere tutto il suo
tempo nella consegna di innumerevoli copie dello stesso messaggio
verso le periferiche di console.


* /proc/kmsg

Tutti i messaggi del kernel, sia quelli che vengono visualizzati in
console sia quelli che non superano "console_loglevel", vengono
registrati in un buffer circolare. La dimensione del buffer è
normalmente 16kB o 32kB (su macchine SMP) ma può venire selezionata
durante la compilazione del kernel ad un valore tra 4kB e 1MB.

Il buffer viene riempito da _printk_ e vuotato da _syslog(2)_ oppure
dalla lettura di _/proc/kmsg_.  Nelle normali installazioni di
macchine da tavolo o server di rete, tale compito è svolto dal
processo _klogd_, il quale legge _/proc/kmsg_, decodifica le priorità
associate a ciascun messaggio e passa il tutto a _syslogd_ tramite
_syslog(3)_.

Questo meccanismo a due processi permette di separare la specificità
del kernel Linux (cioè _/proc/kmsg_) dal servizio di gestione dei
messaggi di sistema, un servizio standardizzato e interoperabile tra
tutte le piattaforme Unix.

In pratica, _klogd_ effettua una lettura bloccante dal file dei
messaggi che si comporta come una pipe, il processo che ha tentato la
lettura verra` quindi sospeso finche la lettura non puo` essere
completata con successo, probabilmente perche` un nuovo messaggio e`
stato inserito nel buffer.  Durante lo sviluppo di driver è prassi
comune uccidere _klogd_ e sostituirlo con un semplice "==cat
/proc/kmsg==" su un terminale testuale, in particolare quando si
generano abbondanti messaggi di diagnostica. La morte di _klogd_ non
danneggia in alcun modo la gestione degli altri messaggi di sistema,
in quanto per _syslogd_ si tratta semplicemente della chiusura di un
processo cliente, ma alleggerisce notevolmente il carico della
macchina perche` risparmia _syslogd_ dal compito di salvare su disco
tutti i messaggi generati dal kernel.

La differenza principale che si osserva nei dati raccolti tramite _cat_, se
confrontati con quelli che _klogd_ invia a _syslogd_, è la presenza
nell'output testuale dei valori di priorità nel loro formato
originale, come numero decimale tra parentesi ad angolo.  Per esempio:

	<4>nfs warning: mount version older than kernel
	<7>request_module: failed /sbin/modprobe
	<6>loop: loaded (max 8 devices)
	<6>EXT3-fs: mounted filesystem with ordered data mode.


* syslog(2)

La chiamata di sistema _syslog_, oltre a poter vuotare il buffer
circolare del kernel come alternativa a _/proc/kmsg_, permette varie
altre operazioni sul buffer dei messaggi e sui livelli dei messaggi
inviati in console, anche se queste ultime operazioni sono effettuate
molto piu` facilmente tramite _sysctl_.

La funzionalita` piu` interessante di _syslog(2)_ e` la possibilita`
di leggere tutto il contenuto del buffer dei messaggi del kernel,
anche se tali messaggi sono gia` stati estratti da
_/proc/kmsg_. Naturalmente potra` essere recuperata una quantita` di
dati pari al massimo alla dimensione del buffer circolare, poiche` i
messaggi precedenti sono gia` stati sovrascritti da _printk_.

Questa funzionalita` di _syslog(2)_ e` quella che viene usata dal
comando _dmesg_.  Una versione estremamente semplificata del comando,
chiamata _mdm_ (Mini D-Mesg), e` visibile nel riquadro 4;
il riquadro 3 spiega come _mdm_ riesce a
 chiamare _syslog(2)_ invece di
_syslog(3)_.  Come nell'uso di _cat_ in alternativa a _klogd_, la
differenza principale di _mdm_ rispetto al _dmesg_ canonico e` la
presenza nell'output della priorita` associata ad ogni messaggio,
proprio come apparre nel buffer circolare del kernel.

Il programma _mdm_ puo` essere facilmente modificato per provare gli
altri comandi offerti dalla chiamata di sistema _syslog_.  Non si
tratta, pero`, di un programma significativo al di la` dei fini di studio,
perche` tutte le funzionalita` di _syslog_ sono gia` disponibili
tramite altri comandi di sistema o tramite il meccanismo _sysctl_.


* /dev/printk

Per meglio provare i meccanismi associati ai messaggi del kernel, in
particolare l'effetto dei parametri in _/proc/sys/dev/printk_ e il
meccanismo di limitazione della cadenza dei messaggi, puo` essere
interessante caricare il modulo _dpk_. Tale modulo implementa due file
speciali a carattere: _/dev/printk_ e _/dev/printk\_ratelimit_,
che vanno creati tramite i due comandi:

	mknod /dev/printk           c 10 68
	mknod /dev/printk_ratelimit c 10 69

Tutto quello che viene scritto nel primo file viene trasformato in
_printk_ (con la priorita` di default); tutto quello che viene scritto
nel secondo file viene trasformato in _printk_ se permesso da
_printk\_ratelimit()_, come descritto in precedenza. Il modulo
permette quindi di osservare facilmente l'effetto della modifica dei
primi due valori di _/proc/sys/kernel/printk_ e dei due parametri
relativi alla limitazione di cadenza. Per esempio:

	# echo 1 3 > /proc/sys/kernel/printk
	# echo test1 > /dev/printk
	# echo 8 8 > /proc/sys/kernel/printk
	# echo test2 > /dev/printk
	# ./mdm | tail -2
	<3>test1
	<8>test2
	# ls -l /dev | dd bs=1 > /dev/printk_ratelimit
	# sleep 5
	# echo done > /dev/printk_ratelimit
	# ./mdm | tail -3
	<8>c
	<4>printk: 81377 messages suppressed.
	<8>done

Il modulo _dpk_, oltre che come strumento di studio, risulta anche
utile in alcune situazioni particolari, per esempio in sistemi molto
limitati che girano senza _syslogd_. Tutti i messaggi di log dei vari
servizi, una volta inviati su _/dev/printk_ possono essere raccolti
insieme ai messaggi del kernel dal file _/proc/kmsg_ e poi inviati
sulla rete locale come pacchetti UDP, oppure semplicemente possono
essere lasciati nel buffer circolare, da dove _dmesg_ puo` comunque
raccogliere le ultime informazioni, in caso si renda necessario
per diagnosticare un errore.


RIQUADRI

<Riquadro 1 - syslog(2) e syslog(3)>
<Riquadro 2 - Le priorità dei messaggi>
<Riquadro 3 - Dichiarare una chiamata di sistema>
<Riquadro 4 - mdm.c>
<Riquadro 5 – dpk.c>
<Riquadro 6 – approfondimenti>


<Riquadro 1 - syslog(2) e syslog(3)>

Non e` raro in un sistema GNU/Linux che uno stesso nome sia usato per
indicare cose diverse, anche se in qualche modo correlate.  Per
evitare di usare lunghe locuzioni come "la chiamata di sistema syslog"
o "il comando printf" (per distinguerli dalle due funzioni di libreria
con lo stesso nome) e` normale usare la convenzione delle pagine del
manuale Unix: indicare tra parentesi il numero del capitolo del
manuale al quale ci si riferisce. I capitoli piu` usati
sono il capitolo 1 (comandi), il 2 (chiamate di sistema) e il 3 (funzioni
di libreria).  Come ci si puo` aspettare, la pagina _man(1)_ 
enumera anche gli altri capitoli.

In questo articolo e nei successivi usero` questa notazione, per
evitare di dover sempre specificare per esteso a quale _syslog_ mi
sto riferendo.


<Riquadro 2 - Le priorità dei messaggi>

Le 8 priorita` dei messaggi del kernel sono:

--
#define KERN_EMERG   "<0>" /* system is unusable               */
#define KERN_ALERT   "<1>" /* action must be taken immediately */
#define KERN_CRIT    "<2>" /* critical conditions              */
#define KERN_ERR     "<3>" /* error conditions                 */
#define KERN_WARNING "<4>" /* warning conditions               */
#define KERN_NOTICE  "<5>" /* normal but significant condition */
#define KERN_INFO    "<6>" /* informational                    */
#define KERN_DEBUG   "<7>" /* debug-level messages             */
--


<Riquadro 3 - Dichiarare una chiamata di sistema>

Le chiamate di sistema sono delle chiamate a funzione che utilizzano
dei meccanismi particolari, dipendenti dal processore e dalle
convenzioni usate dall'implementazione specifica del sistema
operativo, per poter passare dallo spazio utente allo spazio kernel.

Il modo in cui invocare una chiamata di sistema e` definito in
==<asm/unistd.h>== (incluso da ==<linux/unistd.h>==) tramite macro un
po' bizzarre. In pratica, il file contiene una macro di preprocessore
per definire le chiamate di sistema con zero argomenti, un'altra macro
per le chiamate di sistema con un argomento, eccetera.

L'espansione di ognuna di queste macro diventa la dichiarazione di una
funzione, i cui argomenti e il cui valore di ritorno sono specificati
come argomenti della macro stessa. La funzione cosi` definita assegna
gli argomenti ai registri macchina secondo la convenzione usata per il
passaggio dei parametri sulla piattaforma specifica e usa l'istruzione
assmebly appropriata per richiedere al sistema l'evasione della
richiesta.

Per esempio (si veda il riquadro 4), la macro ==_syscall3== dichiara
una funzione con tre argomenti; gli otto parametri della macro
rappresentano tipo di dato e nome della funzione e di ciascuno dei
suoi tre argomenti. Provando a preprocessare il file _mdm.c_ (cone
==gcc -E==, per esempio), si vede chiaramente come ==_syscall3==
genera una funzione scritta in assembly, anche se il significato del
codice generato non e` comprensibile a colpo d'occhio.


<Riquadro 4 - mdm.c>

#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <linux/unistd.h>

/* define the system call, to override the library function */
static inline _syscall3(int, syslog,
			int, type, char *, bufp, int, len);

#define BUFFERSIZE 64*1024
static char buffer[BUFFERSIZE];

int main(int argc, char **argv)
{
    int len;

    len = syslog(3, buffer, BUFFERSIZE);
    if (len < 0) {
        fprintf(stderr,"%s: syslog(2): %s\n",
                argv[0],strerror(errno));
        exit(1);
    }
    fwrite(buffer, 1, len, stdout);
    exit(0);
}


<Riquadro 5 – dpk.c>

#include <linux/module.h>
#include <linux/init.h>
#include <linux/fs.h>
#include <linux/miscdevice.h>
#include <asm/uaccess.h>

#define DPK_MINOR           68 /* random */
#define DPK_MINOR_RATELIMIT 69 /* random too */
#define DPK_BUF 1023
static char localbuf[DPK_BUF+1];

ssize_t dpk_write(struct file *filp, const char *ubuff,
		  size_t count, loff_t *offp)
{
	int c;

	if (count > DPK_BUF) count = DPK_BUF;
	if (copy_from_user(localbuf, ubuff, count))
		return -EFAULT;
	c = count;
	/* remove trailing newline, if any: we add it later */
	if (localbuf[c-1] == '\n') c--;
	localbuf[c] = '\0';
	if (MINOR(filp->f_dentry->d_inode->i_rdev) == DPK_MINOR
	    || printk_ratelimit() )
		printk("%s\n", localbuf);
	return count;
}

struct file_operations dpk_fops = {
	.owner = THIS_MODULE,
	.write =    dpk_write,
};

struct miscdevice dpk_misc = {
	.minor = DPK_MINOR,
	.name = "printk",
	.fops = &dpk_fops,
};
struct miscdevice dpk_misc_r = {
	.minor = DPK_MINOR_RATELIMIT,
	.name = "printk_ratelimit",
	.fops = &dpk_fops,
};

int dpk_init(void)
{
	misc_register(&dpk_misc);
	misc_register(&dpk_misc_r);
	return 0;
}

void dpk_exit(void)
{
    misc_deregister(&dpk_misc);
    misc_deregister(&dpk_misc_r);
}

module_init(dpk_init);
module_exit(dpk_exit);


<Riquadro 6 – approfondimenti>

In questo articolo si e` accennato a _sysctl_ ed e` stato usato
il meccanismo _miscdevice_ per registrare i file speciali del
modulo _dpk_.

Entrambi questi meccanismi sono sostanzialmente immutati da quando
sono stati introdotti. Per chi fosse interessato i
due articoli seguenti (in inglese) son ancora validi:

	http://www.linux.it/kerneldocs/sysctl/
	http://www.linux.it/kerneldocs/misc/