mercoledì 24 marzo 2021

25 - Diagnostica: Windows Software Trace Preprocessor (WPP)

Inviare e ricevere messaggi di diagnostica o di tracciamento in fase di debugging di un programma o di un driver è un'attività che si rivela spesso molto utile. Scrivere, seppur in fase di debug, informazioni su un file di log o inviarle direttamente ad un programma che le visualizzi non è un operazione banale perché si deve tener conto del calo di prestazioni che il codice aggiuntivo comporterebbe. Ad esempio, se si volessero scrivere i messaggi di tracing in formato testo su un file di log questo richiederebbe che il programma o driver che invia i messaggi si occupi anche della creazione del file di log, della codifica e della formattazione dei messaggi, ecc. Windows Software Trace Preprocessor (WPP) è stato ideato per gestire il tracciameto in modo efficiente poiché tutto quello che è richiesto al programma che invia i messaggi è di segnalare da dove inviarli e cosa questi debbano contenere. Tali messaggi vengono poi salvati in formato binario non formattato in un buffer predefinito e copiati in un file di log creato da un programma esterno (che non è quindi il programma che invia i messaggi). Allo stesso modo, è possibile inoltrare i messaggi direttamente al programma che visualizza i messaggi senza passare dal file di log. In entrambi i casi, comunque, il programma dovrà sapere come leggere ed interpretare i dati binari (nel file di log o ricevuti direttamente) e come formattarli prima della presentazione a schermo. L'architettura, ed i componenti che compongono WPP ,è quella mostrata nella seguente immagine, che verrà ripresa e spiegata nel corso di questa lezione.




Il codice sorgente utilizzato per questa lezione è preso dal sample TraveDriver, che si trova nel repository ufficiale di Microsoft (si veda [1]). Tale sample è composto da due progetti: un driver (TraceDrv) che è in grado di inviare messaggi di tracciamento ed un client user-mode (TraceCtl) che installa il driver e lo interroga (tramite DeviceIoControl) al fine di fargli inviare tali messaggi.



Test diagnostico

Prima di esaminare le varie componenti di WPP ed il codice sorgente del sample è utile vedere un esempio pratico di test diagnostico per il driver TraceDrv. Innanzitutto è necessario aver già i file SYS ed EXE, rispettivamente di TraceDrv e TraceCtl. Ad ogni modo, al momento ci si limiti a seguire leggendo, senza mettere mano a Visual Studio (si vedrà in seguito come compilare i due progetti).

- Si esegua TraceView con privilegi di amministratore (di solito lo si può trovare in %PROGRAMFILES(x86)%\Windows Kits\10\Tools\x64)

- Si selezioni File -> Create New Log Session

- Nella finestra "Provider Control GIUD Setup" si selezioni "PDB (Debug Information) File" e si selezioni il file TraceDrv.pdb




- Si selezioni il pulsante OK e nella finestra successiva, denominata "Log Session Options", ci si assicuri del fatto che l'opzione "Real Time Display" è spuntata.




- Si provi a selezionare il pulsante a destra di "Set Flags and Level". Si noterà un GUID all'interno del quale ci sono due voci: Level e Flags. A loro volta, queste due voci contengono alcuni valori che è possibile selezionare e deselezionare con l'uso di spunte o radio button. Al momento si lasci tutto com'è e si prema OK o Cancel.




- Si prema OK nella finestra "Log Session Options" e si avvii TraceCtl.exe con privilegi di amministratore. Si prema un pulsante qualsiasi per inviare una richiesta al TraceDrv ed infine il tasto "q" per uscire.




- Si torni a TraceView e si guardi il risultato. Come si può notare, alcuni messaggi sono comparsi nella parte inferiore della finestra. Questi sono i messaggi di tracing inviati da TraceDrv in ordine di invocazione.




- Ora si chiuda tutto e si ripeta il procedimento togliendo la spunta a FLAG_TWO e/o selezionare None nelle voci Flags e Level della finestra "Tracing Flags and Level Selection" (che si apre selezionando il pulsante a destra di "Set Flags and Level"). Il risultato sarà il seguente.




Come si può notare, rispetto a prima manca il messaggio "Machine State :: Offline". Per quanto appena visto, quindi, si può intuire che Flags e Level servono a scegliere, tra i vari messaggi, quelli a cui si è interessati. Naturalmente, è possibile anche provare a salvare i messaggi in un file di log togliendo la spunta a "Real Time Display" e mettendola a "Log Trace Event Data to File". In quest'ultimo caso, dopo aver avviato TraceCtl, premuto un tasto per inviare una richiesta al driver e premuto "q" per uscire, bisogna andare in TraceView e

- Selezionare File -> Open Existing Log File 

- Selezionare il file di log in cui sono salvati i messaggi




- Selezionare Auto (oppure "PDB (Debug Information) File" e selezionare TraceDrv.pdb) e premere OK.




Verrà creata una nuova sessione di tracing che mostrerà gli stessi risultati ottenuti in precedenza con la sessione in real time.




Architettura

E' ora possibile fare una breve panoramica sulle varie componenti coinvolte nel software tracing tramite WPP. Si consideri la seguente immagine.




Provider
Per provider si intende il programma, oppure una sua componente, che invia i messaggi di tracing. Nel caso del test diagnostico precedente il provider era il driver TraceDrv. In questa lezione si tratterà solo il caso in cui il provider è l'intero programma che invia messaggi di tracciamento.

Controller
Un provider genera messaggi solo se è abilitato a farlo. Tale abilitazione deve essere fornita da un controller, che è un applicazione che gestisce una sessione di tracing.

Buffer
Il sistema mantiene dei buffer dove vengono salvati i messaggi in formato binario non formattato. Questi buffer vengono poi svuotati (copiati) su un file di log o passati direttamente ad un consumer quando sono pieni o ad intervalli regolari prestabiliti. Un controller è in grado di configurare la dimensione di questi buffer per la sessione che sta gestendo. Inoltre, un controller è autorizzato anche a svuotare un buffer (sempre su un file di log o in un consumer) on demand oppure ad intervalli regolari.

Session
Una sessione è il periodo di tempo in cui un provider, abilitato da un controller, scrive messaggi su un buffer. Un controller configura ed avvia una sessione, abilita un provider e lo associa alla sessione.

Log File
Un insieme di messaggi di tracciamento, binari e non formattati, ordinati in base al momento della loro ricezione, è considerato un file di log.

Consumer
Un consumer è un'applicazione che legge ed è in grado di interpretare il contenuto di un file di log o dei dati ricevuti direttamente dal buffer. Il consumer formatta i messaggi di tracing grazie alle informazioni contenute nel file PDB del provider. Spesso controller e consumer vengono implementati in un unico tool o programma. E' questo il caso di TraceView, visto nell'esempio di test diagnostico ad inizio lezione.

Come si può notare dall'immagine, è possibile che più provider vengano associati alla stessa sessione. Tali provider possono appartenere a programmi diversi ma è possibile avere più provider all'interno dello stesso programma, addirittura all'interno dello stesso file sorgente. Per quanto riguarda gli scopi di questa lezione, si può tralasciare tutto questo concentrandosi sul caso in cui il provider è semplicemente il programma che invia messaggi di tracing.
Si noti anche che i messaggi vengono effettivamente inviati solo se il controller abilita il provider (cioè il programma) a farlo. Al contrario, tutto il codice di tracciamento e diagnostica non è eseguito ed è come se non ci fosse. Inoltre, anche abilitando l'invio dei messaggi, questi sono in formato binario non formattato e copiati su un buffer predefinito quindi il calo di performance è minimo.
Infine, WPP è basato su ETW (Event tracing for Windows, argomento della prossima lezione) che è un infrastruttura molto più potente ma anche più complicata. In poche parole, WPP è un layer sopra ETW che serve a semplificarne l'utilizzo. In pratica, un driver inserisce delle macro WPP per configurare il software tracing ed inviare messaggi. Il preprocessore di WPP passa il codice al setaccio prima del compilatore vero e proprio e converte le macro nel relativo codice ETW. Il codice generato dal preprocessore viene messo in un file TMH (Trace Message Header) che è generato automaticamente prima della compilazione. Tale file header contiene anche le informazioni su come formattare i messaggi binari e deve essere incluso nel codice e compilato insieme a tutto il resto. Le informazioni sulla formattazione verranno inserite nel file PDB del provider.

Per inviare un messaggio di tracing è possibile usare la macro DoTraceMessage, che il preprocessore WPP convertirà in una invocazione alla una funzione ETW corrispondente. Tale macro ha la seguente firma:

DoTraceMessage(Flag, Message, MessageVariables...);

Flag è un valore preso tra un insieme di valori definiti dal programmatore, che servono ad identificare il tipo/genere di messaggio di tracing o semplicemente a distinguerli uno dall'altro. Si ricordino i valori FLAG_ONE e FLAG_TWO del test di diagnostica effettuato all'inizio della lezione. In quel caso è stato possibile disattivare uno dei flag per non ricevere i relativi messaggi. Quindi un controller è in grado di attivare il tracciamento solo per alcuni messaggi proprio grazie ai flag. A breve si vedrà come definire un insieme di flag.

Message è una stringa di formato simile a quella che si passa a funzioni come printf o KdPrint. WPP supporta anche alcuni specificatori di formato personalizzati (si veda la documentazione) e la possibilità di definirne di nuovi. Si vedrà un esempio di specificatore personalizzato a breve.

MessageVariable è la lista di variabili relative agli specificatori di formato che si trovano nella stringa Message.

Se si volesse maggiore personalizzazione è possibile definire la propria macro per inviare i messaggi di tracing. In questo caso la firma deve essere la seguente:

FunctionName(Condition1Condition2, ..., Message, MessageVariables...);

ConditionX è un valore che specifica una informazione sul messaggio di tracing. In DoTraceMessage si usava il valore Flag per distinguere i messaggi mentre, in questo caso, si possono passare molte più informazioni. In genere due condition sono più che sufficienti e, nella maggior parte dei casi, una delle due è un Flag definito dal programmatore mentre l'altra è uno dei valori definiti nel file header predefinito evntrace.h, dove si possono trovare i livelli di "gravità" del messaggio di tracing. Anche in questo caso, come visto nel test di diagnostica, è possibile disattivare i messaggi inviati in base a flag e livelli.

#define TRACE_LEVEL_NONE        0   // Tracing is not on
#define TRACE_LEVEL_CRITICAL    1   // Abnormal exit or termination
#define TRACE_LEVEL_FATAL       1   // Deprecated name for Abnormal exit or termination
#define TRACE_LEVEL_ERROR       2   // Severe errors that need logging
#define TRACE_LEVEL_WARNING     3   // Warnings such as allocation failure
#define TRACE_LEVEL_INFORMATION 4   // Includes non-error cases(e.g.,Entry-Exit)
#define TRACE_LEVEL_VERBOSE     5   // Detailed traces from intermediate steps
#define TRACE_LEVEL_RESERVED6   6
#define TRACE_LEVEL_RESERVED7   7
#define TRACE_LEVEL_RESERVED8   8
#define TRACE_LEVEL_RESERVED9   9

Il significato degli altri parametri è lo stesso di quello visto per DoTraceMessage. Quando si definisce e si usa una macro personalizzata è necessario scrivere del codice aggiuntivo, che verrà esaminato a breve.




Compilazione

Per compilare il driver (TraceDrv) ed il programma utente (TraceCtl) si scarichi il repository tramite link fornito a fine lezione (si veda [1]). Si apra il file soluzione TraceDrv.sln (in General\Tracing\TraceDriver) e si apra la pagina delle proprietà del progetto TraceDrv. In Wpp Tracing -> General ci si assicuri che alla voce Run Wpp Tracing sia selezionato Si.




Il questo modo si indica al compilatore che deve prima essere avviato e passato il preprocessore WPP. Sempre in Wpp Tracing, alla voce Search and Formatting, si inserisca la firma della macro personalizzata che si vuole usare per inviare messaggi di tracing. Tale firma in genere è fornita dal programmatore in base alle sue esigenze ma in questo caso stiamo compilando un driver scritto da altri quindi serve la firma della macro usata in questo contesto. Tale firma si può dedurre guardando l'invocazione dei vari metodi di tracciamento ma fortunatamente, in questo caso, la firma è inserita bella e pronta come commento in TraceDrv.h.

// -func:DoTraceLevelMessage(LEVEL,FLAGS,MSG,...). 



A questo punto si può avviare la compilazione di TraceDrv. Si noterà che prima della compilazione vera e propria viene creato un file TraceDrv.tmh, necessario perché incluso in TraceDrv.c. La compilazione di TraceCtl non presenta invece novità di rilievo rispetto alla normale compilazione di ogni programma user-mode. A questo punto si può provare ad effettuare un test di diagnostica come quello eseguito all'inizio della lezione.




Implementazione

L'implementazione di TraceCtl è banale oppure non interessante ai fini della lezione quindi di passerà direttamente al codice di TraceDrv.

TraceDrv.h
//
// Ogni provider deve essere unicamente identificato con un GUID.
// WPP_CONTROL_GUIDS serve sia ad associare un GUID al provider che a definire i vari 
// flag da passare ai metodi di tracciamento.
// WPP_DEFINE_CONTROL_GUID accetta un GUID come secondo parametro ed un nome associato 
// ad esso come primo param.
// WPP_DEFINE_BIT serve a definire il nome di flag. Il suo valore è dato da quello 
// del bit associato (al max si possono occupare 31 bit). Ad esempio, in questo caso 
// FLAG_ONE è messo come primo quindi il suo valore è quello associato al primo bit 
// (0, quello meno significativo) e sarà quindi 1. FLAG_TWO è associato al secondo 
// bit ed avrà quindi valore 2. Se ci fosse stato un terzo flag avrebbe avuto valore
// 4 (quello associato al terzo bit) e se ci fosse stato un quarto flag avrebbe avuto 
// valore 8 (quello associato al quarto bit), ecc.
//
#define WPP_CONTROL_GUIDS \
    WPP_DEFINE_CONTROL_GUID(CtlGuid,(d58c126f, b309, 11d1, 969e, 0000f875a5bc),  \
        WPP_DEFINE_BIT(FLAG_ONE)        /* bit  0 = 0x00000001 */ \
        WPP_DEFINE_BIT(FLAG_TWO) )      /* bit  1 = 0x00000002 */
 
//
// DoTraceLevelMessage è una macro personalizzata che aggiunge il supporto 
// ai livelli, oltre che ai soli flag offerti dalla macro di default DoTraceMessage.
// In questo driver i flag identificano il tipo di messaggio e i livelli la loro
// gravità ma in entrambi i casi servono a attivare/disattivare la generazione
// di alcuni messaggi di tracing. Come? Innanzitutto il preprocessore WPP
// deve conoscere tutte le macro che generano messaggi. Al momento conosce solo
// DoTraceMessage. Ed ecco perché si è inserita la firma di DoTraceLevelMessage
// DoTraceLevelMessage(LEVEL,FLAGS,MSG,...) nelle proprietà del progetto.
// Le discriminanti per capire se un messaggio verrà inviato o no sono flag e
// livelli, che vengono valutati dalla WPP_LEVEL_ENABLED. Questa ritorna true
// se il flag passato come parametro è attivo. Quindi DoTraceMessage invia il
// messaggio semplicemente controllando se il suo flag è attivo.
// Per i livelli è necessario definire una macro ad-hoc tipo quella definita 
// sotto: WPP_LEVEL_FLAGS_ENABLED. Questa ritorna true se il flag passato come 
// secondo parametro è attivo ed il livello attualmente selezionato (solo uno 
// può esserlo) è maggiore o uguale del livello passato come primo parametro.
// Quindi DoTraceLevelMessage invia il messaggio semplicemente controllando se 
// il suo flag è attivo ed il suo livello è quello attualmente selezionato.
// WPP_LEVEL_LOGGER serve ad ottenere un handle alla sessione di tracing
// associata dal controller al provider. Anche in questo caso, se ci sono
// di mezzo i livelli è necessario fornire una definizione ad-hoc, come
// quella che si può vedere sotto: WPP_LEVEL_FLAGS_LOGGER.
// Se si usa solo DoTraceMessage non è necessario definire alcunché.
// 
#define WPP_LEVEL_FLAGS_LOGGER(level,flags) WPP_LEVEL_LOGGER(flags)
#define WPP_LEVEL_FLAGS_ENABLED(level, flags) (WPP_LEVEL_ENABLED(flags) && \ 
                             WPP_CONTROL(WPP_BIT_ ## flags).Level >= level)
 
//
// Per specificatori di formato personalizzato è necessario definire un 
// blocco di configurazione. In questo caso si informa che _MachineState
// può essere usato come specificatore di formato e di mostrare il nome
// dell'enumeratore piùttosto che il valore intero.
//
typedef enum _MachineState {
	Offline = 2,
	Online = 1,
	Failed = 0xFF000001,
	Stalled = 0xFF000002
} MachineState;
// begin_wpp config
// CUSTOM_TYPE(state, ItemEnum(_MachineState));
// end_wpp
 
 
// MACRO: TRACE_RETURN
// Non si entrerà nei dettagli della macro TRACE_RETURN e dunque si può semplicemente
// considerare che questa si espande in:
//
// {if (Status != STATUS_SUCCESS){
//     DoTraceMessage(FLAG_ONE, "Function Return = %!STATUS!", Status)
// ;}}
//                                 

Tutto quello che c'è da dire a riguardo è stato inserito nei commenti.



TraceDrv.c
#include "tracedrv.h"
#include "tracedrv.tmh"      //  generato dopo il passaggio del preprocessore WPP

Innanzitutto è necessario includere il file TMH con il codice generato dal preprocessore WPP. Bisogna metterlo dopo TraceDrv.h perché quest'ultimo contiene alcune definizioni usate nel file TMH.

NTSTATUS
DriverEntry(
           IN PDRIVER_OBJECT DriverObject,
           IN PUNICODE_STRING RegistryPath
           )
{ 
 
    // ...
 
 
    //
    // Macro necessaria ad inizializzare varie strutture usate durante
    // la sessione di tracing e per registrare il GUID del provider. 
    // 
    WPP_INIT_TRACING(pTracedrvDeviceObject,RegistryPath);
 
 
    return STATUS_SUCCESS;
}

VOID
DriverUnload(
                    IN PDRIVER_OBJECT DriverObject
                    )
{ 

    // ...
 
    // 
    // Ripulisce tutto.
    // 
    WPP_CLEANUP(pDevObj);
 
    // ...
 
}

NTSTATUS
DispatchDeviceControl(
                             IN PDEVICE_OBJECT pDO,
                             IN PIRP Irp
                             )
{

    // ...
 
    switch ( ControlCode ) {
    case IOCTL_TRACEKMP_TRACE_EVENT:
        //
        // Ogni volta che si ottiene questo IOCTL, loggiamo un messaggio
        // in base ai flag abilitati ed al livello attualmente selezionato.
        //
        
        ioctlCount++;
 
        // 
        // Logga un singolo e semplice messaggio se FLAG_ONE (valore 1) è abilitato.
        //
        DoTraceMessage(FLAG_ONE, "IOCTL = %d"ioctlCount);
 
        while (i++ < MAXEVENTS) {
            //
            // Logga in un loop se FLAG_ONE è abilitato.
            //
            DoTraceMessage(FLAG_ONE,  "Hello, %d %s"i"Hi" );
 
            if ( !(i%MAXEVENTS)){
                //
                // Logga se livello selezionato attualmente è >= TRACE_LEVEL_ERROR (valore 2)
                // e FLAG_TWO (valore 2) è abilitato.
                //
                DoTraceLevelMessage(
                    TRACE_LEVEL_ERROR,          // Level definito in evntrace.h
                    FLAG_TWO,                   // Flag definito in WPP_CONTROL_GUIDS
                    "Machine State :: %!state!",
                    CurrentState                // parametro enumeratore
                    );
            }
        }
 
        // ...
    }
 
    //
    // Logga lo stato ritornato tramite la macro TRACE_RETURN.
    TRACE_RETURN(status);
 
    // ...
        
    return status;
}
TraceCtl, quindi, non fa altro che interrogare il driver invocando DeviceIoControl ed  indicando IOCTL_TRACEKMP_TRACE_EVENT come codice di controllo.




Considerazioni finali

Si sarà certamente osservato che le macro per inviare messaggi di tracing, tipo DoTraceMessage, somigliano molto alle macro per inviare messaggi di testo al kernel debugger (KdPrint, KdPrintEx, ecc.). E' interessante notare che è possibile convertibile tali macro a quelle per inviare messaggi di tracing semplicemente definendo un blocco di configurazione simile a quello visto per definire lo specificatore di formato personalizzato. Tale argomento, però, non verrà trattato in questa lezione e si rimanda alla documentazione ufficiale per maggiori informazioni (si veda [3]).




Riferimenti:


Nessun commento:

Posta un commento