Your explanation of what designates octet-counting definitely clears up why
the octet framing issue is occurring.
Removing the octet-counting check in imptcp allows me to log the call
records but obviously isn't the correct way of doing things. Is there a
secret rsyslog config parameter like "$bMessagesStartWithNumber" I could
specify for a port that only the phone system talks to? Would such a
configuration parameter be a useful option for any other dump devices that
insist on sending messages starting with a number?
--- plugins/imptcp/imptcp.c 2011-08-31 05:13:51.000000000 -0500
+++ plugins/imptcp/imptcp.c.new 2011-09-07 14:05:11.000000000 -0500
@@ -541,7 +541,7 @@
DEFiRet;
if(pThis->inputState == eAtStrtFram) {
- if(isdigit((int) c)) {
+ if(!cs.bMessagesStartWithNumber && isdigit((int) c)) {
pThis->inputState = eInOctetCnt;
pThis->iOctetsRemain = 0;
pThis->eFraming = TCP_FRAMING_OCTET_COUNTING;
Might it be possible to add such a configuration option for those of us
unlucky enough to own such a device?
On Wed, Sep 7, 2011 at 1:01 PM, Rainer Gerhards <[email protected]>wrote:
> From phone:
>
> If the message starts with a number, it uses octet counting framing and the
> number is the number of octets in the frame. Now look at your failing
> messages ;-)
>
> Rainer
> Mark Reidenbach <[email protected]> hat geschrieben:I won't
> argue that the phone system may have issues with octect-counted
> framing, but the same symptom occurs when using telnet. If telnet is a
> valid test then the actual message text seems to be causing an issue. The
> debug log from the test is available here:
> http://www.everytruckjob.com/rsyslog.log
>
> My telnet test sent the following lines:
> Sep 6 15:36:19 server avaya: 2011/09/06
>
> 14:53:04,00:00:07,0,107,O,92422131,92422131,,0,1000191,0,E107,mark,T9001,Line
> 1.22,0,0,,,,,,,,,,,U,mark,
> Sep 6 15:36:19 server avaya: 2011/09/06
>
> 14:53:04,00:00:07,0,107,O,92422131,92422131,,0,1000191,0,E107,mark,T9001,Line
> 1.22,0,0,,,,,,,,,,,U,mark,
> Sep 6 15:36:19 server avaya: 2011/09/06
>
> 14:53:04,00:00:07,0,107,O,92422131,92422131,,0,1000191,0,E107,mark,T9001,Line
> 1.22,0,0,,,,,,,,,,,U,mark,
> Sep 6 15:36:19 server avaya: 2011/09/06
>
> 14:53:04,00:00:07,0,107,O,92422131,92422131,,0,1000191,0,E107,mark,T9001,Line
> 1.22,0,0,,,,,,,,,,,U,mark,
> Sep 6 15:36:19 server avaya: 2011/09/06
>
> 14:53:04,00:00:07,0,107,O,92422131,92422131,,0,1000191,0,E107,mark,T9001,Line
> 1.22,0,0,,,,,,,,,,,U,mark,
> 2011/09/06
>
> 14:53:04,00:00:07,0,107,O,92422131,92422131,,0,1000191,0,E107,mark,T9001,Line
> 1.22,0,0,,,,,,,,,,,U,mark,
> 2011/09/06
>
> 14:53:04,00:00:07,0,107,O,92422131,92422131,,0,1000191,0,E107,mark,T9001,Line
> 1.22,0,0,,,,,,,,,,,U,mark,
> 2011/09/06
>
> 14:53:04,00:00:07,0,107,O,92422131,92422131,,0,1000191,0,E107,mark,T9001,Line
> 1.22,0,0,,,,,,,,,,,U,mark,
> 2011/09/06
>
> 14:53:04,00:00:07,0,107,O,92422131,92422131,,0,1000191,0,E107,mark,T9001,Line
> 1.22,0,0,,,,,,,,,,,U,mark,
> 2011/09/06
>
> 14:53:04,00:00:07,0,107,O,92422131,92422131,,0,1000191,0,E107,mark,T9001,Line
> 1.22,0,0,,,,,,,,,,,U,mark,
>
> The first 5 lines are logged ok, but the 6th line causes the octet-counter
> framing error:
> 3309.688933361:7ffe54db5700: TCP Message with octet-counter, size
> 2011.
> 3309.688958730:7ffe54db5700: Called LogError, msg: Framing Error in
> received
> TCP message: delimiter is not SP but has ASCII value 47.
>
> The last 4 lines result in only:
> 3310.828859835:7ffe54db5700: poll returned with i 0, pUsr 0x7ffe4c002190
> 3310.828889679:7ffe54db5700: netstream 0x7ffe4c0020c0 with new data
> 3311.738870777:7ffe54db5700: poll returned with i 0, pUsr 0x7ffe4c002190
> 3311.738906355:7ffe54db5700: netstream 0x7ffe4c0020c0 with new data
> 3312.608796839:7ffe54db5700: poll returned with i 0, pUsr 0x7ffe4c002190
> 3312.608825078:7ffe54db5700: netstream 0x7ffe4c0020c0 with new data
> 3314.018822814:7ffe54db5700: poll returned with i 0, pUsr 0x7ffe4c002190
> 3314.018867595:7ffe54db5700: netstream 0x7ffe4c0020c0 with new data
>
>
> The log file contains the following after the test (first 5 lines sent via
> telnet only):
> Sep 7 11:34:59 192.168.13.151 Sep 6 15:36:19 server avaya: 2011/09/06
>
> 14:53:04,00:00:07,0,107,O,92422131,92422131,,0,1000191,0,E107,mark,T9001,Line
> 1.22,0,0,,,,,,,,,,,U,mark,#015
> Sep 7 11:35:00 192.168.13.151 Sep 6 15:36:19 server avaya: 2011/09/06
>
> 14:53:04,00:00:07,0,107,O,92422131,92422131,,0,1000191,0,E107,mark,T9001,Line
> 1.22,0,0,,,,,,,,,,,U,mark,#015
> Sep 7 11:35:01 192.168.13.151 Sep 6 15:36:19 server avaya: 2011/09/06
>
> 14:53:04,00:00:07,0,107,O,92422131,92422131,,0,1000191,0,E107,mark,T9001,Line
> 1.22,0,0,,,,,,,,,,,U,mark,#015
> Sep 7 11:35:02 192.168.13.151 Sep 6 15:36:19 server avaya: 2011/09/06
>
> 14:53:04,00:00:07,0,107,O,92422131,92422131,,0,1000191,0,E107,mark,T9001,Line
> 1.22,0,0,,,,,,,,,,,U,mark,#015
> Sep 7 11:35:03 192.168.13.151 Sep 6 15:36:19 server avaya: 2011/09/06
>
> 14:53:04,00:00:07,0,107,O,92422131,92422131,,0,1000191,0,E107,mark,T9001,Line
> 1.22,0,0,,,,,,,,,,,U,mark,#015
>
>
>
> On Wed, Sep 7, 2011 at 2:56 AM, Rainer Gerhards <[email protected]
> >wrote:
>
> > > -----Original Message-----
> > > From: [email protected] [mailto:rsyslog-
> > > [email protected]] On Behalf Of [email protected]
> > > Sent: Wednesday, September 07, 2011 8:44 AM
> > > To: rsyslog-users
> > > Subject: Re: [rsyslog] Log avaya ip office phone system - how to
> > > prepend a tcp message
> > >
> > > On Tue, 6 Sep 2011, Mark Reidenbach wrote:
> > >
> > > > I have an avaya phone system that logs call records via tcp, but the
> > > format
> > > > of the message does not include a timestampm hostname or tag. It
> > > sends a
> > > > line of csv data like the following line (the lines end in a CR/LF
> > > according
> > > > to tcpdump):
> > > > 2011/09/06
> > > >
> > > 16:01:34,00:00:08,2,918176574009,I,550,2477,,0,1000237,0,E101,connie,T9
> > > 001,Line
> > > > 1.1,0,0,,,,,,,,,,,,,mark,
> > > >
> > > > This causes debug messages like:
> > > > 2903.519225673:7f6457fff700: TCP Message with octet-counter, size
> > > 2011.
> > > > 2903.519236548:7f6457fff700: Called LogError, msg: Framing Error in
> > > received
> > > > TCP message: delimiter is not SP but has ASCII value 47.
> > > >
> > > > Using telnet to send the same data causes the same error, but if the
> > > data is
> > > > sent prefixed with "Sep 6 15:36:19 server avaya: " the message is
> > > logged as
> > > > hoped:
> > > > Sep 6 15:36:19 server avaya: 2011/09/06
> > > >
> > > 14:53:04,00:00:07,0,107,O,92422131,92422131,,0,1000191,0,E107,mark,T900
> > > 1,Line
> > > > 1.22,0,0,,,,,,,,,,,U,mark,
> > > >
> > > > I had hoped to use a template to add the generated timestamp, host
> > > and tag,
> > > > but it seems like the message is discarded in the input phase before
> > > using a
> > > > template to add the missing info is possible.
> > > >
> > > > Is it possible to prefix tcp messages without writing a custom input
> > > module
> > > > in C?
> > >
> > > I think this needs the custom parser module (much simpler than a custom
> > > imput module), but still a bit of C programming
> >
> > The main problem is that the message looks like it uses TCP
> octect-counted
> > framing, but does not do so. This would require at least changes the the
> > tcp
> > input, or a new input. A parser can not handle that part of the problem,
> as
> > it is not just a malformed message, but also a protocol violation.
> >
> > > so is that two lines, or three (line wrapping makes it hard to tell)
> >
> > If it is multiple lines, that would be even more complicated and requie a
> > dedicated input in any case.
> >
> > Rainer
> > >
> > > David Lang
> > >
> > > _______________________________________________
> > > 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
> >
> _______________________________________________
> 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
>
_______________________________________________
rsyslog mailing list
http://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com
