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.
