Mailing List Archive

Gaute Amundsen <gaute at pht.no> 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

On Tuesday 03 July 2007 15:18, Dag-Erling Sm?rgrav wrote:
> Gaute Amundsen <gaute at pht.no> 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.

I know, in theory, except for tail -f into varnshncsa, but when all is ok I
have not gotten more than half a screenfull yet.

> Have you verified that logrotate is correctly set up?
>
Not thorougly, but all I have changed is addning:
prerotate
/usr/bin/python /root/bin/awstats_from_varnishlog.py
endscript

Rotation is weekly, and the previous logs have sane dates.

G.

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

Gaute Amundsen <gaute at pht.no> 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.

Have you checked the file size limit (ulimit -f) that varnishlog
operates under?

DES
--
Dag-Erling Sm?rgrav
Senior Software Developer
Linpro AS - www.linpro.no

Gaute Amundsen <gaute at pht.no> 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

-------------- next part --------------
A non-text attachment was scrubbed...
Name: cache_pipe.diff
Type: text/x-diff
Size: 1105 bytes
Desc: not available
Url : http://projects.linpro.no/pipermail/varnish-misc/attachments/20070703/d56146c2/attachment.diff

On Tuesday 03 July 2007 16:05, Dag-Erling Sm?rgrav wrote:
> Gaute Amundsen <gaute at pht.no> 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

Gaute Amundsen <gaute at pht.no> writes:
> On Tuesday 03 July 2007 16:05, Dag-Erling Sm?rgrav wrote:
> > Gaute Amundsen <gaute at pht.no> 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

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

Gaute Amundsen <gaute at pht.no> writes:
> On Tuesday 03 July 2007 16:30, Dag-Erling Sm?rgrav wrote:
> > Is this a 32-bit machine, BTW?
> It is. Quad Xeon 3 GHz.

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.

> > 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?

What configure options did you use? The difference in size is probably
due to debugging symbols.

> Is there a way to get the binary made without doing an install?

You can install into a staging directory (make install
DESTDIR=/tmp/varnish) and copy the files over manually if you prefer.

DES
--
Dag-Erling Sm?rgrav
Senior Software Developer
Linpro AS - www.linpro.no

On Wednesday 04 July 2007 09:47, Dag-Erling Sm?rgrav wrote:
> Gaute Amundsen <gaute at pht.no> writes:
> > On Tuesday 03 July 2007 16:30, Dag-Erling Sm?rgrav wrote:
> > > Is this a 32-bit machine, BTW?
> >
> > It is. Quad Xeon 3 GHz.
>
> 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.

Hm.. I had not tought of that. But we only have a 30G /var, so we wil need to
keep the files fairly small anyway.
Perhaps we can just save the nsca-log and delete the varnishlog right in the
postrotate-script, and then rotate every hour.

> > > 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?
>
> What configure options did you use? The difference in size is probably
> due to debugging symbols.

None at all. I'm not very knowledgeable about c development...

> > Is there a way to get the binary made without doing an install?
>
> You can install into a staging directory (make install
> DESTDIR=/tmp/varnish) and copy the files over manually if you prefer.

Ah, that's an improvement :)


But, anyway, I had much better results with the rpm, just a few K difference.
1.0.4-4el4.i386 running nicely now :)
( I cheked the cache_pipe.c that rpmbuild left behind to verify that the patch
was applied. )

But.. the problem with "Pipe Shut" persists.
Logging stopps within 5 minutes.

Doing 'tail /var/log/varnish/varnish.log | varnishlog -or /dev/stdin'
displays:
<snip>
276 VCL_call
26992 RxRequest e Shut read(read)
30578 (null) ite(read)
277 VCL_call
26992 (null) e Shut write(read)
8306 (null) ead(read)
25888 (null) Shut write(read)
24932 (null) )
276 VCL_call
26992 RxRequest e Shut read(read)
30578 (null) ite(read)
277 VCL_call
26992 (null) e Shut write(read)
8306 (null) ead(read)
25888 (null) Shut write(read)
24932 (null) )
276 VCL_call
26992 RxRequest e Shut read(read)
9269 BackendOpen b


When I let the vcl_recv default be pass, it seems much more stable.

Gaute

> 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

Gaute Amundsen <gaute at pht.no> 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

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 <des at linpro.no> writes:
> > > Gaute Amundsen <gaute at pht.no> 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