Una panoramica sul mondo della Sicurezza Informatica, del Networking, della Virtualizzazione e non solo. Blog particolarmente indicato per i reparti IT che comunque alterna articoli scritti per specialisti con articoli formulati con linguaggio semplice e comprensibile a tutti.

Ogni articolo di questo blog è stato integralmente scritto dall'autore. Il contenuto è completamente originale e la riproduzione, anche parziale, è vietata salvo autorizzazione.

martedì 12 maggio 2015

Raspberry PI, w1 Linux Raspian Kernel bug & Process Priority

Scenario

In alcune particolari condizioni, abbiamo avuto modo di verificare, io ed il mio collaboratore Senior Luca, dei Kernel Panic sollecitati dalla lettura del modulo 1wire.

Il kernel panic si verifica:

  • su kernel 3.18.9+, Raspian armv6l (non ho informazioni circa versioni differenti, più o meno recenti rispetto a questa)
  • solo su CPU mono core (quindi RaspBerry Pi 1 e non RaspBerry Pi 2)
  • quando istruzioni pygame sono in esecuzione
  • quando si verifica un overload della CPU (tuttavia questo non è estremamente rilevante)
  • quando il numero di processi python aumenta
  • a prescindere dalle sonde (ne abbiamo cambiate 10 e abbiamo cambiato 5 raspberry, riproducendo il problema anche con hardware completamente differente)

Cosa Accade

Inizialmente una serie di letture delle sonde w1 danno errori di CRC:


May 11 20:11:16 AS15C3101B kernel: [  392.757953] w1_slave_driver 28-000005a01d7f: Read failed CRC check
May 11 20:11:43 AS15C3101B kernel: [  419.917527] w1_slave_driver 28-00000696eb99: Read failed CRC check
May 11 20:12:30 AS15C3101B kernel: [  466.413438] w1_slave_driver 28-00000696eb99: Read failed CRC check
May 11 20:12:44 AS15C3101B kernel: [  480.799177] w1_slave_driver 28-0000054ebd49: Read failed CRC check
May 11 20:12:50 AS15C3101B kernel: [  486.936962] w1_slave_driver 28-000005a01d7f: Read failed CRC check
May 11 20:13:06 AS15C3101B kernel: [  502.939939] w1_slave_driver 28-0000054ebd49: Read failed CRC check
May 11 20:13:14 AS15C3101B kernel: [  510.917800] w1_slave_driver 28-000005a01d7f: Read failed CRC check
May 11 20:13:28 AS15C3101B kernel: [  524.425806] w1_slave_driver 28-0000054ebd49: Read failed CRC check
May 11 20:13:36 AS15C3101B kernel: [  532.149026] w1_slave_driver 28-000005a01d7f: Read failed CRC check
May 11 20:13:51 AS15C3101B kernel: [  547.247455] w1_slave_driver 28-0000054ebd49: Read failed CRC check
May 11 20:22:55 AS15C3101B kernel: [  394.467714] w1_slave_driver 28-0000054e5d76: Read failed CRC check
May 11 20:23:35 AS15C3101B kernel: [  433.749331] w1_slave_driver 28-00000696eb99: Read failed CRC check
May 11 20:23:49 AS15C3101B kernel: [  448.129373] w1_slave_driver 28-0000054e5d76: Read failed CRC check
May 11 20:23:59 AS15C3101B kernel: [  457.658434] w1_slave_driver 28-00000696eb99: Read failed CRC check
May 11 20:24:55 AS15C3101B kernel: [  513.698751] w1_slave_driver 28-000005a137c6: Read failed CRC check
May 11 20:27:48 AS15C3101B kernel: [  687.187439] w1_slave_driver 28-000005a137c6: Read failed CRC check
May 11 20:28:02 AS15C3101B kernel: [  701.376795] w1_slave_driver 28-000005a137c6: Read failed CRC check
May 11 20:33:18 AS15C3101B kernel: [ 1017.072088] w1_slave_driver 28-00000696eb99: Read failed CRC check



Successivamente tendono persino a scomparire per poi ricomparire a breve e, per finire, il kernel va in panic dando messaggi di errore anche in broadcast. 

Message from syslogd@AS15C1302B at May 11 20:39:56  ...
 kernel:[ 2614.966264] 5f00: 5550f5f9 37b02fc0 00001a62 dcef5f78 dcef5f3c dba05320 01825000 dcef4000
Message from syslogd@AS15C1302B at May 11 20:39:56 ...
 kernel:[ 2614.966286] 5f20: dcef5f78 00008000 01825000 00000000 dcef5f74 dcef5f40 c0137e6c c01a9a38
Segmentation fault


Nei /var/log/messages non c'è molto, a dire il vero:


May 11 20:34:56 AS15C3101B kernel: [ 1115.363581] Modules linked in: i2c_dev stmpe_ts snd_bcm2835 snd_pcm snd_seq snd_seq_device snd_timer snd evdev uinput fb_ili9340(C) fbtft(C) syscopyarea sysfillrect sysimgblt fb_sys_fops spi_bcm2708 i2c_bcm2708 8192cu w1_therm lirc_rpi(C) w1_gpio wire lirc_dev cn rc_core uio_pdrv_genirq uio
May 11 20:34:56 AS15C3101B kernel: [ 1115.363724] CPU: 0 PID: 24237 Comm: cat Tainted: G         C     3.18.9+ #768
May 11 20:34:56 AS15C3101B kernel: [ 1115.363742] task: dbb0b600 ti: daf0e000 task.ti: daf0e000
May 11 20:34:56 AS15C3101B kernel: [ 1115.363778] PC is at w1_slave_show+0x2d8/0x398 [w1_therm]
May 11 20:34:56 AS15C3101B kernel: [ 1115.363804] LR is at vsnprintf+0x27c/0x3e0
May 11 20:34:56 AS15C3101B kernel: [ 1115.363820] pc : [<bf04336c>]    lr : [<c02fb36c>]    psr: 20000113
May 11 20:34:56 AS15C3101B kernel: [ 1115.363820] sp : daf0fe08  ip : bf0435c0  fp : daf0fe54
May 11 20:34:56 AS15C3101B kernel: [ 1115.363840] r10: 0000001f  r9 : daf0fe27  r8 : daf0fe27
May 11 20:34:56 AS15C3101B kernel: [ 1115.363854] r7 : dcf70a50  r6 : dcfb8000  r5 : 00000fe5  r4 : 00000000
May 11 20:34:56 AS15C3101B kernel: [ 1115.363867] r3 : 00000000  r2 : 1002ff7f  r1 : 464b01de  r0 : 0000000d
May 11 20:34:56 AS15C3101B kernel: [ 1115.363882] Flags: nzCv  IRQs on  FIQs on  Mode SVC_32  ISA ARM  Segment user
May 11 20:34:56 AS15C3101B kernel: [ 1115.363896] Control: 00c5387d  Table: 1ad54008  DAC: 00000015
May 11 20:34:56 AS15C3101B kernel: [ 1115.364356] [<bf04336c>] (w1_slave_show [w1_therm]) from [<c0361650>] (dev_attr_show+0x2c/0x58)
May 11 20:34:56 AS15C3101B kernel: [ 1115.364394] [<c0361650>] (dev_attr_show) from [<c01aa838>] (sysfs_kf_seq_show+0x9c/0x104)
May 11 20:34:56 AS15C3101B kernel: [ 1115.364424] [<c01aa838>] (sysfs_kf_seq_show) from [<c01a9168>] (kernfs_seq_show+0x34/0x38)
May 11 20:34:56 AS15C3101B kernel: [ 1115.364452] [<c01a9168>] (kernfs_seq_show) from [<c015c310>] (seq_read+0x1b8/0x488)
May 11 20:34:56 AS15C3101B kernel: [ 1115.364481] [<c015c310>] (seq_read) from [<c01a9b50>] (kernfs_fop_read+0x124/0x16c)
May 11 20:34:56 AS15C3101B kernel: [ 1115.364511] [<c01a9b50>] (kernfs_fop_read) from [<c0137e6c>] (vfs_read+0x98/0x188)
May 11 20:34:56 AS15C3101B kernel: [ 1115.364538] [<c0137e6c>] (vfs_read) from [<c0138580>] (SyS_read+0x4c/0xa0)
May 11 20:34:56 AS15C3101B kernel: [ 1115.364573] [<c0138580>] (SyS_read) from [<c000e800>] (ret_fast_syscall+0x0/0x48)
May 11 20:34:56 AS15C3101B kernel: [ 1115.364679] ---[ end trace d47c3c19eebad7da ]---

Da questo momento in poi qualsiasi interrogazione sulle sonde w1 rimarrà in hang e bloccherà la shell o qualsiasi script che richiami questa informazione. Anche un semplice cat del valore di w1_slave.

rmmod e modprobe dei moduli w1 rimarranno in hang esattamente come tutto ciò che riguarda anche il modulo w1_thermal w1_slave e w1_bus.


Scatenare l'errore

Più interrogazioni si fanno sulle sonde w1, più avremo probabilità di scatenare il Kernel Panic.

Un modo efficace per mandare in hang il sistema può essere questo:

(bash)# while [ true ]; do cat /sys/bus/w1/devices/28-*/w1_slave; sleep 1; done

Se il sistema è affetto dal problema, nel giro di 60 minuti diventerà instabile.


Ipotesi

Una delle ipotesi che abbiamo formulato si basa sull'assenza di clock hardware nel Raspberry. Tale mancanza, emulata a livello software tramite timer interrupt, potrebbe produrre (in determinate e rare circostanze di carico e utilizzo di risorse) una dilatazione del clock, causando difficoltà nella gestione dell'hardware comunicante in half-duplex (che quindi utilizza dei timing precisi) come quello w1.

E' solo un'ipotesi, ma nel paragrafo successivo vedremo come lavorando sui nice del processore si producano dei miglioramenti.


Soluzioni (più o meno artigianali)

Intendiamoci, può accadere qualsiasi cosa, ma un Kernel deve gestire questo tipo di problema. Il fatto che si pianti (non del tutto, perchè riusciamo ancora a riavviare mediante un reset di tipo echo 1 > /proc/sys/kernel/sysrq ), non è comunque normale. Di fatto tutta la parte w1 entra irrimediabilmente in hang fino al riavvio del sistema.

Perdendoci la testa, correlando l'errore non presente sui sistemi multicore e seguendo la traccia dell'ottimizzazione dell'utilizzo della singola risorsa CPU, ci siamo accorti di una cosa:

# ps -lfax | grep w1_bus_master
F   UID   PID  PPID PRI  NI    VSZ   RSS WCHAN  STAT TTY        TIME COMMAND
1     0      247     2    20   0        0        0     w1_pro           S    ?              0:17   \_ [w1_bus_master1]

# nice
0

(Per chi non lo sapesse, nice è il comando linux in grado di forzare una priorità di CPU durante l'esecuzione di un processo. Renice è il suo omonimo in grado di cambiarla ad un processo esistente.)

Nonostante il nice di default fosse 0, w1_bus_master veniva eseguito con nice 20. In situazioni di high-cpu-load, quindi, un processo "tradizionale" parrebbe essere eseguito con una priorità maggiore di un processo di sistema così delicato.

Tanto per iniziare, quindi, abbiamo dato una priorità di utilizzo CPU a -20 (il massimo impostabile "tradizionalmente"):

# renice -n -20 $( ps -aux | grep w1_bus_master | grep -v "grep" | sed -n 1p | awk '{ print $2 }' );

Successivamente abbiamo trovato una profonda correlazione scatenante con l'esecuzione di uno script python contenente librerie pygame. Abbiamo, quindi, startato lo script con nice -n 39 python script.py

Questi due accorgimenti, insieme ad un'ottimizzazione dello script python e al numero di processi che esso generava, sono bastati a ridurre drasticamente i kernel panic e gli errori CRC in lettura del bus w1. Ad ora, dopo quasi 4.000 interrogazioni, non ho avuto nemmeno un CRC error e, ovviamente, di conseguenza nessun Kernel Panic o Kernel Mod Hang. 
Senza gli accorgimenti di cui sopra, ricevevo circa il 20% di errori CRC, prima di causare (prima o poi) un prevedibile crash del Kernel e del suo modulo di gestione w1.
Pubblicato da
Etichette: ,