Table of Contents

Logging

Bitdefender este un lider recunoscut în domeniul securității IT, care oferă soluții superioare de prevenție, detecție și răspuns la incidente de securitate cibernetică. Milioane de sisteme folosite de oameni, companii și instituții guvernamentale sunt protejate de soluțiile companiei, ceea ce face Bitdefender cel mai de încredere expert în combaterea amenințărilor informatice, în protejarea intimității și datelor și în consolidarea rezilienței la atacuri. Ca urmare a investițiilor susținute în cercetare și dezvoltare, laboratoarele Bitdefender descoperă 400 de noi amenințări informatice în fiecare minut și validează zilnic 30 de miliarde de interogări privind amenințările. Compania a inovat constant în domenii precum antimalware, Internetul Lucrurilor, analiză comportamentală și inteligență artificială, iar tehnologiile Bitdefender sunt licențiate către peste 150 dintre cele mai cunoscute branduri de securitate din lume. Fondată în 2001, compania Bitdefender are clienți în 170 de țări și birouri pe toate continentele. Mai multe detalii sunt disponibile pe www.bitdefender.ro.

Resposabili:

Cuprins

De ce logăm?

Logurile sunt fișiere în care aplicația pe care o dezvoltăm scrie informații care ulterior ne pot fi de folosi în depanarea unor probleme în aplicație.

Loggingul este un aspect foarte important atât în procesul de dezvoltare al unei aplicații, cât și în cel de mentenanță. Atunci când dezvoltăm o aplicație și ajunge în producție, la foarte mulți utilizatori, inevitabil vor exista probleme care erau foarte greu de prevăzut, care apar doar în situații specifice. Logurile ne pot ajuta să reproducem un context în care aplicația noastră nu s-a comportat așa cum ne așteptam.

Să presupunem că avem o aplicație ce are o sută de mii de utilizatori și avem un sistem care ne informează atunci când s-a produs un crash. Chiar dacă aplicația a fost testată foarte mult, în diverse scenarii, în fiecare zi primim aproximativ 20 de notificări care ne spun faptul că s-a produs un crash la anumite ore. Acest lucru doar ne spune ca avem o problemă (un bug) în aplicație. Ce putem face în această situație? Debugging direct pe dispozitivul clientului nu putem face. Putem încerca să reproducem noi crash-ul, însă avem nevoie de un context în care s-a produs.

Logurile permit analiza unor evenimente care s-au întâmplat în trecut. Astfel, daca s-a întâmplat ceva neașteptat, putem vedea în ce zonă a codului a apărut problema, care era starea aplicației / sistemului în acel moment precum și ce acțiuni au precedat apariția problemei. Toate acestea formează contextul care a determinat problema, pe care îl putem folosi pentru a identifica bug-ul.

Ce logăm?

În general, este foarte util ca o linie de log să conțină metadate, pentru a găsi foarte ușor locația de interes. Acestea pot fi:

Pentru exemplificare, alegem un model de logging, dintr-un sistem foarte cunoscut - Apache Log Files. O linie de log din acest sistem arată astfel: 

[Fri Sep 09 10:42:29.902022 2011] [core:error] [pid 35708:tid 4328636416] [client 72.15.99.187] File does not exist: /usr/local/apache2/htdocs/favicon.ico

Observăm prezența metadatelor într-un header 

[Fri Sep 09 10:42:29.902022 2011] [core:error] [pid 35708:tid 4328636416] [client 72.15.99.187]

atașat înaintea mesajului proriu-zis 

File does not exist: /usr/local/apache2/htdocs/favicon.ico

Unde logăm?

Se poate folosi logarea la terminal împreună cu logarea în fișier.

Terminal

Primul contact pe care îl aveți cu loggingul este prin afișarea informațiilor în terminal:

Persistent în fișier

Pe lângă opțiunea anterioară de a redirecta STDOUT / STDERR, putem face ca programul scris de noi să stocheze mesajele de log direct într-un fișier pe disc.

Cu ce logăm?

Pentru a putea realiza cu ușurință partea de logging descrisă mai sus, avem nevoie de o bibliotecă care să ne ofere o implementare pentru funcționalitățile dorite, astfel încât să nu rescriem de fiecare dată logica de logare atunci când începem un proiect nou.

De cele mai multe ori, bibliotecile de logging expun o interfață standard / cunoscută, astfel că exemplele pe care le vom parcurge în continuare sunt relevante și pentru alte biblioteci de logging scrise în C sau în alte limbaje. Putem face o analogie cu funcția printf, care are un format standard pentru “stringul format”. Acesta a fost folosit drept model în designul altor sisteme de logare din mai multe limbaje de programare.

În continuare vom parcurge 2 exemple:

syslog

syslog este un standard de logging adoptat de sistemele UNIX. De asemenea, syslog este și numele folosit pentru implementarea de pe Linux - man syslog.

Sistemul permite logarea din mai multe aplicații simultan și centralizarea mesajelor în același fișier.

Acest sistem poate fi configurat prin /etc/syslog.conf. În exemplele următoare vom presupune un config default, ceea ce implică salvea logurile în calea /var/log/syslog.

Afișăm tot conținul directorului /var/log. 

$ ls -lh /var/log/
total 10M
...
-rw-r-----  1 syslog            adm             1,9M dec 23 03:30 syslog
-rw-r-----  1 syslog            adm             3,8M dec 19 00:24 syslog.1
...

Observăm că există 2 fișiere:

syslog în codul C

Putem folosi syslog prin funcțiile expuse în biblioteca C - man syslog. 

// syslog_example.c
 
#include <syslog.h>
 
int main(int argc, char **argv)
{
    // in cazul executabilelor rulate din terminal, putem presupune ca numele / identitatea este chiar numele executabilului
    const char* identity = argv[0];
 
    // initializare biblioteca cu identitatea specificata si configurari default (0)
    openlog(identity, 0, 0);
 
    // afiseaza o linie cu log level debug
    syslog(LOG_DEBUG, "Hello %s!\n", identity);
 
    // afiseaza o linie cu log level error
    syslog(LOG_ERR, "Ups! Something failed...");
 
    closelog();
 
    return 0;
}

Compilăm și rulăm: 

$ gcc syslog_example.c -o syslog_example
 
$ ./syslog_example
 
$ cat /var/log/syslog | grep syslog_example
Dec 23 03:42:37 pc ./syslog_example: Hello ./syslog_example!
Dec 23 03:42:37 pc ./syslog_example: Ups! Something failed...

Observăm prezența celor 2 linii de log din codul nostru. Prima este o linie cu log level debug (LOG_DEBUG), iar cealaltă are log level error (LOG_ERR).

Comportamentul default din syslog este că nu printează în fișier și prioritatea / log level. Putem să schimbăm acest lucru prin editarea fișierului /etc/rsyslog.conf: 

$ cat /etc/rsyslog.conf | grep "RSYSLOG_DebugFormat" -A2
$template precise,"%timegenerated% %syslogpriority-text% %HOSTNAME% %syslogtag% %msg%\n"
$ActionFileDefaultTemplate precise
$ sudo service rsyslog restart

Dacă rulăm din nou programul nostru obținem: 

$ ./syslog_example
$ tail -2 /var/log/syslog
Dec 23 15:29:39 debug pc ./syslog_example:  Hello ./syslog_example!
 
Dec 23 15:29:39 err pc ./syslog_example:  Ups! Something failed...

Observăm că acum se printează și log levelul în fișier! Acest lucru permite filtarea logurilor (dacă este nevoie): 

$ cat /var/log/syslog | grep syslog_example
Dec 23 15:32:02 debug pc ./syslog_example:  Hello ./syslog_example!
Dec 23 15:32:02 err pc ./syslog_example:  Ups! Something failed...
 
$ cat /var/log/syslog | grep syslog_example | grep debug
Dec 23 15:32:02 debug pc ./syslog_example:  Hello ./syslog_example!
 
$ cat /var/log/syslog | grep syslog_example | grep err
Dec 23 15:32:02 err pc ./syslog_example:  Ups! Something failed...

Acest fitru simplu poate identifica rapid posibile erori în aplicație, dacă acestea au fost logate: ne uităm mai întâi după logurile cu nivel err!

Exerciții

Hint man setlogmask && operații pe biți

pclog

În această secțiune vom scrie o bibliotecă minimală de logging, numită pclog.

De unde luăm metadatele în C?

După cum am văzut în exemplele anterioare, pentru a ști când și unde s-a întâmplat un anumit eveniment, trebuie să avem metadate într-o linie de log.

În continuare o să analizăm ce astfel de metadate ne expune ușor biblioteca C. Fiecare astfel de informație este accesibilă printr-un macro predefinit din compilator. De exemplu numele funcției, există macroul __FILE__ care este înlocuit la preprocesare cu numele fișierului în care este folosit.

Putem citi mai multe despre aceste macrouri pe pagina GCC Standard Predefined Macros, unde găsim lista de macrouri standard din C, implementate de orice compilator.

Tot pe aceeași pagină de documentație vedem un simbol extra, care este o variabilă const (nu un macro) - __FUNCTION__ - introdus in C99. Deoarece programatorul doar va afișa această valoare, este irelevant daca este un macro sau o variabilă. Astfel GCC a ales să foloseacă tot un nume cu majuscule, sugerând că toate formează împreună un singur set de metadate.

Exemple cu macrourile predefinite

Fie următoarele fișiere sursă: 

// macros_example.c
 
#include "foo.h"
 
#include <stdio.h>
 
void bar(void)
{
    printf("__FILE__ = %s\n", __FILE__); // __FILE__ -> "macros_example.c"
    printf("__FUNCTION__ = %s\n", __FUNCTION__); // __FUNCTION__ -> "bar"
    printf("__LINE__ = %d\n", __LINE__); // __LINE__ -> 11
    printf("__LINE__ = %d\n", __LINE__); // __LINE__ -> 12
    printf("__LINE__ = %d\n", __LINE__); // __LINE__ -> 13
    printf("__DATE__ = %s\n", __DATE__); // __DATE__ -> data compilare
    printf("__TIME__ = %s\n", __TIME__); // __TIME__ -> ora compilare
}
 
int main(void)
{
    printf("__FILE__ = %s\n", __FILE__); // __FILE__ -> "macros_example.c"
    printf("__FUNCTION__ = %s\n", __FUNCTION__); // __FUNCTION__ -> "main"
    printf("__LINE__ = %d\n", __LINE__); // __LINE__ -> 22
    printf("__LINE__ = %d\n", __LINE__); // __LINE__ -> 23
    printf("__LINE__ = %d\n", __LINE__); // __LINE__ -> 24
    printf("__DATE__ = %s\n", __DATE__); // __DATE__ -> data compilare
    printf("__TIME__ = %s\n", __TIME__); // __TIME__ -> ora compilare
 
    foo();
    bar();
 
    return 0;
}
#pragma once
 
void foo(void);
// foo.c
 
#include "foo.h"
 
#include <stdio.h>
 
void foo(void)
{
    printf("__FILE__ = %s\n", __FILE__); // __FILE__ -> "foo.c"
    printf("__FUNCTION__ = %s\n", __FUNCTION__); // __FUNCTION__ -> "foo"
    printf("__LINE__ = %d\n", __LINE__); // __LINE__ -> 11
    printf("__LINE__ = %d\n", __LINE__); // __LINE__ -> 12
    printf("__LINE__ = %d\n", __LINE__); // __LINE__ -> 13
    printf("__DATE__ = %s\n", __DATE__); // __DATE__ -> data compilare
    printf("__TIME__ = %s\n", __TIME__); // __TIME__ -> ora compilare
}

Compilăm și rulăm programul (format din mai multe fișiere): 

$ gcc -Wall -Wextra -o macro_example foo.c macros_example.c
 
$ ./macro_example
# logurile din main()
__FILE__ = macros_example.c
__FUNCTION__ = main
__LINE__ = 22
__LINE__ = 23
__LINE__ = 24
__DATE__ = Dec 23 2021
__TIME__ = 09:11:46
 
# logurile din foo()
__FILE__ = foo.c
__FUNCTION__ = foo
__LINE__ = 11
__LINE__ = 12
__LINE__ = 13
__DATE__ = Dec 23 2021
__TIME__ = 09:11:46
__FILE__ = macros_example.c
 
# logurile din bar()
__FUNCTION__ = bar
__LINE__ = 11
__LINE__ = 12
__LINE__ = 13
__DATE__ = Dec 23 2021
__TIME__ = 09:11:46

Observăm că fiecare symbol a fost înlocuit cu valoarea precizată în comentariu (așteptată).

Putem face o verificare în plus (și vedea care simbol este macro și care este variabilă), compilăm și afișăm rezultatul etapei de preprocesare pentru fiecare fișier de interes: 

$ gcc -E -c macros_example.c | tail -26
void bar(void)
{
    printf("__FILE__ = %s\n", "macros_example.c");
    printf("__FUNCTION__ = %s\n", __FUNCTION__);
    printf("__LINE__ = %d\n", 11);
    printf("__LINE__ = %d\n", 12);
    printf("__LINE__ = %d\n", 13);
    printf("__DATE__ = %s\n", "Dec 23 2021");
    printf("__TIME__ = %s\n", "09:25:43");
}
 
int main(void)
{
    printf("__FILE__ = %s\n", "macros_example.c");
    printf("__FUNCTION__ = %s\n", __FUNCTION__);
    printf("__LINE__ = %d\n", 22);
    printf("__LINE__ = %d\n", 23);
    printf("__LINE__ = %d\n", 24);
    printf("__DATE__ = %s\n", "Dec 23 2021");
    printf("__TIME__ = %s\n", "09:25:43");
 
    foo();
    bar();
 
    return 0;
}
 
$ gcc -E -c foo.c | tail -10
void foo(void)
{
    printf("__FILE__ = %s\n", "foo.c");
    printf("__FUNCTION__ = %s\n", __FUNCTION__);
    printf("__LINE__ = %d\n", 11);
    printf("__LINE__ = %d\n", 12);
    printf("__LINE__ = %d\n", 13);
    printf("__DATE__ = %s\n", "Dec 23 2021");
    printf("__TIME__ = %s\n", "09:25:44");
}

Observăm că __FUNCTION__ este o variabilă, prin urmare nu este înlocuită la preprocesare. Celelalte sunt macrouri și se înlocuiesc în prima etapă din compilare.

Idei implementare pclog

pclog() - funcție

Prima idee pe care o avem este să implementăm funcția pclog care să primească toți parametri necesari (inclusiv metadate).

Funția folosește un număr variabil de paramteri (similar cu printf - man printf): 

void pclog(const char* date, const char* time, const char* file, const char* func, int line, const char* format, ...)
{
  // ...
 
  printf("...", ...); // se apelează printf, paremetri nu sunt relevanți în acest exemplu
}

Exemple de apelare: 

int main(void)
{
    pclog(__DATE__, __TIME__, __FILE__, __FUNCTION__, __LINE__, "Hello, PC!");
 
    // ...
 
    pclog(__DATE__, __TIME__, __FILE__, __FUNCTION__, __LINE__, "Hello again, PC!");
 
    return 0;
}

Observăm că de fiecare dată când o apelăm trebuie să pasăm cei 5 parametri de metadate, ceea ce îngreunează citirea codului. Putem muta __DATE__, __TIME__ și să fie puse automat de funcția pclog(), însă pentru celelalte nu putem face asta (exemplu - __FUNCTION__ trebuie folosit în main() dacă vrem să se afișele numele funcției main).

pclog() - macro

Ceea ce ne dorim noi să facem este, în esență, să apelăm printf() cu anumiți parametri, printre care știm sigur că 5 sunt aceste macrouri! De asemenea, putem fixa poziția lor (exemplu primele 5 argumente).

Totuși, să fie nevoie să scriem de fiecare dată aceiași 5 parametri atunci când vrem să folosim un log, este redundant. Putem folosi un macro, care să primească doar ceea ce dorim să printăm propriu-zis într-un log și acest macro să adauge metadatele în plus, apelând printf cu toate datele.

Dorim să putem să apelăm pclog() astfel: 

// exemplu apelare
int year = 2021;
pclog("Hello, PC %d\n", y);

Definirea macroului este similară cu definiția unei semnături de funcții, 

#define pclog(format, year) printf(format, year)

adică un macro care are 2 parametri. Acest macro se va înlocui cu un apel de printf.

Compilăm și rulăm un astfel de exemplu: 

// 01-pclog_macro.c
 
#include <stdio.h>
 
#define pclog(format, year) printf(format, year)
 
int main(void)
{
    int n = 2021;
    pclog("Hello, PC %d!\n", n);
    return 0;
}
$ gcc -E 01-pclog_macro.c | tail -6
int main(void)
{
    int n = 2021;
    printf("Hello, PC %d!\n", n);
    return 0;
}
 
$ gcc -o 01-pclog_macro 01-pclog_macro.c
 
$ ./01-pclog_macro
Hello, PC 2021!

Următorul pas este să putem pasa oricâți parametri prin pclog către printf, care deja acceptă un număr variabil de parameri: 

printf(const char *restrict format, ...);

Sintaxa ... semnifică număr variabil de parametri (vezi laborator 13) și poate fi folosită și pentru macrouri cu număr variabil de parametri - Variadic Macros - C99.

Obținem următoare implementare: 

// 01-pclog_macro.c
 
#include <stdio.h>
 
#define pclog(format, ...) printf(format, ##__VA_ARGS__)
 
int main(void)
{
    pclog("Hello, PC\n");
 
    int n = 2021;
    pclog("Hello, PC %d!\n", n);
    pclog("Hello, PC %d! year = %d!\n", n, n);
    return 0;
}

Compilăm și rulăm: 

$ gcc -o 01-pclog_macro 01-pclog_macro.c
 
$ ./01-pclog_macro
Hello, PC
Hello, PC 2021!
Hello, PC 2021! year = 2021!

Am reușit să implementăm un macro cu număr variabil de parametri! Trebuie să adaugăm parametri în plus la printf. Obținem următoarea implementare (pe care vom analiza și rula mai jos): 

// 02-pclog_full_macro.c
 
#include <stdio.h>
 
#define pclog(format, ...)                                                     \
    printf("%s %s [%s][%s():%d] " format "\n",                                 \
           __DATE__, __TIME__, __FILE__, __FUNCTION__, __LINE__,               \
    ##__VA_ARGS__);
 
int main(int argc, char **argv)
{
    char *identity = argv[0];
 
    pclog("Hello, %s!", identity);
    pclog("Bye, %s!", identity);
 
    return 0;
}

Observații:

Compilăm și rulăm: 

# putem observa cum au fost înlocuite macrourile la preprocesare
$ gcc -E 02-pclog_full_macro.c | tail -9
int main(int argc, char **argv)
{
    char *identity = argv[0];
 
    printf("%s %s [%s][%s():%d] " "Hello, %s!" "\n", "Dec 23 2021", "10:12:23", "02-pclog_full_macro.c", __FUNCTION__, 12, identity);;
    printf("%s %s [%s][%s():%d] " "Bye, %s!" "\n", "Dec 23 2021", "10:12:23", "02-pclog_full_macro.c", __FUNCTION__, 13, identity);;
 
    return 0;
}
 
# rulăm să vedem că rezultatul este cel așteptat
$ gcc -o 02-pclog_full_macro 02-pclog_full_macro.c
$ ./02-pclog_full_macro
Dec 23 2021 10:12:29 [02-pclog_full_macro.c][main():12] Hello, ./02-pclog_full_macro!
Dec 23 2021 10:12:29 [02-pclog_full_macro.c][main():13] Bye, ./02-pclog_full_macro!

Mai avem de adăugat o mică opțiune codului nostru - posibilitatea de a activa / dezactiva complet logurile (adică să putem păstra în continuare apelurile de pclog() în cod, dar acestea să fie operații fără efect - adică să nu printeze).

Pentru aceasta putem să folosim în continuare directivele de preprocesare - dacă un anumit simbol este definit la compilare din linia de comandă, atunci pclog() va loga, altfel nu.

Vom folosi conveția cu simbolul _DEBUG (prezentată în secțiunea syslog - Exerciții). 

// 03-pclog_toggle.c
 
#include <stdio.h>
 
#ifdef _DEBUG
 
// logging enabled - use the actual implementation
#define pclog(format, ...)                                                     \
    printf("%s %s [%s][%s():%d] " format "\n",                                 \
           __DATE__, __TIME__, __FILE__, __FUNCTION__, __LINE__,               \
    ##__VA_ARGS__);
 
#else
 
// logging disabled - dummy implementation
#define pclog(format, ...)
 
#endif
 
int main(int argc, char **argv)
{
    char *identity = argv[0];
 
    pclog("Hello, %s!", identity);
    pclog("Bye, %s!", identity);
 
    return 0;
}

Compilăm și rulăm: 

# compilam mai intai fara sa definim _DEBUG
# rezultatul astepta este sa nu logheze
$ gcc -E 03-pclog_toggle.c | tail -9
int main(int argc, char **argv)
{
    char *identity = argv[0];
 
    ;
    ;
 
    return 0;
}
$ gcc -o 03-pclog_toggle 03-pclog_toggle.c
$ ./03-pclog_toggle
 
# recompilam cu _DEBUG definit
# rezultatul așteptat este să logheze
$ gcc -D_DEBUG -E 03-pclog_toggle.c | tail -9
int main(int argc, char **argv)
{
    char *identity = argv[0];
 
    printf("%s %s [%s][%s():%d] " "Hello, %s!" "\n", "Dec 23 2021", "10:38:10", "03-pclog_toggle.c", __FUNCTION__, 24, identity);;
    printf("%s %s [%s][%s():%d] " "Bye, %s!" "\n", "Dec 23 2021", "10:38:10", "03-pclog_toggle.c", __FUNCTION__, 25, identity);;
 
    return 0;
}
$ gcc -D_DEBUG -o 03-pclog_toggle 03-pclog_toggle.c
$ ./03-pclog_toggle
Dec 23 2021 10:38:21 [03-pclog_toggle.c][main():24] Hello, ./03-pclog_toggle!
Dec 23 2021 10:38:21 [03-pclog_toggle.c][main():25] Bye, ./03-pclog_toggle!
$

pclog.h

Implementarea poate fi aranjată puțin:

De asemenea, putem să facem și macroul fpclog, echivelentul lui pclog, dar care loghează într-un fișier (FILE*) primit ca parametru. Putem urma modelul printf - fprintf, în care un apel de forma printf(format, ...); este echivalent cu fprintf(stdout, format, ...);. Cu alte cuvinte putem avea logica doar în macroul fpclog, deoarece este mai generic, iar pclog îl va apela tot pe acesta. 

// pclog.h
 
#pragma once
 
#include <stdio.h>
 
#ifdef _DEBUG
 
// logging enabled - use the actual implementation
#define fpclog(log, format, ...)                                      \
    do                                                                \
    {                                                                 \
        fprintf(log, "%s %s [%s][%s():%d] " format "\n",              \
                __DATE__, __TIME__, __FILE__, __FUNCTION__, __LINE__, \
                ##__VA_ARGS__);                                       \
    } while (0)
 
#define pclog(format, ...) fpclog(stdout, format, ##__VA_ARGS__)
 
#else
 
// logging disabled - dummy implementation
#define fpclog(log, format, ...)
#define pclog(format, ...)
 
#endif

Exemple utilizare: 

// myapp.c
 
#include "pclog.h"
 
int main(void)
{
    int n;
    scanf("%d", &n);
 
    pclog("STDOUT log example - n = %d", n);
 
    FILE *log = fopen("myapp.log", "w");
    if (!log) {
        fprintf(stderr, "Cannot open file\n");
        return -1;
    }
 
    fpclog(log, "Example of log line saved into file - n = %d", n);
 
    fclose(log);
 
    return 0;
}

Compilăm și rulăm: 

# logging dezactivat (nu definim _DEBUG)
$ gcc -o myapp myapp.c
$ ./myapp
2021
 
# logging activat (definim _DEBUG)
$ gcc -D_DEBUG -o myapp myapp.c
$ ./myapp
2021
Dec 23 2021 10:49:01 [myapp.c][main():8] STDOUT log example - n = 2021

Exerciții

Vă propunem să vă jucați puțin cu implementarea oferită, adaugând funcționalițăți. 

Dec 23 2021 10:58:46 31523 [myapp.c][main():8] STDOUT log example - n = 2021

Hint man getpid 

2021-12-23 11:31:59 32855 [myapp.c][main():10] STDOUT log example - n = 2021

Hint man strftime / localtime 

2021-12-23 11:31:59.123 32855 [myapp.c][main():10] STDOUT log example - n = 2021

Hint man gettimeofday / localtime

Hint C enum / man syslog