El mié., 6 mar. 2019 a las 15:41, Peter Viskup (<[email protected]>) escribió: > > It is very old 8.15 version, cannot update at the moment. > Is there any way to reorder the queue entries?
sorry, I missed > How that could happen? first-class program bug. Dug out the issue: https://github.com/rsyslog/rsyslog/issues/1404 commit is: c49e42f4f8381fc8e92579c41cefb2c85fe45929 HTH Rainer > > On Wed, Mar 6, 2019 at 3:37 PM Rainer Gerhards <[email protected]> > wrote: >> >> El mié., 6 mar. 2019 a las 15:29, Peter Viskup (<[email protected]>) >> escribió: >> > >> > Just spent some time to get more debugging information. >> > Discovered the first queue file is always successfully processed and >> > removed by rsyslog, but then it is getting stuck. >> > The rsyslog reports opening all queue files, but also reports issues with >> > dequeueing. >> > >> > 1103.425656259:main thread : FWD queue[DA]: starting queue >> > 1103.425663333:main thread : FWD queue[DA]: .qi file name is >> > '/var/spool/rsyslog/fq_fwd.qi', len 28 >> > 1103.425669339:main thread : FWD queue[DA]: I am a child >> > 1103.425681264:main thread : file stream /var/spool/rsyslog/fq_fwd.qi >> > params: flush interval 0, async write 0 >> > 1103.425695986:main thread : file '/var/spool/rsyslog/fq_fwd.qi' opened >> > as #6 with mode 384 >> > 1103.425706903:main thread : strm 0x561bc0071b10: opened file >> > '/var/spool/rsyslog/fq_fwd.qi' for READ as 6 >> > 1103.425715579:main thread : strm 0x561bc0071b10: file 6 read 494 bytes >> > 1103.425734836:main thread : file stream fq_fwd params: flush interval >> > 0, async write 0 >> > 1103.425814667:main thread : file stream fq_fwd params: flush interval >> > 0, async write 0 >> > 1103.425825255:main thread : file stream fq_fwd params: flush interval >> > 0, async write 0 >> > 1103.425841762:main thread : file '/var/spool/rsyslog/fq_fwd.00000883' >> > opened as #7 with mode 384 >> > 1103.425852933:main thread : strm 0x561bc0072f50: opened file >> > '/var/spool/rsyslog/fq_fwd.00000883' for WRITE as 7 >> > 1103.425859374:main thread : strm 0x561bc0072f50: file 7 seek, pos >> > 909312 >> > 1103.425870898:main thread : file '/var/spool/rsyslog/fq_fwd.00000003' >> > opened as #8 with mode 384 >> > 1103.425879677:main thread : strm 0x561bc0074370: opened file >> > '/var/spool/rsyslog/fq_fwd.00000003' for READ as 8 >> > 1103.425885753:main thread : strm 0x561bc0074370: file 8 seek, pos 0 >> > 1103.425896027:main thread : file '/var/spool/rsyslog/fq_fwd.00000003' >> > opened as #9 with mode 384 >> > 1103.425904545:main thread : strm 0x561bc0075640: opened file >> > '/var/spool/rsyslog/fq_fwd.00000003' for READ as 9 >> > 1103.425910921:main thread : strm 0x561bc0075640: file 9 seek, pos 0 >> > 1103.425923089:main thread : strm 0x561bc0071b10: file >> > 6(/var/spool/rsyslog/fq_fwd.qi) closing >> > 1103.425998623:main thread : FWD queue[DA]: params: type 2, enq-only 0, >> > disk assisted 0, spoolDir '/var/spool/rsyslog', maxFileSz 1048576, >> > maxQSize 0, lqsize 295760, pqsize 295760, child 1, full delay -1, light >> > delay -1, deq batch size 8, high wtrmrk 0, low wtrmrk 1, discardmrk 0, max >> > wrkr 1, min msgs f. wrkr 0 >> > 1103.426008834:main thread : FWD queue[DA]:Reg: finalizing construction >> > of worker thread pool (numworkerThreads 1) >> > 1103.426015987:main thread : FWD queue[DA]:Reg/w0: finalizing >> > construction of worker instance data (for 4 actions) >> > 1103.426022435:main thread : FWD queue[DA]: queue finished >> > initialization >> > 1103.426028716:main thread : FWD queue[DA]:Reg: high activity - >> > starting 1 additional worker thread(s). >> > 1103.426076030:main thread : FWD queue[DA]:Reg: started with state 0, >> > num workers now 1 >> > 1103.426086592:main thread : FWD queue: DA queue initialized, disk >> > queue 0x561bc0071740 >> > 1103.426093044:main thread : FWD queue: queue finished initialization >> > 1103.426100687:main thread : Action builtin:omfwd[0x561bc0061fc0]: >> > queue 0x561bc006eb90 started >> > 1103.426107448:main thread : Activating Ruleset Queue[(nil)] for >> > Ruleset RSYSLOG_DefaultRuleset >> > ....(lines with main queue init) >> > 1103.427736595:FWD queue[DA]:Reg/w0: strm 0x561bc0075640: file 9 read 4096 >> > bytes >> > 1103.427781297:FWD queue[DA]:Reg/w0: FWD queue[DA]: error -2308 dequeueing >> > element - ignoring, but strange things may happen >> >> I guess this is the root cause. It is: >> >> RS_RET_DS_PROP_SEQ_ERR = -2308,/**< property sequence error >> deserializing object */ >> >> So it looks like the properties are not within proper sequence inside >> the queue file. I remember we had some issues with some older versions >> (2 yrs ago?) but haven't heard that since then. If it is rsyslog >> current (8.1901 or later), I'd say there is an issue with the queue >> file itself. We then need to have a look at it's content. >> >> Rainer >> >> > 1103.427819347:FWD queue[DA]:Reg/w0: regular consumer finished, >> > iret=-2308, szlog 295759 sz phys 295760 >> > 1103.427826789:FWD queue[DA]:Reg/w0: DeleteProcessedBatch: we deleted 0 >> > objects and enqueued 0 objects >> > 1103.427833027:FWD queue[DA]:Reg/w0: doDeleteBatch: delete batch from >> > store, new sizes: log 295759, phys 295760 >> > 1103.427839158:FWD queue[DA]:Reg/w0: objDeserialize error -2029 during >> > header processing - trying to recover >> > 1103.427845810:FWD queue[DA]:Reg/w0: deserializer has possibly been able >> > to re-sync and recover, state 0 >> > 1103.427883003:FWD queue[DA]:Reg/w0: strm 0x561bc0075640: file 9 read 4096 >> > bytes >> > 1103.427913803:FWD queue[DA]:Reg/w0: FWD queue[DA]: error -2308 dequeueing >> > element - ignoring, but strange things may happen >> > 1103.427920657:FWD queue[DA]:Reg/w0: regular consumer finished, >> > iret=-2308, szlog 295758 sz phys 295760 >> > 1103.427926772:FWD queue[DA]:Reg/w0: DeleteProcessedBatch: we deleted 0 >> > objects and enqueued 0 objects >> > 1103.427932759:FWD queue[DA]:Reg/w0: doDeleteBatch: delete batch from >> > store, new sizes: log 295758, phys 295760 >> > 1103.427942303:FWD queue[DA]:Reg/w0: objDeserialize error -2029 during >> > header processing - trying to recover >> > 1103.427949142:FWD queue[DA]:Reg/w0: deserializer has possibly been able >> > to re-sync and recover, state 0 >> > ....(same log entries) >> > ....(and the same after switch to next queue file) >> > 1103.466645194:FWD queue[DA]:Reg/w0: strm 0x561bc0075640: file 9 read 4096 >> > bytes >> > 1103.466657741:FWD queue[DA]:Reg/w0: FWD queue[DA]: error -2308 dequeueing >> > element - ignoring, but strange things may happen >> > 1103.466664393:FWD queue[DA]:Reg/w0: regular consumer finished, >> > iret=-2308, szlog 295424 sz phys 295760 >> > 1103.466670503:FWD queue[DA]:Reg/w0: DeleteProcessedBatch: we deleted 0 >> > objects and enqueued 0 objects >> > 1103.466680360:FWD queue[DA]:Reg/w0: doDeleteBatch: delete batch from >> > store, new sizes: log 295424, phys 295760 >> > 1103.466686560:FWD queue[DA]:Reg/w0: objDeserialize error -2029 during >> > header processing - trying to recover >> > 1103.466726572:FWD queue[DA]:Reg/w0: deserializer has possibly been able >> > to re-sync and recover, state 0 >> > 1103.466765643:FWD queue[DA]:Reg/w0: FWD queue[DA]: error -2308 dequeueing >> > element - ignoring, but strange things may happen >> > 1103.466772781:FWD queue[DA]:Reg/w0: regular consumer finished, >> > iret=-2308, szlog 295423 sz phys 295760 >> > 1103.466779061:FWD queue[DA]:Reg/w0: DeleteProcessedBatch: we deleted 0 >> > objects and enqueued 0 objects >> > 1103.466785131:FWD queue[DA]:Reg/w0: doDeleteBatch: delete batch from >> > store, new sizes: log 295423, phys 295760 >> > 1103.466791068:FWD queue[DA]:Reg/w0: objDeserialize error -2029 during >> > header processing - trying to recover >> > 1103.466805481:FWD queue[DA]:Reg/w0: strm 0x561bc0075640: file 9 read 46 >> > bytes >> > 1103.466813286:FWD queue[DA]:Reg/w0: strm 0x561bc0075640: file 9 read 0 >> > bytes >> > 1103.466819304:FWD queue[DA]:Reg/w0: strm 0x561bc0075640: file 9 EOF >> > 1103.466830741:FWD queue[DA]:Reg/w0: strm 0x561bc0075640: file 9(fq_fwd) >> > closing >> > 1103.466855189:FWD queue[DA]:Reg/w0: file >> > '/var/spool/rsyslog/fq_fwd.00000004' opened as #9 with mode 384 >> > 1103.466865694:FWD queue[DA]:Reg/w0: strm 0x561bc0075640: opened file >> > '/var/spool/rsyslog/fq_fwd.00000004' for READ as 9 >> > 1103.467635746:FWD queue[DA]:Reg/w0: strm 0x561bc0075640: file 9 read 4096 >> > bytes >> > 1103.467646862:FWD queue[DA]:Reg/w0: deserializer has possibly been able >> > to re-sync and recover, state 0 >> > 1103.467775663:FWD queue[DA]:Reg/w0: FWD queue[DA]: error -2308 dequeueing >> > element - ignoring, but strange things may happen >> > 1103.467786682:FWD queue[DA]:Reg/w0: regular consumer finished, >> > iret=-2308, szlog 295422 sz phys 295760 >> > 1103.467793132:FWD queue[DA]:Reg/w0: DeleteProcessedBatch: we deleted 0 >> > objects and enqueued 0 objects >> > 1103.467799188:FWD queue[DA]:Reg/w0: doDeleteBatch: delete batch from >> > store, new sizes: log 295422, phys 295760 >> > 1103.467805425:FWD queue[DA]:Reg/w0: objDeserialize error -2029 during >> > header processing - trying to recover >> > 1103.467812104:FWD queue[DA]:Reg/w0: deserializer has possibly been able >> > to re-sync and recover, state 0 >> > 1103.467842910:FWD queue[DA]:Reg/w0: strm 0x561bc0075640: file 9 read 4096 >> > bytes >> > 1103.467897344:FWD queue[DA]:Reg/w0: FWD queue[DA]: error -2308 dequeueing >> > element - ignoring, but strange things may happen >> > 1103.467913962:FWD queue[DA]:Reg/w0: regular consumer finished, >> > iret=-2308, szlog 295421 sz phys 295760 >> > 1103.467957133:FWD queue[DA]:Reg/w0: DeleteProcessedBatch: we deleted 0 >> > objects and enqueued 0 objects >> > 1103.467964731:FWD queue[DA]:Reg/w0: doDeleteBatch: delete batch from >> > store, new sizes: log 295421, phys 295760 >> > 1103.467976624:FWD queue[DA]:Reg/w0: objDeserialize error -2029 during >> > header processing - trying to recover >> > 1103.467983341:FWD queue[DA]:Reg/w0: deserializer has possibly been able >> > to re-sync and recover, state 0 >> > >> > Seems strange. Any thoughts? >> > >> > Peter >> > >> > >> > On Wed, Mar 6, 2019 at 12:10 PM Rainer Gerhards <[email protected]> >> > wrote: >> >> >> >> looks like two different queue. I need the full log - or at least a >> >> couple of thousand lines around the place of where you think the error >> >> is. The 2040 seems to be pretty ok, but the .00001 file open above is >> >> not. >> >> >> >> Rainer >> >> >> >> El mié., 6 mar. 2019 a las 10:26, Peter Viskup (<[email protected]>) >> >> escribió: >> >> > >> >> > Following is complete log entry with 3 lines up and down: >> >> > >> >> > 3292.107997776:main thread : file >> >> > '/var/spool/rsyslog/fq_fwd.00000001' opened as #-1 with mode 384 >> >> > 3292.108007930:main thread : strm 0x5557282b2370: open error 2, >> >> > file '/var/spool/rsyslog/fq_fwd.00000001': No such file or directory >> >> > 3292.108014657:main thread : strm 0x5557282afb10: file >> >> > 6(/var/spool/rsyslog/fq_fwd.qi) closing >> >> > 3292.108023902:main thread : FWD queue[DA]: state -2040 reading .qi >> >> > file - can not read persisted info (if any) >> >> > 3292.108030552:main thread : file stream N/A params: flush interval >> >> > 0, async write 0 >> >> > 3292.108043010:main thread : file stream N/A params: flush interval >> >> > 0, async write 0 >> >> > 3292.108052306:main thread : file stream N/A params: flush interval >> >> > 0, async write 0 >> >> > >> >> > Peter >> >> > >> >> > On Tue, Mar 5, 2019 at 3:05 PM Rainer Gerhards >> >> > <[email protected]> wrote: >> >> > > >> >> > > El mar., 5 mar. 2019 a las 15:00, Peter Viskup via rsyslog >> >> > > (<[email protected]>) escribió: >> >> > > > >> >> > > > After rsyslog crash and recover.qi.pl run the DA queue is not >> >> > > > dequeued. >> >> > > > Rsyslog debug prints the message from queue.c file [1]. >> >> > > > What is could be the reason for this? Only some servers are affected >> >> > > > by this issue. Others dequeue just fine. >> >> > > >> >> > > What's the state reported in the message? >> >> > > >> >> > > Rainer >> >> > > > >> >> > > > [1] >> >> > > > https://github.com/rsyslog/rsyslog/blob/master/runtime/queue.c#L863 >> >> > > > >> >> > > > Peter >> >> > > > _______________________________________________ >> >> > > > rsyslog mailing list >> >> > > > http://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 http://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.
