Varnishd stops sending logs to VSM after a while

Mon Mar 17 17:53:15 CET 2014

On Mon, Mar 17, 2014 at 9:03 AM, Cédric Jeanneret <varnish at tengu.ch> wrote:
> Hello Dridi,
>
> that was it: the varnishd (run only in order to check the syntax,
> really, the reload itself is done later) was indeed overriding the _.vsm…
>
> I didn't thought about this first, because I wasn't aware it was taking
> using the already-present instance… Now, I updated the script in order
> to force the use of a new, temporary instance, forcing the user (-u) as
> well so that it will work in any cases.

Check the varnishd(1) man page, there's a "-C" option you can use to
check the VCL syntax. And you can even skip this check, since
varnishadm will fail to vcl.load a bogus VCL.

Cheers,
Dridi

> This was a bit vicious :].
>
> Cheers,
>
> C.
>
> On 03/17/2014 08:46 AM, Dridi Boukelmoune wrote:
>> 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
>
> _______________________________________________
> varnish-misc mailing list
> varnish-misc at varnish-cache.org
> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc