[Home]

Summary:ASTERISK-10432: [patch] Logging goes to wrong destination
Reporter:non-poster (non-poster)Labels:
Date Opened:2007-10-02 14:18:22Date Closed:2011-06-07 14:08:05
Priority:MinorRegression?No
Status:Closed/CompleteComponents:General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) 20071002__issue10871.diff.txt
Description:Some log messages show up in /var/log/messages on my machine.

Code:
# grep -v ^\; /etc/asterisk/logger.conf

[general]
[logfiles]
syslog.local0 => notice,warning,error,verbose,debug


/etc/syslog-ng/syslog-ng.conf:

filter f_asterisk { program(asterisk); };
destination asterisk { file("/var/log/asterisk/messages"); };
log { source(src); filter(f_asterisk); destination(asterisk); };

destination messages { file("/var/log/messages"); };
filter f_messages { not facility(auth,authpriv,kern,mail,daemon) and
                                       ...
                                       not program(asterisk) and
                                       ...
                                       ;
                                       };
log { source(src); filter(f_messages); destination(messages); };


The messages:

Oct  1 18:39:04 myhostname unparseable log message: "<--- Transmitting (NAT) to 192.168.49.99:55954 --- >"
Oct  1 18:39:04 myhostname SIP/2.0 401 Unauthorized
Oct  1 18:39:04 myhostname Via: SIP/2.0/UDP 192.168.49.99:55954;branch=z9hG4bK-d87543-71067059a5075507-1--d87543-;received=192.168.49.99;rport=55954
Oct  1 18:39:04 myhostname From: "myhostname"<sip:6100@myhostname.com>;tag=407c2746
Oct  1 18:39:04 myhostname To: "myhostname"<sip:6100@myhostname.com>;tag=as7a8d5495
Oct  1 18:39:04 myhostname Call-ID: MzQ0ZmE5Nzg5MjI0ZWQxYjJkNGFiZjFhYzk1YWI0OGQ.  CSeq: 3 REGISTER  User-Agent: Asterisk PBX  Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY  Supported: replaces  WWW-Authenticate: Digest algorithm=MD5, realm="myhostname.com", nonce="24e57166"  Content-Length: 0     <------------>
Oct  1 18:53:46 myhostname HTTP/1.1 404 Not Found  Content-Type: text/html  Content-Length: 345  Date: Tue, 02 Oct 2007 01:53:46 GMT  Server: lighttpd/1.4.18
Oct  1 19:27:35 myhostname unparseable log message: "<--- Transmitting (NAT) to 192.168.48.100:5060 --- >"
Oct  1 19:27:35 myhostname SIP/2.0 100 Trying
Oct  1 19:27:35 myhostname Via: SIP/2.0/UDP myhostname.com;branch=z9hG4bKpqqzyktg;received=192.168.48.100;rport=5060  From: "non-poster" <sip:nonposter@myhostname.com>;tag=sgmhb  To: <sip:18003733411@myhostname.com>  Call-ID: totikozjpilfjfs@myhostname.com  CSeq: 100 INVITE  User-Agent: Asterisk PBX  Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY  Supported: replaces  Contact: <sip:18003733411@192.168.48.1>  Content-Length: 0     <------------>



The "unparseable log message" comes from syslog-ng.



Asterisk 1.4.11, gcc 4.1.2, glibc 2.5, amd64
Comments:By: Jason Parker (jparker) 2007-10-02 14:35:08

I don't get it.  You're telling asterisk to log everything to syslog.  How is this an Asterisk problem?
By: non-poster (non-poster) 2007-10-02 14:55:50

Yes, asterisk should (and does) send everything to syslog.  However, my syslog rule should send everything that asterisk logs to /var/log/asterisk/messages, and most log entries do, except this one still goes to /var/log/messages, and syslog notes that it is unparseable.  None of the other services on my system have ever caused syslog to log an "unparseable" message.
By: Tilghman Lesher (tilghman) 2007-10-02 15:41:48

It relates entirely to Asterisk using the '<' character in the log message, which syslog-ng seems to think is a meta character.  There isn't anything we really can do about this.  It seems like a deficiency in syslog-ng itself, though none of the FAQs for that project even acknowledge that it's a problem.

In any case, this works fine if you use the traditional syslog daemon, and I encourage you to make the transition.
By: non-poster (non-poster) 2007-10-02 15:47:07

# grep \< /var/log/asterisk/messages|wc -l
1132


Other asterisk log entries contain "<", so apparently it is possible to use this character correctly in a message to be logged.


Note that I will not be switching away from syslog-ng.
By: Tilghman Lesher (tilghman) 2007-10-02 15:50:24

non-poster:  if you can figure out what exactly syslog-ng does not like, I'm all ears.  However, Google has a ton of examples of this error with no resolution.
By: Tilghman Lesher (tilghman) 2007-10-02 18:10:41

Okay, figured out what syslog-ng doesn't like.  It thinks that it should parse the initial '<', as if it were a numeric priority.  So I've added a new option to logger.conf for the [general] section, which says "syslog_ng => true" if you want the alternate logging, which simply logs an '_' as the first character of the log message.  That will stop syslog-ng from puking.
By: non-poster (non-poster) 2007-10-02 18:16:47

Why add the complexity?  Just change the bad log statements to have a space or '_' at the beginning.
By: non-poster (non-poster) 2007-10-02 18:23:25

Example commands to find such log statements:
find|xargs egrep -e ast_\(verbose\|debug\|log\).*\"\<
find|xargs egrep -e ast_\(verbose\|debug\|log\).*\"\\\\n\<
By: Tilghman Lesher (tilghman) 2007-10-02 18:46:43

It's not that simple.  The messages arrive as a format and a list of arguments and by the time I know what the first character is, it's already too late to insert the '_'.  So it's arguably better (and faster) to always insert the extra character when using syslog-ng.
By: non-poster (non-poster) 2007-10-02 19:50:53

I don't understand.  I thought code in Asterisk was the source of these bad log statements, eg the ast_log() or ast_verbose() or ast_debug() statements generate the message to be logged.  I would expect that we could just change that code.  Why isn't that simple?  (I haven't done any development on this code, so I don't understand it's complexities, etc.)
By: Tilghman Lesher (tilghman) 2007-10-03 17:58:38

I am not going to change the rest of Asterisk because of a bug in syslog-ng, especially as it is far from the only syslogger out there.  The traditional syslog daemon works fine; this is a hack to get around the syslog-ng bug.
By: non-poster (non-poster) 2007-10-03 18:54:08

The rest of Asterisk?  A dozen (or less) log statements?

Why "hack" the logging to accommodate this bug in syslog-ng?  This is a poor way to work around (not even fix) the problem.

Can I submit a patch to fix the logging statements to keep this "hack" from adding an unnecessary configuration option and the related code?
By: Tilghman Lesher (tilghman) 2007-10-03 22:05:01

Quite right.  Ask the syslog-ng project to fix the bug, please.
By: non-poster (non-poster) 2007-10-10 21:46:50

It looks like version 2.0.5 of syslog-ng does not exhibit this problem.  (Problem reported when using 1.6.11)