Varnishd stops sending logs to VSM after a while

[Cédric Jeanneret]

Hello,

Sorry for the delay, but…

So, some more information:

Logrotate:
this shouldn't be a problem, as logrotate doesn't touch the _.vsm file…

Varnishncsa/Varnishlog:
I don't think the problem is on their side either, as they perform
read-only access to the _.vsm (tell me if I'm wrong with this statement)

VSM:
the four varnishes had the very same problem this weekend (of course,
when nobody's here…). I'm keeping one of them at hand with the problem
"enabled" in order to be able to debug a bit.

Here are what I can tell:

Inodes:
indeed, the inodes aren't the same for the one used by the process
(marked as DEL in lsof, inode 264058) and the one on the system (268725).
Creation date of the system one: March 16, 2014, 16:10.

After a quick look in the logs, it seems there's a configuration
modification at this very time: some filters were added, calling a
reload of the VCL.

Please see bellow for the "hot-reload" script content.

Is there anything weird in this script?

Thank you in advance.

Cheers,

C.



#!/bin/bash
# Reload a varnish config
# Author: Kristian Lyngstol

# Original version:
http://kly.no/posts/2009_02_18__Easy_reloading_of_varnish__VCL__.html

if [ $# -lt 1 -o $# -gt 2 ]; then
  echo "Usage: $0 vcl_file [secret_file]"
  exit 1
fi
FILE=$1

if [ $# -eq 2 ]; then
  SECRET_OPT="-S $2"
fi

# Hostname and management port
# (defined in /etc/default/varnish or on startup)
HOSTPORT="localhost:6082"
NOW=`date +%F_%T`

error()
{
    echo 1>&2 "Failed to reload $FILE."
    exit 1
}
echo "@@@ Checking VCL file syntax:"
varnishd -d -s malloc -f $FILE < /dev/null || error

echo -e "\n@@@ Loading new VCL file:"
varnishadm $SECRET_OPT -T $HOSTPORT vcl.load reload$NOW $FILE || error
varnishadm $SECRET_OPT -T $HOSTPORT vcl.use reload$NOW || error


echo -e "\n@@@ Currently available VCL configs:"
varnishadm $SECRET_OPT -T $HOSTPORT vcl.list

exit 0


On 03/14/2014 10:01 PM, Stephen Wood wrote:
> My first thought is that logrotate is running and varishncsa is not
> properly catching a SIGHUP after a rotate. Therefore the logfile gets
> rotated but varnishncsa continues writing to the old fd.
> 
> If you run varnishncsa by itself on the command line during these periods,
> do you get output? If so then it's probably not a problem with shared
> memory.
> 
> If you want to test this, you can simply change the varnishncsa logrotate
> behavior to use copytruncate and not bother sending a HUP, which will
> truncate the log without rotating it.
> 
> For reference here's what my logrotate file looks like:
> 
> /var/log/varnish/varnish.log /var/log/varnish/varnishncsa.log {
>   size 1G
>   rotate 7
>   missingok
>   compress
>   delaycompress
>   postrotate
>     for service in varnishlog varnishncsa; do
>       if /usr/bin/pgrep -P 1 $service >/dev/null; then
>         service $service reload > /dev/null
>       fi
>     done
>   endscript
> }
> 
> If you want to try copytruncate:
> 
> /var/log/varnish/varnish.log /var/log/varnish/varnishncsa.log {
>   size 1G
>   rotate 7
>   missingok
>   compress
>   delaycompress
>   copytruncate
> }
> 
> Note that you'll get a message in your log file that states it was
> truncated. It may mess up your log parsing software.
> 
> 
> On Thu, Mar 13, 2014 at 4:33 AM, Raymond Jennings <
> raymond.jennings at nytimes.com> wrote:
> 
>> I have what might be a related problem.  I can only get varnishlog to
>> write to a file after I stop it and restart it.  I am running on ec2.
>> I tried various tricks to wait so many seconds after varnished starts
>> then start varnishlog.   Varnishncsa runs perfectly fine right out of
>> the gate.  I have had this problem for about two years now.
>> Varnishlog is clearly running and "service varnishlog stop"
>> successfully stops it.   "service varnishlog start" and things are
>> good.
>>
>>> On Mar 13, 2014, at 6:27 AM, Thomas Lecomte <
>> thomas.lecomte at virtual-expo.com> wrote:
>>>
>>>> On Thu, Mar 13, 2014 at 10:25:52AM +0100, Cédric Jeanneret wrote:
>>>>
>>>> Hmm, _.vsm is shown when we perform a simple "ls" in the directory...
>>>> Else, I would get some errors from either varnishncsa or varnishlog when
>>>> I start them (I tried that this morning, just to see what would
>> happen)...
>>>
>>> Maybe you could compare the inodes using ls -i on the visible _.vsm
>>> against the one shown by lsof on the varnish process.
>>>
>>> --
>>> Thomas Lecomte / +33 4 86 13 48 65
>>> Sysadmin / Virtual Expo / Marseille
>>>
>>> _______________________________________________
>>> varnish-misc mailing list
>>> varnish-misc at varnish-cache.org
>>> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
>>
>> _______________________________________________
>> varnish-misc mailing list
>> varnish-misc at varnish-cache.org
>> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
>>
> 
> 
> 
> 
> 
> _______________________________________________
> varnish-misc mailing list
> varnish-misc at varnish-cache.org
> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
>