[syslog-ng] 3.2.5 and Multiline(?) messages from Solaris

[Ray Van Dolson]

The lines are from the sniffer (I used the "copy text summary" function
in Wireshark for the relevant packets).

Will have to see if there's a more verbose view that isn't hex. :)

On Tue, May 12, 2015 at 09:18:22PM +0200, Scheidler, Balázs wrote:
> Hmm what was the sniffer that printed these lines? I would prefer to see what
> was in the wire exactly as these seem to have been processed somewhat.
> 
> On May 12, 2015 5:02 PM, "Ray Van Dolson" <rvandolson at esri.com> wrote:
> 
>     On Tue, May 12, 2015 at 08:49:20AM +0200, Scheidler, Balázs wrote:
>     > The most important thing with multiline is the transport.
>     >
>     > Udp can transmit multiline messages just as syslog(transport(tcp))
>     > but of course the client has to support the same protocol.
>     >
>     > What do you use on the solaris side?
> 
>     Using the default syslog daemon in Solaris 10 (uses UDP).
> 
>     >
>     > If you haven't changed the client I don't see why the message would
>     > be truncated like that. Once received syslog-ng would only replace
>     > newlines with spaces.
>     >
>     > So I guess it is a transport issue on the sending side. But
>     > tcpdump/wireshark should help a lot here.
> 
>     Packet capture results leave me scratching my head a bit:
> 
>     714 2015-05-12 03:41:06.172567 10.49.6.166 10.49.7.16  Syslog  150
>     KERN.WARNING: May 12 03:41:06 scsi: [ID 243001 kern.warning] WARNING: /
>     pci at 0,0/pci8086,3410 at 9/pci15d9,400 at 0 (mpt_sas0):
>     715 2015-05-12 03:41:06.172575 10.49.6.166 10.49.7.16  Syslog  127
>     KERN.WARNING: May 12 03:41:06 \tmptsas_handle_event_sync: IOCStatus=0x8000,
>     IOCLogInfo=0x31110610
> 
>     718 2015-05-12 03:41:10.172475  10.49.6.166 10.49.7.16  Syslog  138
>     KERN.INFO: May 12 03:41:10 scsi: [ID 365881 kern.info] /pci at 0,0/
>     pci8086,3410 at 9/pci15d9,400 at 0 (mpt_sas0):
>     719 2015-05-12 03:41:10.172483 10.49.6.166 10.49.7.16  Syslog  105
>     KERN.INFO: May 12 03:41:10 \tLog info 0x31110610 received for target 24.
> 
>     721 2015-05-12 03:41:10.172487 10.49.6.166 10.49.7.16  Syslog  142
>     KERN.WARNING: May 12 03:41:10 scsi: [ID 107833 kern.warning] WARNING: /
>     scsi_vhci/disk at g5000c50019bc81e1 (sd31):
>     722 2015-05-12 03:41:10.172491 10.49.6.166 10.49.7.16  Syslog  110
>     KERN.WARNING: May 12 03:41:10 \tSCSI transport failed: reason 'reset':
>     giving up
> 
>     (Sorry for the word-wrap).
> 
>     So, you can see the second line comes through as a completely separate
>     message with a tab character '\t' at the beginning.
> 
>     The odd thing?  Packets 714 & 715 come through fine and syslog-ng
>     appends them both to my output log.
> 
>     However, for pairs 718 & 719 and 721 & 722, only the first line comes
>     through.  In both cases the tab character is 0x09 so not seeing a
>     difference there.
> 
>     Makes me think it's something in the syslog-ng config rather than the
>     message.  Probably will move to something super simple to see that
>     fixes it (keeping in mind this behavior didn't occur w/ syslog-ng 2.x).
> 
>     Ray
> 
>     >
>     > On May 12, 2015 05:43, "Ray Van Dolson" <rvandolson at esri.com> wrote:
>     >
>     >     Admittedly haven't done enough searching or testing on this, but am
>     >     hoping someone might have a quick answer.
>     >
>     >     Recently moved from the 2.x verions to 3.2.5 (as part of EPEL on
>     >     RHEL6).  Have noticed that we're no longer getting the full messages
>     >     from some Solaris boxen using the tcp() and udp() source definitions.
>     >
>     >     Messages like this:
>     >
>     >     May 10 02:29:30 dev-zfs2 scsi: [ID 365881 kern.info] /pci at 0,0/
>     >     pci8086,3410 at 9/pci15d9,400 at 0 (mpt_sas0):
>     >     May 10 02:29:30 dev-zfs2        Log info 0x31080000 received for
>     target 24.
>     >     May 10 02:29:30 dev-zfs2        scsi_status=0x0, ioc_status=0x804b,
>     >     scsi_state=0x0
>     >
>     >     Come through looking like this:
>     >
>     >     May 10 02:29:30 dev-zfs2 scsi: [ID 365881 kern.info] /pci at 0,0/
>     >     pci8086,3410 at 9/pci15d9,400 at 0 (mpt_sas0):
>     >
>     >     (Only the initial line)
>     >
>     >     However, messages like this one:
>     >
>     >     May  9 04:12:57 dev-zfs2 scsi: [ID 243001 kern.warning] WARNING: /
>     pci at 0,0/
>     >     pci8086,3410 at 9/pci15d9,400 at 0 (mpt_sas0):
>     >     May  9 04:12:57 dev-zfs2        mptsas_handle_event_sync: IOCStatus=
>     0x8000,
>     >     IOCLogInfo=0x31110610
>     >
>     >     .. do seem to be coming through "whole" (I do note that the priority
>     >     is different in both).
>     >
>     >     Relevant config items are as follows:
>     >
>     >     log {
>     >         source(remote);
>     >         filter(syslog);
>     >         destination(hosts_syslog);
>     >     };
>     >
>     >     source remote {
>     >         udp();
>     >         tcp();
>     >         # udp(ip(0.0.0.0) port(514));
>     >         # tcp(ip(0.0.0.0) port(514));
>     >     };
>     >
>     >     destination hosts_syslog {
>     >         file("/logs/hosts/$HOST/$YEAR/$MONTH/
>     syslog.$HOST.$YEAR.$MONTH.log"
>     >             create_dirs(yes));
>     >         pipe("/logs/hosts/everything.fifo");
>     >     };
>     >
>     >     filter syslog {
>     >         (not facility(mail)
>     >         and not filter(f_ucgw)
>     >         and not filter(f_esx));
>     >     };
>     >
>     >     Will try and do some packet captures to confirm Solaris is, in fact,
>     >     sending the entire message (I believe it is since this worked on
>     >     syslog-ng 2.x).
>     >
>     >     Thanks,
>     >     Ray