On 18.10.2011 20:06, Andreas Piesk wrote:
> On 18.10.2011 08:39, Rainer Gerhards wrote:
>>
>> Indeed and that is another story. Of course, that should not be blocked.
>> Trying to dig deeper into the issue: what happens if you do not monitor the
>> file but just use syslog() input. Does it then block?
>>
> 
> no, without any file monitors it does not block.
> even if i have a file monitor configured but do not write into the monitored 
> file is does not block.
> 

any news on this issue?

in the meantime i tested your idea of changing imfile's flow control type:

# cat rsyslog-filedelay.patch
diff -Purp rsyslog-5.8.6/plugins/imfile/imfile.c 
rsyslog-5.8.6.mod/plugins/imfile/imfile.c
--- rsyslog-5.8.6/plugins/imfile/imfile.c       2011-10-21 11:53:02.000000000 
+0200
+++ rsyslog-5.8.6.mod/plugins/imfile/imfile.c   2011-10-24 21:05:30.000000000 
+0200
@@ -113,7 +113,7 @@ static rsRetVal enqLine(fileInfo_t *pInf
        }

        CHKiRet(msgConstruct(&pMsg));
-       MsgSetFlowControlType(pMsg, eFLOWCTL_FULL_DELAY);
+       MsgSetFlowControlType(pMsg, eFLOWCTL_LIGHT_DELAY);
        MsgSetInputName(pMsg, pInputName);
        MsgSetRawMsg(pMsg, (char*)rsCStrGetSzStr(cstrLine), cstrLen(cstrLine));
        MsgSetMSGoffs(pMsg, 0); /* we do not have a header... */

the good news: it doesn't block anymore.
the bad news: the message order changes when the backlog is transferred to the 
logserver.

this is how i tested it using the latest 5.8.6 on 64bit with the same config as 
before:

the message generator generates messages with a timestamp and a counter:

# typeset -i i=0; while true; do echo "$(date) : $i"; echo "$(date) : $i" >> 
/var/log/test.log; echo
"$(date) : $i" | logger; i=$i+1; sleep 1; done

after re-enabling the network access to the syslog server the incoming messages 
have not the same
order as they were generated, this happens for both syslog and imfile messages. 
the '..' denotes
blocks with sequential counter values.

messages written by syslog():

2011-10-24T21:36:09.876045+02:00 gold-centos5-x86_64 test: Mon Oct 24 21:36:08 
CEST 2011 : 26
2011-10-24T21:36:09.876152+02:00 gold-centos5-x86_64 test: Mon Oct 24 21:36:09 
CEST 2011 : 27
<network blocked, re-enabled>
2011-10-24T21:36:19.876794+02:00 gold-centos5-x86_64 test: Mon Oct 24 21:36:10 
CEST 2011 : 28
2011-10-24T21:36:19.876825+02:00 gold-centos5-x86_64 test: Mon Oct 24 21:36:11 
CEST 2011 : 29
..
2011-10-24T21:38:58.194452+02:00 gold-centos5-x86_64 logger: Mon Oct 24 
21:38:58 CEST 2011 : 190
2011-10-24T21:38:59.230003+02:00 gold-centos5-x86_64 logger: Mon Oct 24 
21:38:59 CEST 2011 : 191
2011-10-24T21:44:31.663370+02:00 gold-centos5-x86_64 logger: Mon Oct 24 
21:44:31 CEST 2011 : 512
2011-10-24T21:44:32.697829+02:00 gold-centos5-x86_64 logger: Mon Oct 24 
21:44:32 CEST 2011 : 513
..
2011-10-24T21:47:41.191575+02:00 gold-centos5-x86_64 logger: Mon Oct 24 
21:47:41 CEST 2011 : 695
2011-10-24T21:47:42.225602+02:00 gold-centos5-x86_64 logger: Mon Oct 24 
21:47:42 CEST 2011 : 696
2011-10-24T21:39:00.266370+02:00 gold-centos5-x86_64 logger: Mon Oct 24 
21:39:00 CEST 2011 : 192
2011-10-24T21:39:01.301951+02:00 gold-centos5-x86_64 logger: Mon Oct 24 
21:39:01 CEST 2011 : 193
..
2011-10-24T21:44:29.592028+02:00 gold-centos5-x86_64 logger: Mon Oct 24 
21:44:29 CEST 2011 : 510
2011-10-24T21:44:30.629308+02:00 gold-centos5-x86_64 logger: Mon Oct 24 
21:44:30 CEST 2011 : 511
2011-10-24T21:47:45.341005+02:00 gold-centos5-x86_64 logger: Mon Oct 24 
21:47:45 CEST 2011 : 699
2011-10-24T21:47:46.376808+02:00 gold-centos5-x86_64 logger: Mon Oct 24 
21:47:46 CEST 2011 : 700
2011-10-24T21:47:47.412188+02:00 gold-centos5-x86_64 logger: Mon Oct 24 
21:47:47 CEST 2011 : 701
<in sync with generator>

same for messages collected by imfile:

2011-10-24T21:36:09.876045+02:00 gold-centos5-x86_64 test: Mon Oct 24 21:36:08 
CEST 2011 : 26
2011-10-24T21:36:09.876152+02:00 gold-centos5-x86_64 test: Mon Oct 24 21:36:09 
CEST 2011 : 27
<network blocked, re-enabled>
2011-10-24T21:36:19.876794+02:00 gold-centos5-x86_64 test: Mon Oct 24 21:36:10 
CEST 2011 : 28
2011-10-24T21:36:19.876825+02:00 gold-centos5-x86_64 test: Mon Oct 24 21:36:11 
CEST 2011 : 29
..
2011-10-24T21:38:59.893033+02:00 gold-centos5-x86_64 test: Mon Oct 24 21:38:58 
CEST 2011 : 190
2011-10-24T21:38:59.893036+02:00 gold-centos5-x86_64 test: Mon Oct 24 21:38:59 
CEST 2011 : 191
2011-10-24T21:44:39.925036+02:00 gold-centos5-x86_64 test: Mon Oct 24 21:44:30 
CEST 2011 : 511
2011-10-24T21:44:39.925052+02:00 gold-centos5-x86_64 test: Mon Oct 24 21:44:31 
CEST 2011 : 512
..
2011-10-24T21:47:39.942124+02:00 gold-centos5-x86_64 test: Mon Oct 24 21:47:38 
CEST 2011 : 692
2011-10-24T21:47:39.942127+02:00 gold-centos5-x86_64 test: Mon Oct 24 21:47:39 
CEST 2011 : 693
2011-10-24T21:39:09.893706+02:00 gold-centos5-x86_64 test: Mon Oct 24 21:39:00 
CEST 2011 : 192
2011-10-24T21:39:09.893718+02:00 gold-centos5-x86_64 test: Mon Oct 24 21:39:01 
CEST 2011 : 193
..
2011-10-24T21:44:29.923811+02:00 gold-centos5-x86_64 test: Mon Oct 24 21:44:28 
CEST 2011 : 509
2011-10-24T21:44:29.923814+02:00 gold-centos5-x86_64 test: Mon Oct 24 21:44:29 
CEST 2011 : 510
2011-10-24T21:47:49.943314+02:00 gold-centos5-x86_64 test: Mon Oct 24 21:47:40 
CEST 2011 : 694
2011-10-24T21:47:49.943328+02:00 gold-centos5-x86_64 test: Mon Oct 24 21:47:41 
CEST 2011 : 695
<in sync with generator>

doesn't rsyslog transfer the spool file first and then the new messages to 
preserve the order of the
messages?

i ran the same test with only syslog() writing messages and got a similar but 
worse result:

2011-10-24T22:16:19.968852+02:00 gold-centos5-x86_64 logger: Mon Oct 24 
22:16:19 CEST 2011 : 29
2011-10-24T22:16:20.997981+02:00 gold-centos5-x86_64 logger: Mon Oct 24 
22:16:20 CEST 2011 : 30
<network blocked, re-enabled>
2011-10-24T22:18:51.246842+02:00 gold-centos5-x86_64 logger: Mon Oct 24 
22:18:51 CEST 2011 : 176
2011-10-24T22:18:52.274474+02:00 gold-centos5-x86_64 logger: Mon Oct 24 
22:18:52 CEST 2011 : 177
..
2011-10-24T22:19:13.907656+02:00 gold-centos5-x86_64 logger: Mon Oct 24 
22:19:13 CEST 2011 : 198
2011-10-24T22:19:14.939596+02:00 gold-centos5-x86_64 logger: Mon Oct 24 
22:19:14 CEST 2011 : 199
2011-10-24T22:30:03.772399+02:00 gold-centos5-x86_64 logger: Mon Oct 24 
22:30:03 CEST 2011 : 828
2011-10-24T22:30:04.793107+02:00 gold-centos5-x86_64 logger: Mon Oct 24 
22:30:04 CEST 2011 : 829
<and so on>

the missing messages 31-175, almost 2min, disturb me the most.

any ideas what happened and why?

i will run some more tests with a disk queue instead of a DA queue.

regards,
-ap
_______________________________________________
rsyslog mailing list
http://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com

Reply via email to