Questo articolo spiega come il kernel gestisce i messaggi stampati dalla funzione printk e come questi raggiungono la console e lo spazio utente.
Riprodotto con il permesso di Linux Magazine, Edizioni Master.
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.
Riquadro 2 - syslog(2) e syslog(3)
Non è 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) è 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 più usati sono il capitolo 1 (comandi), il 2 (chiamate di sistema) e il 3 (funzioni di libreria). Come ci si può aspettare, la pagina man(1) enumera anche gli altri capitoli.
In questo articolo e nei successivi userò questa notazione, per evitare di dover sempre specificare per esteso a quale syslog mi sto riferendo.
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.
Riquadro 2 - Le priorità dei messaggi
Le 8 priorità 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 */
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à),
"minimumconsoleloglevel" (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 comodità dell'utente, anche quando un file di sysctl contiene più valori è 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.
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.
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 verrà quindi sospeso finche la lettura non può essere
completata con successo, probabilmente perché un nuovo messaggio è
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 perché 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.
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 è 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 così 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 è comprensibile a colpo d'occhio.
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 più facilmente tramite sysctl.
La funzionalità più interessante di syslog(2) è la possibilità di leggere tutto il contenuto del buffer dei messaggi del kernel, anche se tali messaggi sono già stati estratti da /proc/kmsg. Naturalmente potrà essere recuperata una quantità di dati pari al massimo alla dimensione del buffer circolare, poiché i messaggi precedenti sono già stati sovrascritti da printk.
Questa funzionalità di syslog(2) è quella che viene usata dal comando dmesg. Una versione estremamente semplificata del comando, chiamata mdm (Mini D-Mesg), è 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 è la presenza nell'output della priorità associata ad ogni messaggio, proprio come apparre nel buffer circolare del kernel.
Il programma mdm può essere facilmente modificato per provare gli altri comandi offerti dalla chiamata di sistema syslog. Non si tratta, però, di un programma significativo al di là dei fini di studio, perché tutte le funzionalità di syslog sono già disponibili tramite altri comandi di sistema o tramite il meccanismo sysctl.
#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);
}
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, può essere interessante caricare il modulo dpk (dispobinile in src.tar.gz e mostrato nel riquadro 5). 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 priorità 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 può comunque raccogliere le ultime informazioni, in caso si renda necessario per diagnosticare un errore.
In questo articolo si è accennato a sysctl ed è 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/
#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);
Alessandro Rubini
La copia letterale e la redistribuzione su qualsiasi supporto di questo articolo nella sua integrità è permessa, purchè questa nota sia conservata.