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.
