Correlacionando / var / log / * timestamps

20

/var/log/messages,, /var/log/sysloge alguns outros arquivos de log usam um carimbo de data / hora que contém um tempo absoluto, como Jan 13 14:13:10.

/var/log/Xorg.0.loge /var/log/dmesg, assim como a saída de $ dmesg, use um formato parecido com

[50595.991610] malkovich: malkovich malkovich malkovich malkovich

Eu estou supondo / reunindo que os números representam segundos e microssegundos desde a inicialização.

No entanto, minha tentativa de correlacionar esses dois conjuntos de carimbos de data / hora (usando a saída de uptime) deu uma discrepância de cerca de 5000 segundos.

Essa é aproximadamente a quantidade de tempo que meu computador foi suspenso.

Existe uma maneira conveniente de mapear os carimbos de data e hora numéricos usados ​​pelo dmesg e Xorg em carimbos de data e hora absolutos?

atualizar

Como um passo preliminar para descobrir isso, e também para tornar minha pergunta um pouco mais clara, escrevi um script Python para analisar /var/log/sysloge gerar a inclinação do tempo. Na minha máquina, executando o ubuntu 10.10, esse arquivo contém várias linhas originadas pelo kernel, que são carimbadas com o carimbo de data / hora dmesg e o carimbo de data / hora do syslog. O script gera uma linha para cada linha desse arquivo que contém um registro de data e hora do kernel.

Uso:

python syslogdriver.py /var/log/syslog | column -nts $'\t'

Saída expurgada (veja abaixo as definições de coluna):

abs              abs_since_boot  rel_time      rel_offset  message
Jan 13 07:49:15  32842.1276569   32842.301498  0           malkovich malkovich

... rel_offseté 0 para todas as linhas intermediárias ...

Jan 13 09:55:14  40401.1276569   40401.306386  0           PM: Syncing filesystems ... done.
Jan 13 09:55:14  40401.1276569   40401.347469  0           PM: Preparing system for mem sleep
Jan 13 11:23:21  45688.1276569   40402.128198  -5280       Skipping EDID probe due to cached edid
Jan 13 11:23:21  45688.1276569   40402.729152  -5280       Freezing user space processes ... (elapsed 0.03 seconds) done.
Jan 13 11:23:21  45688.1276569   40402.760110  -5280       Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jan 13 11:23:21  45688.1276569   40402.776102  -5280       PM: Entering mem sleep

... rel_offseté -5280 para todas as linhas restantes ...

Jan 13 11:23:21  45688.1276569   40403.149074  -5280       ACPI: Preparing to enter system sleep state S3
Jan 13 11:23:21  45688.1276569   40403.149477  -5280       PM: Saving platform NVS memory
Jan 13 11:23:21  45688.1276569   40403.149495  -5280       Disabling non-boot CPUs ...
Jan 13 11:23:21  45688.1276569   40403.149495  -5280       Back to C!
Jan 13 11:23:21  45688.1276569   40403.149495  -5280       PM: Restoring platform NVS memory
Jan 13 11:23:21  45688.1276569   40403.151034  -5280       ACPI: Waking up from system sleep state S3

... As linhas finais são um pouco mais abaixo, ainda bem acima do final da saída. Presumivelmente, alguns deles foram gravados no dmesgbuffer circular de antes da suspensão ocorrer e foram propagados apenas syslogdepois. Isso explica por que todos eles têm o mesmo registro de data e hora do syslog.

Definições de coluna:

abs é o tempo registrado pelo syslog.

abs_since_booté o mesmo tempo em segundos desde a inicialização do sistema, com base no conteúdo /proc/uptimee no valor de time.time().

rel_time é o registro de data e hora do kernel.

rel_offseté a diferença entre abs_since_boote rel_time. Estou arredondando isso para dezenas de segundos, a fim de evitar erros pontuais devido aos syslogcarimbos de data e hora absolutos ( gerados), apenas com precisão de segundos. Na verdade, essa não é a maneira correta de fazê-lo, pois realmente (eu acho ..) resulta apenas em uma menor chance de ocorrer um erro de 10 por 10. Se alguém tiver uma ideia melhor, entre em contato.

Eu também tenho algumas perguntas sobre o formato de data do syslog; em particular, estou me perguntando se um ano aparece nele. Estou supondo que não, e de qualquer forma provavelmente poderia me ajudar com essas informações no TFM, mas se alguém souber que isso seria útil. .. Supondo, é claro, que alguém use esse script em algum momento no futuro, em vez de apenas interromper algumas linhas do código Perl.

Próximo:

Portanto, a menos que alguma revelação bem-vinda me seja dada por um de vocês, meu próximo passo será adicionar uma função para obter o tempo inclinado para um determinado registro de data e hora do kernel. Deveria poder alimentar um script ou um conjunto de syslogs, juntamente com um carimbo de data / hora do kernel, para obter um carimbo de data / hora absoluto. Depois, posso voltar a depurar meus problemas com o Xorg, que me escapam no momento.

linux xorg logs timestamps intuído
fonte
11
Eu acho que isso se qualifica como um bug e deve ser relatado. O syslog-ng da BTW usa carimbos de data / hora sensatos com os quais você pode classificar sort, ter ano, fuso horário etc. +1 para o script python.
stribika
@ stribika: isso seria um problema do kernel ou um syslog? Ou ambos? Parece que o syslog precisa ser notificado de que o sistema foi suspenso .. talvez possa fazer isso sozinho com suspender e retomar os ganchos.
intuído
Para mim, parece que o kernel está com defeito. Os valores rel_time não "pulam" o tempo enquanto o sistema foi suspenso. Acho estranho, no entanto, que a inclinação comece antes que a suspensão realmente aconteça. Os valores já estão errados, o Freezing user space processesque é claramente feito antes do sono.
stribika
2
@stribika: Minha teoria de trabalho é que esses eventos não são enviados para o syslog até depois do resumo, porque ocorrem depois que o próprio syslog foi suspenso.
intuído
@stribika: Além disso, você está certo sobre o kernel estar "com defeito": como eu o entendo (após reconsiderar), o syslog apenas prefixa o carimbo de data e hora absoluto ao texto (começando com [12345.6789]..) emitido pelo kernel, por isso está fazendo as coisas corretamente , sujeito aos problemas abordados pelo meu último comentário. Não tenho certeza do que o kernel deveria estar fazendo aqui; depende do que esses registros de data e hora relativos à inicialização devem indicar. O tempo de execução (em oposição ao tempo desde a inicialização) pode ser significativo em alguns contextos. Eu acho que idealmente haveria um registro confiável desses dois valores.
intuited

Respostas:

4

Problema interessante, não tenho certeza se já tentei fazer isso. Mas notei o carimbo de data e hora do qual você está falando e sempre acreditei que passavam segundos desde a inicialização.

No meu syslog que tenho no meu servidor, tenho:

Jan 10 19:58:55 wdgitial kernel: [    0.000000] Initializing cgroup subsys cpuset
Jan 10 19:58:55 wdgitial kernel: [    0.000000] Initializing cgroup subsys cpu
Jan 10 19:58:55 wdgitial kernel: [    0.000000] Linux version 2.6.32-21-server (buildd@yellow) (gcc version 4.4.3 (Ubuntu 4.4.3-4ubuntu5) ) #32-Ubuntu SMP Fri Apr 16     09:17:34 UTC 2010 (Ubuntu 2.6.32-21.32-server 2.6.32.11+drm33.2)
Jan 10 19:58:55 wdgitial kernel: [    0.000000] Command line:  root=/dev/xvda1 ro quiet splash

Eu imagino que isso seja bastante consistente entre a maioria das distribuições Linux, já que este é o kernel que cuspiu as coisas.

E aqui eu tenho a data junto com o carimbo de data e hora.

Ryan Gibbons
fonte
3

Você pode tentar:

Primeiro, obtenha o registro de data e hora do arquivo dmesg (suponho que seja o tempo 0 do dmesg). Você vai usar

ls -l - timetime style = +% s

/var/log$ ls -l --time-style=+%s dmesg
-rw-r----- 1 root adm 56181 1294941018 dmesg

Você pode converter os segundos em uma data legível por humanos com

perl -e 'print scalar localtime(1294941018)'

Portanto, para ver um horário de evento legível, adicione os segundos do evento em dmesg. Se o evento dmesg tiver 55.290387 segundos, adicione 55 ou 55.290387:

perl -e 'print scalar localtime(1294953978 + 55)'

Outra maneira de transformar segundos com raiz de época em tempo legível é usar a data-d, conforme sugerido. Se você indicar 'date' para representar um horário fornecido com -d, poderá indicar que o horário a ser convertido é em segundos desde a época usando @.

date -d "@1294953978"

Isso fornece algo como "Qui 13 de janeiro 15:26:18 CST 2011" como saída.

data +% s
imprimirá a hora atual no formato de segundos desde a época.

Não me lembro de como fazer matemática shell, então normalmente uso o método perl como acima. :)

belacqua
fonte
11
@jgbelacqua: Você quer date -d @$((1294953978 + 55)), pelo menos no bash. No entanto, alguns registros de data e hora do kernel são inclinados, o que significa que os horários produzidos por esse método seriam anteriores aos registros de data e hora correspondentes /var/log/syslog. Parece que isso acontece como resultado de eventos de suspensão para RAM, provavelmente além da hibernação e possivelmente de outras coisas, porque o tempo do kernel não está aumentando durante esses períodos. Veja a atualização da pergunta para mais informações.
intuído
2

A maneira mais fácil de mapear o número de dmesg para uma data é usando o dateprograma.

date -d "-50595 seconds"

Este comando exibe a data para a hora atual menos 50595 segundos.

De man date:

-d, --date=STRING
       display time described by STRING, not `now'

O número é igual ao tempo de inicialização, não ao tempo decorrido desde o tempo de inicialização.

Lekensteyn
fonte
2

Como você observou a alteração na inclinação do tempo durante a suspensão / retomada, observarei que isso está documentado em pelo menos um local. A página do manual dmesg (1) diz:

A fonte de tempo usada para os logs não é atualizada após o sistema SUSPEND / RESUME.

Não consegui encontrar uma maneira de fazer o kernel manter esses carimbos de data / hora sincronizados com o tempo da parede.

Andrew
fonte
1

Rápido, sujo, funciona.

$ dmesg | grep 3w | perl /root/print_time_offset.pl

Conteúdo desse script:

$ cat /root/print_time_offset.pl

#!/usr/bin/perl

$uptime = `cat /proc/uptime | awk '{print $1}';`;
$boot = time() - $uptime;
chomp $boot;
while (<STDIN>) {
        if ($_ =~ /^\[([\s\d\.]+)\]/) {
                $time_offset = $1;
        }
        $real_time = sprintf scalar localtime($boot + $time_offset);
        $_ =~ s/\[[\s\d\.]+\]/\[$real_time\]/;
        print $_;
}

A saída de amostra é a seguinte:

[Mon Feb 21 23:06:33 2011] 3ware 9000 Storage Controller device driver for Linux v2.26.02.012.
[Mon Feb 21 23:06:33 2011] 3w-9xxx 0000:03:00.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
[Mon Feb 21 23:06:33 2011] 3w-9xxx 0000:03:00.0: setting latency timer to 64
[Mon Feb 21 23:06:33 2011] scsi4 : 3ware 9000 Storage Controller
[Mon Feb 21 23:06:33 2011] 3w-9xxx: scsi4: Found a 3ware 9000 Storage Controller at 0xfbcde000, IRQ: 16.
[Mon Feb 21 23:06:34 2011] 3w-9xxx: scsi4: Firmware FE9X 4.08.00.006, BIOS BE9X 4.08.00.001, Ports: 4.
[Mon Feb 21 23:06:35 2011] 3w-9xxx: scsi4: ERROR: (0x03:0x0101): Invalid command opcode:opcode=0x85.
[Mon Feb 21 23:06:35 2011] 3w-9xxx: scsi4: ERROR: (0x03:0x0101): Invalid command opcode:opcode=0x85.
[Mon Feb 21 23:06:35 2011] 3w-9xxx: scsi4: ERROR: (0x03:0x0101): Invalid command opcode:opcode=0x85.
[Mon Feb 21 23:06:35 2011] 3w-9xxx: scsi4: ERROR: (0x03:0x0101): Invalid command opcode:opcode=0x85.
[Mon Feb 21 23:06:35 2011] 3w-9xxx: scsi4: ERROR: (0x03:0x0101): Invalid command opcode:opcode=0x85.
[Mon Feb 21 23:06:35 2011] 3w-9xxx: scsi4: ERROR: (0x03:0x0101): Invalid command opcode:opcode=0x85.
[Sat Feb 26 02:01:01 2011] 3w-9xxx: scsi4: AEN: INFO (0x04:0x0029): Verify started:unit=0, subunit=1.
[Sat Feb 26 02:01:01 2011] 3w-9xxx: scsi4: AEN: INFO (0x04:0x0029): Verify started:unit=0, subunit=0.
[Sat Feb 26 16:49:13 2011] 3w-9xxx: scsi4: AEN: INFO (0x04:0x002B): Verify completed:unit=0, subunit=1.
[Sat Feb 26 17:07:19 2011] 3w-9xxx: scsi4: AEN: INFO (0x04:0x002B): Verify completed:unit=0, subunit=0.
[Sat Mar  5 02:00:16 2011] 3w-9xxx: scsi4: AEN: INFO (0x04:0x0029): Verify started:unit=0, subunit=1.
[Sat Mar  5 02:00:16 2011] 3w-9xxx: scsi4: AEN: INFO (0x04:0x0029): Verify started:unit=0, subunit=0.
[Sat Mar  5 18:48:57 2011] 3w-9xxx: scsi4: AEN: INFO (0x04:0x002B): Verify completed:unit=0, subunit=1.
[Sat Mar  5 19:05:17 2011] 3w-9xxx: scsi4: AEN: INFO (0x04:0x002B): Verify completed:unit=0, subunit=0.
[Sat Mar 12 02:00:30 2011] 3w-9xxx: scsi4: AEN: INFO (0x04:0x0029): Verify started:unit=0, subunit=1.
[Sat Mar 12 02:00:30 2011] 3w-9xxx: scsi4: AEN: INFO (0x04:0x0029): Verify started:unit=0, subunit=0.
Dacav
fonte
11
Acho que você leu apenas os primeiros parágrafos da pergunta. Confira novamente em mais detalhes. Ou, como alternativa, tente suspender o computador e verificar se o script relata corretamente os carimbos de data e hora absolutos das mensagens recém-registradas.
intuído