Neither the errors nor rate-limiting occurred since early yesterday (12/13) morning, examples of which I've already posted.
The sole intent of the database logging is tracking all incoming remote file transfer (SFTP) activities. There is a firewall between this host and the internet. Only "whitelisted" IP addresses can get through, and are to be inserted into the database. Apparently, at least one client connects in the early morning hours, and this unusual SFTP unusual activity results in multi-line syslog entries that come in very large numbers. One problem is, the multiple line entries are not written to /var/log/messages, are not inserted into the database, and rate-limiting obscures all content. Hence, this support request is our attempt to understand what is happening, after which we can act to correct these problems. Interestingly, we are not aware of any missing files from this or any other file transfer clients. On Wed, Dec 14, 2022 at 2:54 AM Rainer Gerhards <rgerha...@hq.adiscon.com> wrote: > 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.
