Логирование в сервисах

Настройки логирования
Принцип работы логгера
Уровни логирования
Краткий итог

Настройки логирования

Все сервисы, входящие в дистрибутивы Пульт.Онлайн, имеют единую систему логирования. Настройки логирования задаются в конфигурационных файлах сервисов и выглядят примерно так:

                                        # Параметры записи лога:

logger_enabled=1 			# включение логирования, 0 | 1
logger_print=1				# вывод лога в консоль, 0 | 1
logger_write=1				# запись лога в файл, 0 | 1
logger_dir=logs				# папка логов (относительно папки исполняемого файла)
logger_title=some_service_log		# заголовок файлов логов
logger_maxline=256			# максимальная длина строки лога, байты
logger_maxsize=100000			# максимальный размер файла лога, байты
logger_maxfiles=5			# максимальное количество файлов логов в ротации
logger_detailed_http=0			# детальный вывод лога уровня библиотеки HTTP

                                        # Уровни логирования:

log_app=1				# вывод основной логики приложения
log_drv=1				# общий вывод общей библиотеки драйверов переменных
log_var=1				# вывод общей библиотеки драйверов переменных по каждой переменой 
log_api=1				# вывод общей библиотеки стандартного API
log_srv=0				# вывод общей библиотеки стандартного сервиса
log_rpc=0				# вывод общей библиотеки протокола JSONRPC2.0
log_ws=0				# вывод общей библиотеки протокола Websocket
log_http=0				# вывод общей библиотеки протокола HTTP
log_mjpeg=0				# вывод общей библиотеки протокола MJPEG
log_bnry=0				# вывод общей библиотеки собственного протокола BNRY
log_mb=0				# вывод общей библиотеки протокола Modbus
log_mqtt=0				# вывод общей библиотеки протокола MQTT
log_ns=0				# общий вывод общей библиотеки сетевых сокетов
log_data=0				# вывод общей библиотеки сетевых сокетов для каждого пакета транслируемых данных

Принцип работы логгера

Функции логирования инициализируются при старте приложения, сразу после считывания конфигурационного файла. С этого момента логгер начинает выводить в файл и/или в консоль записи от компонентов приложения, согласно включенным уровням логирования.

Файлы логов ротируются. При достижении файлом максимального размера (параметр logger_maxsize), логгер отрывает на запись новый файл, удаляя при этом самый старый лог, если количество файлов логов превышает указанное в параметре logger_maxfiles. Таким образом, общий объем файлов логов приложения никогда не превысит заданное количество и размер.

Уровни логирования

Уровни логирования представляют вывод, который инициируется отдельными компонентами приложения (сервиса).

Например, приложение построено на общей библиотеке сетевых сокетов, общей библиотеке Modbus и конечно имеет основную логику самого приложения.

В таком приложении мы можем включить log_app - наименее детальный вывод, генерируемый в коде основной логики приложения. В этом выводе мы можем увидеть записи о запуске приложения, его инициализации и о действиях в рамках главной логики приложения.

Например, приложение является Modbus-клиентом, опрашивающим Modbus-устройства. Тогда в log_app мы увидим следующие записи:

DRV_MBTCP     | Sep 03 03:43:57.265  APP [000000004] 13F2 |     45.8.248.56:00502    SLV001 RD03 HR 100 | request created 
DRV_MBTCP     | Sep 03 03:43:57.266  APP [000000004] 13F2 |     45.8.248.56:00502 <- SLV001 RD03 HR 100 | request sent 
DRV_MBTCP     | Sep 03 03:43:57.278  APP [000000004] 13F2 |     45.8.248.56:00502 -> SLV001 RD03 HR 100 | response received 
DRV_MBTCP     | Sep 03 03:43:57.278  APP [000000004] 13F2 |     45.8.248.56:00502    SLV001 RD03 HR 100 | request processed 

Где сначала идут 4 общих для всех сервисов столбца:

• DRV_MBTCP - Заголовок файла лога (обычно соответствует имени сервиса)
• Sep 03 03:43:57.265 - время записи
• APP - уровень логирования (log_app)
• [000000004] - индекс сетевого соединения, к которому имеет отношение логируемое событие

Далее идут данные, специфичные для конкретного приложения и уровня логирования. В данном случае, DRV_MBTCP пишет следующую информацию:

• 13F2 - идентификатор ModbusTCP-транзакции
• 45.8.248.56:00502 - хост и порт опрашиваемого узла
• SLV001 RD03 HR 100 - Slave ID (1), Команда чтения (RD - ReaD, код 3), Тип читаемого регистра (HR - Holding Register), Адрес регистра (100)
• request created - событие, связанное с регистром (запрос сформирован и поставлен в очередь, для отправки при первой возможности)

Таким образом, уровень log_app информирует нас о событиях в контексте основной логики приложения:

• 03:43:57.265 - создан запрос на чтение регистра HR 100 из Slave 1 узла 45.8.248.56 через порт 502
• 03:43:57.266 - запрос отправлен
• 03:43:57.278 - получен валидный ответ (т.к. нет записи об ошибке)
• 03:43:57.278 - запрос обработан

Если нам требуется более детальная информация, например содержание Modbus-пакетов, мы можем включить уровень log_mb: тогда общая Modbus-библиотека, которая используется нашим приложением для отправки, приема и парсинга Modbus-пакетов, начнет выводить в общий поток лога свои записи. С включенным log_mb наш вывод будет выглядеть так:

DRV_MBTCP     | Sep 03 03:43:57.265  APP [000000004] 13F2 |     45.8.248.56:00502    SLV001 RD03 HR 100 | request created 
DRV_MBTCP     | Sep 03 03:43:57.266  APP [000000004] 13F2 |     45.8.248.56:00502 <- SLV001 RD03 HR 100 | request sent 
DRV_MBTCP     | Sep 03 03:43:57.266   MB [000000004]  TCP |     45.8.248.56:00502 <- SLV001 13 F2 00 00 00 06 01 03 00 64 00 01
DRV_MBTCP     | Sep 03 03:43:57.278   MB [000000004]  TCP |     45.8.248.56:00502 -> SLV001 13 F2 00 00 00 05 01 03 02 AB CD
DRV_MBTCP     | Sep 03 03:43:57.278  APP [000000004] 13F2 |     45.8.248.56:00502 -> SLV001 RD03 HR 100 | response received 
DRV_MBTCP     | Sep 03 03:43:57.278  APP [000000004] 13F2 |     45.8.248.56:00502    SLV001 RD03 HR 100 | request processed 

Мы видим, что между request sent и response received добавились две записи от имени log_mb:

DRV_MBTCP     | Sep 03 03:43:57.266   MB [000000004]  TCP |     45.8.248.56:00502 <- SLV001 13 F2 00 00 00 06 01 03 00 64 00 01
DRV_MBTCP     | Sep 03 03:43:57.278   MB [000000004]  TCP |     45.8.248.56:00502 -> SLV001 13 F2 00 00 00 05 01 03 02 AB CD

Вывод этих записей инициировала Modbus-библиотека. Данный вывод содержит более детальную информацию по запросу - мы видим содержание запроса и ответа в виде отдельных байт.

В свою очередь, Modbus-библиотека использует для работы с сетевыми сокетами общую библиотеку сетевых сокетов, основной вывод которой включается параметром log_ns, а детальный вывод трафика - параметром log_data. Включение этих параметров увеличит детализацию лога, и, как правило, требуется только в очень сложных случаях, когда информации, предоставляемой уровнями APP и MB недостаточно.

Уровень NS предоставляет вывод самого низкого сетевого уровня, доступный для логирования в сервисах Пульт.Онлайн: это события на уровне сокетов и сетевых буферов, такие как прием входящих подключений (наш сервис DRV_MBTCP не только выполняет исходящие Modbus-запросы, но и предоставляет свое JSONRPC API по UNIX-сокету другим сервисам системы), прием и отправка сырых данных в сокеты, системные события на дескрипторах сокетов и т. п. низкоуровневые операции:

DRV_MBTCP     | Sep 03 05:49:20.759   NS [000000007] UNIX | accept connection on drv_mbtcp.us
DRV_MBTCP     | Sep 03 05:49:20.759   NS [000000007] UNIX | connected
DRV_MBTCP     | Sep 03 05:49:20.759 DATA [000000007] -> 375 B | 424E525980000D05424E5259000001677B226A736F6E727063223A22322E30222C226964223A223635222C226D6574686F64223A22737562736372696265222C22706172616D73223A7B226576656E74223A22757064617465222C226F7074696F6E73223A7B2...
DRV_MBTCP     | Sep 03 05:49:20.759   NS [000000007] UNIX | read 375 bytes
DRV_MBTCP     | Sep 03 05:49:20.759   NS [000000007] UNIX | send 66 bytes
...
DRV_MBTCP     | Sep 03 05:49:24.396   NS [000000004]  TCP | EPOLLIN
DRV_MBTCP     | Sep 03 05:49:24.396   NS [000000004]  TCP | EPOLLOUT
DRV_MBTCP     | Sep 03 05:49:24.396 DATA [000000004] -> 11 B | 002A00000005010302ABCD
DRV_MBTCP     | Sep 03 05:49:24.396   NS [000000004]  TCP | read 11 bytes
DRV_MBTCP     | Sep 03 05:49:24.396   MB [000000004]  TCP |     45.8.248.56:00502 -> SLV001 00 2A 00 00 00 05 01 03 02 AB CD
DRV_MBTCP     | Sep 03 05:49:24.396  APP [000000004] 002A |     45.8.248.56:00502 -> SLV001 RD03 HR 100 | response received 
DRV_MBTCP     | Sep 03 05:49:24.396  APP [000000004] 002A |     45.8.248.56:00502    SLV001 RD03 HR 100 | request processed 
DRV_MBTCP     | Sep 03 05:49:24.396  APP [000000004] 002B |     45.8.248.56:00502 <- SLV001 RD03 HR 200 | request sent 
DRV_MBTCP     | Sep 03 05:49:24.396   MB [000000004]  TCP |     45.8.248.56:00502 <- SLV001 00 2B 00 00 00 06 01 03 00 C8 00 01
DRV_MBTCP     | Sep 03 05:49:24.396   NS [000000004]  TCP | send 12 bytes
DRV_MBTCP     | Sep 03 05:49:24.396 DATA [000000004] <- 12 B | 002B00000006010300C80001

Краткий итог

• Сервисы Пульт.Онлайн предоставляют информацию в логах в едином стандарте, с возможностью детализации работы отдельных компонентов, из которых состоят исполняемые файлы сервисов.
• При работе с логами выбирайте оптимальную комбинацию уровней логирования, начиная с компонентов верхних уровней (log_app, log_drv, log_srv, log_api и далее вниз по списку уровней).
• Включайте более низкие уровни логирования только при недостаточности информации от верхних уровней.
• Не забывайте выключать логирование по завершению разбора событий, чтобы не нагружать приложения лишней работой и не занимать место на диске.