[syslog-ng] syslog-ng reset connection before data transfer

14 Feb 2023

      Hi everybody,
I hope you are well.

I was hoping if you can help me with some issue.
I am trying to collect logs from some servers via syslog.
TLS session seems to be established - handshake, certs, ciphers all looking ok.
But when data need to be send it seems syslog-ng server disconnects the session from some reason.

In /var/log/messages I can only see start/stop messages even after turning on verbose logging:

Feb 10 16:11:48 xxx syslog-ng[21262]: Syslog connection accepted; fd='175', client='AF_INET(x.y.w.z:34986)', local='AF_INET(0.0.0.0:xxx)'
Feb 10 16:11:49 xxx syslog-ng[21262]: Syslog connection closed; fd='175', client='AF_INET(x.y.w.z:34986)', local='AF_INET(0.0.0.0:xxx)'

This is the configuration I am using:

source s_xxx {
    syslog(
        ip(0.0.0.0)
        port(xxx)
        transport("tls")
        tls(
            key-file("/etc/syslog-ng/key.d/xxx.key")
            cert-file("/etc/syslog-ng/cert.d/xxx.cer")
            ca-dir("/etc/syslog-ng/ca.d")
            peer-verify(required-trusted)
            cipher-suite("xxx...xxx")
        )
        flags(store-raw-message)
    );
};

filter filter_xxx {

                host("xxx") ... or host("xxx");
};

destination folder_xxx {

                file(
                        "/var/log/xxx/${R_YEAR}${R_MONTH}${R_DAY}/${SOURCEIP}_${HOST}_${R_HOUR}.log"
                        template("${RAWMSG}\n")
                        dir-group(xxx)
                        dir-perm(0650)
                        group(xxx)
                );
};

log {
                source(s_xxx); filter(filter_xxx); destination(folder_xxx); flags(flow-control);
};

And bellow is last part of the session captured with tcpdump from source side.
It is interesting to me that there is 1h offset comparing to /var/log/messages on syslog-ng. Src and dst server are in same environment.

24    2023-02-10 15:11:49,073335    x.y.w.z     x.y.w.z     TLSv1.2     445   Application Data
Frame 24: 445 bytes on wire (3560 bits), 445 bytes captured (3560 bits)
    Encapsulation type: Ethernet (1)
    Arrival Time: Feb 10, 2023 15:11:49.073335000 Central Europe Standard Time
    [Time shift for this packet: 0.000000000 seconds]
    Epoch Time: 1676038309.073335000 seconds
    [Time delta from previous captured frame: 0.906559000 seconds]
    [Time delta from previous displayed frame: 0.906559000 seconds]
    [Time since reference or first frame: 6.775677000 seconds]
    Frame Number: 24
    Frame Length: 445 bytes (3560 bits)
    Capture Length: 445 bytes (3560 bits)
    [Frame is marked: False]
    [Frame is ignored: False]
    [Protocols in frame: eth:ethertype:ip:tcp:tls]
    [Coloring Rule Name: TCP]
    [Coloring Rule String: tcp]
Ethernet II, Src: xxx, Dst: xxx
    Destination: xxx
        Address: xxx
        .... ..0. .... .... .... .... = LG bit: Globally unique address (factory default)
        .... ...0 .... .... .... .... = IG bit: Individual address (unicast)
    Source: xxx
        Address: xxx
        .... ..0. .... .... .... .... = LG bit: Globally unique address (factory default)
        .... ...0 .... .... .... .... = IG bit: Individual address (unicast)
    Type: IPv4 (0x0800)
Internet Protocol Version 4, Src: x.y.z.w, Dst: x.y.z.w
    0100 .... = Version: 4
    .... 0101 = Header Length: 20 bytes (5)
    Differentiated Services Field: 0x00 (DSCP: CS0, ECN: Not-ECT)
        0000 00.. = Differentiated Services Codepoint: Default (0)
        .... ..00 = Explicit Congestion Notification: Not ECN-Capable Transport (0)
    Total Length: 431
    Identification: 0xeebc (61116)
    010. .... = Flags: 0x2, Don't fragment
        0... .... = Reserved bit: Not set
        .1.. .... = Don't fragment: Set
        ..0. .... = More fragments: Not set
    ...0 0000 0000 0000 = Fragment Offset: 0
    Time to Live: 64
    Protocol: TCP (6)
    Header Checksum: 0x0a89 [validation disabled]
    [Header checksum status: Unverified]
    Source Address: x.y.z.w
    Destination Address: x.y.z.w
Transmission Control Protocol, Src Port: 34986, Dst Port: xxx, Seq: 2380, Ack: 5750, Len: 391
    Source Port: 34986
    Destination Port: xxx
    [Stream index: 1]
    [Conversation completeness: Complete, WITH_DATA (63)]
    [TCP Segment Len: 391]
    Sequence Number: 2380    (relative sequence number)
    Sequence Number (raw): 2630184540
    [Next Sequence Number: 2771    (relative sequence number)]
    Acknowledgment Number: 5750    (relative ack number)
    Acknowledgment number (raw): 2509794849
    0101 .... = Header Length: 20 bytes (5)
    Flags: 0x018 (PSH, ACK)
        000. .... .... = Reserved: Not set
        ...0 .... .... = Accurate ECN: Not set
        .... 0... .... = Congestion Window Reduced: Not set
        .... .0.. .... = ECN-Echo: Not set
        .... ..0. .... = Urgent: Not set
        .... ...1 .... = Acknowledgment: Set
        .... .... 1... = Push: Set
        .... .... .0.. = Reset: Not set
        .... .... ..0. = Syn: Not set
        .... .... ...0 = Fin: Not set
        [TCP Flags: ·······AP···]
    Window: 318
    [Calculated window size: 40704]
    [Window size scaling factor: 128]
    Checksum: 0x41a5 [unverified]
    [Checksum Status: Unverified]
    Urgent Pointer: 0
    [Timestamps]
        [Time since first frame in this TCP stream: 1.007330000 seconds]
        [Time since previous frame in this TCP stream: 0.906559000 seconds]
    [SEQ/ACK analysis]
        [iRTT: 0.003010000 seconds]
        [Bytes in flight: 391]
        [Bytes sent since last PSH flag: 391]
    TCP payload (391 bytes)
Transport Layer Security
    TLSv1.2 Record Layer: Application Data Protocol: Application Data
        Content Type: Application Data (23)
        Version: TLS 1.2 (0x0303)
        Length: 386
        Encrypted Application Data: 000000000000000146f17ff0e884c81f9317ba9e01c3b48763944e3905fb27fc96ce76fc…

25    2023-02-10 15:11:49,076214    x.y.z.w     x.y.z.w     TCP   60    xxx → 34986 [FIN, ACK] Seq=5750 Ack=2771 Win=65536 Len=0
Frame 25: 60 bytes on wire (480 bits), 60 bytes captured (480 bits)
    Encapsulation type: Ethernet (1)
    Arrival Time: Feb 10, 2023 15:11:49.076214000 Central Europe Standard Time
    [Time shift for this packet: 0.000000000 seconds]
    Epoch Time: 1676038309.076214000 seconds
    [Time delta from previous captured frame: 0.002879000 seconds]
    [Time delta from previous displayed frame: 0.002879000 seconds]
    [Time since reference or first frame: 6.778556000 seconds]
    Frame Number: 25
    Frame Length: 60 bytes (480 bits)
    Capture Length: 60 bytes (480 bits)
    [Frame is marked: False]
    [Frame is ignored: False]
    [Protocols in frame: eth:ethertype:ip:tcp]
    [Coloring Rule Name: TCP SYN/FIN]
    [Coloring Rule String: tcp.flags & 0x02 || tcp.flags.fin == 1]
Ethernet II, Src: xxx, Dst: xxx
    Destination: xxx
        Address: xxx
        .... ..0. .... .... .... .... = LG bit: Globally unique address (factory default)
        .... ...0 .... .... .... .... = IG bit: Individual address (unicast)
    Source: xxx
        Address: xxx
        .... ..0. .... .... .... .... = LG bit: Globally unique address (factory default)
        .... ...0 .... .... .... .... = IG bit: Individual address (unicast)
    Type: IPv4 (0x0800)
    Trailer: 000085725dce
Internet Protocol Version 4, Src: x.y.z.w, Dst: x.y.z.w
    0100 .... = Version: 4
    .... 0101 = Header Length: 20 bytes (5)
    Differentiated Services Field: 0x00 (DSCP: CS0, ECN: Not-ECT)
        0000 00.. = Differentiated Services Codepoint: Default (0)
        .... ..00 = Explicit Congestion Notification: Not ECN-Capable Transport (0)
    Total Length: 40
    Identification: 0xea10 (59920)
    010. .... = Flags: 0x2, Don't fragment
        0... .... = Reserved bit: Not set
        .1.. .... = Don't fragment: Set
        ..0. .... = More fragments: Not set
    ...0 0000 0000 0000 = Fragment Offset: 0
    Time to Live: 52
    Protocol: TCP (6)
    Header Checksum: 0x1cbc [validation disabled]
    [Header checksum status: Unverified]
    Source Address: x.y.z.w
    Destination Address: x.y.z.w
Transmission Control Protocol, Src Port: xxx, Dst Port: 34986, Seq: 5750, Ack: 2771, Len: 0
    Source Port: xxx
    Destination Port: 34986
    [Stream index: 1]
    [Conversation completeness: Complete, WITH_DATA (63)]
    [TCP Segment Len: 0]
    Sequence Number: 5750    (relative sequence number)
    Sequence Number (raw): 2509794849
    [Next Sequence Number: 5751    (relative sequence number)]
    Acknowledgment Number: 2771    (relative ack number)
    Acknowledgment number (raw): 2630184931
    0101 .... = Header Length: 20 bytes (5)
    Flags: 0x011 (FIN, ACK)
        000. .... .... = Reserved: Not set
        ...0 .... .... = Accurate ECN: Not set
        .... 0... .... = Congestion Window Reduced: Not set
        .... .0.. .... = ECN-Echo: Not set
        .... ..0. .... = Urgent: Not set
        .... ...1 .... = Acknowledgment: Set
        .... .... 0... = Push: Not set
        .... .... .0.. = Reset: Not set
        .... .... ..0. = Syn: Not set
        .... .... ...1 = Fin: Set
        [TCP Flags: ·······A···F]
    Window: 4
    [Calculated window size: 65536]
    [Window size scaling factor: 16384]
    Checksum: 0xc512 [unverified]
    [Checksum Status: Unverified]
    Urgent Pointer: 0
    [Timestamps]
        [Time since first frame in this TCP stream: 1.010209000 seconds]
        [Time since previous frame in this TCP stream: 0.002879000 seconds]
    [SEQ/ACK analysis]
        [This is an ACK to the segment in frame: 24]
        [The RTT to ACK the segment was: 0.002879000 seconds]
        [iRTT: 0.003010000 seconds]

26    2023-02-10 15:11:49,117776    x.y.z.w     x.y.z.w     TCP   54    34986 → xxx [ACK] Seq=2771 Ack=5751 Win=40704 Len=0
Frame 26: 54 bytes on wire (432 bits), 54 bytes captured (432 bits)
    Encapsulation type: Ethernet (1)
    Arrival Time: Feb 10, 2023 15:11:49.117776000 Central Europe Standard Time
    [Time shift for this packet: 0.000000000 seconds]
    Epoch Time: 1676038309.117776000 seconds
    [Time delta from previous captured frame: 0.041562000 seconds]
    [Time delta from previous displayed frame: 0.041562000 seconds]
    [Time since reference or first frame: 6.820118000 seconds]
    Frame Number: 26
    Frame Length: 54 bytes (432 bits)
    Capture Length: 54 bytes (432 bits)
    [Frame is marked: False]
    [Frame is ignored: False]
    [Protocols in frame: eth:ethertype:ip:tcp]
    [Coloring Rule Name: TCP]
    [Coloring Rule String: tcp]
Ethernet II, Src: Mellanox_69:6f:47 (1c:34:da:69:6f:47), Dst: ICANNIAN_00:40:20 (00:00:5e:00:40:20)
    Destination: ICANNIAN_00:40:20 (00:00:5e:00:40:20)
        Address: ICANNIAN_00:40:20 (00:00:5e:00:40:20)
        .... ..0. .... .... .... .... = LG bit: Globally unique address (factory default)
        .... ...0 .... .... .... .... = IG bit: Individual address (unicast)
    Source: Mellanox_69:6f:47 (1c:34:da:69:6f:47)
        Address: Mellanox_69:6f:47 (1c:34:da:69:6f:47)
        .... ..0. .... .... .... .... = LG bit: Globally unique address (factory default)
        .... ...0 .... .... .... .... = IG bit: Individual address (unicast)
    Type: IPv4 (0x0800)
Internet Protocol Version 4, Src: x.y.z.w, Dst: x.y.z.w
    0100 .... = Version: 4
    .... 0101 = Header Length: 20 bytes (5)
    Differentiated Services Field: 0x00 (DSCP: CS0, ECN: Not-ECT)
        0000 00.. = Differentiated Services Codepoint: Default (0)
        .... ..00 = Explicit Congestion Notification: Not ECN-Capable Transport (0)
    Total Length: 40
    Identification: 0xeebd (61117)
    010. .... = Flags: 0x2, Don't fragment
        0... .... = Reserved bit: Not set
        .1.. .... = Don't fragment: Set
        ..0. .... = More fragments: Not set
    ...0 0000 0000 0000 = Fragment Offset: 0
    Time to Live: 64
    Protocol: TCP (6)
    Header Checksum: 0x0c0f [validation disabled]
    [Header checksum status: Unverified]
    Source Address: x.y.z.w
    Destination Address: x.y.z.w
Transmission Control Protocol, Src Port: 34986, Dst Port: xxx, Seq: 2771, Ack: 5751, Len: 0
    Source Port: 34986
    Destination Port: xxx
    [Stream index: 1]
    [Conversation completeness: Complete, WITH_DATA (63)]
    [TCP Segment Len: 0]
    Sequence Number: 2771    (relative sequence number)
    Sequence Number (raw): 2630184931
    [Next Sequence Number: 2771    (relative sequence number)]
    Acknowledgment Number: 5751    (relative ack number)
    Acknowledgment number (raw): 2509794850
    0101 .... = Header Length: 20 bytes (5)
    Flags: 0x010 (ACK)
        000. .... .... = Reserved: Not set
        ...0 .... .... = Accurate ECN: Not set
        .... 0... .... = Congestion Window Reduced: Not set
        .... .0.. .... = ECN-Echo: Not set
        .... ..0. .... = Urgent: Not set
        .... ...1 .... = Acknowledgment: Set
        .... .... 0... = Push: Not set
        .... .... .0.. = Reset: Not set
        .... .... ..0. = Syn: Not set
        .... .... ...0 = Fin: Not set
        [TCP Flags: ·······A····]
    Window: 318
    [Calculated window size: 40704]
    [Window size scaling factor: 128]
    Checksum: 0x401e [unverified]
    [Checksum Status: Unverified]
    Urgent Pointer: 0
    [Timestamps]
        [Time since first frame in this TCP stream: 1.051771000 seconds]
        [Time since previous frame in this TCP stream: 0.041562000 seconds]
    [SEQ/ACK analysis]
        [This is an ACK to the segment in frame: 25]
        [The RTT to ACK the segment was: 0.041562000 seconds]
        [iRTT: 0.003010000 seconds]

27    2023-02-10 15:12:10,183395    x.y.w.z     x.y.w.z     TLSv1.2     457   Application Data
Frame 27: 457 bytes on wire (3656 bits), 457 bytes captured (3656 bits)
    Encapsulation type: Ethernet (1)
    Arrival Time: Feb 10, 2023 15:12:10.183395000 Central Europe Standard Time
    [Time shift for this packet: 0.000000000 seconds]
    Epoch Time: 1676038330.183395000 seconds
    [Time delta from previous captured frame: 21.065619000 seconds]
    [Time delta from previous displayed frame: 21.065619000 seconds]
    [Time since reference or first frame: 27.885737000 seconds]
    Frame Number: 27
    Frame Length: 457 bytes (3656 bits)
    Capture Length: 457 bytes (3656 bits)
    [Frame is marked: False]
    [Frame is ignored: False]
    [Protocols in frame: eth:ethertype:ip:tcp:tls]
    [Coloring Rule Name: TCP]
    [Coloring Rule String: tcp]
Ethernet II, Src: xxx, Dst: xxx
    Destination: xxx
        Address: xxx
        .... ..0. .... .... .... .... = LG bit: Globally unique address (factory default)
        .... ...0 .... .... .... .... = IG bit: Individual address (unicast)
    Source: xxx
        Address: xxx
        .... ..0. .... .... .... .... = LG bit: Globally unique address (factory default)
        .... ...0 .... .... .... .... = IG bit: Individual address (unicast)
    Type: IPv4 (0x0800)
Internet Protocol Version 4, Src: x.y.w.z, Dst: x.y.w.z
    0100 .... = Version: 4
    .... 0101 = Header Length: 20 bytes (5)
    Differentiated Services Field: 0x00 (DSCP: CS0, ECN: Not-ECT)
        0000 00.. = Differentiated Services Codepoint: Default (0)
        .... ..00 = Explicit Congestion Notification: Not ECN-Capable Transport (0)
    Total Length: 443
    Identification: 0xeebe (61118)
    010. .... = Flags: 0x2, Don't fragment
        0... .... = Reserved bit: Not set
        .1.. .... = Don't fragment: Set
        ..0. .... = More fragments: Not set
    ...0 0000 0000 0000 = Fragment Offset: 0
    Time to Live: 64
    Protocol: TCP (6)
    Header Checksum: 0x0a7b [validation disabled]
    [Header checksum status: Unverified]
    Source Address: x.y.w.z
    Destination Address: x.y.w.z
Transmission Control Protocol, Src Port: 34986, Dst Port: xxx, Seq: 2771, Ack: 5751, Len: 403
    Source Port: 34986
    Destination Port: xxx
    [Stream index: 1]
    [Conversation completeness: Complete, WITH_DATA (63)]
    [TCP Segment Len: 403]
    Sequence Number: 2771    (relative sequence number)
    Sequence Number (raw): 2630184931
    [Next Sequence Number: 3174    (relative sequence number)]
    Acknowledgment Number: 5751    (relative ack number)
    Acknowledgment number (raw): 2509794850
    0101 .... = Header Length: 20 bytes (5)
    Flags: 0x018 (PSH, ACK)
        000. .... .... = Reserved: Not set
        ...0 .... .... = Accurate ECN: Not set
        .... 0... .... = Congestion Window Reduced: Not set
        .... .0.. .... = ECN-Echo: Not set
        .... ..0. .... = Urgent: Not set
        .... ...1 .... = Acknowledgment: Set
        .... .... 1... = Push: Set
        .... .... .0.. = Reset: Not set
        .... .... ..0. = Syn: Not set
        .... .... ...0 = Fin: Not set
        [TCP Flags: ·······AP···]
    Window: 318
    [Calculated window size: 40704]
    [Window size scaling factor: 128]
    Checksum: 0x41b1 [unverified]
    [Checksum Status: Unverified]
    Urgent Pointer: 0
    [Timestamps]
        [Time since first frame in this TCP stream: 22.117390000 seconds]
        [Time since previous frame in this TCP stream: 21.065619000 seconds]
    [SEQ/ACK analysis]
        [iRTT: 0.003010000 seconds]
        [Bytes in flight: 403]
        [Bytes sent since last PSH flag: 403]
    TCP payload (403 bytes)
Transport Layer Security
    TLSv1.2 Record Layer: Application Data Protocol: Application Data
        Content Type: Application Data (23)
        Version: TLS 1.2 (0x0303)
        Length: 398
        Encrypted Application Data: 0000000000000002be4aae5822b205849734ad881717619991987bc9817d0b0417781265…

28    2023-02-10 15:12:10,185930    x.y.w.z     x.y.w.z     TCP   60    xxx → 34986 [RST] Seq=5751 Win=0 Len=0
Frame 28: 60 bytes on wire (480 bits), 60 bytes captured (480 bits)
    Encapsulation type: Ethernet (1)
    Arrival Time: Feb 10, 2023 15:12:10.185930000 Central Europe Standard Time
    [Time shift for this packet: 0.000000000 seconds]
    Epoch Time: 1676038330.185930000 seconds
    [Time delta from previous captured frame: 0.002535000 seconds]
    [Time delta from previous displayed frame: 0.002535000 seconds]
    [Time since reference or first frame: 27.888272000 seconds]
    Frame Number: 28
    Frame Length: 60 bytes (480 bits)
    Capture Length: 60 bytes (480 bits)
    [Frame is marked: False]
    [Frame is ignored: False]
    [Protocols in frame: eth:ethertype:ip:tcp]
    [Coloring Rule Name: TCP RST]
    [Coloring Rule String: tcp.flags.reset eq 1]
Ethernet II, Src: xxx, Dst: xxx
    Destination: xxx
        Address: xxx
        .... ..0. .... .... .... .... = LG bit: Globally unique address (factory default)
        .... ...0 .... .... .... .... = IG bit: Individual address (unicast)
    Source: xxx
        Address: xxx
        .... ..0. .... .... .... .... = LG bit: Globally unique address (factory default)
        .... ...0 .... .... .... .... = IG bit: Individual address (unicast)
    Type: IPv4 (0x0800)
    Trailer: 00003b22a540
Internet Protocol Version 4, Src: x.y.w.z, Dst: x.y.w.z
    0100 .... = Version: 4
    .... 0101 = Header Length: 20 bytes (5)
    Differentiated Services Field: 0x00 (DSCP: CS0, ECN: Not-ECT)
        0000 00.. = Differentiated Services Codepoint: Default (0)
        .... ..00 = Explicit Congestion Notification: Not ECN-Capable Transport (0)
    Total Length: 40
    Identification: 0xd52f (54575)
    010. .... = Flags: 0x2, Don't fragment
        0... .... = Reserved bit: Not set
        .1.. .... = Don't fragment: Set
        ..0. .... = More fragments: Not set
    ...0 0000 0000 0000 = Fragment Offset: 0
    Time to Live: 52
    Protocol: TCP (6)
    Header Checksum: 0x319d [validation disabled]
    [Header checksum status: Unverified]
    Source Address: x.y.w.z
    Destination Address: x.y.w.z
Transmission Control Protocol, Src Port: xxx, Dst Port: 34986, Seq: 5751, Len: 0
    Source Port: xxx
    Destination Port: 34986
    [Stream index: 1]
    [Conversation completeness: Complete, WITH_DATA (63)]
    [TCP Segment Len: 0]
    Sequence Number: 5751    (relative sequence number)
    Sequence Number (raw): 2509794850
    [Next Sequence Number: 5751    (relative sequence number)]
    Acknowledgment Number: 0
    Acknowledgment number (raw): 0
    0101 .... = Header Length: 20 bytes (5)
    Flags: 0x004 (RST)
        000. .... .... = Reserved: Not set
        ...0 .... .... = Accurate ECN: Not set
        .... 0... .... = Congestion Window Reduced: Not set
        .... .0.. .... = ECN-Echo: Not set
        .... ..0. .... = Urgent: Not set
        .... ...0 .... = Acknowledgment: Not set
        .... .... 0... = Push: Not set
        .... .... .1.. = Reset: Set
        .... .... ..0. = Syn: Not set
        .... .... ...0 = Fin: Not set
        [TCP Flags: ·········R··]
    Window: 0
    [Calculated window size: 0]
    [Window size scaling factor: 16384]
    Checksum: 0xd1cb [unverified]
    [Checksum Status: Unverified]
    Urgent Pointer: 0
    [Timestamps]
        [Time since first frame in this TCP stream: 22.119925000 seconds]
        [Time since previous frame in this TCP stream: 0.002535000 seconds]

I have other log collections working fine with TLS.

Can you please give me some hint what could cause this?

Thank you.

Br,
Dragan

[syslog-ng] syslog-ng reset connection before data transfer

Dragan Zecevic