Varnishd stops sending logs to VSM after a while

[Dridi Boukelmoune]

Hi,

On Mon, Mar 17, 2014 at 7:51 AM, Cédric Jeanneret <varnish at tengu.ch> wrote:
> 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

Maybe this varnishd instance you bring up deletes the file and creates its own.

Btw, why would you need a storage for a simple syntax check ?

And isn't your redirection from /dev/null in the wrong direction ?

Dridi

> 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
>>
>
> _______________________________________________
> varnish-misc mailing list
> varnish-misc at varnish-cache.org
> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc