Thx - I do not see anything obviously wrong. Could it be that those messages arrive e.g. via imklog instead of imjournal?
Can you check inside the debug log for occurrences of the ratelimited message - and find where it actually is emitted. Alternatively, you may want to post a full debug log which shows the problem (I guess that's out of option, so an excerpt could do it, but would probably require some turnaround to nail the actual info items needed). Rainer El mar, 13 dic 2022 a las 16:59, helices (<mike+rsys...@mdsresource.net>) escribió: > > https://pastebin.com/DUgwmPCs > > On Tue, Dec 13, 2022 at 9:02 AM Rainer Gerhards <rgerha...@hq.adiscon.com> > wrote: >> >> well, for the debug log to make sense to me, I need the whole thing at >> least for the startup sequence. You can post it in a gist or something >> like pastebin. I guess David would also be interested in it. >> >> Rainer >> >> El mar, 13 dic 2022 a las 15:57, helices >> (<mike+rsys...@mdsresource.net>) escribió: >> > >> > I'm trying to understand what is really happening. Recently, it seems one >> > of our clients initiates many SFTP connections to this host in the early >> > morning hours. There are many, many rsyslog entries for this, and they are >> > also those - apparently - wrapping across multiple lines, which fail >> > insertion into our database. >> > >> > we have not yet identified a full entry that fails mysql insertion. So, >> > no, we did not "manually try the insert statement." Nor have we found >> > appropriate mysql error log entries. >> > >> > "Could you at least post the startup part of the debug log?" - How much? >> > >> > NOTE: 'ratelimit.interval' and 'ratelimit.burst' are set; but, >> > 'ratelimitinterval' and 'ratelimitburst' are BOTH UNSET. What is that >> > about? >> > >> > 0953.048546212:main thread : glbl.c: debug level 2 set via config file >> > 0953.048561879:main thread : glbl.c: This is rsyslog version 8.2212.0 >> > 0953.048577415:main thread : rsconf.c: cnf:global:obj: obj: 'module' >> > 0953.048587780:main thread : rainerscript.c: nvlst 0x561102c16ca0: >> > 0953.048592371:main thread : rainerscript.c: name: 'StateFile', >> > value 'imjournal.state' >> > 0953.048596753:main thread : rainerscript.c: name: >> > 'Ratelimit.Interval', value '1000' >> > 0953.048600958:main thread : rainerscript.c: name: >> > 'Ratelimit.Burst', value '30000' >> > 0953.048605071:main thread : rainerscript.c: name: 'load', >> > value 'imjournal' >> > 0953.048636752:main thread : rainerscript.c: nvlstGetParam: name >> > 'load', type 13, valnode->bUsed 0 >> > 0953.048643952:main thread : modules.c: modulesProcessCnf params: >> > 0953.048647990:main thread : rainerscript.c: load: 'imjournal' >> > 0953.048666065:main thread : modules.c: Requested to load module >> > 'imjournal' >> > 0953.048671930:main thread : modules.c: loading module >> > '/usr/lib64/rsyslog/imjournal.so' >> > 0953.049450325:main thread : modules.c: module imjournal of type 0 >> > being loaded (keepType=0). >> > 0953.049461922:main thread : modules.c: module config name is >> > 'imjournal' >> > 0953.049466285:main thread : modules.c: module imjournal supports >> > rsyslog v6 config interface >> > 0953.049471442:main thread : imjournal.c: entry point >> > 'activateCnfPrePrivDrop' not present in module >> > 0953.049476234:main thread : imjournal.c: entry point 'newInpInst' not >> > present in module >> > 0953.049480495:main thread : imjournal.c: entry point 'doHUP' not >> > present in module >> > 0953.049486505:main thread : rainerscript.c: nvlstGetParam: name >> > 'statefile', type 13, valnode->bUsed 0 >> > 0953.049491290:main thread : rainerscript.c: nvlstGetParam: name >> > 'ratelimit.interval', type 6, valnode->bUsed 0 >> > 0953.049497144:main thread : rainerscript.c: nvlstGetParam: name >> > 'ratelimit.burst', type 6, valnode->bUsed 0 >> > 0953.049502097:main thread : imjournal.c: module (global) param blk for >> > imjournal: >> > 0953.049506011:main thread : rainerscript.c: statefile: >> > 'imjournal.state' >> > 0953.049515590:main thread : rainerscript.c: ratelimit.interval: 1000 >> > 0953.049524703:main thread : rainerscript.c: ratelimit.burst: 30000 >> > 0953.049533615:main thread : rainerscript.c: persiststateinterval: >> > (unset) >> > 0953.049542575:main thread : rainerscript.c: ignorepreviousmessages: >> > (unset) >> > 0953.049551231:main thread : rainerscript.c: ignorenonvalidstatefile: >> > (unset) >> > 0953.049559845:main thread : rainerscript.c: defaultseverity: (unset) >> > 0953.049568448:main thread : rainerscript.c: defaultfacility: (unset) >> > 0953.049577070:main thread : rainerscript.c: usepidfromsystem: (unset) >> > 0953.049585721:main thread : rainerscript.c: usepid: (unset) >> > 0953.049594328:main thread : rainerscript.c: workaroundjournalbug: >> > (unset) >> > 0953.049602947:main thread : rainerscript.c: fsync: (unset) >> > 0953.049611537:main thread : rainerscript.c: remote: (unset) >> > 0953.049648880:main thread : rsconf.c: cnf:global:obj: obj: 'module' >> > 0953.049656182:main thread : rainerscript.c: nvlst 0x561102c16cd0: >> > 0953.049660452:main thread : rainerscript.c: name: 'load', >> > value 'imklog' >> > 0953.049665572:main thread : rainerscript.c: nvlstGetParam: name >> > 'load', type 13, valnode->bUsed 0 >> > 0953.049669812:main thread : modules.c: modulesProcessCnf params: >> > 0953.049673667:main thread : rainerscript.c: load: 'imklog' >> > 0953.049683199:main thread : modules.c: Requested to load module >> > 'imklog' >> > 0953.049688342:main thread : modules.c: loading module >> > '/usr/lib64/rsyslog/imklog.so' >> > 0953.050263553:main thread : modules.c: module imklog of type 0 being >> > loaded (keepType=0). >> > 0953.050274236:main thread : imklog.c: entry point >> > 'isCompatibleWithFeature' not present in module >> > 0953.050279240:main thread : modules.c: module config name is 'imklog' >> > 0953.050283500:main thread : modules.c: module imklog supports rsyslog >> > v6 config interface >> > 0953.050289536:main thread : imklog.c: entry point 'newInpInst' not >> > present in module >> > 0953.050293692:main thread : imklog.c: entry point 'doHUP' not present >> > in module >> > 0953.050308677:main thread : imklog.c: module (global) param blk for >> > imklog: >> > 0953.050313296:main thread : rainerscript.c: ruleset: (unset) >> > 0953.050322440:main thread : rainerscript.c: logpath: (unset) >> > 0953.050331135:main thread : rainerscript.c: permitnonkernelfacility: >> > (unset) >> > 0953.050339793:main thread : rainerscript.c: consoleloglevel: (unset) >> > 0953.050348442:main thread : rainerscript.c: parsekerneltimestamp: >> > (unset) >> > 0953.050357122:main thread : rainerscript.c: keepkerneltimestamp: >> > (unset) >> > 0953.050365783:main thread : rainerscript.c: internalmsgfacility: >> > (unset) >> > 0953.050374403:main thread : rainerscript.c: ratelimitinterval: (unset) >> > 0953.050383057:main thread : rainerscript.c: ratelimitburst: (unset) >> > >> > >> > >> > >> > On Tue, Dec 13, 2022 at 8:37 AM Rainer Gerhards <rgerha...@hq.adiscon.com> >> > wrote: >> >> >> >> I am a bit confused if/how this shall relate to the imjournal rate >> >> limiter, but... well.. you may know - especially if it helped ;-) >> >> >> >> As to troubleshooting the SQL issue: did you manually try the insert >> >> statement? Did the sql server error log give you more information? >> >> >> >> Could you at least post the startup part of the debug log? Be sure to >> >> check for passwords etc. before doing so. >> >> >> >> Rainer >> >> >> >> El mar, 13 dic 2022 a las 15:21, helices >> >> (<mike+rsys...@mdsresource.net>) escribió: >> >> > >> >> > Done. >> >> > >> >> > Apparently, this issue happens mostly in the very early morning hours. >> >> > >> >> > It seems to be associated with the original issue in my original post: >> >> > >> >> > 2022-12-13T02:23:44.392947-06:00 hermes rsyslogd[2539]: action 'Sftp' >> >> > (module 'ommysql.so') message lost, could not be processed. Check for >> >> > additional error messages before this one. [v8.2212.0 try >> >> > https://www.rsyslog.com/e/2218 ] >> >> > 2022-12-13T02:23:44.399259-06:00 hermes rsyslogd[2539]: ommysql: db >> >> > error (1172): Result consisted of more than one row [v8.2212.0] >> >> > 2022-12-13T02:23:44.399470-06:00 hermes rsyslogd[2539]: The error >> >> > statement was: insert into SystemEvents (Message, Facility, FromHost, >> >> > Priority, DeviceReportedTime, ReceivedAt, InfoUnitID, SysLogTag) values >> >> > ('Received disconnect from 44.228.232.55 port 53606:11: disconnected by >> >> > user [postauth]', 10, 'hermes', 6, '20221213020903', '20221213020903', >> >> > 1, 'sshd[23880]:') [v8.2212.0 try https://www.rsyslog.com/e/2218 ] >> >> > >> >> > I remain unclear on how to get more details regarding this to a log >> >> > file. >> >> > >> >> > Thank you for your assistance. >> >> > >> >> > ~ Mike >> >> > >> >> > >> >> > >> >> > On Tue, Dec 13, 2022 at 8:01 AM Rainer Gerhards >> >> > <rgerha...@hq.adiscon.com> wrote: >> >> >> >> >> >> I would probably make sense to create a debug log, at least for >> >> >> startup, to show what actually happened. >> >> >> >> >> >> Doc: https://www.rsyslog.com/doc/master/troubleshooting/howtodebug.html >> >> >> >> >> >> Rainer >> >> >> >> >> >> El mar, 13 dic 2022 a las 15:00, helices >> >> >> (<mike+rsys...@mdsresource.net>) escribió: >> >> >> > >> >> >> > No, it still rate-limits. I verified that the restart restarted >> >> >> > rsyslogd: >> >> >> > >> >> >> > # systemctl -l status rsyslog >> >> >> > * rsyslog.service - System Logging Service >> >> >> > Loaded: loaded (/usr/lib/systemd/system/rsyslog.service; enabled; >> >> >> > vendor preset: enabled) >> >> >> > Active: active (running) since Mon 2022-12-12 13:58:40 CST; 18h >> >> >> > ago >> >> >> > Docs: man:rsyslogd(8) >> >> >> > https://www.rsyslog.com/doc/ >> >> >> > Main PID: 2539 (rsyslogd) >> >> >> > CGroup: /system.slice/rsyslog.service >> >> >> > `-2539 /usr/sbin/rsyslogd -n >> >> >> > >> >> >> > Dec 13 04:58:43 hermes.provell.com rsyslogd[2539]: -- MARK -- >> >> >> > Dec 13 05:18:43 hermes.provell.com rsyslogd[2539]: -- MARK -- >> >> >> > Dec 13 05:38:43 hermes.provell.com rsyslogd[2539]: -- MARK -- >> >> >> > Dec 13 05:58:43 hermes.provell.com rsyslogd[2539]: -- MARK -- >> >> >> > Dec 13 06:18:43 hermes.provell.com rsyslogd[2539]: -- MARK -- >> >> >> > Dec 13 06:38:43 hermes.provell.com rsyslogd[2539]: -- MARK -- >> >> >> > Dec 13 06:58:43 hermes.provell.com rsyslogd[2539]: -- MARK -- >> >> >> > Dec 13 07:18:43 hermes.provell.com rsyslogd[2539]: -- MARK -- >> >> >> > Dec 13 07:38:43 hermes.provell.com rsyslogd[2539]: -- MARK -- >> >> >> > Dec 13 07:58:43 hermes.provell.com rsyslogd[2539]: -- MARK -- >> >> >> > >> >> >> > >> >> >> > Yet, it is still rate-limiting: >> >> >> > >> >> >> > 2022-12-13T02:23:38.001127-06:00 hermes rsyslogd[2539]: >> >> >> > rsyslogd[internal_messages]: 1808 messages lost due to rate-limiting >> >> >> > (500 allowed within 5 seconds) >> >> >> > 2022-12-13T02:23:44.003241-06:00 hermes rsyslogd[2539]: >> >> >> > rsyslogd[internal_messages]: 1792 messages lost due to rate-limiting >> >> >> > (500 allowed within 5 seconds) >> >> >> > 2022-12-13T02:23:50.001278-06:00 hermes rsyslogd[2539]: >> >> >> > rsyslogd[internal_messages]: 1779 messages lost due to rate-limiting >> >> >> > (500 allowed within 5 seconds) >> >> >> > 2022-12-13T02:23:56.001273-06:00 hermes rsyslogd[2539]: >> >> >> > rsyslogd[internal_messages]: 1835 messages lost due to rate-limiting >> >> >> > (500 allowed within 5 seconds) >> >> >> > 2022-12-13T02:24:02.005300-06:00 hermes rsyslogd[2539]: >> >> >> > rsyslogd[internal_messages]: 1768 messages lost due to rate-limiting >> >> >> > (500 allowed within 5 seconds) >> >> >> > >> >> >> > >> >> >> > Please, advise. Thank you. >> >> >> > >> >> >> > >> >> >> > On Mon, Dec 12, 2022 at 2:03 PM helices >> >> >> > <mike+rsys...@mdsresource.net> wrote: >> >> >> >> >> >> >> >> I just now restarted again, like this: >> >> >> >> >> >> >> >> # systemctl restart rsyslog >> >> >> >> >> >> >> >> We'll see overnight if that does the trick. >> >> >> >> >> >> >> >> >> >> >> >> # date; grep -v "^\(#\|\s*$\)" /etc/rsyslog.conf ;date >> >> >> >> Mon Dec 12 13:56:12 CST 2022 >> >> >> >> module(load="imjournal" Ratelimit.Burst="30000" >> >> >> >> Ratelimit.Interval="1000" StateFile="imjournal.state") >> >> >> >> module(load="imklog") >> >> >> >> module(load="immark") >> >> >> >> module(load="impstats" interval="600" severity="7") >> >> >> >> syslog.=debug /var/log/rsyslog-stats >> >> >> >> module(load="imtcp") >> >> >> >> input(type="imtcp" port="514") >> >> >> >> module(load="imudp") >> >> >> >> input(type="imudp" port="514") >> >> >> >> module(load="ommysql.so") >> >> >> >> global(workDirectory="/var/lib/rsyslog") >> >> >> >> authpriv.none;cron.none;*.info;mail.none /var/log/messages >> >> >> >> authpriv.* /var/log/secure >> >> >> >> cron.* /var/log/cron >> >> >> >> *.emerg :omusrmsg:* >> >> >> >> ftp.* /var/log/vsftpd.log >> >> >> >> local7.* /var/log/boot.log >> >> >> >> mail.* /var/log/maillog >> >> >> >> uucp,news.crit /var/log/spooler >> >> >> >> $ActionName Ftp >> >> >> >> $ActionQueueFileName dbFtpQueue # Set file name, also enables >> >> >> >> disk mode >> >> >> >> $ActionQueueSaveOnShutdown on # Save messages to disk on >> >> >> >> shutdown >> >> >> >> $ActionQueueType LinkedList # Use asynchronous processing >> >> >> >> $ActionResumeRetryCount -1 # Infinite retries on insert >> >> >> >> failure >> >> >> >> ftp.* >> >> >> >> :ommysql:10.199.5.177,vsftplog,hermesvsftplog,_____ >> >> >> >> $ActionName Sftp >> >> >> >> $ActionQueueFileName dbSftpQueue # Set file name, also enables >> >> >> >> disk mode >> >> >> >> $ActionQueueSaveOnShutdown on # Save messages to disk on >> >> >> >> shutdown >> >> >> >> $ActionQueueType LinkedList # Use asynchronous processing >> >> >> >> $ActionResumeRetryCount -1 # Infinite retries on insert >> >> >> >> failure >> >> >> >> authpriv.* >> >> >> >> :ommysql:10.199.5.177,sftplogDB,hermesvsftplog,_____ >> >> >> >> $ActionName Admin >> >> >> >> $ActionQueueFileName ZenossQueue # Set file name, also enables >> >> >> >> disk mode >> >> >> >> $ActionQueueSaveOnShutdown on # Save messages to disk on >> >> >> >> shutdown >> >> >> >> $ActionQueueType LinkedList # Use asynchronous processing >> >> >> >> $ActionResumeRetryCount -1 # Infinite retries on insert >> >> >> >> failure >> >> >> >> *.* @@10.199.1.160 >> >> >> >> Mon Dec 12 13:56:12 CST 2022 >> >> >> >> >> >> >> >> On Mon, Dec 12, 2022 at 1:34 PM David Lang <da...@lang.hm> wrote: >> >> >> >>> >> >> >> >>> did you do a full restart after making the change? can you show >> >> >> >>> the full config? >> >> >> >>> >> >> >> >>> the messages you are showing are saying taht the config line you >> >> >> >>> show isn't >> >> >> >>> being used. >> >> >> >>> >> >> >> >>> David Lang >> >> >> >>> >> >> >> >>> On Mon, 12 Dec 2022, helices via rsyslog wrote: >> >> >> >>> >> >> >> >>> > Date: Mon, 12 Dec 2022 12:39:54 -0600 >> >> >> >>> > From: helices via rsyslog <rsyslog@lists.adiscon.com> >> >> >> >>> > To: Rainer Gerhards <rgerha...@hq.adiscon.com> >> >> >> >>> > Cc: helices <mike+rsys...@mdsresource.net>, >> >> >> >>> > rsyslog-users <rsyslog@lists.adiscon.com> >> >> >> >>> > Subject: Re: [rsyslog] Rsyslogd/ommysql.so: Not writing to DB >> >> >> >>> > intermittently >> >> >> >>> > >> >> >> >>> > We're still missing something: >> >> >> >>> > >> >> >> >>> > module(load="imjournal" Ratelimit.Burst="30000" >> >> >> >>> > Ratelimit.Interval="1000" >> >> >> >>> > StateFile="imjournal.state") >> >> >> >>> > >> >> >> >>> > >> >> >> >>> > 2022-12-12T00:53:14.001626-06:00 hermes rsyslogd[1536]: >> >> >> >>> > rsyslogd[internal_messages]: 1728 messages lost due to >> >> >> >>> > rate-limiting (500 >> >> >> >>> > allowed within 5 seconds) >> >> >> >>> > 2022-12-12T00:53:20.004006-06:00 hermes rsyslogd[1536]: >> >> >> >>> > rsyslogd[internal_messages]: 1818 messages lost due to >> >> >> >>> > rate-limiting (500 >> >> >> >>> > allowed within 5 seconds) >> >> >> >>> > 2022-12-12T00:53:26.003870-06:00 hermes rsyslogd[1536]: >> >> >> >>> > rsyslogd[internal_messages]: 1794 messages lost due to >> >> >> >>> > rate-limiting (500 >> >> >> >>> > allowed within 5 seconds) >> >> >> >>> > 2022-12-12T00:53:32.005388-06:00 hermes rsyslogd[1536]: >> >> >> >>> > rsyslogd[internal_messages]: 1797 messages lost due to >> >> >> >>> > rate-limiting (500 >> >> >> >>> > allowed within 5 seconds) >> >> >> >>> > 2022-12-12T00:53:38.001367-06:00 hermes rsyslogd[1536]: >> >> >> >>> > rsyslogd[internal_messages]: 1812 messages lost due to >> >> >> >>> > rate-limiting (500 >> >> >> >>> > allowed within 5 seconds) >> >> >> >>> > 2022-12-12T00:53:44.006085-06:00 hermes rsyslogd[1536]: >> >> >> >>> > rsyslogd[internal_messages]: 1791 messages lost due to >> >> >> >>> > rate-limiting (500 >> >> >> >>> > allowed within 5 seconds) >> >> >> >>> > 2022-12-12T00:53:50.005487-06:00 hermes rsyslogd[1536]: >> >> >> >>> > rsyslogd[internal_messages]: 1797 messages lost due to >> >> >> >>> > rate-limiting (500 >> >> >> >>> > allowed within 5 seconds) >> >> >> >>> > 2022-12-12T00:53:56.001546-06:00 hermes rsyslogd[1536]: >> >> >> >>> > rsyslogd[internal_messages]: 1808 messages lost due to >> >> >> >>> > rate-limiting (500 >> >> >> >>> > allowed within 5 seconds) >> >> >> >>> > 2022-12-12T00:54:02.007743-06:00 hermes rsyslogd[1536]: >> >> >> >>> > rsyslogd[internal_messages]: 1759 messages lost due to >> >> >> >>> > rate-limiting (500 >> >> >> >>> > allowed within 5 seconds) >> >> >> >>> > >> >> >> >>> > >> >> >> >>> > What are we missing? >> >> >> >>> > >> >> >> >>> > Please, advise. Thank you. >> >> >> >>> > >> >> >> >>> > >> >> >> >>> > On Fri, Dec 9, 2022 at 8:49 AM Rainer Gerhards >> >> >> >>> > <rgerha...@hq.adiscon.com> >> >> >> >>> > wrote: >> >> >> >>> > >> >> >> >>> >> you set the interval, but not ratelimit.burst >> >> >> >>> >> >> >> >> >>> >> doc: >> >> >> >>> >> https://www.rsyslog.com/doc/v8-stable/configuration/modules/imjournal.html >> >> >> >>> >> >> >> >> >>> >> Rainer >> >> >> >>> >> >> >> >> >>> >> El mar, 6 dic 2022 a las 15:16, helices via rsyslog >> >> >> >>> >> (<rsyslog@lists.adiscon.com>) escribió: >> >> >> >>> >> > >> >> >> >>> >> > David, >> >> >> >>> >> > >> >> >> >>> >> > What am I doing wrong? >> >> >> >>> >> > >> >> >> >>> >> > module(load="imjournal" Ratelimit.Interval="10000" >> >> >> >>> >> > StateFile="imjournal.state") >> >> >> >>> >> > >> >> >> >>> >> > 2022-12-06T07:19:26.004772-06:00 hermes rsyslogd[29735]: >> >> >> >>> >> > rsyslogd[internal_messages]: 1755 messages lost due to >> >> >> >>> >> > rate-limiting (500 >> >> >> >>> >> > allowed within 5 seconds) >> >> >> >>> >> > >> >> >> >>> >> > Please, advise. Thank you. >> >> >> >>> >> > >> >> >> >>> >> > ~ Mike >> >> >> >>> >> > >> >> >> >>> >> > >> >> >> >>> >> > >> >> >> >>> >> > On Thu, Dec 1, 2022 at 3:12 PM David Lang <da...@lang.hm> >> >> >> >>> >> > wrote: >> >> >> >>> >> > >> >> >> >>> >> > > On Thu, 1 Dec 2022, helices wrote: >> >> >> >>> >> > > >> >> >> >>> >> > > > [1] What is "action() syntax?" Which lines ought to be >> >> >> >>> >> > > > converted? >> >> >> >>> >> How? >> >> >> >>> >> > > >> >> >> >>> >> > > >> >> >> >>> >> > > >> >> >> >>> >> https://www.rsyslog.com/doc/master/configuration/basic_structure.html#statement-types >> >> >> >>> >> > > >> >> >> >>> >> > > instead of >> >> >> >>> >> > > >> >> >> >>> >> > > @@10.0.0.1 >> >> >> >>> >> > > >> >> >> >>> >> > > you would do >> >> >> >>> >> > > >> >> >> >>> >> > > action(type="omfwd" target="10.0.0.1" port="514" >> >> >> >>> >> > > protocol="tcp") >> >> >> >>> >> > > >> >> >> >>> >> > > for this trivial example, the earlier syntax makes more >> >> >> >>> >> > > sense, but when >> >> >> >>> >> > > you have >> >> >> >>> >> > > more complex things (like the queues that you have), adding >> >> >> >>> >> > > them all >> >> >> >>> >> into >> >> >> >>> >> > > the >> >> >> >>> >> > > action makes it clearer exactly what is happening >> >> >> >>> >> > > >> >> >> >>> >> > > >> >> >> >>> >> > > so you currently have >> >> >> >>> >> > > >> >> >> >>> >> > > >>> $ActionName Admin >> >> >> >>> >> > > >>> $ActionQueueDequeueSlowdown 1000 # How long (in >> >> >> >>> >> > > >>> microseconds) >> >> >> >>> >> > > dequeueing >> >> >> >>> >> > > >>> should be delayed >> >> >> >>> >> > > >>> $ActionQueueFileName ZenossQueue # Set file name, also >> >> >> >>> >> > > >>> enables >> >> >> >>> >> disk >> >> >> >>> >> > > mode >> >> >> >>> >> > > >>> $ActionQueueSaveOnShutdown on # Save messages to >> >> >> >>> >> > > >>> disk on >> >> >> >>> >> shutdown >> >> >> >>> >> > > >>> $ActionQueueType LinkedList # Use asynchronous >> >> >> >>> >> > > >>> processing >> >> >> >>> >> > > >>> $ActionResumeRetryCount -1 # Infinite retries on >> >> >> >>> >> > > >>> insert >> >> >> >>> >> failure >> >> >> >>> >> > > >>> *.* @@10.199.1.160 >> >> >> >>> >> > > >> >> >> >>> >> > > >> >> >> >>> >> > > This would be >> >> >> >>> >> > > >> >> >> >>> >> > > action(name="Admin" type="omfwd" target="10.199.1.160" >> >> >> >>> >> > > protocol="tcp" >> >> >> >>> >> > > queue.filename="ZenossQueue" queue.saveonshutdown="on" >> >> >> >>> >> > > queue.type="linkedlist" >> >> >> >>> >> > > resumeretrycount="-1" queue.dequeueslowdown="1000") >> >> >> >>> >> > > >> >> >> >>> >> > > this makes it very clear that all these parameters apply >> >> >> >>> >> > > only to this >> >> >> >>> >> > > action >> >> >> >>> >> > > (which is what the old syntax does, but it's less obvious >> >> >> >>> >> > > to people >> >> >> >>> >> that >> >> >> >>> >> > > it only >> >> >> >>> >> > > applies to the next action) >> >> >> >>> >> > > >> >> >> >>> >> > > > [2] Where is the "pause" you mention? I don't recognize >> >> >> >>> >> > > > that. >> >> >> >>> >> > > >> >> >> >>> >> > > $ActionQueueDequeueSlowdown 1000 # How long (in >> >> >> >>> >> > > microseconds) >> >> >> >>> >> dequeueing >> >> >> >>> >> > > >> >> >> >>> >> > > This tells rsyslog to pause after each batch of messages >> >> >> >>> >> > > before >> >> >> >>> >> processing >> >> >> >>> >> > > the >> >> >> >>> >> > > next batch. >> >> >> >>> >> > > >> >> >> >>> >> > > > [3] impstats? Permanently? Only for this debugging? >> >> >> >>> >> > > >> >> >> >>> >> > > I like to have it on permanently, but especially for >> >> >> >>> >> > > debugging it >> >> >> >>> >> provides >> >> >> >>> >> > > a lot >> >> >> >>> >> > > of useful info >> >> >> >>> >> > > >> >> >> >>> >> > > > [4] How to modify imjournal rate limits? >> >> >> >>> >> > > >> >> >> >>> >> > > see >> >> >> >>> >> > > >> >> >> >>> >> https://www.rsyslog.com/doc/v8-stable/configuration/modules/imjournal.html >> >> >> >>> >> > > >> >> >> >>> >> > > > [5] RSYSLOG_DebugFormat? I found this: >> >> >> >>> >> > > > https://www.rsyslog.com/doc/v8-stable/configuration/templates.html >> >> >> >>> >> - Is >> >> >> >>> >> > > > that example proper by itself? Where does this template >> >> >> >>> >> > > > go? How can I >> >> >> >>> >> > > > specify the file and location for debugging? >> >> >> >>> >> > > >> >> >> >>> >> > > as I said below >> >> >> >>> >> > > >> >> >> >>> >> > > >> ftp.* /var/log/ftp;RSYSLOG_DebugFormat (legacy format, >> >> >> >>> >> > > >> add >> >> >> >>> >> > > template="RSYSLOG_DebugFormat" to that action() format) >> >> >> >>> >> > > >> >> >> >>> >> > > > If there are URLs to inform me, I appreciate your >> >> >> >>> >> > > > direction. >> >> >> >>> >> > > >> >> >> >>> >> > > >> >> >> >>> >> https://www.rsyslog.com/doc/v8-stable/configuration/modules/imjournal.html >> >> >> >>> >> > > >> >> >> >>> >> https://www.rsyslog.com/doc/v8-stable/configuration/modules/ommysql.html >> >> >> >>> >> > > https://www.rsyslog.com/doc/v8-stable/configuration/modules/omfwd.html >> >> >> >>> >> > > https://www.rsyslog.com/doc/master/configuration/actions.html >> >> >> >>> >> > > https://www.rsyslog.com/doc/master/rainerscript/queue_parameters.html >> >> >> >>> >> > > >> >> >> >>> >> https://www.rsyslog.com/doc/v8-stable/configuration/modules/omfile.html >> >> >> >>> >> > > >> >> >> >>> >> > > feel free to keep asking questions. >> >> >> >>> >> > > >> >> >> >>> >> > > David Lang >> >> >> >>> >> > > >> >> >> >>> >> > > >> >> >> >>> >> > > > ~ Mike >> >> >> >>> >> > > > >> >> >> >>> >> > > > >> >> >> >>> >> > > > >> >> >> >>> >> > > > On Thu, Dec 1, 2022 at 1:33 PM David Lang <da...@lang.hm> >> >> >> >>> >> > > > wrote: >> >> >> >>> >> > > > >> >> >> >>> >> > > >> it would be useful to convert to the action() syntax as >> >> >> >>> >> > > >> it makes it >> >> >> >>> >> > > >> clearer >> >> >> >>> >> > > >> what's happening. >> >> >> >>> >> > > >> >> >> >> >>> >> > > >> Why are you pausing between writing logs? (this could be >> >> >> >>> >> > > >> why you are >> >> >> >>> >> > > >> dropping >> >> >> >>> >> > > >> logs) >> >> >> >>> >> > > >> >> >> >> >>> >> > > >> given the number of queues and actions, look at >> >> >> >>> >> > > >> configuring >> >> >> >>> >> impstats so >> >> >> >>> >> > > >> that you >> >> >> >>> >> > > >> can see the number of messages in the queues, number >> >> >> >>> >> > > >> processed, etc. >> >> >> >>> >> > > >> >> >> >> >>> >> > > >> imjournal defaults to some fairly aggressive rate >> >> >> >>> >> > > >> limiting, I find >> >> >> >>> >> that >> >> >> >>> >> > > I >> >> >> >>> >> > > >> always >> >> >> >>> >> > > >> need to drastically increase the limits. >> >> >> >>> >> > > >> >> >> >> >>> >> > > >> writing logs using the RSYSLOG_DebugFormat is adding the >> >> >> >>> >> > > >> template >> >> >> >>> >> to the >> >> >> >>> >> > > >> file >> >> >> >>> >> > > >> >> >> >> >>> >> > > >> ftp.* /var/log/ftp;RSYSLOG_DebugFormat (legacy format, >> >> >> >>> >> > > >> add >> >> >> >>> >> > > >> template="RSYSLOG_DebugFormat" to that action() format) >> >> >> >>> >> > > >> >> >> >> >>> >> > > >> the debug format is large, but you really need to see >> >> >> >>> >> > > >> the message >> >> >> >>> >> that's >> >> >> >>> >> > > >> failing >> >> >> >>> >> > > >> to figure out why it's failing. The MySQL logs may give >> >> >> >>> >> > > >> you better >> >> >> >>> >> info >> >> >> >>> >> > > on >> >> >> >>> >> > > >> that. >> >> >> >>> >> > > >> >> >> >> >>> >> > > >> David Lang >> >> >> >>> >> > > >> >> >> >> >>> >> > > >> On Thu, 1 Dec 2022, helices wrote: >> >> >> >>> >> > > >> >> >> >> >>> >> > > >>> Date: Thu, 1 Dec 2022 13:26:47 -0600 >> >> >> >>> >> > > >>> From: helices <mike+rsys...@mdsresource.net> >> >> >> >>> >> > > >>> To: David Lang <da...@lang.hm> >> >> >> >>> >> > > >>> Cc: helices via rsyslog <rsyslog@lists.adiscon.com> >> >> >> >>> >> > > >>> Subject: Re: [rsyslog] Rsyslogd/ommysql.so: Not writing >> >> >> >>> >> > > >>> to DB >> >> >> >>> >> > > >> intermittently >> >> >> >>> >> > > >>> >> >> >> >>> >> > > >>> Thank you. >> >> >> >>> >> > > >>> >> >> >> >>> >> > > >>> [1] rsyslog.conf >> >> >> >>> >> > > >>> >> >> >> >>> >> > > >>> # date; grep -v "^\(#\|\s*$\)" /etc/rsyslog.conf ;date >> >> >> >>> >> > > >>> Thu Dec 1 13:19:34 CST 2022 >> >> >> >>> >> > > >>> module(load="imjournal" StateFile="imjournal.state") >> >> >> >>> >> > > >>> module(load="imklog") >> >> >> >>> >> > > >>> module(load="immark") >> >> >> >>> >> > > >>> module(load="impstats" interval="600" severity="7") >> >> >> >>> >> > > >>> syslog.=debug /var/log/rsyslog-stats >> >> >> >>> >> > > >>> module(load="imtcp") >> >> >> >>> >> > > >>> input(type="imtcp" port="514") >> >> >> >>> >> > > >>> module(load="imudp") >> >> >> >>> >> > > >>> input(type="imudp" port="514") >> >> >> >>> >> > > >>> module(load="ommysql.so") >> >> >> >>> >> > > >>> global(workDirectory="/var/lib/rsyslog") >> >> >> >>> >> > > >>> authpriv.none;cron.none;*.info;mail.none >> >> >> >>> >> > > >>> /var/log/messages >> >> >> >>> >> > > >>> authpriv.* >> >> >> >>> >> > > >>> /var/log/secure >> >> >> >>> >> > > >>> cron.* >> >> >> >>> >> > > >>> /var/log/cron >> >> >> >>> >> > > >>> *.emerg :omusrmsg:* >> >> >> >>> >> > > >>> ftp.* >> >> >> >>> >> > > >>> /var/log/vsftpd.log >> >> >> >>> >> > > >>> local7.* >> >> >> >>> >> > > >>> /var/log/boot.log >> >> >> >>> >> > > >>> mail.* >> >> >> >>> >> > > >>> /var/log/maillog >> >> >> >>> >> > > >>> uucp,news.crit >> >> >> >>> >> > > >>> /var/log/spooler >> >> >> >>> >> > > >>> $ActionName Ftp >> >> >> >>> >> > > >>> $ActionQueueDequeueSlowdown 1000 # How long (in >> >> >> >>> >> > > >>> microseconds) >> >> >> >>> >> > > dequeueing >> >> >> >>> >> > > >>> should be delayed >> >> >> >>> >> > > >>> $ActionQueueFileName dbFtpQueue # Set file name, also >> >> >> >>> >> > > >>> enables >> >> >> >>> >> disk >> >> >> >>> >> > > mode >> >> >> >>> >> > > >>> $ActionQueueSaveOnShutdown on # Save messages to >> >> >> >>> >> > > >>> disk on >> >> >> >>> >> shutdown >> >> >> >>> >> > > >>> $ActionQueueType LinkedList # Use asynchronous >> >> >> >>> >> > > >>> processing >> >> >> >>> >> > > >>> $ActionResumeRetryCount -1 # Infinite retries on >> >> >> >>> >> > > >>> insert >> >> >> >>> >> failure >> >> >> >>> >> > > >>> ftp.* >> >> >> >>> >> > > >>> :ommysql:10.199.5.177,vsftplog,hermesvsftplog,_____ >> >> >> >>> >> > > >>> $ActionName Sftp >> >> >> >>> >> > > >>> $ActionQueueDequeueSlowdown 1000 # How long (in >> >> >> >>> >> > > >>> microseconds) >> >> >> >>> >> > > >> dequeueing >> >> >> >>> >> > > >>> should be delayed >> >> >> >>> >> > > >>> $ActionQueueFileName dbSftpQueue # Set file name, >> >> >> >>> >> > > >>> also enables >> >> >> >>> >> disk >> >> >> >>> >> > > >> mode >> >> >> >>> >> > > >>> $ActionQueueSaveOnShutdown on # Save messages to >> >> >> >>> >> > > >>> disk on >> >> >> >>> >> shutdown >> >> >> >>> >> > > >>> $ActionQueueType LinkedList # Use asynchronous >> >> >> >>> >> > > >>> processing >> >> >> >>> >> > > >>> $ActionResumeRetryCount -1 # Infinite retries >> >> >> >>> >> > > >>> on insert >> >> >> >>> >> failure >> >> >> >>> >> > > >>> authpriv.* >> >> >> >>> >> > > >>> :ommysql:10.199.5.177,sftplogDB,hermesvsftplog,_____ >> >> >> >>> >> > > >>> $ActionName Admin >> >> >> >>> >> > > >>> $ActionQueueDequeueSlowdown 1000 # How long (in >> >> >> >>> >> > > >>> microseconds) >> >> >> >>> >> > > dequeueing >> >> >> >>> >> > > >>> should be delayed >> >> >> >>> >> > > >>> $ActionQueueFileName ZenossQueue # Set file name, also >> >> >> >>> >> > > >>> enables >> >> >> >>> >> disk >> >> >> >>> >> > > mode >> >> >> >>> >> > > >>> $ActionQueueSaveOnShutdown on # Save messages to >> >> >> >>> >> > > >>> disk on >> >> >> >>> >> shutdown >> >> >> >>> >> > > >>> $ActionQueueType LinkedList # Use asynchronous >> >> >> >>> >> > > >>> processing >> >> >> >>> >> > > >>> $ActionResumeRetryCount -1 # Infinite retries on >> >> >> >>> >> > > >>> insert >> >> >> >>> >> failure >> >> >> >>> >> > > >>> *.* @@10.199.1.160 >> >> >> >>> >> > > >>> Thu Dec 1 13:19:34 CST 2022 >> >> >> >>> >> > > >>> >> >> >> >>> >> > > >>> >> >> >> >>> >> > > >>> [2] How do we "log the message with the template >> >> >> >>> >> RSYSLOG_DebugFormat >> >> >> >>> >> > > to a >> >> >> >>> >> > > >>> file?" How much disk space is needed? This problem >> >> >> >>> >> > > >>> appears to have >> >> >> >>> >> > > >> started >> >> >> >>> >> > > >>> recently, and appears to happen once or twice per day, >> >> >> >>> >> > > >>> without a >> >> >> >>> >> common >> >> >> >>> >> > > >>> time. >> >> >> >>> >> > > >>> >> >> >> >>> >> > > >>> [3] I didn't notice the rate-limiting until now. It is >> >> >> >>> >> > > >>> not >> >> >> >>> >> uncommon. >> >> >> >>> >> > > How >> >> >> >>> >> > > >>> can we avoid losing so many messages? >> >> >> >>> >> > > >>> >> >> >> >>> >> > > >>> ~ Mike >> >> >> >>> >> > > >>> >> >> >> >>> >> > > >>> >> >> >> >>> >> > > >>> On Thu, Dec 1, 2022 at 1:05 PM David Lang >> >> >> >>> >> > > >>> <da...@lang.hm> wrote: >> >> >> >>> >> > > >>> >> >> >> >>> >> > > >>>> please post your full config. >> >> >> >>> >> > > >>>> >> >> >> >>> >> > > >>>> It would also help to log the message with the template >> >> >> >>> >> > > >>>> RSYSLOG_DebugFormat to a >> >> >> >>> >> > > >>>> file and find the log entry that is failing to insert. >> >> >> >>> >> > > >>>> >> >> >> >>> >> > > >>>> my guess is that the quotes in the message are >> >> >> >>> >> > > >>>> confusing mysql >> >> >> >>> >> > > >>>> >> >> >> >>> >> > > >>>> note that rate limiting is throwing away messages >> >> >> >>> >> > > >>>> because you are >> >> >> >>> >> > > trying >> >> >> >>> >> > > >>>> to >> >> >> >>> >> > > >>>> process them too fast. >> >> >> >>> >> > > >>>> >> >> >> >>> >> > > >>>> David Lang >> >> >> >>> >> > > >>>> >> >> >> >>> >> > > >>>> On Thu, 1 Dec 2022, helices via rsyslog wrote: >> >> >> >>> >> > > >>>> >> >> >> >>> >> > > >>>>> Date: Thu, 1 Dec 2022 10:08:01 -0600 >> >> >> >>> >> > > >>>>> From: helices via rsyslog <rsyslog@lists.adiscon.com> >> >> >> >>> >> > > >>>>> To: rsyslog-users <rsyslog@lists.adiscon.com> >> >> >> >>> >> > > >>>>> Cc: helices <mike+rsys...@mdsresource.net> >> >> >> >>> >> > > >>>>> Subject: [rsyslog] Rsyslogd/ommysql.so: Not writing >> >> >> >>> >> > > >>>>> to DB >> >> >> >>> >> > > >> intermittently >> >> >> >>> >> > > >>>>> >> >> >> >>> >> > > >>>>> # date; /bin/yum list rsyslog rsyslog-mysql ;date >> >> >> >>> >> > > >>>>> Thu Dec 1 09:47:18 CST 2022 >> >> >> >>> >> > > >>>>> Loaded plugins: fastestmirror >> >> >> >>> >> > > >>>>> Loading mirror speeds from cached hostfile >> >> >> >>> >> > > >>>>> * base: download.cf.centos.org >> >> >> >>> >> > > >>>>> * epel: mirror.genesisadaptive.com >> >> >> >>> >> > > >>>>> * extras: download.cf.centos.org >> >> >> >>> >> > > >>>>> * remi-php56: mirror.pit.teraswitch.com >> >> >> >>> >> > > >>>>> * remi-safe: mirror.pit.teraswitch.com >> >> >> >>> >> > > >>>>> * updates: download.cf.centos.org >> >> >> >>> >> > > >>>>> Installed Packages >> >> >> >>> >> > > >>>>> rsyslog.x86_64 >> >> >> >>> >> > > 8.2210.0-1.el7 >> >> >> >>> >> > > >>>>> @rsyslog_v8 >> >> >> >>> >> > > >>>>> rsyslog-mysql.x86_64 >> >> >> >>> >> > > 8.2210.0-1.el7 >> >> >> >>> >> > > >>>>> @rsyslog_v8 >> >> >> >>> >> > > >>>>> Thu Dec 1 09:47:19 CST 2022 >> >> >> >>> >> > > >>>>> >> >> >> >>> >> > > >>>>> >> >> >> >>> >> > > >>>>> Sample of numerous error messages (/var/log/messages): >> >> >> >>> >> > > >>>>> rsyslogd[17344]: ommysql: db error (1172): Result >> >> >> >>> >> > > >>>>> consisted of >> >> >> >>> >> more >> >> >> >>> >> > > >> than >> >> >> >>> >> > > >>>>> one row [v8.2210.0] >> >> >> >>> >> > > >>>>> rsyslogd[17344]: The error statement was: insert into >> >> >> >>> >> SystemEvents >> >> >> >>> >> > > >>>>> (Message, Facility, FromHost, Priority, >> >> >> >>> >> > > >>>>> DeviceReportedTime, >> >> >> >>> >> > > ReceivedAt, >> >> >> >>> >> > > >>>>> InfoUnitID, SysLogTag) values ('close >> >> >> >>> >> > > >>>>> "/incoming/wood.pgez.scen.11302022.sa.pgp" bytes read >> >> >> >>> >> > > >>>>> 0 written >> >> >> >>> >> 2603 >> >> >> >>> >> > > >>>>> [postauth]', 10, 'hermes', 6, '20221201081257', >> >> >> >>> >> '20221201081257', 1, >> >> >> >>> >> > > >>>>> 'sshd[19654]:') [v8.2210.0 try >> >> >> >>> >> > > >>>>> https://www.rsyslog.com/e/2218 ] >> >> >> >>> >> > > >>>>> rsyslogd[17344]: rsyslogd[internal_messages]: 215 >> >> >> >>> >> > > >>>>> messages lost >> >> >> >>> >> due >> >> >> >>> >> > > to >> >> >> >>> >> > > >>>>> rate-limiting (500 allowed within 5 seconds) >> >> >> >>> >> > > >>>>> rsyslogd[17344]: action 'Sftp' (module 'ommysql.so') >> >> >> >>> >> > > >>>>> message >> >> >> >>> >> lost, >> >> >> >>> >> > > >> could >> >> >> >>> >> > > >>>>> not be processed. Check for additional error messages >> >> >> >>> >> > > >>>>> before this >> >> >> >>> >> > > one. >> >> >> >>> >> > > >>>>> [v8.2210.0 try https://www.rsyslog.com/e/2218 ] >> >> >> >>> >> > > >>>>> >> >> >> >>> >> > > >>>>> >> >> >> >>> >> > > >>>>> We have been writing all data from Internet file >> >> >> >>> >> > > >>>>> transfers to a >> >> >> >>> >> Mysql >> >> >> >>> >> > > >>>> table >> >> >> >>> >> > > >>>>> for years. Recently, we began seeing intermittent >> >> >> >>> >> > > >>>>> errors like >> >> >> >>> >> those >> >> >> >>> >> > > >>>> above. >> >> >> >>> >> > > >>>>> >> >> >> >>> >> > > >>>>> What is happening here? >> >> >> >>> >> > > >>>>> >> >> >> >>> >> > > >>>>> What can we do to fix this problem? >> >> >> >>> >> > > >>>>> >> >> >> >>> >> > > >>>>> Please, advise. Thank you. >> >> >> >>> >> > > >>>>> >> >> >> >>> >> > > >>>>> ~ Mike >> >> >> >>> >> > > >>>>> _______________________________________________ >> >> >> >>> >> > > >>>>> 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. >> >> >> >>> >> >> >> >> >>> > _______________________________________________ >> >> >> >>> > 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.
