Mailing List Archive

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.

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).

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

_______________________________________________
rsyslog mailing list
http://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com

On Mon, 2009-01-19 at 22:21 +0800, Patrick Shen wrote:
> >> 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?

Actually, I should have read your mail more careful. You already use
rawmsg, which is the second best thing after the packet capture. But in
this case, you'll see exactly the same thing (if you don't trust me, use
WireShark, an excellent open source capture app).

Look at this:

rawmsg: '<171> at
net.netm.me.coim.GenericImportWorker.run(GenericImportWorker.java:47)'

Compare that the the header that is describe in RFC 3164 and you will
see that there is nothing close to a real header inside that message. As
the message is malformed, funny things can happen. In other words,
results are unpredictable, and this is what you are seeing.

>
> 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?

that's probably the case with current code, but I don't guarantee that
will stay. Again: invalid format => unpredictable results on all header
fields
>
>
> > 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'
> ######################################################################################
>
that's a correctly formatted message

> 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?

To get the name, you indeed need to enable remote lookups. One solution
would be to permit different settings for different remote hosts, but
that would be a feature request. Would make sense, but I am currently
rather busy. If you add it to the bugzilla http://bugzilla.adiscon.com
I'll see that I implement it when nothing of higher priority is in front
of it.

Rainer
>
> > 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

_______________________________________________
rsyslog mailing list
http://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com

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

On Tue, 2009-01-20 at 11:05 +0800, Patrick Shen wrote:
> >> 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?
> >
> > that's probably the case with current code, but I don't guarantee that
> > will stay. Again: invalid format => unpredictable results on all header
> > fields
>
> OK, now I see the malformed format messages will cause unpredictable results in rsyslog.
> That's quite helpful.
>
> >>
> >> 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'
> >> ######################################################################################
> >>
> > that's a correctly formatted message
> >
> >> 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?
> >
> > To get the name, you indeed need to enable remote lookups. One solution
> > would be to permit different settings for different remote hosts, but
> > that would be a feature request. Would make sense, but I am currently
> > rather busy. If you add it to the bugzilla http://bugzilla.adiscon.com
> > I'll see that I implement it when nothing of higher priority is in front
> > of it.
>
> I've filed a bugzilla report [1] for your information. Anyway, one more question, if I use rsyslog at
> the client side, will it avoid malformed/invalid format message sending out?

I have tweaked the feature request a bit so that it matches the actual
request ;)

As far as rsyslog on the client side is concerned, you need to do
nothing. If you use the default templates, it emits correctly formatted
messages.

Rainer

_______________________________________________
rsyslog mailing list
http://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com

Rainer Gerhards wrote:
> On Mon, 2009-01-19 at 22:21 +0800, Patrick Shen wrote:
>> Ah, so simple. I'm surprised. Could you please recommend which app for packet capture?
>
> Actually, I should have read your mail more careful. You already use
> rawmsg, which is the second best thing after the packet capture. But in
> this case, you'll see exactly the same thing (if you don't trust me, use
> WireShark, an excellent open source capture app).
>
> Look at this:
>
> rawmsg: '<171> at
> net.netm.me.coim.GenericImportWorker.run(GenericImportWorker.java:47)'
>
> Compare that the the header that is describe in RFC 3164 and you will
> see that there is nothing close to a real header inside that message. As
> the message is malformed, funny things can happen. In other words,
> results are unpredictable, and this is what you are seeing.
>
>> 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?
>
> that's probably the case with current code, but I don't guarantee that
> will stay. Again: invalid format => unpredictable results on all header
> fields

OK, now I see the malformed format messages will cause unpredictable results in rsyslog.
That's quite helpful.

>>
>> 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'
>> ######################################################################################
>>
> that's a correctly formatted message
>
>> 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?
>
> To get the name, you indeed need to enable remote lookups. One solution
> would be to permit different settings for different remote hosts, but
> that would be a feature request. Would make sense, but I am currently
> rather busy. If you add it to the bugzilla http://bugzilla.adiscon.com
> I'll see that I implement it when nothing of higher priority is in front
> of it.

I've filed a bugzilla report [1] for your information. Anyway, one more question, if I use rsyslog at
the client side, will it avoid malformed/invalid format message sending out?

[1]: http://bugzilla.adiscon.com/show_bug.cgi?id=116

Thanks a lot for your help,
Patrick
_______________________________________________
rsyslog mailing list
http://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com