Mailing List Archive: Behavior during shutdown

Behavior during shutdown

Apr 29, 2020, 4:00 AM

Post #1 of 5 (736 views)

Just testing the message forwarding and reliability of plain TCP. Am aware
of the un-reliability of that forwarding.
See some missing messages after the rsyslog proper process restart on
destination side.
Configured simple TCP omfwd action with keepalive enabled.
On receiving side imptcp input with keepalive enabled and
global(inputs.timeout.shutdown="10000").
Unfortunately see rsyslog going down and closing listeners too fast - not
accepting the timeout.shutdown value. After that the receiver does not wait
for FIN,ACK from client side and just close the socket. The data being
flushed from buffer on client side are responded with RST packet. Would
expect the receiver to wait up to 10 seconds to let the clients flush the
data. Have some remote sites with slow link - due to long distance -
causing the socket sending queue being occupied most of the time.

Do not see this behavior as appropriate. Could anybody review the code? Is
it bug or configuration issue?

Found this code:
https://github.com/rsyslog/rsyslog/blob/69f8e1d1f7fe62fd2c5f38a81d4102a9a62d1722/plugins/imptcp/imptcp.c#L2381

According to the documentation the two shutdown()s can be called before
close(), but are not strictly required.
Digging a little deeper discovered SO_LINGER is referenced, but with value
of 0
https://github.com/rsyslog/rsyslog/blob/6f74f7e7b43eb32ab165c5975a0f7777cbbf0f21/runtime/nsd_ptcp.c#L359
which might be ok as with plain TCP there is no data transferred to
client from the listener. And the SO_LINGER covers only flush buffered
output (does not wait for incoming data)
https://www.gnu.org/software/libc/manual/html_node/Opening-and-Closing-Files.html#Opening-and-Closing-Files

Was not able to find the LINGERing on client side code. Traced socket
handling in omfwd
https://github.com/rsyslog/rsyslog/blob/1f8f621a97df6b1989e1aebd8cb15cd6a552fa9c/tools/omfwd.c
was able to find the abort data in netstrm driver
https://github.com/rsyslog/rsyslog/blob/6f74f7e7b43eb32ab165c5975a0f7777cbbf0f21/runtime/netstrm.c#L83
which seems related.
Hopefully from the tcpdump that part of the code seems to be working as it
is seen the client is trying to flush the data, all of which are responded
with RST packet.
Both sides are running Debian10 with Debian's rsyslog 8.1901.0-1.

Any help to sort this out is appreciated.

Peter
_______________________________________________
rsyslog mailing list
https://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com/professional-services/
What's up with rsyslog? Follow https://twitter.com/rgerhards
NOTE WELL: This is a PUBLIC mailing list, posts are ARCHIVED by a myriad of sites beyond our control. PLEASE UNSUBSCRIBE and DO NOT POST if you DON'T LIKE THAT.

Re: Behavior during shutdown [ In reply to ]

rsyslog at lists

Apr 29, 2020, 4:03 AM

Post #2 of 5 (736 views)

Permalink

no, the receiver shuts down as soon as possible. This is intended.
Otherwise you get even longer shutdown times.

Rainer

El mié., 29 abr. 2020 a las 13:00, Peter Viskup via rsyslog
(<rsyslog@lists.adiscon.com>) escribió:
>
> Just testing the message forwarding and reliability of plain TCP. Am aware
> of the un-reliability of that forwarding.
> See some missing messages after the rsyslog proper process restart on
> destination side.
> Configured simple TCP omfwd action with keepalive enabled.
> On receiving side imptcp input with keepalive enabled and
> global(inputs.timeout.shutdown="10000").
> Unfortunately see rsyslog going down and closing listeners too fast - not
> accepting the timeout.shutdown value. After that the receiver does not wait
> for FIN,ACK from client side and just close the socket. The data being
> flushed from buffer on client side are responded with RST packet. Would
> expect the receiver to wait up to 10 seconds to let the clients flush the
> data. Have some remote sites with slow link - due to long distance -
> causing the socket sending queue being occupied most of the time.
>
> Do not see this behavior as appropriate. Could anybody review the code? Is
> it bug or configuration issue?
>
> Found this code:
> https://github.com/rsyslog/rsyslog/blob/69f8e1d1f7fe62fd2c5f38a81d4102a9a62d1722/plugins/imptcp/imptcp.c#L2381
>
> According to the documentation the two shutdown()s can be called before
> close(), but are not strictly required.
> Digging a little deeper discovered SO_LINGER is referenced, but with value
> of 0
> https://github.com/rsyslog/rsyslog/blob/6f74f7e7b43eb32ab165c5975a0f7777cbbf0f21/runtime/nsd_ptcp.c#L359
> which might be ok as with plain TCP there is no data transferred to
> client from the listener. And the SO_LINGER covers only flush buffered
> output (does not wait for incoming data)
> https://www.gnu.org/software/libc/manual/html_node/Opening-and-Closing-Files.html#Opening-and-Closing-Files
>
> Was not able to find the LINGERing on client side code. Traced socket
> handling in omfwd
> https://github.com/rsyslog/rsyslog/blob/1f8f621a97df6b1989e1aebd8cb15cd6a552fa9c/tools/omfwd.c
> was able to find the abort data in netstrm driver
> https://github.com/rsyslog/rsyslog/blob/6f74f7e7b43eb32ab165c5975a0f7777cbbf0f21/runtime/netstrm.c#L83
> which seems related.
> Hopefully from the tcpdump that part of the code seems to be working as it
> is seen the client is trying to flush the data, all of which are responded
> with RST packet.
> Both sides are running Debian10 with Debian's rsyslog 8.1901.0-1.
>
> Any help to sort this out is appreciated.
>
> Peter
> _______________________________________________
> rsyslog mailing list
> https://lists.adiscon.net/mailman/listinfo/rsyslog
> http://www.rsyslog.com/professional-services/
> What's up with rsyslog? Follow https://twitter.com/rgerhards
> NOTE WELL: This is a PUBLIC mailing list, posts are ARCHIVED by a myriad of sites beyond our control. PLEASE UNSUBSCRIBE and DO NOT POST if you DON'T LIKE THAT.
_______________________________________________
rsyslog mailing list
https://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com/professional-services/
What's up with rsyslog? Follow https://twitter.com/rgerhards
NOTE WELL: This is a PUBLIC mailing list, posts are ARCHIVED by a myriad of sites beyond our control. PLEASE UNSUBSCRIBE and DO NOT POST if you DON'T LIKE THAT.

Re: Behavior during shutdown [ In reply to ]

rsyslog at lists

Apr 29, 2020, 4:45 AM

Post #3 of 5 (736 views)

Permalink

What's the purpose of inputs.timeout.shutdown then.
Thought it should cover this scenario in a way that the clients will have
enough time to send the data from buffers before closing the socket.
Shouldn't the listener wait the time defined in inputs.timeout.shutdown for
client's response with FIN,ACK? Would expect that.

Peter

On Wed, Apr 29, 2020 at 1:03 PM Rainer Gerhards <rgerhards@hq.adiscon.com>
wrote:

> no, the receiver shuts down as soon as possible. This is intended.
> Otherwise you get even longer shutdown times.
>
> Rainer
>
> El mié., 29 abr. 2020 a las 13:00, Peter Viskup via rsyslog
> (<rsyslog@lists.adiscon.com>) escribió:
> >
> > Just testing the message forwarding and reliability of plain TCP. Am
> aware
> > of the un-reliability of that forwarding.
> > See some missing messages after the rsyslog proper process restart on
> > destination side.
> > Configured simple TCP omfwd action with keepalive enabled.
> > On receiving side imptcp input with keepalive enabled and
> > global(inputs.timeout.shutdown="10000").
> > Unfortunately see rsyslog going down and closing listeners too fast - not
> > accepting the timeout.shutdown value. After that the receiver does not
> wait
> > for FIN,ACK from client side and just close the socket. The data being
> > flushed from buffer on client side are responded with RST packet. Would
> > expect the receiver to wait up to 10 seconds to let the clients flush the
> > data. Have some remote sites with slow link - due to long distance -
> > causing the socket sending queue being occupied most of the time.
> >
> > Do not see this behavior as appropriate. Could anybody review the code?
> Is
> > it bug or configuration issue?
> >
> > Found this code:
> >
> https://github.com/rsyslog/rsyslog/blob/69f8e1d1f7fe62fd2c5f38a81d4102a9a62d1722/plugins/imptcp/imptcp.c#L2381
> >
> > According to the documentation the two shutdown()s can be called before
> > close(), but are not strictly required.
> > Digging a little deeper discovered SO_LINGER is referenced, but with
> value
> > of 0
> >
> https://github.com/rsyslog/rsyslog/blob/6f74f7e7b43eb32ab165c5975a0f7777cbbf0f21/runtime/nsd_ptcp.c#L359
> > which might be ok as with plain TCP there is no data transferred to
> > client from the listener. And the SO_LINGER covers only flush buffered
> > output (does not wait for incoming data)
> >
> https://www.gnu.org/software/libc/manual/html_node/Opening-and-Closing-Files.html#Opening-and-Closing-Files
> >
> > Was not able to find the LINGERing on client side code. Traced socket
> > handling in omfwd
> >
> https://github.com/rsyslog/rsyslog/blob/1f8f621a97df6b1989e1aebd8cb15cd6a552fa9c/tools/omfwd.c
> > was able to find the abort data in netstrm driver
> >
> https://github.com/rsyslog/rsyslog/blob/6f74f7e7b43eb32ab165c5975a0f7777cbbf0f21/runtime/netstrm.c#L83
> > which seems related.
> > Hopefully from the tcpdump that part of the code seems to be working as
> it
> > is seen the client is trying to flush the data, all of which are
> responded
> > with RST packet.
> > Both sides are running Debian10 with Debian's rsyslog 8.1901.0-1.
> >
> > Any help to sort this out is appreciated.
> >
> > Peter
> > _______________________________________________
> > rsyslog mailing list
> > https://lists.adiscon.net/mailman/listinfo/rsyslog
> > http://www.rsyslog.com/professional-services/
> > What's up with rsyslog? Follow https://twitter.com/rgerhards
> > NOTE WELL: This is a PUBLIC mailing list, posts are ARCHIVED by a myriad
> of sites beyond our control. PLEASE UNSUBSCRIBE and DO NOT POST if you
> DON'T LIKE THAT.
>
_______________________________________________
rsyslog mailing list
https://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com/professional-services/
What's up with rsyslog? Follow https://twitter.com/rgerhards
NOTE WELL: This is a PUBLIC mailing list, posts are ARCHIVED by a myriad of sites beyond our control. PLEASE UNSUBSCRIBE and DO NOT POST if you DON'T LIKE THAT.

Re: Behavior during shutdown [ In reply to ]

rsyslog at lists

Apr 29, 2020, 5:30 AM

Post #4 of 5 (736 views)

Permalink

oh, that's a good question - maybe I was on the wrong path. I need to
investigate.

Rainer

El mié., 29 abr. 2020 a las 13:45, Peter Viskup
(<skupko.sk@gmail.com>) escribió:
>
> What's the purpose of inputs.timeout.shutdown then.
> Thought it should cover this scenario in a way that the clients will have enough time to send the data from buffers before closing the socket.
> Shouldn't the listener wait the time defined in inputs.timeout.shutdown for client's response with FIN,ACK? Would expect that.
>
> Peter
>
> On Wed, Apr 29, 2020 at 1:03 PM Rainer Gerhards <rgerhards@hq.adiscon.com> wrote:
>>
>> no, the receiver shuts down as soon as possible. This is intended.
>> Otherwise you get even longer shutdown times.
>>
>> Rainer
>>
>> El mié., 29 abr. 2020 a las 13:00, Peter Viskup via rsyslog
>> (<rsyslog@lists.adiscon.com>) escribió:
>> >
>> > Just testing the message forwarding and reliability of plain TCP. Am aware
>> > of the un-reliability of that forwarding.
>> > See some missing messages after the rsyslog proper process restart on
>> > destination side.
>> > Configured simple TCP omfwd action with keepalive enabled.
>> > On receiving side imptcp input with keepalive enabled and
>> > global(inputs.timeout.shutdown="10000").
>> > Unfortunately see rsyslog going down and closing listeners too fast - not
>> > accepting the timeout.shutdown value. After that the receiver does not wait
>> > for FIN,ACK from client side and just close the socket. The data being
>> > flushed from buffer on client side are responded with RST packet. Would
>> > expect the receiver to wait up to 10 seconds to let the clients flush the
>> > data. Have some remote sites with slow link - due to long distance -
>> > causing the socket sending queue being occupied most of the time.
>> >
>> > Do not see this behavior as appropriate. Could anybody review the code? Is
>> > it bug or configuration issue?
>> >
>> > Found this code:
>> > https://github.com/rsyslog/rsyslog/blob/69f8e1d1f7fe62fd2c5f38a81d4102a9a62d1722/plugins/imptcp/imptcp.c#L2381
>> >
>> > According to the documentation the two shutdown()s can be called before
>> > close(), but are not strictly required.
>> > Digging a little deeper discovered SO_LINGER is referenced, but with value
>> > of 0
>> > https://github.com/rsyslog/rsyslog/blob/6f74f7e7b43eb32ab165c5975a0f7777cbbf0f21/runtime/nsd_ptcp.c#L359
>> > which might be ok as with plain TCP there is no data transferred to
>> > client from the listener. And the SO_LINGER covers only flush buffered
>> > output (does not wait for incoming data)
>> > https://www.gnu.org/software/libc/manual/html_node/Opening-and-Closing-Files.html#Opening-and-Closing-Files
>> >
>> > Was not able to find the LINGERing on client side code. Traced socket
>> > handling in omfwd
>> > https://github.com/rsyslog/rsyslog/blob/1f8f621a97df6b1989e1aebd8cb15cd6a552fa9c/tools/omfwd.c
>> > was able to find the abort data in netstrm driver
>> > https://github.com/rsyslog/rsyslog/blob/6f74f7e7b43eb32ab165c5975a0f7777cbbf0f21/runtime/netstrm.c#L83
>> > which seems related.
>> > Hopefully from the tcpdump that part of the code seems to be working as it
>> > is seen the client is trying to flush the data, all of which are responded
>> > with RST packet.
>> > Both sides are running Debian10 with Debian's rsyslog 8.1901.0-1.
>> >
>> > Any help to sort this out is appreciated.
>> >
>> > Peter
>> > _______________________________________________
>> > rsyslog mailing list
>> > https://lists.adiscon.net/mailman/listinfo/rsyslog
>> > http://www.rsyslog.com/professional-services/
>> > What's up with rsyslog? Follow https://twitter.com/rgerhards
>> > NOTE WELL: This is a PUBLIC mailing list, posts are ARCHIVED by a myriad of sites beyond our control. PLEASE UNSUBSCRIBE and DO NOT POST if you DON'T LIKE THAT.
_______________________________________________
rsyslog mailing list
https://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com/professional-services/
What's up with rsyslog? Follow https://twitter.com/rgerhards
NOTE WELL: This is a PUBLIC mailing list, posts are ARCHIVED by a myriad of sites beyond our control. PLEASE UNSUBSCRIBE and DO NOT POST if you DON'T LIKE THAT.

Re: Behavior during shutdown [ In reply to ]

rsyslog at lists

Jul 20, 2020, 3:16 AM

Post #5 of 5 (688 views)

Permalink

Just had a look on this.
Running rsyslog 8.1901 version we do see this behavior.
Rsyslog receiver restarts, sends the FIN packet, client responds with ACK,
but after a while it sends another message to the already closed socket.
Not sure whether the behavior is correct or not. There is FIN ACK at
09:44:36.597404 and another message sent at 09:44:37.899188.

(tcpdump from client/relay 10.0.0.130, 10.0.0.138 is the receiver)
09:44:19.614994 IP 10.0.0.130.41498 > 10.0.0.138.2514: Flags [P.], seq
7629:7822, ack 1, win 502, options [nop,nop,TS val 2488259817 ecr
1259647639], length 193
.O..K...<30>1 2020-07-20T09:44:19+00:00 loco01-10.0.0.130 snmpd 629 -
[syslogTimes@29171 10.0.0.130="2020-07-20T09:44:19.610564+00:00"]
Connection from UDP: [10.0.0.20]:42624->[10.0.0.130]:161
09:44:19.615009 IP 10.0.0.138.2514 > 10.0.0.130.41498: Flags [.], ack 7822,
win 8190, options [nop,nop,TS val 1259654040 ecr 2488259817], length 0
09:44:36.588199 IP 10.0.0.138.2514 > 10.0.0.130.41498: Flags [F.], seq 1,
ack 7822, win 8190, options [nop,nop,TS val 1259671013 ecr 2488259817],
length 0
09:44:36.597404 IP 10.0.0.130.41498 > 10.0.0.138.2514: Flags [.], ack 2,
win 502, options [nop,nop,TS val 2488276799 ecr 1259671013], length 0
09:44:37.899188 IP 10.0.0.130.41498 > 10.0.0.138.2514: Flags [P.], seq
7822:8024, ack 2, win 502, options [nop,nop,TS val 2488278101 ecr
1259671013], length 202
.P.UK...<30>1 2020-07-20T11:44:37.894029+02:00 services-10.0.0.34 snmpd
1714 - [syslogTimes@29171 10.0.0.130="2020-07-20T09:44:37.894927+00:00"]
Connection from UDP: [10.0.0.20]:47156->[10.0.0.34]:161
09:44:37.899213 IP 10.0.0.138.2514 > 10.0.0.130.41498: Flags [R], seq
3960804835, win 0, length 0

Peter

On Wed, Apr 29, 2020 at 2:30 PM Rainer Gerhards <rgerhards@hq.adiscon.com>
wrote:

> oh, that's a good question - maybe I was on the wrong path. I need to
> investigate.
>
> Rainer
>
> El mié., 29 abr. 2020 a las 13:45, Peter Viskup
> (<skupko.sk@gmail.com>) escribió:
> >
> > What's the purpose of inputs.timeout.shutdown then.
> > Thought it should cover this scenario in a way that the clients will
> have enough time to send the data from buffers before closing the socket.
> > Shouldn't the listener wait the time defined in inputs.timeout.shutdown
> for client's response with FIN,ACK? Would expect that.
> >
> > Peter
> >
> > On Wed, Apr 29, 2020 at 1:03 PM Rainer Gerhards <
> rgerhards@hq.adiscon.com> wrote:
> >>
> >> no, the receiver shuts down as soon as possible. This is intended.
> >> Otherwise you get even longer shutdown times.
> >>
> >> Rainer
> >>
> >> El mié., 29 abr. 2020 a las 13:00, Peter Viskup via rsyslog
> >> (<rsyslog@lists.adiscon.com>) escribió:
> >> >
> >> > Just testing the message forwarding and reliability of plain TCP. Am
> aware
> >> > of the un-reliability of that forwarding.
> >> > See some missing messages after the rsyslog proper process restart on
> >> > destination side.
> >> > Configured simple TCP omfwd action with keepalive enabled.
> >> > On receiving side imptcp input with keepalive enabled and
> >> > global(inputs.timeout.shutdown="10000").
> >> > Unfortunately see rsyslog going down and closing listeners too fast -
> not
> >> > accepting the timeout.shutdown value. After that the receiver does
> not wait
> >> > for FIN,ACK from client side and just close the socket. The data being
> >> > flushed from buffer on client side are responded with RST packet.
> Would
> >> > expect the receiver to wait up to 10 seconds to let the clients flush
> the
> >> > data. Have some remote sites with slow link - due to long distance -
> >> > causing the socket sending queue being occupied most of the time.
> >> >
> >> > Do not see this behavior as appropriate. Could anybody review the
> code? Is
> >> > it bug or configuration issue?
> >> >
> >> > Found this code:
> >> >
> https://github.com/rsyslog/rsyslog/blob/69f8e1d1f7fe62fd2c5f38a81d4102a9a62d1722/plugins/imptcp/imptcp.c#L2381
> >> >
> >> > According to the documentation the two shutdown()s can be called
> before
> >> > close(), but are not strictly required.
> >> > Digging a little deeper discovered SO_LINGER is referenced, but with
> value
> >> > of 0
> >> >
> https://github.com/rsyslog/rsyslog/blob/6f74f7e7b43eb32ab165c5975a0f7777cbbf0f21/runtime/nsd_ptcp.c#L359
> >> > which might be ok as with plain TCP there is no data transferred to
> >> > client from the listener. And the SO_LINGER covers only flush buffered
> >> > output (does not wait for incoming data)
> >> >
> https://www.gnu.org/software/libc/manual/html_node/Opening-and-Closing-Files.html#Opening-and-Closing-Files
> >> >
> >> > Was not able to find the LINGERing on client side code. Traced socket
> >> > handling in omfwd
> >> >
> https://github.com/rsyslog/rsyslog/blob/1f8f621a97df6b1989e1aebd8cb15cd6a552fa9c/tools/omfwd.c
> >> > was able to find the abort data in netstrm driver
> >> >
> https://github.com/rsyslog/rsyslog/blob/6f74f7e7b43eb32ab165c5975a0f7777cbbf0f21/runtime/netstrm.c#L83
> >> > which seems related.
> >> > Hopefully from the tcpdump that part of the code seems to be working
> as it
> >> > is seen the client is trying to flush the data, all of which are
> responded
> >> > with RST packet.
> >> > Both sides are running Debian10 with Debian's rsyslog 8.1901.0-1.
> >> >
> >> > Any help to sort this out is appreciated.
> >> >
> >> > Peter
> >> > _______________________________________________
> >> > rsyslog mailing list
> >> > https://lists.adiscon.net/mailman/listinfo/rsyslog
> >> > http://www.rsyslog.com/professional-services/
> >> > What's up with rsyslog? Follow https://twitter.com/rgerhards
> >> > NOTE WELL: This is a PUBLIC mailing list, posts are ARCHIVED by a
> myriad of sites beyond our control. PLEASE UNSUBSCRIBE and DO NOT POST if
> you DON'T LIKE THAT.
>
_______________________________________________
rsyslog mailing list
https://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com/professional-services/
What's up with rsyslog? Follow https://twitter.com/rgerhards
NOTE WELL: This is a PUBLIC mailing list, posts are ARCHIVED by a myriad of sites beyond our control. PLEASE UNSUBSCRIBE and DO NOT POST if you DON'T LIKE THAT.