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:

• Cristi Olaru
• Cristi Pătrașcu
• Cristi Popa
• Darius Neațu
• Liza Babu
• Radu Nichita

• De ce logăm?
• Ce logăm?
• Unde logăm?
  • Terminal
  • Persistent în fișier
• Cu ce logăm?
• syslog
  • syslog în codul C
  • Exerciții
• pclog
  • De unde luăm metadatele în C?
    • Exemple cu macrourile predefinite
  • Idei implementare pclog
    • pclog() - funcție
    • pclog() - macro
    • pclog.h
  • Exerciții

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.

• Pași executați cu eroare / succes, în funcție de importanța lor(e.g. alocare de memorie, parsare a inputului, încărcare de biblioteci etc.)
• Starea aplicației (e.g. mesaje periodice cu informatii despre componentele aplicației)
• Resurse folosite (e.g. informații periodice despre RAM, CPU, etc.)
• Perechi inițiere - finalizare acțiune (în special pentru aplicații cu operații asincrone)
• Orice considerăm util, fără a fi totuși prea mult

Î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:

• numele fișierului de unde s-a logat
• numele funcției de unde s-a logat
• linia unde s-a logat
• data evenimentului
• PID-ul procesului

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

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

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

• STDOUT:
  • Se va afișa un mesaj de tip rezultat / eveniment în terminal la standard output
  • Implementare C:

    printf("stdout example\n");
    // sau
    fprintf(stdout, "stdout example\n");

  • Redirectare terminal

    # e.g. redirectare STDOUT pentru "executable" în fișierul "log.out"
    $ /path/to/executable > log.out

• STDERR:
  • Se va afișa un mesaj de tip eroare / avertisment în terminal la standard error
  • Implementare C:

    fprintf(stderr, "stderr example\n")`;

  • Redirectare terminal

    # e.g. redirectare STDERR pentru "executable" în fișierul "log.err"
    $ /path/to/executable 2> log.err

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.

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:

• vom folosi o bibliotecă standard de pe Linux
• vom încerca să scriem o bibliotecă minimală de logging în C, exercițiu care se poate dovedi util în debuggingul aplicațiilor pe care le veți scrie în semestrele următoare

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:

• /var/log/syslog: fișierul curent în care se loghează
• /var/log/syslog.1: fișier anterior în care s-a logat, iar cand s-a atins limita de 3.8M s-a considerat plin și s-a rotit (proces în care s-a redenumit fișierul prin adaugare de versiune la final). Scopul rotirii fișierelor de log este de a nu avea un singur fișier foarte mare.

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

• void openlog(const char *ident, int option, int facility);
  • inițializează biblioteca de logging; deschide fișierul /var/log/syslog
    • ident: logurile sunt asociate cu o aplicație / identitate care va apărea explicit în linia logată
    • option și facility reprezintă opțiuni avansate de configurare, pe care le vom seta pe 0 (default) în acest tutorial
• void syslog(int priority, const char *format, ...);
  • loghează o linie în fișier
    • logul este asociat cu o anumită categorie / prioritate / nivel de logging (log level)
      • syslog definește mai multe nivele de logare
      • nivele de logare sunt folosite pentru filtrare de loguri
      • în acest tutorial vom folosi 2 nivele de logare
        • LOG_ERR: loguri care reprezintă erori (critice) - exemplu: nu s-a putut deschide un fișier / aloca un buffer
        • LOG_DEBUG: loguri care conțin informație utilă pentru debug și care nu sunt asociate cu erori - exemplu: fișierul deschis are n bytes / bufferul alocat se află la adresa X
    • combinația de argumente const char* format, ... respectă aceeași convenție folosită și de printf
• void closelog(void);
  • oprește biblioteca de logging (și închide fișierul deschis)

// 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:

• comentăm linia cu formatul default

$ cat /etc/rsyslog.conf | grep "RSYSLOG_DebugFormat" -A2

• adăugăm propriul format de linie

$template precise,"%timegenerated% %syslogpriority-text% %HOSTNAME% %syslogtag% %msg%\n"
$ActionFileDefaultTemplate precise

• sintaxa este descrisă în documentația rsync - secțiunea System Properties)
  • timegenerated: data la care a fost generat eventul
  • syslogpriority-text: log level / prioritea pasată funcției syslog în C
  • HOSTNAME: numele stației pe care se rulează
  • syslogtag: numele entității care loghează (parametrul ident pasat la openlog)
  • msg: mesajul de log propriu-zis
  • '\n': newline (mereu un apel de syslog loghează o linie completă)
• Notă: Observați și rețineți analogia cu modelul printf!
• restartăm serviciul de logging pentru a folosi noul config

$ 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!

• Filtrare loguri
  • Există situații, când din motive de limitare de resurse, dorim să păstrăm în producție doar anumite loguri - un exemplu simplificat ar fi să păstrăm doar logurile cu nivel err în programul syslog_example pentru mediul de producție. Deoarece în continuare vrem să avem și liniile cu debug, pentru atunci cînd compilăm și testăm local, syslog permite setarea unui nivel maxim de prioritatea / de logging (în cazul nostru err este nivelul cel mai mic, iar debug este nivelul cel mai mare)Ș
    • dacă nivelul maxim setat este err, atunci doar liniile de forma syslog(LOG_ERR, ...); vor loga efectiv în fișier
    • dacă nivelul maxim setat este debug, atunci și logurile cu și logurile cu se vor vedea în fișier
  • Acest task presupune să modificați syslog_example.c astfel încât să puteți compila în 2 moduri diferite programul: unul care să producă doar loguri de err, iar celălalt să producă ambele tipuri de loguri.
    • O convenție des întâlnită este definirea simbolului _DEBUG, care poate fi apoi verificat din codul C dacă este definit, folosind directivele de preprocesare #ifdef _DEBUG / #if defined(_DEBUG). Prezența simbolului înseamnă build de debug (unde putem loga oricât de mult, deoarece doar noi vom folosi acest build). Absența acestuia este asociată cu un build de release / production (în care logăm doar ce este strict necesar, acesta este executabilul care urmează a fi livrat oficial).

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

• Avem nevoie să obținem în final implementarea unei funcții numite pclog(format, ...), care se va comporta analog funcțiilor printf (din punct de vedere al formatului) și syslog (adaugă un header cu cât mai multe metadate!).
• În final vom avea implementarea in pclog.h / pclog.c.
• Veți putea reutiliza codul scris de voi pentru pclog atunci când faceți debug la teme.

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.

• __FILE__:
  • tip asociat: string (a.k.a. const char* → "%s")
  • semnificație: macro care se înlocuiește cu numele fișierului sursă în care este folosit.
• __LINE__:
  • tip asociat: integer (a.k.a. int → "%d")
  • semnificație: macro care se înlocuiește cu numărul liniei de cod din fișierul sursă în care este folosit.
• __DATE__:
  • tip asociat: string (a.k.a. const char* → "%s")
  • semnificație: macro care se înlocuiește cu data (exemplu "Feb 12 1996") la care programul s-a compilat.
• __TIME__:
  • tip asociat: string (a.k.a. const char* → "%s")
  • semnificație: macro care se înlocuiește cu ora (exemplu "23:50:01") la care programul s-a compilat.

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.

• __FUNCTION__:
  • tip asociat: string (a.k.a. const char* → "%s")
  • semnificație: macro care se înlocuiește cu numele funcției în care este folosit.

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.

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).

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.

• ...: semnifică în declararea macroului că poate primi un număr variabil de parametri opționali
• __VA_ARGS__: este un macro care permite manipularea tuturor acestor parametri opționali.
• ##__VA_ARGS__: înseamnă valoarea acelor argumente și reprezintă expresia pe care o vom transmite lui printf, cu semnificația că toți parametri opționali primiți de pclog vor fi pasați către printf.

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:

• Dorim să avem în continuare un singur apel de printf.
  • Parametrul format dat în main trebuie modificat, mai exact ne dorim ca, de exemplu pentru afișarea datei cu __DATE__ __TIME__ să adăugăm la început "%s %s". Analog și pentru celelalte.
  • Deoarece format stringul dat de user este un string literal, iar noi dorim să îl extindem cu alt string literal, putem să solicităm compilatorului să le concateneze dacă le folosim alăturat.
    • Exemplu - pentru codul printf("%s %s " "<some_format_string>" "\n"); , deși noi specificăm 3 string literals, deoarece sunt consecutivi (între ei avem doar whitespace), compilatorul concateneaza aceste valori, rezultă un singur string format pe care îl pasează lui printf, codul care urmează a se executa fiind echivalent cu printf("%s %s <format>\n");.
• Metadatele reprezentate de cel 5 valori menționate anterior sunt asociate cu headerul "%s %s [%s][%s():%d] care are semnificația date time [file][function():line].
• Deoarece mereu dorim să logăm linii (adică un mesaj care mereu se termină cu newline), putem să adaugăm terminatorul de linie ('\n') tot din macroul pclog.
• Putem să să scriem definiția macroului pe mai multe linii mai scurte.

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!
$

Implementarea poate fi aranjată puțin:

• Folosim convenția conform căreia un macro care are mai multe linii va avea definiția cuprinsă într-un block do - while. Putem vedea astfel de exemple pe pagina de coding style a kernelului Linux, secțiunea Macros, Enums and RTL.
• Mutăm implementarea în pclog.h.

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

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

• Adăugați pid-ul procesului curent în liniile de log. Exemplu, pentru procesul cu PID-ul 31523, linia din exemplu anterior cu myapp, va arăta astfel:

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

• Schimbați formatul datei / orei afișate, astfel încât o linie de log să arate astfel:

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

• Modificați soluția anterioară să printeze și milisecunda (din struct tm).

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

• Extindeți pclog pentru a suporta folosirea de log level (pentru simplitate păstrăm în continuare 2 niveluri: err și debug).