Despre timestamp in log-uri pe ESXi

Uneori mai ajungem să analizăm înregistrări în log-uri pe host-uri ESXi. Pentru referință, acestea sunt întotdeauna însoțite cu un timestamp (marcaj de timp) care ne ajută să localizăm în timp un eveniment sau altul. Valoarea timestamp-ului la un moment dat se deduce din valoarea clock-ului de sistem pentru acel moment, așa că pentru o localizare corectă a evenimentelor avem nevoie de un clock setat corect sau și mai bine sincronizat la o sursa de timp de referință. Sincronizarea la o sursă de referință comună e cu atât mai importantă cu cât avem de corelat mai mult evenimente pe mai multe sisteme separate.

Ceea ce vreau să descriu mai jos e modul in care se formează timestamp-urile in log-urile pe ESXi. Pentru claritate vom face următoarele câteva teste simple:

  • configurăm serverul ESXi pentru o sincronizare a ceasului de sistem la o sursă de timp de referință.  
  • verificam valorile pentru system time pină și după sincronizarea cu sursa de referință
  • producem un eveniment pe ESXi după care analizam în log-uri amprenta lăsată de acesta. Verificăm modul în care se formează timestamp-ul.

Așadar, pe ESXi (eu am folosit unul nested in VMware Workstation) accesăm setările de timp prin vSphere Client – Host – Configuration – Software – Time Configuration. În fereastra deschisă verificăm valoarea curentă Date & Time care cel mai probabil e abătută de la timpul și data corectă. Tot de aici se observă că nu avem setat nici un server sursă de timp de referință (NTP server) – configurație implicită. 

Printr-un click pe Properties (link dreapta sus) deschidem fereastra Time Configuration în care reconfigurăm timpul și data la valorile curente. Intenționat, introducem o abatere mică pe timp (de câteva minute) astfel încât să observăm mai târziu efectul sincronizării cu un server NTP. Se recomandă ca înainte de a configura serverul NTP de ajustat manual timpul si data la cât mai aproape de valorile curente, motivul nu-l cunosc dar intuiesc că sincronizarea are loc iterativ și cu cât ceasul de sistem e mai aproape de adevăr cu atât mai puține iterați au loc deci și o durata mai scurtă pentru perioada de sincronizare totală (trebuie verificat). 

În fereastra Time Configuration click pe Options …  după care in NTP Daemon (ntpd) Option – NTP settings specificam un server NTP (din Internet sau intern din rețeaua companiei). Tot de aici (general settings) ne asigurăm că avem pornit clientul și că acesta va porni automat cu pornirea serverului ESXi.

about_esxi_timestamps_NTP_daemon_options

Așteptăm câteva minute după care comparăm valorile pentru timpul pe ESXi și ceasul de referință – acesta ar trebui să ajungă identice. Într-adevăr in cazul meu NTP-ul și-a făcut treaba și am obținut un timp identic cu sursa de referință.

about_esxi_timestamps_NTP_initial_time

Verificam aceeași data și timp cu următoarele două comenzi din consola ESXi –ului (un pic delayed pentru că am luat screen-urile la diferite momente de timp):

about_esxi_timestamps_time_from_console

Se observă un lucru interesant: Timpul obținut din CLI e cu două ceasuri mai devreme decât ora din vSphere Client. Există o diferență de două ore, 9:22 in comparație cu 11:22. Ora curentă e cea cu 11:22, iar timpul -2 e timpul in reprezentare UTC (timpul universal coordonat). De unde știe ESXi-ul să adauge exact 2 ore că prezinte ora curentă în vSphere Client ? Pentru că nu am configurat nici-unde în altă parte Time Zone intuiesc că acesta se scoate tot prin NTP (trebuie verificat).

De ce m-am legat de subiectul ăsta e pentru că ESXi-ul folosește ca timestamp in log-uri tocmai valoarea în UTC și nu cea curentă (pe care o citim pe ceasul de mănă). Deci odată apucat de analizat log-uri e important să luăm în calcul și ajustarea de +2 ore: la timestamp-ul din log adăugăm două ore ca să ajungem la timpul curent.

Mai este un moment important de remarcat. Plus două ore menționate mai sus sunt valabile doar pentru perioada de iarna nu și cea de vara când va trebui să adăugam deja +3 ore la timestamp-urile din log-uri. Diferența se datorează sistemului de  Daylight Saving Time.  Valorile de +2/+3 reprezintă fusul orar in care se află Republica Moldova, pentru alte țări se folosesc valorile corespunzătoare fusului orar.

Pe final să generam un eveniment pe ESXi după care să urmărim amprenta in unul din log-uri. Cel mai simplu e sa pornim un VM după care sa analizam vmware.log la VM-ul respect. Cu fiecare re-pornire de VM fișierul vmware.log pornește de la început așa că în cazul nostru vom urmări doar evenimentele legate de ultima pornire a VM-ului. Așadar, am pornit VM-ul TEST-VM la ora 11:55 după care am deschis fișierul vmware.log din folderul VM-ului pe datastore (excerpt mai jos):

about_esxi_timestamps_crop_vmware.log

Din screen re-confirmăm că timestamp-ul e deplasat cu 2 ore în trecut (-2) față de ora curentă: 9:55 in comparație cu 11:55. De menționat că în interfață peste tot se afișează totuși ora curent, ca exemplu am urmărit data creării fișierului vmware.log în datastore browser care este afișat ca 11: 55 (coincide cu moment pornirii VM-ului).