Compilling with CFLAGS="-ggdb3 -O0" does not reproduce the issue...

Follow the snapshots Balazs asked for:

Advancing patterndb current time because of timer tick; utc='1382204151'
^C
Program received signal SIGINT, Interrupt.
0x00007ffff6544f03 in epoll_wait () from /lib64/libc.so.6
Missing separate debuginfos, use: debuginfo-install glib2-2.22.5-7.el6.x86_64 glibc-2.12-1.107.el6.x86_64 json-c-0.10-2.el6.x86_64 keyutils-libs-1.4-4.el6.x86_64 krb5-libs-1.10.3-10.el6.x86_64 libcom_err-1.41.12-14.el6.x86_64 libnet-1.1.5-1.el6.x86_64 libselinux-2.0.94-5.3.el6.x86_64 openssl-1.0.0-27.el6.x86_64 pcre-7.8-6.el6.x86_64 zlib-1.2.3-29.el6.x86_64
(gdb) bt
#0  0x00007ffff6544f03 in epoll_wait () from /lib64/libc.so.6
#1  0x00007ffff7baaecd in iv_fd_epoll_poll (st=0x605df0, active=0x7fffffffe3c0, to=0x7fffffffe400) at iv_fd_epoll.c:131
#2  0x00007ffff7ba9837 in iv_fd_poll_and_run (st=0x605df0, to=0x7fffffffe400) at iv_fd.c:147
#3  0x00007ffff7baa054 in iv_main () at iv_main_posix.c:117
#4  0x00007ffff7b8c517 in main_loop_run () at mainloop.c:736
#5  0x0000000000401641 in main (argc=1, argv=0x7fffffffe548) at main.c:267
(gdb) c
Continuing.
Advancing patterndb current time because of timer tick; utc='1382204154'
Advancing patterndb current time because of timer tick; utc='1382204155'
Advancing patterndb current time because of timer tick; utc='1382204156'
^C
Program received signal SIGINT, Interrupt.
0x00007ffff6544f03 in epoll_wait () from /lib64/libc.so.6
(gdb) bt
#0  0x00007ffff6544f03 in epoll_wait () from /lib64/libc.so.6
#1  0x00007ffff7baaecd in iv_fd_epoll_poll (st=0x605df0, active=0x7fffffffe3c0, to=0x7fffffffe400) at iv_fd_epoll.c:131
#2  0x00007ffff7ba9837 in iv_fd_poll_and_run (st=0x605df0, to=0x7fffffffe400) at iv_fd.c:147
#3  0x00007ffff7baa054 in iv_main () at iv_main_posix.c:117
#4  0x00007ffff7b8c517 in main_loop_run () at mainloop.c:736
#5  0x0000000000401641 in main (argc=1, argv=0x7fffffffe548) at main.c:267
(gdb) c
Continuing.
Advancing patterndb current time because of timer tick; utc='1382204161'
Advancing patterndb current time because of timer tick; utc='1382204162'
Advancing patterndb current time because of timer tick; utc='1382204163'
Advancing patterndb current time because of timer tick; utc='1382204164'
^C
Program received signal SIGINT, Interrupt.
0x00007ffff6544f03 in epoll_wait () from /lib64/libc.so.6
(gdb) bt
#0  0x00007ffff6544f03 in epoll_wait () from /lib64/libc.so.6
#1  0x00007ffff7baaecd in iv_fd_epoll_poll (st=0x605df0, active=0x7fffffffe3c0, to=0x7fffffffe400) at iv_fd_epoll.c:131
#2  0x00007ffff7ba9837 in iv_fd_poll_and_run (st=0x605df0, to=0x7fffffffe400) at iv_fd.c:147
#3  0x00007ffff7baa054 in iv_main () at iv_main_posix.c:117
#4  0x00007ffff7b8c517 in main_loop_run () at mainloop.c:736
#5  0x0000000000401641 in main (argc=1, argv=0x7fffffffe548) at main.c:267
(gdb) c
Continuing.



On Sat, Oct 19, 2013 at 3:41 AM, Balazs Scheidler <bazsi77@gmail.com> wrote:

Can you make several snapshots? I mean let it run, break, backtrace and repeat this a number of times?

This backtrace shows that format-json calls the value pairs subsystem to iterate name value pairs. The question is where the infinite loop sits, that's why I would need to look at the backtrace a number of times.

Thanks in advance

On Oct 18, 2013 4:06 PM, "Alexandre Biancalana" <biancalana@gmail.com> wrote:

On Fri, Oct 18, 2013 at 6:01 AM, Balazs Scheidler <bazsi77@gmail.com> wrote:

I remember a bug in that caused similar symptoms when the output template produced zero length strings.

That has been fixed though. But can you try that regardless?

Can you perhaps use gdb to check where it is spinning?

If not, I would need to reproduce it.


It only happens when I parse log using patterndb mentioned earlier with format_json --scope nv-pairs.

Follow the gdb backtrace, let me know if you need anything else.

Program received signal SIGINT, Interrupt.
g_trash_stack_height (name=<value optimized out>, value=0x620d70 "10228", user_data=0x7fffffffe200) at /usr/include/glib-2.0/glib/gutils.h:413
413         i++;
(gdb) bt
#0  g_trash_stack_height (name=<value optimized out>, value=0x620d70 "10228", user_data=0x7fffffffe200) at /usr/include/glib-2.0/glib/gutils.h:413
#1  vp_walker_name_split (name=<value optimized out>, value=0x620d70 "10228", user_data=0x7fffffffe200) at value-pairs.c:455
#2  value_pairs_walker (name=<value optimized out>, value=0x620d70 "10228", user_data=0x7fffffffe200) at value-pairs.c:494
#3  0x00007ffff70a5876 in g_tree_foreach () from /lib64/libglib-2.0.so.0
#4  0x00007ffff7b9ae86 in value_pairs_foreach_sorted (vp=0x6d7590, func=0x7ffff7b9a840 <value_pairs_walker>, compare_func=<value optimized out>, msg=0x61f010, seq_num=0, user_data=0x7fffffffe200)
    at value-pairs.c:329
#5  0x00007ffff7b9afbf in value_pairs_walk (vp=0x6d7590, obj_start_func=<value optimized out>, process_value_func=<value optimized out>, obj_end_func=<value optimized out>, msg=0x61f010, seq_num=0,
    user_data=0x7fffffffe270) at value-pairs.c:534
#6  0x00007ffff3e5bca2 in tf_json_append (self=<value optimized out>, s=0x6d20c0, args=0x7fffffffe320, result=0x636c80) at format-json.c:193
#7  tf_json_call (self=<value optimized out>, s=0x6d20c0, args=0x7fffffffe320, result=0x636c80) at format-json.c:206
#8  0x00007ffff7b98653 in log_template_append_format_with_context (self=0x6d8130, messages=0x7fffffffe3b8, num_messages=1, opts=0x6d7fa0, tz=1, seq_num=0, context_id=0x0, result=0x636c80) at templates.c:1234
#9  0x00007ffff7b988ff in log_template_append_format (self=<value optimized out>, lm=0x61f010, opts=<value optimized out>, tz=<value optimized out>, seq_num=<value optimized out>,
    context_id=<value optimized out>, result=0x636c80) at templates.c:1261
#10 0x00007ffff7b8b87c in log_writer_format_log (self=0x619740, lm=0x61f010, result=0x636c80) at logwriter.c:862
#11 0x00007ffff7b8c310 in log_writer_flush (self=0x619740, flush_mode=LW_FLUSH_NORMAL) at logwriter.c:1005
#12 0x00007ffff7b8c48d in log_writer_work_perform (s=0x619740) at logwriter.c:129
#13 0x00007ffff7b8c4f8 in log_writer_io_flush_output (s=0x619740) at logwriter.c:209
#14 0x00007ffff7ba82ea in iv_run_tasks (st=0x605ba0) at iv_task.c:48
#15 0x00007ffff7baa50c in iv_main () at iv_main_posix.c:106
#16 0x00007ffff7b8c9c7 in main_loop_run () at mainloop.c:736
#17 0x0000000000401641 in main ()
(gdb)
 

______________________________________________________________________________
Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng
Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng
FAQ: http://www.balabit.com/wiki/syslog-ng-faq



______________________________________________________________________________
Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng
Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng
FAQ: http://www.balabit.com/wiki/syslog-ng-faq