NXLog CE misbehavior (may be bug or multithread issue) - variables lost or corrupt between stages.


#1 tubecleaner

I have setup with RHEL 7.9 (kernel  3.10.0-1160.108.1.el7.x86_64) / NXLog CE 3.2.2329 / Postgresql 15 vanilla / libdbi 8.4 with configuration:

User nxlog
Group nxlog

include /etc/nxlog/nxlog.d/*.conf LogFile /var/log/nxlog/nxlog.log LogLevel DEBUG

<Extension charconv> Module xm_charconv </Extension>

<Input sqlite3_dbi> Module im_dbi SQL SELECT * FROM vw_tp_message Driver sqlite3 Option dbname term_refdata.db Option sqlite3_dbdir /app/data/monitoring Option sqlite3_timeout 1000 PollInterval 5 SavePos TRUE </Input>

<Output postgres_dbi> Module om_dbi SQL INSERT INTO msglog.msglog (facility, severity, hostname, timestamp, application, message)
VALUES ($SyslogFacility, $SyslogSeverity, $Hostname, '$EventTime', $SourceName, $Message) Driver pgsql Option host /var/run/postgresql Option username srv_nxlog Option dbname MSGLog Exec $Message = convert($Message, "windows-1251", "utf-8"); </Output>

<Route sqlite_postgres> Path sqlite3_dbi => postgres_dbi </Route>

There are only 2 records in sqlite database:

$  sqlite3 -header /app/data/monitoring/term_refdata.db 'select * from vw_tp_message'
id|SyslogFacility|SyslogSeverity|Hostname|EventTime|SourceName|Message
1293441|USER|INFO|SERVER1-D1-CL|2024-09-12 00:18:22.540|tp_msg|Some text in Windows1251 encoding
1293442|USER|INFO|SERVER1-D1-CL|2024-09-12 00:41:04.677|tp_msg|Another text in Windows1251 encoding

And this is what I get in nxlog.log:

...
2024-09-12 16:54:59 DEBUG logdata missing or undef 'EventTime', setting to NULL
2024-09-12 16:54:59 DEBUG om_dbi SQL: INSERT INTO msglog.msglog (facility, severity, hostname, timestamp, application, message)                 VALUES ('USER', 'INFO', 'SERVER1-D1-CL', 'NULL', 'tp_msg', 'Some text in Windows1251 encoding')
2024-09-12 16:54:59 ERROR [om_dbi.c:256/om_dbi_write()] -;[om_dbi.c:85/om_dbi_error()] om_dbi failed to execute SQL statement "INSERT INTO msglog.msglog (facility, severity, hostname, timestamp, application, message)                 VALUES ('USER', 'INFO', 'SERVER1-D1-CL', 'NULL', 'tp_msg', 'Some text in Windows1251 encoding')". ERROR:  invalid input syntax for type timestamp: "NULL";LINE 1: ...          VALUES ('USER', 'INFO', 'SERVER1-D1-CL', 'NULL', 't...;                                                             ^;[errorcode: 0]
...
2024-09-12 16:54:59 DEBUG logdata missing or undef 'EventTime', setting to NULL
2024-09-12 16:54:59 DEBUG om_dbi SQL: INSERT INTO msglog.msglog (facility, severity, hostname, timestamp, application, message)                 VALUES ('USER', 'INFO', 'SERVER1-D1-CL', 'NULL', 'tp_msg', 'Р?нициализация СЏРґСЂР° после перезапуска')
2024-09-12 16:54:59 ERROR [om_dbi.c:256/om_dbi_write()] -;[om_dbi.c:85/om_dbi_error()] om_dbi failed to execute SQL statement "INSERT INTO msglog.msglog (facility, severity, hostname, timestamp, application, message)                 VALUES ('USER', 'INFO', 'SERVER1-D1-CL', 'NULL', 'tp_msg', 'Р?нициализация СЏРґСЂР° после перезапуска')". ERROR:  invalid input syntax for type timestamp: "NULL";LINE 1: ...          VALUES ('USER', 'INFO', 'ABACUS-D1-CL', 'NULL', 't...;                                                             ^;[errorcode: 0]
...
2024-09-12 16:54:59 ERROR [expr.c:189/nx_expr_statement_execute()] assignment failed at line 61, character 70 in /etc/nxlog/nxlog.conf. statement execution has been aborted;[expr.c:90/nx_expr_statement_assignment_execute()] -;[expr.c:509/nx_expr_evaluate()] function 'convert' failed at line 61, character 69 in /etc/nxlog/nxlog.conf. expression evaluation has been aborted;[expr.c:279/nx_expr_eval_func()] -;[xm_charconv_funcproc_cb.c:283/nx_expr_func__convert()] -;[str.c:106/_nx_string_new_size()] oversized string (1688710), limit is 1048576 bytes
2024-09-12 16:54:59 DEBUG logdata missing or undef 'EventTime', setting to NULL
2024-09-12 16:54:59 DEBUG om_dbi SQL: INSERT INTO msglog.msglog (facility, severity, hostname, timestamp, application, message)                 VALUES ('USER', 'INFO', 'SERVER1-D1-CL', 'NULL', 'tp_msg', 'Р В Р’В РВ<C2>
2024-09-12 16:54:59 ERROR [om_dbi.c:256/om_dbi_write()] -;[om_dbi.c:85/om_dbi_error()] om_dbi failed to execute SQL statement "INSERT INTO msglog.msglog (facility, severity, hostname, timestamp, application, message)                 VALUES ('USER', 'INFO', 'SERVER1-D1-CL', 'NULL', 'tp_msg', 'Р В Р’ВРР<E2><80>
...

As you can see, logdata variable $EventTime just disappear and $Message get corrupted after some retries (note: om_dbi retries crazy fast - about 50000 time every few seconds). If I change om_dbi to simple om_file then all works fine. Another note: this configuration worked fine some time since initial setup, but now error appear every time (maybe postgresql query time affects it?)