Rainer Gerhards wrote: > On Mon, 2009-01-19 at 17:21 +0800, Patrick Shen wrote: >> Hi all, >> >> Recently I encountered a weird problem. Let me explain below: >> >> I've a client which is using traditional syslog (NOT rsyslog) app for >> storing and forwarding >> logs to loghost. >> >> Here are some "snmpd" logs for example: >> ########################################################################################## >> Jan 19 10:03:09 athos snmpd[1104]: Connection from UDP: [192.168.23.7]:34289 >> Jan 19 10:03:09 athos snmpd[1104]: Received SNMP packet(s) from UDP: >> [192.168.23.7]:34289 >> Jan 19 10:04:10 athos snmpd[1104]: Connection from UDP: [192.168.23.7]:58181 >> Jan 19 10:04:10 athos snmpd[1104]: Received SNMP packet(s) from UDP: >> [192.168.23.7]:58181 >> Jan 19 10:04:10 athos snmpd[1104]: Connection from UDP: [192.168.23.7]:58181 >> *Jan 19 10:04:10 athos last message repeated 25 times* >> ########################################################################################## >> >> Please take into account the last line. >> >> And I've a loghost host for receiving by using rsyslog v3.20.2 and used >> following dynamic templates to >> store logs >> ########################################################################################## >> $template >> d_hosts,"/var/rsyslog/HOSTS/%hostname%/%$year%/%$month%/%syslogfacility-text%_%hostname%_%$year%_%$month%_%$day%.log" >> ########################################################################################## >> >> and also opened debug template by following >> configures in rsyslog.conf. >> ########################################################################################## >> $template DEBUG,"Debug line with all properties:\nFROMHOST: '%FROMHOST%', >> HOSTNAME: '%HOSTNAME%', PRI: %PRI%,\nsyslogtag '%syslogtag%', programname: >> '%programname%', APP-NAME: '%APP-NAME%', PROCID: >> '%PROCID%', MSGID: '%MSGID%', FACILITY-TEXT: >> '%syslogfacility-text%'\nTIMESTAMP: '%TIMESTAMP%', STRUCTURED-DATA: >> '%STRUCTURED-DATA%',\nmsg: '%msg%'\nrawmsg: '%rawmsg%'\n\n" >> *.* -/var/rsyslog/debug;DEBUG # or whatever file you like >> ########################################################################################## >> >> I'm monitoring on the server-side now, and checking the last line by raw >> message. >> ########################################################################################## >> Debug line with all properties: >> FROMHOST: 'athos', HOSTNAME: '*last*', PRI: 30, >> syslogtag 'message', programname: 'message', APP-NAME: 'message', PROCID: >> '-', MSGID: '-', FACILITY-TEXT: 'daemon' >> TIMESTAMP: 'Jan 19 09:59:09', STRUCTURED-DATA: '-', >> msg: ' repeated 25 times' >> rawmsg: '<30>last message repeated 25 times' >> ########################################################################################## >> >> Does anyone has any idea why HOSTNAME property is 'last'? (The timestamp is >> not important, because these messages occur often). > > Yes, unfortunately ;) The reason simply is that sysklogd does emit > malformed messages with the "last message repeated..." line. If you look > at a packet capture, you'll see that they do not contain a hostname. > What you see in your sysklogd log is a hostname that is locally > appended.
Ah, so simple. I'm surprised. Could you please recommend which app for packet capture? And I'd like to share another 2 log examples. ###################################################################################### Debug line with all properties: FROMHOST: 'helios', HOSTNAME: 'helios', PRI: 171, syslogtag '', programname: '', APP-NAME: '', PROCID: '-', MSGID: '-', FACILITY-TEXT: 'local5' TIMESTAMP: 'Jan 19 10:13:13', STRUCTURED-DATA: '-', msg: ' at net.netm.me.coim.GenericImportWorker.run(GenericImportWorker.java:47)' rawmsg: '<171> at net.netm.me.coim.GenericImportWorker.run(GenericImportWorker.java:47)' ###################################################################################### You could see some *spaces* between '<171>' and 'at net ...'. And HOSTNAME propety is "helios". ###################################################################################### Debug line with all properties: FROMHOST: 'helios', HOSTNAME: 'Caused', PRI: 171, syslogtag 'by:', programname: 'by', APP-NAME: 'by', PROCID: '-', MSGID: '-', FACILITY-TEXT: 'local5' TIMESTAMP: 'Jan 19 10:13:13', STRUCTURED-DATA: '-', msg: ' java.sql.BatchUpdateException: Batch entry 0 update item set itm_orderid=3722338, itm_masterorderid=0, refOrderId= 0, itm_name1=Bach: Weihnachtsoratorium, itm_name2=New London Consort, itm_author=NULL, itm_info=/var/APP/ME-utf8/content/ import/Universal-ClassicJazz/MusicDataInProgress/2000000338428, itm_info2=[NEW][ClassicJazz] [CONTENT-OK][CONTENT-320-OK] nullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnulln ullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnu ll[CHECK-MMC][CHECK-AGAIN], itm_lang=NULL, itm_isrc=NULL, itm_grid=NULL, itm_icpn=0028948002795, volume=NULL, track=0, it m_pricegroup=1880, itm_providerid=30000, itm_orderidprovider=0, itm_pricegroupprovider=1363, itm_itemidprovider=NULL, itm _viewable=1, itm_copyrightfree=F, itm_withdrmforwardlock=T, externalinfo=NULL, authorizedAge=0, meanEvaluation=0, numEval uations=0, licenseprovider_id=2131264, importSt' rawmsg: '<171>Caused by: java.sql.BatchUpdateException: Batch entry 0 update item set itm_orderid=3722338, itm_masterorde rid=0, refOrderId=0, itm_name1=Bach: Weihnachtsoratorium, itm_name2=New London Consort, itm_author=NULL, itm_info=/var/AP P/ME-utf8/content/import/Universal-ClassicJazz/MusicDataInProgress/2000000338428, itm_info2=[NEW][ClassicJazz] [CONTENT-O K][CONTENT-320-OK]nullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnul lnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnullnull nullnullnullnullnull[CHECK-MMC][CHECK-AGAIN], itm_lang=NULL, itm_isrc=NULL, itm_grid=NULL, itm_icpn=0028948002795, volume =NULL, track=0, itm_pricegroup=1880, itm_providerid=30000, itm_orderidprovider=0, itm_pricegroupprovider=1363, itm_itemid provider=NULL, itm_viewable=1, itm_copyrightfree=F, itm_withdrmforwardlock=T, externalinfo=NULL, authorizedAge=0, meanEva luation=0, numEvaluations=0, licenseprovider_id=2131264, importSt' ###################################################################################### But in above example: Word 'Caused' is between '<171>' and 'by ...'. So the HOSTNAME is accidentally set to 'Caused'. I'm wondering if it's a coincidence that if spaces exist between <PRI> and messages in rawmsg and hostname is not provided, then HOSTNAME will be set correctly? > You can do a similar thing in rsyslog with the fromhost property - it > does not contain the hostname but rather the system that send the > message. In non-relay cases that should be the same, but in relay > scenarios you see only the last hop (thus rsyslog by default uses RFC > 3164 format). And I thought I could use 'FROMHOST' property, but I have another scenario. ###################################################################################### Debug line with all properties: FROMHOST: '172.20.101.6', HOSTNAME: 'icarus', PRI: 174, syslogtag 'httpd8330.sms:', programname: 'httpd8330.sms', APP-NAME: 'httpd8330.sms', PROCID: '-', MSGID: '-', FACILITY-TEXT: 'local5' TIMESTAMP: 'Jan 19 15:14:50', STRUCTURED-DATA: '-', msg: ' xxx.xxx.internal - - [19/Jan/2009:15:14:50 +0100] "GET /itransport/mbg/mbg/io/mbg?provider=TMOBILE_XTC_3ABO_LIVE&request-type=chargeSubscription&critialdata&originator-id=PGW_6686//S0002865748&service-type=web&payment-type=subscr&amount=299&subscription-amount=299&item-amount=299&msisdn=00491704127650&subscription-id=1662126457&subscription-type=2&reply-path=http://pgw:8330/sms/pgw/intern/ReportReception&sms-text=Dein+Abo+wurde+mit+2.99+Euro+gebucht. HTTP/1.1" 200 87#012' rawmsg: '<174>2009-01-19T15:14:50.923441+01:00 icarus httpd8330.sms: xxx.xxx.internal - - [19/Jan/2009:15:14:50 +0100] "GET /itransport/mbg/mbg/io/mbg?provider=TMOBILE_XTC_3ABO_LIVE&request-type=chargeSubscription&critialdata&originator-id=PGW_6686//S0002865748&service-type=web&payment-type=subscr&amount=299&subscription-amount=299&item-amount=299&msisdn=00491704127650&subscription-id=1662126457&subscription-type=2&reply-path=http://pgw:8330/sms/pgw/intern/ReportReception&sms-text=Dein+Abo+wurde+mit+2.99+Euro+gebucht. HTTP/1.1" 200 87#012' ###################################################################################### You could see in HOSTNAME field, it's correct set to 'icarus'. But in FROMHOST field is ip address. And I do have reverse zone for that ip in dns setting. Any ideas? > If you need the relay scenario, there is no way around putting rsyslog > on the sending systems, too (or fixing sysklogd, which I guess you need > to do yourself or it won't happen...). > > Rainer Thanks a lot for your information. Best regards, Patrick _______________________________________________ rsyslog mailing list http://lists.adiscon.net/mailman/listinfo/rsyslog http://www.rsyslog.com
