Re: logging problems - Pipe Shut
Ah, OK, you won't be able to process log files larger than about 2 GB on a 32-bit machine. I should probably figure out a way to get around that. Ok, now I have set up /var/log/varnish/varnish.log to rotate every hour, and a postrotate action on that to pipe through varnishncsa and append to /var/log/varnish/varnish.access_log which in turn gets rotated and processed by awstats dayly. That should take care of the 2G limit in varnishncsa at least. I was hoping it would help with the logging it self but apparently not.. I have about 20 logfiles by now, all under 100M, and have made various observations: Everything went well during the night. The accesstimes are about a minute past the hour, and the last date string in the log corresponds with that. Then at 09:13 suddenly it's all Pipe Shut read(read) and Pipe Shut write(read) again. The situation when I noticed this, about 12:30, this was in 'log.1' whith modtime 09:13 and 'log' was still 0 bytes. I guess that just means warnishlog had stopped responding to SIGHUP. Wil try to do a restart insted in postrotate to see if runningtime has anything to do with it. That's the logging problem, now for the processing problem: I made a small script to run varnish(log|ncsa) on every file and get the returnstatus. log works fine, and a tail of that diplays sensible output and timestamps, but ncsa segfaults on about half of them. No pattern discernible.. I tried to make a small python script to feed a log chunk by chunk into ncsa on stdin, but I was not able to make that work reliably enough to get any hint what precisely is causing the problem. Don't even know if ncsa can work like that.. Tried to look for the last output lines from nscalogs in the varnishlog as well, but nothing jumps out so far... Starting to run out of things to try here... Ideas? Gaute ___ varnish-misc mailing list varnish-misc@projects.linpro.no http://projects.linpro.no/mailman/listinfo/varnish-misc
Re: logging problems - Pipe Shut
Gaute Amundsen [EMAIL PROTECTED] writes: I made a small script to run varnish(log|ncsa) on every file and get the returnstatus. log works fine, and a tail of that diplays sensible output and timestamps, but ncsa segfaults on about half of them. No pattern discernible.. Can you send me one of those? DES -- Dag-Erling Smørgrav Senior Software Developer Linpro AS - www.linpro.no ___ varnish-misc mailing list varnish-misc@projects.linpro.no http://projects.linpro.no/mailman/listinfo/varnish-misc
Re: logging problems - Pipe Shut
That did the trick for the processing :-D Only the logging itself left then. With som luck logger restarts on logrotate every hour will keep that stable til 1.1 is out :-) Gaute On Thursday 05 July 2007 20:20, Gaute Amundsen wrote: On Thursday 05 July 2007 17:18, Dag-Erling Smørgrav wrote: Dag-Erling Smørgrav [EMAIL PROTECTED] writes: Gaute Amundsen [EMAIL PROTECTED] writes: log.1 works, and log.2 segfaults They both work fine here, with varnishncsa from trunk (although on a 64-bit machine) I just realized - maybe you ran across the bug that was fixed in r1531. You mean this one? Wil try that then. Gaute Index: trunk/varnish-cache/bin/varnishncsa/varnishncsa.c === --- trunk/varnish-cache/bin/varnishncsa/varnishncsa.c (revision 1525) +++ trunk/varnish-cache/bin/varnishncsa/varnishncsa.c (revision 1531) @@ -156,5 +156,5 @@ /* trim trailing space */ - while (str[len - 1] == ' ') + while (len str[len - 1] == ' ') --len; -- Programmerer - Pixelhospitalet AS Tørkoppveien 10, 1570 Dilling Tlf. 24 12 97 81 - 9074 7344 ___ varnish-misc mailing list varnish-misc@projects.linpro.no http://projects.linpro.no/mailman/listinfo/varnish-misc
Re: logging problems - Pipe Shut
Gaute Amundsen [EMAIL PROTECTED] writes: We have had logging running for about a week now with no apparent problems, but yesterday I routed all our traffic into varnish, and now bad things happen. /var/log/varnish/varnish.log just stops growing after a while and a tail -n 1 gives me pages after pages of: Pipe Shut write(read)Pipe Shut read(read)Pipe Shut write(read)Pipe Shut read(read)Pipe Shut write(read)Pipe Shut read(read)Pipe Shut write(read)Pipe Over 4 megs of it just now actualy. It's not a text file, so tailing it is meaningless. Have you verified that logrotate is correctly set up? DES -- Dag-Erling Smørgrav Senior Software Developer Linpro AS - www.linpro.no ___ varnish-misc mailing list varnish-misc@projects.linpro.no http://projects.linpro.no/mailman/listinfo/varnish-misc
Re: logging problems - Pipe Shut
Hm.. I was finding quite a bit of Pipe Shut just running varnishlog -o. I's out of my buffer, so I cant paste it in right now, but could it bee that I was opening to many pipes? I the default action in vcl_recv was pipe, and only a few hosts would get a lookup... Trying with pass now, and it has held upp longer than last time anyway. Gaute ___ varnish-misc mailing list varnish-misc@projects.linpro.no http://projects.linpro.no/mailman/listinfo/varnish-misc
Re: logging problems - Pipe Shut
Gaute Amundsen [EMAIL PROTECTED] writes:
I was finding quite a bit of Pipe Shut just running varnishlog -o.
I's out of my buffer, so I cant paste it in right now, but could it
bee that I was opening to many pipes?
pipe shut happens when either the backend or the client closes the
connection, although there is a possibility that the code (rdf() in
cache_pipe.c) is too sensitive and shuts down the pipe as soon as the
client's TCP window fills up. Could you try the attached patch?
DES
--
Dag-Erling Smørgrav
Senior Software Developer
Linpro AS - www.linpro.no
Index: bin/varnishd/cache_pipe.c
===
--- bin/varnishd/cache_pipe.c (revision 1627)
+++ bin/varnishd/cache_pipe.c (working copy)
@@ -50,7 +50,7 @@
rdf(struct pollfd *fds, int idx)
{
int i, j;
- char buf[BUFSIZ];
+ char buf[BUFSIZ], *p;
i = read(fds[idx].fd, buf, sizeof buf);
if (i = 0 || fds[1-idx].events == 0) {
@@ -60,13 +60,16 @@
shutdown(fds[1-idx].fd, SHUT_WR);
fds[idx].events = 0;
} else {
- j = write(fds[1-idx].fd, buf, i);
- if (i != j) {
- VSL(SLT_Debug, fds[idx].fd, Pipe Shut write(write));
- VSL(SLT_Debug, fds[1-idx].fd, Pipe Shut read(write));
- shutdown(fds[idx].fd, SHUT_WR);
- shutdown(fds[1-idx].fd, SHUT_RD);
- fds[1-idx].events = 0;
+ for (p = buf; i 0; i -= j, p += j) {
+ j = write(fds[1-idx].fd, p, i);
+ if (j 0) {
+VSL(SLT_Debug, fds[idx].fd, Pipe Shut write(write));
+VSL(SLT_Debug, fds[1-idx].fd, Pipe Shut read(write));
+shutdown(fds[idx].fd, SHUT_WR);
+shutdown(fds[1-idx].fd, SHUT_RD);
+fds[1-idx].events = 0;
+break;
+ }
}
}
}
___
varnish-misc mailing list
varnish-misc@projects.linpro.no
http://projects.linpro.no/mailman/listinfo/varnish-misc
Re: logging problems - Pipe Shut
On Tuesday 03 July 2007 16:05, Dag-Erling Smørgrav wrote: Gaute Amundsen [EMAIL PROTECTED] writes: Rotation is weekly, and the previous logs have sane dates. Weekly rotation is probably far too seldom, Varnish can easily generate several gigabytes of log data *per hour* under high load. The tought have struck me yes. What would you suggest? Daily ought to stay under 5G by guesstimate, or would it be better to rotate by size? What size is varnishncsa comfortable with? Have you checked the file size limit (ulimit -f) that varnishlog operates under? unlimited Gaute ___ varnish-misc mailing list varnish-misc@projects.linpro.no http://projects.linpro.no/mailman/listinfo/varnish-misc
Re: logging problems - Pipe Shut
Gaute Amundsen [EMAIL PROTECTED] writes: On Tuesday 03 July 2007 16:05, Dag-Erling Smørgrav wrote: Gaute Amundsen [EMAIL PROTECTED] writes: Rotation is weekly, and the previous logs have sane dates. Weekly rotation is probably far too seldom, Varnish can easily generate several gigabytes of log data *per hour* under high load. The tought have struck me yes. What would you suggest? Daily ought to stay under 5G by guesstimate, or would it be better to rotate by size? What size is varnishncsa comfortable with? varnishncsa shouldn't care, as it processes the log file linearly, but I generally prefer to rotate by size. Is this a 32-bit machine, BTW? DES -- Dag-Erling Smørgrav Senior Software Developer Linpro AS - www.linpro.no ___ varnish-misc mailing list varnish-misc@projects.linpro.no http://projects.linpro.no/mailman/listinfo/varnish-misc
Re: logging problems - Pipe Shut
On Tuesday 03 July 2007 16:30, Dag-Erling Smørgrav wrote: snip varnishncsa shouldn't care, as it processes the log file linearly, but I generally prefer to rotate by size. Hm.. ok. But that would have me running awstats at odd times.. Wil just have to try it out I guess Is this a 32-bit machine, BTW? It is. Quad Xeon 3 GHz. Could you try the attached patch? Having some problems with that. My fault I'm sure, but I installed from the RPM originaly, so I can't just re-run. Compilation goes fine, but the binaries ends up widely different sizes. (5567 vs 168684) before make install that is. After that it's 478984 vs 168684. The source rpms are no different i presume? Is there a way to get the binary made without doing an install? I'd rather not do that on our production box.. Gaute ___ varnish-misc mailing list varnish-misc@projects.linpro.no http://projects.linpro.no/mailman/listinfo/varnish-misc
