Segmentation fault while reading log message value parsed via PatternDB from Python template

[siliconbrain]

syslog-ng

Version of syslog-ng

syslog-ng 3 (3.11.1)
Installer-Version: 3.11.1
Revision: 
Compile-Date: Jul 31 2017 15:16:23
Module-Directory: //usr/lib64/syslog-ng
Module-Path: //usr/lib64/syslog-ng
Available-Modules: add-contextual-data,afamqp,affile,afprog,afsocket,afstomp,afuser,basicfuncs,cef,confgen,cryptofuncs,csvparser,date,dbparser,disk-buffer,graphite,json-plugin,kvformat,linux-kmsg-format,map-value-pairs,pseudofile,sdjournal,snmptrapd-parser,stardate,syslogformat,system-source,tfgetent,mod-python
Enable-Debug: off
Enable-GProf: off
Enable-Memtrace: off
Enable-IPv6: on
Enable-Spoof-Source: on
Enable-TCP-Wrapper: on
Enable-Linux-Caps: on
Enable-Systemd: on

Platform

CentOS Linux release 7.3.1611 (Core)

Issue

Failure

Syslog-ng segfaults while trying to read a macro value inside a Python template function if the value was parsed using PatternDB.

Steps to reproduce

1. copy files from GIST to /etc/syslog-ng/conf.d

2. make sure Python module is available

3. start syslog-ng

4. wait for it! (maybe create a new line in the source file matching the template)

Configuration

Copy these into /etc/syslog-ng/conf.d: https://gist.github.com/siliconbrain/4790de2362ed8aca9af878297dfecbf9

Input and output logs (if possible)

[siliconbrain]

Update: Tried it with 3.12 but the issue still exists.

[lbudai]

@siliconbrain : How did you configure syslog-ng? Did you specify Python version (eg.: --with-python=2)?
What is the output of ldd lib/syslog-ng/libmod-python.so ?
Could you attach GDB stacktrace?
For meg, it is working when I'm using Python 2... in case of Python3 it is more interesting.

[lbudai]

@siliconbrain : something was misconfigured in my test env, bug is confirmed.
stacktrace:

Thread 2 "syslog-ng" received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0x7ffff37b0700 (LWP 14111)]
0x00007ffff7b830fc in nv_table_resolve_indirect (self=0x7fffec0043d0, entry=0x7fffec0045f0, length=0x0)
    at ../../syslog-ng.upstream/lib/logmsg/nvtable.c:190
190       *length = MIN(entry->vindirect.ofs + entry->vindirect.len, referenced_length) - entry->vindirect.ofs;
(gdb) bt
#0  0x00007ffff7b830fc in nv_table_resolve_indirect (self=0x7fffec0043d0, entry=0x7fffec0045f0, length=0x0) at ../../syslog-ng.upstream/lib/logmsg/nvtable.c:190
#1  0x00007ffff4f61a29 in nv_table_get_value_if_set (self=0x7fffec0043d0, handle=391, length=0x0) at ../../syslog-ng.upstream/lib/logmsg/nvtable.h:381
#2  0x00007ffff4f61a67 in nv_table_get_value (self=0x7fffec0043d0, handle=391, length=0x0) at ../../syslog-ng.upstream/lib/logmsg/nvtable.h:387
#3  0x00007ffff4f61ad6 in log_msg_get_value (self=0x7fffec002e00, handle=391, value_len=0x0) at ../../syslog-ng.upstream/lib/logmsg/logmsg.h:247
#4  0x00007ffff4f61cf1 in _py_log_message_getattr (o=0x7ffff7ed00f0, key=0x7ffff4291110) at ../../syslog-ng.upstream/modules/python/python-logmsg.c:83
#5  0x00007ffff4a8179d in PyEval_EvalFrameEx () from /usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0
#6  0x00007ffff4bb001c in PyEval_EvalCodeEx () from /usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0
#7  0x00007ffff4b062e0 in ?? () from /usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0
#8  0x00007ffff4ad91e3 in PyObject_Call () from /usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0
#9  0x00007ffff4baf447 in PyEval_CallObjectWithKeywords () from /usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0
#10 0x00007ffff4f614d9 in _py_invoke_template_function (function_name=0x7fffec004000 "template_fun", msg=0x7fffec002e00, argc=1, argv=0x7fffec004210) at ../../syslog-ng.upstream/modules/python/python-tf.c:63
#11 0x00007ffff4f61767 in tf_python (msg=0x7fffec002e00, argc=1, argv=0x7fffec004210, result=0x711140) at ../../syslog-ng.upstream/modules/python/python-tf.c:107
#12 0x00007ffff7b71e11 in tf_simple_func_call (self=0x7ffff516a6a0 <func>, s=0x7054d0, args=0x7ffff37ad6c0, result=0x711140) at ../../syslog-ng.upstream/lib/template/simple-function.c:91
#13 0x00007ffff7b6fc9c in log_template_append_format_with_context (self=0x69b9f0, messages=0x7ffff37ad740, num_messages=1, opts=0x7051b0, tz=1, seq_num=1, context_id=0x0, result=0x711140)
    at ../../syslog-ng.upstream/lib/template/templates.c:160
#14 0x00007ffff7b6fda7 in log_template_append_format (self=0x69b9f0, lm=0x7fffec002e00, opts=0x7051b0, tz=1, seq_num=1, context_id=0x0, result=0x711140) at ../../syslog-ng.upstream/lib/template/templates.c:181
#15 0x00007ffff7b6fe06 in log_template_format (self=0x69b9f0, lm=0x7fffec002e00, opts=0x7051b0, tz=1, seq_num=1, context_id=0x0, result=0x711140) at ../../syslog-ng.upstream/lib/template/templates.c:189
#16 0x00007ffff7b34c50 in log_writer_format_log (self=0x710800, lm=0x7fffec002e00, result=0x711140) at ../../syslog-ng.upstream/lib/logwriter.c:972
#17 0x00007ffff7b350e0 in log_writer_write_message (self=0x710800, msg=0x7fffec002e00, path_options=0x7ffff37ad8b0, write_error=0x7ffff37ad8a0) at ../../syslog-ng.upstream/lib/logwriter.c:1098
#18 0x00007ffff7b35412 in log_writer_flush (self=0x710800, flush_mode=LW_FLUSH_NORMAL) at ../../syslog-ng.upstream/lib/logwriter.c:1205
#19 0x00007ffff7b33103 in log_writer_work_perform (s=0x710800) at ../../syslog-ng.upstream/lib/logwriter.c:184
#20 0x00007ffff7b382cd in _work (self=0x710a18) at ../../syslog-ng.upstream/lib/mainloop-io-worker.c:53
#21 0x00007ffff7b88980 in iv_work_thread_got_event (_thr=0x7103b0) at ../../../../../syslog-ng.upstream/lib/ivykis/src/iv_work.c:106
#22 0x00007ffff7b87470 in __iv_event_run_pending_events (_st=0x7fffec0008c0) at ../../../../../syslog-ng.upstream/lib/ivykis/src/iv_event.c:56
#23 0x00007ffff7b8c239 in iv_fd_epoll_timerfd_poll (st=0x7fffec0008c0, active=0x7ffff37ada60, abs=<optimized out>) at ../../../../../syslog-ng.upstream/lib/ivykis/src/iv_fd_epoll.c:484
#24 0x00007ffff7b895d5 in iv_fd_poll_and_run (st=st@entry=0x7fffec0008c0, abs=<optimized out>) at ../../../../../syslog-ng.upstream/lib/ivykis/src/iv_fd.c:206
#25 0x00007ffff7b8a59a in iv_main () at ../../../../../syslog-ng.upstream/lib/ivykis/src/iv_main_posix.c:112
#26 0x00007ffff7b887a3 in iv_work_thread (_thr=0x7103b0) at ../../../../../syslog-ng.upstream/lib/ivykis/src/iv_work.c:185
#27 0x00007ffff7b8b50c in iv_thread_handler (_thr=0x70a080) at ../../../../../syslog-ng.upstream/lib/ivykis/src/iv_thread_posix.c:112
#28 0x00007ffff75c36ba in start_thread (arg=0x7ffff37b0700) at pthread_create.c:333
#29 0x00007ffff72f93dd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109
(gdb) 

[lbudai]

The problem is with this line:

const gchar *value = log_msg_get_value(py_msg->msg, handle, NULL);

At the end we are trying to dereference a NULL.
I'll send a PR soon that fix the issue.