Varnishd stops sending logs to VSM after a while

Tue Mar 18 09:48:29 CET 2014

Hello Dridi

On 03/17/2014 05:53 PM, Dridi Boukelmoune wrote:
> 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

So it will fail with some error code if there's an error in the VCL?
Will it also show the line error, like the current script does? I'll
give it a try in order to see if this may replace the current varnishd call.

Thanks for your support!

Cheers,

C.

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