<div dir="auto">I will open a PR, sure.<div dir="auto"><br></div><div dir="auto">After fixing this issue I encountered another issue where when a message is re-injected into the queue more than once it triggers a use after free and crash because the message payload is free'd in rdkafka.</div><div dir="auto"><br></div><div dir="auto">After thinking about it a bit I'm not sure the message needs to be re-injected into the queue at all because rdkafka will attempt to retry the configured amount of times. Meanwhile if the internal Kafka buffer fills up (possibly with messages that are being retired) it signals back pressure to syslog-ng, which can in turn trigger flow control when the syslog-ng queue becomes full.</div><div dir="auto"><br></div><div dir="auto">Assuming this is desirable the callback only needs to decrement the message reference and increment stats counter for dropped/written.</div><div dir="auto"><br></div><div dir="auto">Thanks</div><div dir="auto"><br></div></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Wed, Jan 15, 2020, 09:02 Attila Szakacs (aszakacs) <<a href="mailto:Attila.Szakacs@oneidentity.com">Attila.Szakacs@oneidentity.com</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">




<div dir="ltr">
<div style="font-family:Calibri,Arial,Helvetica,sans-serif;font-size:12pt;color:rgb(0,0,0);background-color:rgb(255,255,255)">
Hi John,</div>
<div style="font-family:Calibri,Arial,Helvetica,sans-serif;font-size:12pt;color:rgb(0,0,0);background-color:rgb(255,255,255)">
<br>
</div>
<div style="font-family:Calibri,Arial,Helvetica,sans-serif;font-size:12pt;color:rgb(0,0,0);background-color:rgb(255,255,255)">
Thanks for the detailed explanation, and the patch, hats off!</div>
<div style="font-family:Calibri,Arial,Helvetica,sans-serif;font-size:12pt;color:rgb(0,0,0);background-color:rgb(255,255,255)">
While I am reproducing the issue, would you mind opening a PR with this change, so it gets more spotlight?</div>
<div style="font-family:Calibri,Arial,Helvetica,sans-serif;font-size:12pt;color:rgb(0,0,0);background-color:rgb(255,255,255)">
<br>
</div>
<div style="font-family:Calibri,Arial,Helvetica,sans-serif;font-size:12pt;color:rgb(0,0,0);background-color:rgb(255,255,255)">
If we cannot start periodic timers from worker threads, that is kind of a big problem, so this is really interesting.</div>
<div style="font-family:Calibri,Arial,Helvetica,sans-serif;font-size:12pt;color:rgb(0,0,0);background-color:rgb(255,255,255)">
<br>
</div>
<div style="font-family:Calibri,Arial,Helvetica,sans-serif;font-size:12pt;color:rgb(0,0,0);background-color:rgb(255,255,255)">
Thanks,</div>
<div style="font-family:Calibri,Arial,Helvetica,sans-serif;font-size:12pt;color:rgb(0,0,0);background-color:rgb(255,255,255)">
Attila</div>
<div id="m_3167246965120967721appendonsend"></div>
<hr style="display:inline-block;width:98%">
<div id="m_3167246965120967721divRplyFwdMsg" dir="ltr"><font face="Calibri, sans-serif" style="font-size:11pt" color="#000000"><b>From:</b> syslog-ng <<a href="mailto:syslog-ng-bounces@lists.balabit.hu" target="_blank" rel="noreferrer">syslog-ng-bounces@lists.balabit.hu</a>> on behalf of John Skopis <<a href="mailto:jspam@skopis.com" target="_blank" rel="noreferrer">jspam@skopis.com</a>><br>
<b>Sent:</b> Tuesday, January 14, 2020 2:21 PM<br>
<b>To:</b> Syslog-ng users' and developers' mailing list <<a href="mailto:syslog-ng@lists.balabit.hu" target="_blank" rel="noreferrer">syslog-ng@lists.balabit.hu</a>><br>
<b>Subject:</b> Re: [syslog-ng] librdkafka and messages dropped</font>
<div> </div>
</div>
<div>
<div style="background-color:#ffeb9c;width:100%;border-style:solid;border-color:#9c6500;border-width:1pt;padding:2pt;font-size:10pt;line-height:12pt;font-family:'Calibri';color:Black;text-align:left">
<span style="color:#9c6500;font-weight:bold">CAUTION:</span> This email originated from outside of the organization. Do not follow guidance, click links, or open attachments unless you recognize the sender and know the content is safe.</div>
<br>
<div>
<div dir="ltr">patch attached (doh!)</div>
<br>
<div>
<div dir="ltr">On Tue, Jan 14, 2020 at 1:16 PM John Skopis <<a href="mailto:jspam@skopis.com" target="_blank" rel="noreferrer">jspam@skopis.com</a>> wrote:<br>
</div>
<blockquote style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex">
<div dir="ltr">I think I can explain the behavior I am observing.
<div><br>
</div>
<div>rdkafka has a buffer (<span style="color:rgb(0,0,0);white-space:pre-wrap">queue.buffering.max.messages). I guess this buffer is drained by
</span><span style="color:rgb(0,0,0);white-space:pre-wrap">rd_kafka_poll, which triggers delivery callback.
</span></div>
<div><span style="color:rgb(0,0,0);white-space:pre-wrap">When kafka has a failure (spurious or otherwise)
</span>_kafka_delivery_report_cb reinjects the message into the queue. The amount of messages reinjected can be very large, causing the queue to fill much faster than input log rate (depends on kafka timeout and max inflight requests I guess).</div>
<div>When the queue is full no further messages are inserted into the queue, i.e. syslog-ng drop counter increments and queue is stuck at max fifo size.</div>
<div>rd_kafka_poll is only called by _drain_responses, which is scheduled when messages are inserted into the queue.</div>
<div>Messages can't be inserted to the queue because the queue is full; Messages can't be drained from the rdkafka buffer because it's not possible to add new messages, and rd_kafka_poll is only scheduled on insert.</div>
<div><br>
</div>
<div><br>
</div>
<div>You can reproduce by setting queue.buffering.max.messages to 30 and log-fifo-size to 10. Stop kafka and log messages until the fifo fills up. All messages are dropped after this point. When you restart kafka rdkafka produce into kafka but syslog-ng never
 gets the delivery_cb because rd_kafka_poll isn't called.</div>
<div><br>
</div>
<div>I am not familiar with ivkis (or syslog-ng tbh) codebase but it seems the issue is that the timer is not scheduled because the worker is not scheduled. The only way I can see to fix is in the attached patch -- move the callback out of the worker and into
 mainloop. I know it's probably not ideal but it does seem to fix my issue.</div>
<div><br>
</div>
<div>I did try upgrading our ivykis version to 0.42.4 and it didn't seem to help.</div>
<div><br>
</div>
<div>Thanks,</div>
<div>John</div>
</div>
<br>
<div>
<div dir="ltr">On Mon, Jan 13, 2020 at 9:53 AM Attila Szakacs (aszakacs) <<a href="mailto:Attila.Szakacs@oneidentity.com" target="_blank" rel="noreferrer">Attila.Szakacs@oneidentity.com</a>> wrote:<br>
</div>
<blockquote style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex">
<div dir="ltr">
<div style="font-family:Calibri,Arial,Helvetica,sans-serif;font-size:12pt;color:rgb(0,0,0);background-color:rgb(255,255,255)">
Hi John,</div>
<div style="font-family:Calibri,Arial,Helvetica,sans-serif;font-size:12pt;color:rgb(0,0,0);background-color:rgb(255,255,255)">
<br>
</div>
<div style="font-family:Calibri,Arial,Helvetica,sans-serif;font-size:12pt;color:rgb(0,0,0);background-color:rgb(255,255,255)">
Could you gather debug logs with `syslog-ng -Fedtv`? It would provide a nice starting point.</div>
<div style="font-family:Calibri,Arial,Helvetica,sans-serif;font-size:12pt;color:rgb(0,0,0);background-color:rgb(255,255,255)">
<br>
</div>
<div style="font-family:Calibri,Arial,Helvetica,sans-serif;font-size:12pt;color:rgb(0,0,0);background-color:rgb(255,255,255)">
Thanks,</div>
<div style="font-family:Calibri,Arial,Helvetica,sans-serif;font-size:12pt;color:rgb(0,0,0);background-color:rgb(255,255,255)">
Attila</div>
<div id="m_3167246965120967721x_gmail-m_5168135941599218706gmail-m_-1992065468789522177gmail-m_599157910599484416appendonsend">
</div>
<hr style="display:inline-block;width:98%">
<div id="m_3167246965120967721x_gmail-m_5168135941599218706gmail-m_-1992065468789522177gmail-m_599157910599484416divRplyFwdMsg" dir="ltr">
<font face="Calibri, sans-serif" color="#000000" style="font-size:11pt"><b>From:</b> syslog-ng <<a href="mailto:syslog-ng-bounces@lists.balabit.hu" target="_blank" rel="noreferrer">syslog-ng-bounces@lists.balabit.hu</a>> on behalf of John Skopis <<a href="mailto:jspam@skopis.com" target="_blank" rel="noreferrer">jspam@skopis.com</a>><br>
<b>Sent:</b> Monday, January 13, 2020 10:11 AM<br>
<b>To:</b> <a href="mailto:syslog-ng@lists.balabit.hu" target="_blank" rel="noreferrer">syslog-ng@lists.balabit.hu</a> <<a href="mailto:syslog-ng@lists.balabit.hu" target="_blank" rel="noreferrer">syslog-ng@lists.balabit.hu</a>><br>
<b>Subject:</b> [syslog-ng] librdkafka and messages dropped</font>
<div> </div>
</div>
<div>
<div style="background-color:rgb(255,235,156);width:100%;border-style:solid;border-color:rgb(156,101,0);border-width:1pt;padding:2pt;font-size:10pt;line-height:12pt;font-family:Calibri;color:black;text-align:left">
<span style="color:rgb(156,101,0);font-weight:bold">CAUTION:</span> This email originated from outside of the organization. Do not follow guidance, click links, or open attachments unless you recognize the sender and know the content is safe.</div>
<br>
<div>
<div dir="ltr">Hello,
<div><br>
</div>
<div>We have a syslog-ng aggregator that accepts messages in a few different formats and logs the message format to kafka. The mapping looks something like:</div>
<div><br>
</div>
<div>format1 -> topic1</div>
<div>format2 -> topic2</div>
<div>...</div>
<div><br>
</div>
<div>Each agent will emit messages in ~4 different formats and send to the aggregator.</div>
<div>The aggregator is configured with a kafka_c destination with 8 threads/destination.</div>
<div><br>
</div>
<div>We were previously using the java kafka client without issue.</div>
<div>We recently upgraded to 3.24.1 + librdkafka 1.22</div>
<div><br>
</div>
<div>After upgrading we are seeing an issue where (seemingly randomly) syslog-ng stops producing messages into kafka.</div>
<div><br>
</div>
<div>Checking syslog-ng-ctl stats I can see</div>
<div>d_kafka_format1 has dropped message counter increasing</div>
<div>d_kafka_format1 queued messages counter increases to 80000 (10000*8 threads iw-size)<br>
</div>
<div>d_kafka_format1 processed messages does not increase</div>
<div><br>
</div>
<div>There are messages printed to the log that the destination queue is full for all of the rdkafka threads,</div>
<div><br>
</div>
<div>There are spurious failures to a kafka broker but it seems rdkafka reconnects.</div>
<div><br>
</div>
<div>Seems like once the destination queue becomes full syslog-ng never recovers and the instance must be restarted.</div>
<div>It also seems like rdkafka stops trying to reconnect to kafka (possibly?).</div>
<div><br>
</div>
<div>Is this expected behavior or is there some bug around reconnecting to kafka after a spurious timeout?</div>
<div>Just speculating here but does rdkafka stop trying to reconnect after N times? </div>
<div>Are there any examples of destroy/create destination client after failure thresholds?</div>
<div><br>
</div>
<div>Thanks</div>
<div><br>
</div>
</div>
</div>
</div>
</div>
______________________________________________________________________________<br>
Member info: <a href="https://nam05.safelinks.protection.outlook.com/?url=https%3A%2F%2Flists.balabit.hu%2Fmailman%2Flistinfo%2Fsyslog-ng&data=02%7C01%7CAttila.Szakacs%40oneidentity.com%7Ce19cb6505cdb4b2a226608d798f4aee3%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637146048986792401&sdata=zn1gK82FIcLYJAvXzmGfOxY%2Bp2GMUw3FlrK0Nfm0jpo%3D&reserved=0" rel="noreferrer noreferrer" target="_blank">
https://lists.balabit.hu/mailman/listinfo/syslog-ng</a><br>
Documentation: <a href="https://nam05.safelinks.protection.outlook.com/?url=http%3A%2F%2Fwww.balabit.com%2Fsupport%2Fdocumentation%2F%3Fproduct%3Dsyslog-ng&data=02%7C01%7CAttila.Szakacs%40oneidentity.com%7Ce19cb6505cdb4b2a226608d798f4aee3%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637146048986792401&sdata=TpPr6q0A%2BW10R5AAXjQU5zY1ieh9zBQUS35oNSteyUo%3D&reserved=0" rel="noreferrer noreferrer" target="_blank">
http://www.balabit.com/support/documentation/?product=syslog-ng</a><br>
FAQ: <a href="https://nam05.safelinks.protection.outlook.com/?url=http%3A%2F%2Fwww.balabit.com%2Fwiki%2Fsyslog-ng-faq&data=02%7C01%7CAttila.Szakacs%40oneidentity.com%7Ce19cb6505cdb4b2a226608d798f4aee3%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637146048986802348&sdata=xt8KsVCHz9TTrn2Z9UJK%2BQbSHIv4ckdmsKoRGyX1L4Y%3D&reserved=0" rel="noreferrer noreferrer" target="_blank">
http://www.balabit.com/wiki/syslog-ng-faq</a><br>
<br>
</blockquote>
</div>
</blockquote>
</div>
</div>
</div>
</div>

</blockquote></div>