# Анализ логов ## Введение Во время своей работы ОС Linux ведет журнал происходящих событий уровня ядра и userspace. Стоит задача извлекать из журнала события, представляющие интерес для аналитики и статистики. Лог в текстовом формате можно получить следующей командой от root: `journalctl -b 0` Лог в формате JSON можно получить следующей командой от root: `journalctl -b 0 -o json` Пример находится в [data/journalctl.txt](data/journalctl.txt) Для форматирования JSON можно использовать утилиту jq(1): `journalctl -b 0 -o json | jq "."` [data/journalctl.json](data/journalctl.json) Далее по тексту приводятся выдержки из этих файлов. Т.к. формат JSON обычно удобнее для машинной обработки, приводятся выдержки из него. Все те же самые события есть и в текстовом формате. Механизм централизованного сбора логов находится за рамками настоящего документа. Уникальный идентификатор устройства находится в файле `/etc/machine-id`. При установке по PXE необходимо обеспечивать его уникальность. ## События ### Включение устройства Это первое сообщение в логе. В качестве сообщения выводится uname. ```json { "_TRANSPORT": "kernel", "_SOURCE_MONOTONIC_TIMESTAMP": "0", "__CURSOR": "s=b45ff6a034b548efbbc4ddb9caf572a2;i=2290;b=b7c4b78ba3cb403ea89f99ea2801a34d;m=4fca9f;t=5e8a389e7ec27;x=b5c2a95c90f7981c", "PRIORITY": "5", "_MACHINE_ID": "446da133a2cb49efbe840eb66307756b", "_BOOT_ID": "b7c4b78ba3cb403ea89f99ea2801a34d", "__REALTIME_TIMESTAMP": "1663163974544423", "SYSLOG_FACILITY": "0", "__MONOTONIC_TIMESTAMP": "5229215", "_HOSTNAME": "ncco-2-icl1.local", "SYSLOG_IDENTIFIER": "kernel", "MESSAGE": "Linux version 5.10.137-std-def-alt1 (builder@localhost.localdomain) (gcc-10 (GCC) 10.3.1 20210703 (ALT Sisyphus 10.3.1-alt2), GNU ld (GNU Binutils) 2.35.2.20210110) #1 SMP Wed Aug 24 12:31:53 UTC 2022" } ``` ### Выключение устройства Рекомендуется ориентироваться на вход системы в target systemd `poweroff.target` ```json { "_SYSTEMD_SLICE": "-.slice", "_MACHINE_ID": "446da133a2cb49efbe840eb66307756b", "MESSAGE": "Reached target System Power Off.", "__CURSOR": "s=b45ff6a034b548efbbc4ddb9caf572a2;i=2ce0;b=b7c4b78ba3cb403ea89f99ea2801a34d;m=809f16e0;t=5e8a409eca4e6;x=ab8da413467f46ce", "_EXE": "/lib/systemd/systemd", "UNIT": "poweroff.target", "CODE_FUNC": "job_emit_done_message", "TID": "1", "_COMM": "systemd", "SYSLOG_FACILITY": "3", "_HOSTNAME": "ncco-2-icl1.local", "_SOURCE_REALTIME_TIMESTAMP": "1663166122337374", "CODE_LINE": "713", "_SYSTEMD_UNIT": "init.scope", "_CMDLINE": "/sbin/init splash", "_UID": "0", "SYSLOG_IDENTIFIER": "systemd", "CODE_FILE": "src/core/job.c", "__REALTIME_TIMESTAMP": "1663166122337510", "MESSAGE_ID": "39f53479d3a045ac8e11786248231fbf", "_SYSTEMD_CGROUP": "/init.scope", "__MONOTONIC_TIMESTAMP": "2157909728", "INVOCATION_ID": "1a99252c4e3a4100b16709983339fcc4", "_TRANSPORT": "journal", "_GID": "0", "_PID": "1", "JOB_ID": "3255", "PRIORITY": "6", "JOB_TYPE": "start", "_CAP_EFFECTIVE": "1ffffffffff", "JOB_RESULT": "done", "_BOOT_ID": "b7c4b78ba3cb403ea89f99ea2801a34d" } ``` ### Логин в устройство Можно смотреть события PAM, например: ```json { "__CURSOR": "s=b45ff6a034b548efbbc4ddb9caf572a2;i=280f;b=b7c4b78ba3cb403ea89f99ea2801a34d;m=e36ed39;t=5e8a397cf0ec1;x=53746d37c153ddc", "MESSAGE": "pam_tcb(sddm:auth): Authentication passed for teacher from (uid=0)", "__MONOTONIC_TIMESTAMP": "238480697", "_HOSTNAME": "ncco-2-icl1.local", "_CMDLINE": "/usr/libexec/sddm/sddm-helper --socket /tmp/sddm-authadababf6-da82-470f-a58a-f09332c714af --id 1 --start /usr/lib/kf5/bin/startplasma-x11 --user teacher", "_SYSTEMD_CGROUP": "/system.slice/prefdm.service", "_SYSTEMD_INVOCATION_ID": "d01e87e665194c96a1e2260288444968", "_UID": "0", "_COMM": "sddm-helper", "_MACHINE_ID": "446da133a2cb49efbe840eb66307756b", "_TRANSPORT": "syslog", "_BOOT_ID": "b7c4b78ba3cb403ea89f99ea2801a34d", "SYSLOG_TIMESTAMP": "Sep 14 17:03:27 ", "_PID": "2761", "_SOURCE_REALTIME_TIMESTAMP": "1663164207795860", "PRIORITY": "6", "_GID": "0", "_SYSTEMD_UNIT": "prefdm.service", "_EXE": "/usr/libexec/sddm/sddm-helper", "_CAP_EFFECTIVE": "1ffffffffff", "_SYSTEMD_SLICE": "system.slice", "SYSLOG_FACILITY": "10", "__REALTIME_TIMESTAMP": "1663164207795905", "SYSLOG_IDENTIFIER": "sddm-helper" } ``` Однако будет удобнее ориентироваться на запуск `user-$UID.slice`: ```json { "_SYSTEMD_CGROUP": "/init.scope", "SYSLOG_FACILITY": "3", "_UID": "0", "_BOOT_ID": "b7c4b78ba3cb403ea89f99ea2801a34d", "JOB_RESULT": "done", "SYSLOG_IDENTIFIER": "systemd", "__REALTIME_TIMESTAMP": "1663164207801126", "JOB_ID": "1480", "__CURSOR": "s=b45ff6a034b548efbbc4ddb9caf572a2;i=281a;b=b7c4b78ba3cb403ea89f99ea2801a34d;m=e37019e;t=5e8a397cf2326;x=3103dcbe46f278c8", "_CMDLINE": "/sbin/init splash", "PRIORITY": "6", "_GID": "0", "_SYSTEMD_UNIT": "init.scope", "INVOCATION_ID": "11a0b0538275491d9f27021fde8251a5", "CODE_FUNC": "job_emit_done_message", "MESSAGE_ID": "39f53479d3a045ac8e11786248231fbf", "UNIT": "user-500.slice", "__MONOTONIC_TIMESTAMP": "238485918", "_COMM": "systemd", "JOB_TYPE": "start", "CODE_LINE": "713", "CODE_FILE": "src/core/job.c", "_SOURCE_REALTIME_TIMESTAMP": "1663164207801121", "_CAP_EFFECTIVE": "1ffffffffff", "_MACHINE_ID": "446da133a2cb49efbe840eb66307756b", "_HOSTNAME": "ncco-2-icl1.local", "TID": "1", "_SYSTEMD_SLICE": "-.slice", "_EXE": "/lib/systemd/systemd", "_TRANSPORT": "journal", "MESSAGE": "Created slice User Slice of UID 500.", "_PID": "1" } ``` ### Блокировка устройства Сейчас нормально не логируется. Можно попробовать сделать службу, запускаемую при наступлении нужной target systemd. Или что-то делать (писать в лог), когда polkit выдает разрешение на блокировку. ### Разблокировка устройства Стоит повысить качество логирования приблизительно как описано выше, однако можно видеть события, когда разблокировщик прошел авторизацию: ```json { "SYSLOG_FACILITY": "10", "_SOURCE_REALTIME_TIMESTAMP": "1663164791279391", "_MACHINE_ID": "446da133a2cb49efbe840eb66307756b", "_EXE": "/usr/libexec/kf5/kcheckpass", "_SYSTEMD_USER_SLICE": "-.slice", "PRIORITY": "6", "_HOSTNAME": "ncco-2-icl1.local", "_SYSTEMD_INVOCATION_ID": "9297989dd5504b23a850c1a77e02d08c", "_TRANSPORT": "syslog", "SYSLOG_PID": "3495", "_GID": "500", "SYSLOG_TIMESTAMP": "Sep 14 17:13:11 ", "_BOOT_ID": "b7c4b78ba3cb403ea89f99ea2801a34d", "_UID": "500", "SYSLOG_IDENTIFIER": "kcheckpass", "__CURSOR": "s=67dc1471c824495d8b7ca28b2a9a0b85;i=2939;b=b7c4b78ba3cb403ea89f99ea2801a34d;m=3148c14d;t=5e8a3ba964f53;x=f7329ba3eda2e7c7", "_SYSTEMD_SLICE": "user-500.slice", "_SYSTEMD_OWNER_UID": "500", "_SYSTEMD_CGROUP": "/user.slice/user-500.slice/session-4.scope", "_SYSTEMD_SESSION": "4", "_CMDLINE": "kcheckpass -m classic -S 30", "_CAP_EFFECTIVE": "0", "_AUDIT_LOGINUID": "500", "__REALTIME_TIMESTAMP": "1663164791279443", "_AUDIT_SESSION": "4", "_PID": "3495", "MESSAGE": "pam_tcb(kf5-screenlocker:auth): Authentication passed for teacher from teacher(uid=500)", "_SYSTEMD_UNIT": "session-4.scope", "_COMM": "kcheckpass", "__MONOTONIC_TIMESTAMP": "826851661" } ``` ### Подключение стороннего устройства Данные события отражаются в логе ядра (`dmesg`) и дублируются в `journalctl`, при необходимости можно вешать ionotify на `/sys`. Подключение USB-флешки: ```json { "PRIORITY": "6", "_MACHINE_ID": "446da133a2cb49efbe840eb66307756b", "SYSLOG_IDENTIFIER": "kernel", "_SOURCE_MONOTONIC_TIMESTAMP": "852503228", "__REALTIME_TIMESTAMP": "1663164816917389", "_KERNEL_DEVICE": "+usb:1-2", "_TRANSPORT": "kernel", "MESSAGE": "usb 1-2: new high-speed USB device number 4 using xhci_hcd", "__CURSOR": "s=b45ff6a034b548efbbc4ddb9caf572a2;i=293d;b=b7c4b78ba3cb403ea89f99ea2801a34d;m=32cff589;t=5e8a3bc1d838d;x=564ac454a42de005", "__MONOTONIC_TIMESTAMP": "852489609", "_KERNEL_SUBSYSTEM": "usb", "_HOSTNAME": "ncco-2-icl1.local", "_BOOT_ID": "b7c4b78ba3cb403ea89f99ea2801a34d", "SYSLOG_FACILITY": "0" } ``` ```json { "_KERNEL_DEVICE": "+usb:1-2:1.0", "PRIORITY": "6", "__CURSOR": "s=b45ff6a034b548efbbc4ddb9caf572a2;i=2940;b=b7c4b78ba3cb403ea89f99ea2801a34d;m=32d2859b;t=5e8a3bc2013a1;x=30d8b837a01ad916", "_KERNEL_SUBSYSTEM": "usb", "_HOSTNAME": "ncco-2-icl1.local", "_UDEV_SYSNAME": "1-2:1.0", "SYSLOG_IDENTIFIER": "kernel", "__MONOTONIC_TIMESTAMP": "852657563", "MESSAGE": "usb-storage 1-2:1.0: USB Mass Storage device detected", "_MACHINE_ID": "446da133a2cb49efbe840eb66307756b", "_TRANSPORT": "kernel", "_SOURCE_MONOTONIC_TIMESTAMP": "852671778", "__REALTIME_TIMESTAMP": "1663164817085345", "SYSLOG_FACILITY": "0", "_BOOT_ID": "b7c4b78ba3cb403ea89f99ea2801a34d" } ``` ``` { "_MACHINE_ID": "446da133a2cb49efbe840eb66307756b", "__CURSOR": "s=b45ff6a034b548efbbc4ddb9caf572a2;i=294c;b=b7c4b78ba3cb403ea89f99ea2801a34d;m=32e33ee3;t=5e8a3bc30cce8;x=f090741ef2f21e1e", "PRIORITY": "5", "_SOURCE_MONOTONIC_TIMESTAMP": "853767704", "_HOSTNAME": "ncco-2-icl1.local", "SYSLOG_IDENTIFIER": "kernel", "_KERNEL_SUBSYSTEM": "scsi", "_UDEV_SYSNAME": "3:0:0:0", "_TRANSPORT": "kernel", "MESSAGE": "sd 3:0:0:0: [sdb] Attached SCSI removable disk", "__REALTIME_TIMESTAMP": "1663164818181352", "__MONOTONIC_TIMESTAMP": "853753571", "_BOOT_ID": "b7c4b78ba3cb403ea89f99ea2801a34d", "_KERNEL_DEVICE": "+scsi:3:0:0:0", "SYSLOG_FACILITY": "0" } ``` ### Отключение стороннего устройства Отключение USB-флешки: ```json { "__REALTIME_TIMESTAMP": "1663165049801310", "_KERNEL_SUBSYSTEM": "usb", "_HOSTNAME": "ncco-2-icl1.local", "_UDEV_SYSNAME": "1-2", "MESSAGE": "usb 1-2: USB disconnect, device number 4", "_BOOT_ID": "b7c4b78ba3cb403ea89f99ea2801a34d", "_UDEV_DEVNODE": "/dev/bus/usb/001/004", "PRIORITY": "6", "_KERNEL_DEVICE": "c189:3", "__MONOTONIC_TIMESTAMP": "1085373528", "_MACHINE_ID": "446da133a2cb49efbe840eb66307756b", "_SOURCE_MONOTONIC_TIMESTAMP": "1085390460", "SYSLOG_FACILITY": "0", "__CURSOR": "s=b45ff6a034b548efbbc4ddb9caf572a2;i=2abc;b=b7c4b78ba3cb403ea89f99ea2801a34d;m=40b17c58;t=5e8a3c9ff0a5e;x=ef8248b678039a0f", "_TRANSPORT": "kernel", "SYSLOG_IDENTIFIER": "kernel" } ``` ### Подключение к Wi-Fi ```json { "SYSLOG_PID": "2443", "_CAP_EFFECTIVE": "200534e2", "__REALTIME_TIMESTAMP": "1663164210362279", "_HOSTNAME": "ncco-2-icl1.local", "_GID": "0", "CODE_LINE": "2483", "_SYSTEMD_INVOCATION_ID": "9bb6fc2091444ee9856ef1db55a5def0", "__CURSOR": "s=b45ff6a034b548efbbc4ddb9caf572a2;i=28b0;b=b7c4b78ba3cb403ea89f99ea2801a34d;m=e5e161f;t=5e8a397f637a7;x=ee8629ba9894c074", "NM_DEVICE": "wlp0s20f3", "_BOOT_ID": "b7c4b78ba3cb403ea89f99ea2801a34d", "__MONOTONIC_TIMESTAMP": "241047071", "PRIORITY": "6", "SYSLOG_IDENTIFIER": "NetworkManager", "NM_LOG_LEVEL": "INFO", "CODE_FILE": "src/core/devices/wifi/nm-device-wifi.c", "_SYSTEMD_SLICE": "system.slice", "NM_LOG_DOMAINS": "WIFI,DEVICE", "_SOURCE_REALTIME_TIMESTAMP": "1663164210362119", "_SYSTEMD_CGROUP": "/system.slice/NetworkManager.service", "_PID": "2443", "_UID": "0", "TIMESTAMP_MONOTONIC": "235.046905", "_SYSTEMD_UNIT": "NetworkManager.service", "_COMM": "NetworkManager", "_CMDLINE": "/usr/sbin/NetworkManager --no-daemon", "MESSAGE": " [1663164210.3621] device (wlp0s20f3): Activation: (wifi) Stage 2 of 5 (Device Configure) successful. Connected to wireless network \"DigitalCenter_5G\"", "_EXE": "/usr/sbin/NetworkManager", "_MACHINE_ID": "446da133a2cb49efbe840eb66307756b", "TIMESTAMP_BOOTTIME": "241.046905", "_TRANSPORT": "journal", "SYSLOG_FACILITY": "3" } ``` ### Отключение Wi-Fi ```json { "MESSAGE": " [1663164926.3556] device (wlp0s20f3): state change: activated -> deactivating (reason 'user-requested', sys-iface-state: 'managed')", "__REALTIME_TIMESTAMP": "1663164926355785", "SYSLOG_FACILITY": "3", "_EXE": "/usr/sbin/NetworkManager", "NM_DEVICE": "wlp0s20f3", "_BOOT_ID": "b7c4b78ba3cb403ea89f99ea2801a34d", "_SYSTEMD_INVOCATION_ID": "9bb6fc2091444ee9856ef1db55a5def0", "_UID": "0", "TIMESTAMP_MONOTONIC": "955.927898", "__CURSOR": "s=b45ff6a034b548efbbc4ddb9caf572a2;i=29fa;b=b7c4b78ba3cb403ea89f99ea2801a34d;m=3955db44;t=5e8a3c2a36949;x=8d461b4a324f3fb9", "_SYSTEMD_CGROUP": "/system.slice/NetworkManager.service", "CODE_LINE": "16516", "_CMDLINE": "/usr/sbin/NetworkManager --no-daemon", "TIMESTAMP_BOOTTIME": "961.927898", "CODE_FILE": "src/core/devices/nm-device.c", "PRIORITY": "6", "SYSLOG_PID": "2443", "_CAP_EFFECTIVE": "200534e2", "_GID": "0", "NM_LOG_LEVEL": "INFO", "_SYSTEMD_UNIT": "NetworkManager.service", "_SYSTEMD_SLICE": "system.slice", "SYSLOG_IDENTIFIER": "NetworkManager", "_TRANSPORT": "journal", "NM_LOG_DOMAINS": "DEVICE", "__MONOTONIC_TIMESTAMP": "961928004", "_PID": "2443", "_HOSTNAME": "ncco-2-icl1.local", "_SOURCE_REALTIME_TIMESTAMP": "1663164926355747", "_MACHINE_ID": "446da133a2cb49efbe840eb66307756b", "_COMM": "NetworkManager" } ``` ### Подключение Ethernet ```json { "_MACHINE_ID": "446da133a2cb49efbe840eb66307756b", "_COMM": "NetworkManager", "__MONOTONIC_TIMESTAMP": "1040164086", "NM_LOG_DOMAINS": "DEVICE", "_UID": "0", "_GID": "0", "TIMESTAMP_MONOTONIC": "1034.164025", "TIMESTAMP_BOOTTIME": "1040.164025", "NM_DEVICE": "enp0s31f6", "CODE_LINE": "16738", "_CMDLINE": "/usr/sbin/NetworkManager --no-daemon", "__CURSOR": "s=b45ff6a034b548efbbc4ddb9caf572a2;i=2a4e;b=b7c4b78ba3cb403ea89f99ea2801a34d;m=3dffa4f6;t=5e8a3c74d32fc;x=9effed904fd09e8b", "_SOURCE_REALTIME_TIMESTAMP": "1663165004591824", "_SYSTEMD_SLICE": "system.slice", "_SYSTEMD_CGROUP": "/system.slice/NetworkManager.service", "SYSLOG_PID": "2443", "_CAP_EFFECTIVE": "200534e2", "_PID": "2443", "SYSLOG_FACILITY": "3", "CODE_FILE": "src/core/devices/nm-device.c", "__REALTIME_TIMESTAMP": "1663165004591868", "SYSLOG_IDENTIFIER": "NetworkManager", "_HOSTNAME": "ncco-2-icl1.local", "MESSAGE": " [1663165004.5918] device (enp0s31f6): Activation: successful, device activated.", "NM_LOG_LEVEL": "INFO", "_TRANSPORT": "journal", "_SYSTEMD_INVOCATION_ID": "9bb6fc2091444ee9856ef1db55a5def0", "PRIORITY": "6", "_EXE": "/usr/sbin/NetworkManager", "_BOOT_ID": "b7c4b78ba3cb403ea89f99ea2801a34d", "_SYSTEMD_UNIT": "NetworkManager.service" } ``` ### Отключение Ethernet Событие физического отсоединения кабеля: ``` { "__REALTIME_TIMESTAMP": "1663165006597376", "__MONOTONIC_TIMESTAMP": "1042169594", "_UDEV_SYSNAME": "0000:00:1f.6", "PRIORITY": "6", "_BOOT_ID": "b7c4b78ba3cb403ea89f99ea2801a34d", "_MACHINE_ID": "446da133a2cb49efbe840eb66307756b", "_KERNEL_DEVICE": "+pci:0000:00:1f.6", "_HOSTNAME": "ncco-2-icl1.local", "_TRANSPORT": "kernel", "MESSAGE": "e1000e-ext 0000:00:1f.6 enp0s31f6: NIC Link is Down", "SYSLOG_IDENTIFIER": "kernel", "__CURSOR": "s=b45ff6a034b548efbbc4ddb9caf572a2;i=2a56;b=b7c4b78ba3cb403ea89f99ea2801a34d;m=3e1e3efa;t=5e8a3c76bcd00;x=9fcd1e133f0bb261", "SYSLOG_FACILITY": "0", "_KERNEL_SUBSYSTEM": "pci", "_SOURCE_MONOTONIC_TIMESTAMP": "1042186286" } ``` Событие программного выключения (в данном случае оно автоматически последовало за физическим отсоединением кабеля): ``` { "_SOURCE_REALTIME_TIMESTAMP": "1663165012599797", "_CMDLINE": "/usr/sbin/NetworkManager --no-daemon", "TIMESTAMP_BOOTTIME": "1048.171939", "SYSLOG_IDENTIFIER": "NetworkManager", "NM_LOG_DOMAINS": "DEVICE", "CODE_FILE": "src/core/devices/nm-device.c", "SYSLOG_FACILITY": "3", "_SYSTEMD_SLICE": "system.slice", "_TRANSPORT": "journal", "NM_DEVICE": "enp0s31f6", "MESSAGE": " [1663165012.5997] device (enp0s31f6): state change: activated -> unavailable (reason 'carrier-changed', sys-iface-state: 'managed')", "__CURSOR": "s=b45ff6a034b548efbbc4ddb9caf572a2;i=2a57;b=b7c4b78ba3cb403ea89f99ea2801a34d;m=3e79d622;t=5e8a3c7c76428;x=1140c064ad71ca6a", "PRIORITY": "6", "__REALTIME_TIMESTAMP": "1663165012599848", "__MONOTONIC_TIMESTAMP": "1048172066", "_MACHINE_ID": "446da133a2cb49efbe840eb66307756b", "TIMESTAMP_MONOTONIC": "1042.171939", "_GID": "0", "_SYSTEMD_UNIT": "NetworkManager.service", "_EXE": "/usr/sbin/NetworkManager", "NM_LOG_LEVEL": "INFO", "CODE_LINE": "16516", "_PID": "2443", "_SYSTEMD_CGROUP": "/system.slice/NetworkManager.service", "_BOOT_ID": "b7c4b78ba3cb403ea89f99ea2801a34d", "SYSLOG_PID": "2443", "_COMM": "NetworkManager", "_CAP_EFFECTIVE": "200534e2", "_UID": "0", "_SYSTEMD_INVOCATION_ID": "9bb6fc2091444ee9856ef1db55a5def0", "_HOSTNAME": "ncco-2-icl1.local" } ```