[syslog-ng] blocking on /dev/log

12 Sep 2013

      Hello,

I recently ugpraded a server to Debian Wheezy, which means I get 3.3.5-4
of syslog-ng. I did my best to upgrade the config to the 3.3 format, and
then started it up and it seemed to be working fine. So I started
providing services there, but under load the system seemed to be paused.

Load is quite low on the system, but what was happening was logins via
dovecot or ssh were pausing for a very long time. Typically, this
indicates a DNS issue, but I quickly ruled that out. Eventually, I was
reduced to using strace and I found that strace was pausing for a really
long time trying to write a log message to file descriptor 4, and
looking at what that FD was, I found:

[pid  9051] connect(4, {sa_family=AF_FILE, path="/dev/log"}, 110) = 0

I stopped syslog-ng, and then voila, everything was working as it should
be. I tried to increase my log_fifo_size(2048); to be 4096, but that
didn't help, and so I started searching around and I found a similar bug
in 2009 that was fixed[0]. 

I figured that bug was properly fixed, but maybe something came back, or
something is wrong in my config. I noticed in the bug log that one of
the configuration options that they had I did not, so I tried adding
a max-connections argument to the unix-stream for the /dev/log:

    unix-stream("/dev/log" max-connections(2048));

so far that seems to have made things function ok, although the
syslog-ng startup message produces a warning that has me puzzled:

WARNING: window sizing for tcp sources were changed in syslog-ng 3.3, the configuration value was divided by the value of max-connections(). The result was too small, clamping to 100 entries. Ensure you have a proper log_fifo_size setting to avoid message loss.; orig_log_iw_size='12', new_log_iw_size='100', min_log_fifo_size='204800'

So... I'm wondering, is this a bug in syslog-ng, or a bug in my config?

Thanks for any help, or suggestions of things to try!

Here is my config:

@version: 3.3

# First, set some global options.
options { 
    # default is zero
    flush_lines(25); 
    # default is 10000(10s)
    flush_timeout(20000); 
    use_dns(no); 
    use_fqdn(no);
    owner("root"); 
    group("adm"); 
    perm(0640); 
    stats_freq(0);
    time_reopen(10); 
    time_reap(360); 
    create_dirs(yes);
    log_fifo_size(4096); 
};

########################
# Sources
########################
source s_all { 
    internal();
    unix-stream("/dev/log" max-connections(2048));
    file("/proc/kmsg" program_override("kernel"));
    };

########################
# Rewrites
########################

rewrite r_ip { subst('(25[0-5]|2[0-4][0-9]|[0-1]?[0-9]?[0-9])([\.\-](25[0-5]|2[0-4][0-9]|[0-1]?[0-9]?[0-9])){3}', "0.0.0.0", value("MESSAGE"), type("pcre"), flags("global" "nobackref")); };

########################
# Filters
########################

filter f_dbg { level(debug); };
filter f_info { level(info); };
filter f_notice { level(notice); };
filter f_warn { level(warn); };
filter f_err { level(err); };
filter f_crit { level(crit .. emerg); };

filter f_debug { level(debug) and not facility(auth, authpriv, news, mail); };
filter f_error { level(err .. emerg) ; };
filter f_cron { facility(cron) and not filter(f_debug); };
filter f_local { facility(local0, local1, local3, local4, local5,
                        local6, local7) and not filter(f_debug); };
filter f_syslog3 { not facility(auth, authpriv, mail) and not filter(f_debug); };
filter f_cother { level(debug, info, notice, warn) or facility(daemon, mail); };
filter f_console { level(warn .. emerg); };

########################
# Destinations
########################

############################################################
## apache.log

filter f_apache { program("apache") and level(info); };
destination d_apache { file("/var/log/apache/access.log"); };
log {
        source(s_all);
        filter(f_apache);
        rewrite(r_ip);
        destination(d_apache);
        flags(final);
};

filter f_apache_err { program("apache") and level(err); };
destination d_apache_err { file("/var/log/apache/error.log"); };
log {
        source(s_all);
        filter(f_apache_err);
        rewrite(r_ip);
        destination(d_apache_err);
        flags(final);
};

############################################################
## auth.log

filter f_auth { facility(auth, authpriv); };
destination df_auth { file("/var/log/auth.log"); };
log {
    source(s_all);
    filter(f_auth);
    destination(df_auth);
};

############################################################
## clamav.log
filter f_clamav { program("^clamav-milter|clamd"); };
destination d_clamav { file("/var/log/clamav.log"); };
log {
    source(s_all);
    filter(f_clamav);
    destination(d_clamav);
    flags(final);
};

############################################################
## courier.log

filter f_courier { program("courier|imap|pop"); };
destination d_courier { file("/var/log/courier.log"); };
log {
        source(s_all);
        filter(f_courier);
        rewrite(r_ip);
        destination(d_courier);
        flags(final);
};

############################################################
## dovecot.log
filter f_dovecot { program("dovecot.*") and not message("^lda"); };
destination d_dovecot { file("/var/log/dovecot/dovecot.log", group("dovecot")); };
log {  
        source(s_all);
        filter(f_dovecot);
        rewrite(r_ip);
        destination(d_dovecot);
        flags(final);
};

############################################################
## dovecot-lda.log

filter f_dovecot-lda { program("dovecot.*") and message("^lda"); };
destination d_dovecot-lda { file("/var/log/dovecot/dovecot-lda.log", group("dovecot")); };

log {  
        source(s_all);
        filter(f_dovecot-lda);
        rewrite(r_ip);
        destination(d_dovecot-lda);
        flags(final);
};
############################################################
## daemon.log

filter f_daemon { facility(daemon); };
destination df_daemon { file("/var/log/daemon.log"); };
log {
    source(s_all);
    filter(f_daemon);
    rewrite(r_ip);
    destination(df_daemon);
};

############################################################
## errors.log

filter f_errors {
        level(warn,err,crit,alert,emerg)
        and not facility(auth,authpriv,daemon,mail,user,kern,local1);
};
destination df_errors { file("/var/log/errors.log"); };
log {
        source(s_all);
        filter(f_errors);
        destination(df_errors);
};

############################################################
## emergencies

filter f_emerg { level(emerg); };
destination du_all { usertty("*"); };
log {
        source(s_all);
        filter(f_emerg);
        destination(du_all);
};

############################################################
## kern.log

filter f_kern { facility(kern); };
destination df_kern { file("/var/log/kern.log"); };
log {
    source(s_all);
    filter(f_kern);
    destination(df_kern);
};

############################################################
## ldap.log

filter f_ldap { program("slapd"); };
destination d_ldap { file("/var/log/ldap.log"); };
log {
        source(s_all);
        filter(f_ldap);
        destination(d_ldap);
        flags(final);
};

############################################################
## maildrop.log

filter f_maildrop { program("^maildrop"); };
destination d_maildrop { file("/var/log/maildrop.log"); };
log {
        source(s_all);
        filter(f_maildrop);
        destination(d_maildrop);
        flags(final);
};

############################################################
## mail.log

filter f_mail { facility(mail) and not facility(local1) and not program("^postfix/"); };
destination df_mail { file("/var/log/mail.log"); };

log {
    source(s_all);
    filter(f_mail);
    destination(df_mail);
};

############################################################
## messages.log

filter f_messages {
        level(debug,info,notice)
        and not facility(auth,authpriv,daemon,mail,user,kern,local1);
};
destination df_messages { file("/var/log/messages.log"); };
log {
    source(s_all);
    filter(f_messages);
    destination(df_messages);
};

############################################################
## perdition.log

filter f_perdition { program("perdition"); };
destination d_perdition { file("/var/log/perdition.log"); };
log {
        source(s_all);
        filter(f_perdition);
        destination(d_perdition);
        flags(final);
};

############################################################
## postfix.log

filter f_postfix { program("^postfix/"); };
# We increase the flush lines/timeout since postfix writes so much
destination d_postfix { file("/var/log/postfix.log" flush_lines(500) flush_timeout(60000)); };
log {
        source(s_all);
        filter(f_postfix);
        rewrite(r_ip);
        destination(d_postfix);
        flags(final);
};

############################################################
## rails logging

filter f_rails { program("rails"); };
destination d_rails { file("/var/log/rails.log"); };
log {
      source(s_all);
      filter(f_rails);
      destination(d_rails);
      flags(final);
};

############################################################
## user.log

filter f_user { facility(user) and not facility(local1); };
destination df_user { file("/var/log/user.log"); };
log {
    source(s_all);
    filter(f_user);
    destination(df_user);
};

# Some `catch-all' logfiles.
#
destination d_debug { file("/var/log/debug"); };
destination d_error { file("/var/log/error"); };
destination d_messages { file("/var/log/messages"); };

# The root's console.
#
destination d_console { usertty("root"); };

# Virtual console.
#
destination d_console_all { file("/dev/tty10"); };

0. https://bugzilla.balabit.com/show_bug.cgi?id=48

[syslog-ng] blocking on /dev/log

Micah Anderson