Double timestamps cause DB issue
Hello, Running syslog-ng version 1.5.26 on Solaris 8. All is working well, except now I want to log to a MySQL database. I can also get that to work, the problem is the double time stamp in the syslog entry. When it gets put in the database the second timestamp ends up in the program field instead of the actual program. Looking thru the archives, I can find reference to the template macros, but there only appears to be one MSG macro available. Below is a sample log line: Apr 25 11:40:36 mydevice.mydomain.com Apr 25 2003 11:13:09: %PIX-4-106023: Deny tcp src inside:111.222.333.444/1343 dst outside:555.999.777.888/80 by access-group "outbound" And my database definition from syslog-ng.conf: destination d_mysql { pipe("/tmp/mysql.pipe" template("INSERT INTO logs (host, facility, priority, level, tag, date,time, program, msg) VALUES ( '$HOST', '$FACILITY', '$PRIORITY', '$LEVEL', '$TAG','$YEAR-$MONTH-$DAY', '$HOUR:$MIN:$SEC', '$PROGRAM', '$MSG' );\n") template-escape(yes)); }; And a sample from the database: host,facility,priority,level,tag,date,time,program,msg,seq mydevice.mydomain.com,local5,warning,warning,ac,2003-04-25,10:26:14,Apr, Apr 25 2003 09:58:46: %PIX-4-106023: Deny tcp src inside:192.168.176.204/3954 dst outside:216.23.181.206/80 by access-group "outbound",1 "Apr" is put in the program field and the message plus the second timestamp is added to the msg filed. Any suggestions appreciated. Regards, Robin
On Fri, Apr 25, 2003 at 12:17:32PM -0400, Robin Brown wrote:
Hello,
Running syslog-ng version 1.5.26 on Solaris 8. All is working well, except now I want to log to a MySQL database. I can also get that to work, the problem is the double time stamp in the syslog entry. When it gets put in the database the second timestamp ends up in the program field instead of the actual program.
Looking thru the archives, I can find reference to the template macros, but there only appears to be one MSG macro available. Below is a sample log line:
Apr 25 11:40:36 mydevice.mydomain.com Apr 25 2003 11:13:09: %PIX-4-106023: Deny tcp src inside:111.222.333.444/1343 dst outside:555.999.777.888/80 by access-group "outbound"
And my database definition from syslog-ng.conf:
destination d_mysql { pipe("/tmp/mysql.pipe" template("INSERT INTO logs (host, facility, priority, level, tag, date,time, program, msg) VALUES ( '$HOST', '$FACILITY', '$PRIORITY', '$LEVEL', '$TAG','$YEAR-$MONTH-$DAY', '$HOUR:$MIN:$SEC', '$PROGRAM', '$MSG' );\n") template-escape(yes)); };
And a sample from the database:
host,facility,priority,level,tag,date,time,program,msg,seq mydevice.mydomain.com,local5,warning,warning,ac,2003-04-25,10:26:14,Apr, Apr 25 2003 09:58:46: %PIX-4-106023: Deny tcp src inside:192.168.176.204/3954 dst outside:216.23.181.206/80 by access-group "outbound",1
"Apr" is put in the program field and the message plus the second timestamp is added to the msg filed.
you can play with check_hostname and bad_hostname options, what does syslog-ng receive in the UDP packet? -- Bazsi PGP info: KeyID 9AF8D0A9 Fingerprint CD27 CFB0 802C 0944 9CFD 804E C82C 8EB1
UDP is: SYSLOG: ----- SYSLOG: ----- SYSLOG: SYSLOG: "<172>Apr 25 2003 14:06:02: %PIX-4-106023: Deny tcp src insid" SYSLOG: Thanks, Robin -----Original Message----- From: syslog-ng-admin@lists.balabit.hu [mailto:syslog-ng-admin@lists.balabit.hu] On Behalf Of Balazs Scheidler Sent: Friday, April 25, 2003 2:17 PM To: syslog-ng@lists.balabit.hu Subject: Re: [syslog-ng]Double timestamps cause DB issue On Fri, Apr 25, 2003 at 12:17:32PM -0400, Robin Brown wrote:
Hello,
Running syslog-ng version 1.5.26 on Solaris 8. All is working well, except now I want to log to a MySQL database. I can also get that to work, the problem is the double time stamp in the syslog entry. When it gets put in the database the second timestamp ends up in the program field instead of the actual program.
Looking thru the archives, I can find reference to the template macros, but there only appears to be one MSG macro available. Below is a sample log line:
Apr 25 11:40:36 mydevice.mydomain.com Apr 25 2003 11:13:09: %PIX-4-106023: Deny tcp src inside:111.222.333.444/1343 dst outside:555.999.777.888/80 by access-group "outbound"
And my database definition from syslog-ng.conf:
destination d_mysql { pipe("/tmp/mysql.pipe" template("INSERT INTO logs (host, facility, priority, level, tag, date,time, program, msg) VALUES ( '$HOST', '$FACILITY', '$PRIORITY', '$LEVEL', '$TAG','$YEAR-$MONTH-$DAY', '$HOUR:$MIN:$SEC', '$PROGRAM', '$MSG' );\n") template-escape(yes)); };
And a sample from the database:
host,facility,priority,level,tag,date,time,program,msg,seq
mydevice.mydomain.com,local5,warning,warning,ac,2003-04-25,10:26:14,Apr,
Apr 25 2003 09:58:46: %PIX-4-106023: Deny tcp src inside:192.168.176.204/3954 dst outside:216.23.181.206/80 by access-group "outbound",1
"Apr" is put in the program field and the message plus the second timestamp is added to the msg filed.
you can play with check_hostname and bad_hostname options, what does syslog-ng receive in the UDP packet? -- Bazsi PGP info: KeyID 9AF8D0A9 Fingerprint CD27 CFB0 802C 0944 9CFD 804E C82C 8EB1 _______________________________________________ syslog-ng maillist - syslog-ng@lists.balabit.hu https://lists.balabit.hu/mailman/listinfo/syslog-ng Frequently asked questions at http://www.campin.net/syslog-ng/faq.html
On Fri, Apr 25, 2003 at 02:44:45PM -0400, Robin Brown wrote:
UDP is:
SYSLOG: ----- SYSLOG: ----- SYSLOG: SYSLOG: "<172>Apr 25 2003 14:06:02: %PIX-4-106023: Deny tcp src insid" SYSLOG:
as it seems the problem is caused by the bad date stamp. I might add support for this stamp if you are willing to test it. -- Bazsi PGP info: KeyID 9AF8D0A9 Fingerprint CD27 CFB0 802C 0944 9CFD 804E C82C 8EB1
Yes, of course I will test it. Thanks again, Robin -----Original Message----- From: syslog-ng-admin@lists.balabit.hu [mailto:syslog-ng-admin@lists.balabit.hu] On Behalf Of Balazs Scheidler Sent: Friday, April 25, 2003 3:06 PM To: syslog-ng@lists.balabit.hu Subject: Re: [syslog-ng]Double timestamps cause DB issue On Fri, Apr 25, 2003 at 02:44:45PM -0400, Robin Brown wrote:
UDP is:
SYSLOG: ----- SYSLOG: ----- SYSLOG: SYSLOG: "<172>Apr 25 2003 14:06:02: %PIX-4-106023: Deny tcp src insid" SYSLOG:
as it seems the problem is caused by the bad date stamp. I might add support for this stamp if you are willing to test it. -- Bazsi PGP info: KeyID 9AF8D0A9 Fingerprint CD27 CFB0 802C 0944 9CFD 804E C82C 8EB1 _______________________________________________ syslog-ng maillist - syslog-ng@lists.balabit.hu https://lists.balabit.hu/mailman/listinfo/syslog-ng Frequently asked questions at http://www.campin.net/syslog-ng/faq.html
On Fri, Apr 25, 2003 at 03:21:55PM -0400, Robin Brown wrote:
Yes, of course I will test it.
against 1.6.0rc3: Index: log.c =================================================================== RCS file: /var/cvs/syslog-ng/syslog-ng/src/log.c,v retrieving revision 1.29 diff -u -r1.29 log.c --- log.c 8 Jan 2003 09:31:37 -0000 1.29 +++ log.c 26 Apr 2003 07:42:27 -0000 @@ -86,11 +86,27 @@ /* If the next chars look like a date, then read them as a date. */ if (left >= 15) { - /* Expected buffer format: MMM DD HH:MM:SS ... */ + struct tm tm, *nowtm; - if (src[3] == ' ' && src[6] == ' ' && - src[9] == ':' && src[12] == ':') { - struct tm tm, *nowtm; + if (left >= 21 && + src[3] == ' ' && src[6] == ' ' && src[11] == ' ' && + src[14] == ':' && src[17] == ':' && src[20] ==':') { + /* PIX time stamp, format: MMM DD YYYY HH:MM:SS: */ + + src[20] = 0; + memset(&tm, 0, sizeof(tm)); + strptime(src, "%b %e %Y %H:%M:%S", &tm); + tm.tm_isdst = -1; + lm->date = ol_string_alloc(16); + strftime(lm->date->data, 16, "%b %e %H:%M:%S", &tm); + src[20] = ':'; + src += 21; + left -= 21; + lm->stamp = mktime(&tm); + } + else if (src[3] == ' ' && src[6] == ' ' && + src[9] == ':' && src[12] == ':') { + /* Expected buffer format: MMM DD HH:MM:SS ... */ /* Just read the buffer data into a textual datestamp. */ -- Bazsi PGP info: KeyID 9AF8D0A9 Fingerprint CD27 CFB0 802C 0944 9CFD 804E C82C 8EB1
On Fri, Apr 25, 2003 at 09:06:25PM +0200, Balazs Scheidler wrote:
SYSLOG: SYSLOG: "<172>Apr 25 2003 14:06:02: %PIX-4-106023: Deny tcp src insid" SYSLOG:
as it seems the problem is caused by the bad date stamp. I might add support for this stamp if you are willing to test it.
Is it really needed? This "issue" is caused by Cisco routers. It is optional to configure them to timestamp each syslog transmission themselves - instead of relying on the Syslog server to do it - as all other syslog clients I've ever come across do. Personally, I think this Cisco "feature" sucks ;-) I trust the clock on the Syslog server - I don't trust the clock on some remote router... I'd suggest that Robin fix up the Ciscos rather than "fix" syslog-ng when it isn't broken... If it is needed, at least make it optional so that you can choose to: a) ignore it (old behaviour) b) allow timestamp to override Syslog server timestamp (why would you ever want this?) c) skip the timestamp - so that the syslog record looks like the Cisco was correctly configured ;-) -- Cheers Jason Haar Information Security Manager, Trimble Navigation Ltd. Phone: +64 3 9635 377 Fax: +64 3 9635 417 PGP Fingerprint: 7A2E 0407 C9A6 CAF6 2B9F 8422 C063 5EBB FE1D 66D1
On Sat, Apr 26, 2003 at 11:20:36PM +1200, Jason Haar wrote:
On Fri, Apr 25, 2003 at 09:06:25PM +0200, Balazs Scheidler wrote:
SYSLOG: SYSLOG: "<172>Apr 25 2003 14:06:02: %PIX-4-106023: Deny tcp src insid" SYSLOG:
as it seems the problem is caused by the bad date stamp. I might add support for this stamp if you are willing to test it.
Is it really needed? This "issue" is caused by Cisco routers. It is optional to configure them to timestamp each syslog transmission themselves - instead of relying on the Syslog server to do it - as all other syslog clients I've ever come across do.
Personally, I think this Cisco "feature" sucks ;-) I trust the clock on the Syslog server - I don't trust the clock on some remote router...
I'd suggest that Robin fix up the Ciscos rather than "fix" syslog-ng when it isn't broken...
If it is needed, at least make it optional so that you can choose to:
a) ignore it (old behaviour) b) allow timestamp to override Syslog server timestamp (why would you ever want this?) c) skip the timestamp - so that the syslog record looks like the Cisco was correctly configured ;-)
it is already possible to override the sender's timestamp by using the use_time_recvd() global option (which affects macro expansion), or one of the time macros prefixed by 'S_' e.g. destination router_logs { file("/var/log/messages" template("$DATE $HOST $MSG\n"); }; outputs the timestamp as received from the sender when use_time_recvd = no, and the server's timestamp when use_time_recvd = yes. But you can refer to these properties of the messages directly by either using the R_DATE or the S_DATE macros. The possibility to recognize sent timestamps (while allowing to override it) is good IMHO. -- Bazsi PGP info: KeyID 9AF8D0A9 Fingerprint CD27 CFB0 802C 0944 9CFD 804E C82C 8EB1
participants (3)
-
Balazs Scheidler
-
Jason Haar
-
Robin Brown