How to get a summarized Varnishlog

Question

I want to use Varnishlog with Logstash, Elasticsearch and Kibana to get an overview over the important things like 'how long does my server take to answer on a request'. My problem is, that Varnish logs every request in to many lines.

e.g.:

   14 BackendOpen  b default 127.0.0.1 42697 127.0.0.1 2727
   14 BackendXID   b 722117072
   14 TxRequest    b GET
   14 TxURL        b /images/maske.png
   14 TxProtocol   b HTTP/1.1
   14 TxHeader     b Host: ecomxenvm01:7272
   14 TxHeader     b User-Agent: Mozilla/5.0 (Windows NT 6.1; rv:38.0) Gecko/20100101 Firefox/38.0
   14 TxHeader     b Accept: image/png,image/*;q=0.8,*/*;q=0.5
   14 TxHeader     b Accept-Language: de,en-US;q=0.7,en;q=0.3
   14 TxHeader     b Referer: http://ecomxenvm01:7272/format.css
   14 TxHeader     b X-Varnish: 722117072
   14 TxHeader     b Accept-Encoding: gzip
   14 RxProtocol   b HTTP/1.1
   14 RxStatus     b 200
   14 RxResponse   b OK
   14 RxHeader     b Date: Thu, 02 Jul 2015 08:27:38 GMT
   14 RxHeader     b Server: Apache/2.2.15 (CentOS)
   14 RxHeader     b Last-Modified: Wed, 24 Jun 2015 08:08:38 GMT
   14 RxHeader     b ETag: "60010-111f8-5193f039fed80"
   14 RxHeader     b Accept-Ranges: bytes
   14 RxHeader     b Content-Length: 70136
   14 RxHeader     b Connection: close
   14 RxHeader     b Content-Type: image/png
   14 Fetch_Body   b 4(length) cls 0 mklen 1
   14 Length       b 70136
   14 BackendClose b default
   12 ReqStart     c 172.16.145.134 57776 722117072
   12 RxRequest    c GET
   12 RxURL        c /images/maske.png
   12 RxProtocol   c HTTP/1.1
   12 RxHeader     c Host: ecomxenvm01:7272
   12 RxHeader     c User-Agent: Mozilla/5.0 (Windows NT 6.1; rv:38.0) Gecko/20100101 Firefox/38.0
   12 RxHeader     c Accept: image/png,image/*;q=0.8,*/*;q=0.5
   12 RxHeader     c Accept-Language: de,en-US;q=0.7,en;q=0.3
   12 RxHeader     c Accept-Encoding: gzip, deflate
   12 RxHeader     c Referer: http://ecomxenvm01:7272/format.css
   12 RxHeader     c Connection: keep-alive
   12 VCL_call     c recv lookup
   12 VCL_call     c hash
   12 Hash         c /images/maske.png
   12 Hash         c ecomxenvm01:7272
   12 VCL_return   c hash
   12 VCL_call     c miss fetch
   12 Backend      c 14 default default
   12 TTL          c 722117072 RFC 120 -1 -1 1435825659 0 1435825658 0 0
   12 VCL_call     c fetch deliver
   12 ObjProtocol  c HTTP/1.1
   12 ObjResponse  c OK
   12 ObjHeader    c Date: Thu, 02 Jul 2015 08:27:38 GMT
   12 ObjHeader    c Server: Apache/2.2.15 (CentOS)
   12 ObjHeader    c Last-Modified: Wed, 24 Jun 2015 08:08:38 GMT
   12 ObjHeader    c ETag: "60010-111f8-5193f039fed80"
   12 ObjHeader    c Content-Type: image/png
   12 VCL_call     c deliver deliver
   12 TxProtocol   c HTTP/1.1
   12 TxStatus     c 200
   12 TxResponse   c OK
   12 TxHeader     c Server: Apache/2.2.15 (CentOS)
   12 TxHeader     c Last-Modified: Wed, 24 Jun 2015 08:08:38 GMT
   12 TxHeader     c ETag: "60010-111f8-5193f039fed80"
   12 TxHeader     c Content-Type: image/png
   12 TxHeader     c Content-Length: 70136
   12 TxHeader     c Accept-Ranges: bytes
   12 TxHeader     c Date: Thu, 02 Jul 2015 08:27:38 GMT
   12 TxHeader     c X-Varnish: 722117072
   12 TxHeader     c Age: 0
   12 TxHeader     c Via: 1.1 varnish
   12 TxHeader     c Connection: keep-alive
   12 Length       c 70136
   12 ReqEnd       c 722117072 1435825658.602955103 1435825658.603794336 0.012183905 0.000789165 0.000050068
   14 BackendOpen  b default 127.0.0.1 42698 127.0.0.1 2727
   14 BackendXID   b 722117073
   14 TxRequest    b GET
   14 TxURL        b /images/arrow.png
   14 TxProtocol   b HTTP/1.1
   14 TxHeader     b Host: ecomxenvm01:7272
   14 TxHeader     b User-Agent: Mozilla/5.0 (Windows NT 6.1; rv:38.0) Gecko/20100101 Firefox/38.0
   14 TxHeader     b Accept: image/png,image/*;q=0.8,*/*;q=0.5
   14 TxHeader     b Accept-Language: de,en-US;q=0.7,en;q=0.3
   14 TxHeader     b Referer: http://ecomxenvm01:7272/format.css
   14 TxHeader     b X-Varnish: 722117073
   14 TxHeader     b Accept-Encoding: gzip
   14 RxProtocol   b HTTP/1.1
   14 RxStatus     b 200
   14 RxResponse   b OK
   14 RxHeader     b Date: Thu, 02 Jul 2015 08:27:38 GMT
   14 RxHeader     b Server: Apache/2.2.15 (CentOS)
   14 RxHeader     b Last-Modified: Wed, 24 Jun 2015 08:08:37 GMT
   14 RxHeader     b ETag: "60009-af-5193f0390ab40"
   14 RxHeader     b Accept-Ranges: bytes
   14 RxHeader     b Content-Length: 175
   14 RxHeader     b Connection: close
   14 RxHeader     b Content-Type: image/png
   14 Fetch_Body   b 4(length) cls 0 mklen 1
   14 Length       b 175
   14 BackendClose b default
   12 ReqStart     c 172.16.145.134 57776 722117073
   12 RxRequest    c GET
   12 RxURL        c /images/arrow.png
   12 RxProtocol   c HTTP/1.1
   12 RxHeader     c Host: ecomxenvm01:7272
   12 RxHeader     c User-Agent: Mozilla/5.0 (Windows NT 6.1; rv:38.0) Gecko/20100101 Firefox/38.0
   12 RxHeader     c Accept: image/png,image/*;q=0.8,*/*;q=0.5
   12 RxHeader     c Accept-Language: de,en-US;q=0.7,en;q=0.3
   12 RxHeader     c Accept-Encoding: gzip, deflate
   12 RxHeader     c Referer: http://ecomxenvm01:7272/format.css
   12 RxHeader     c Connection: keep-alive
   12 VCL_call     c recv lookup
   12 VCL_call     c hash
   12 Hash         c /images/arrow.png
   12 Hash         c ecomxenvm01:7272
   12 VCL_return   c hash
   12 VCL_call     c miss fetch
   12 Backend      c 14 default default
   12 TTL          c 722117073 RFC 120 -1 -1 1435825659 0 1435825658 0 0
   12 VCL_call     c fetch deliver
   12 ObjProtocol  c HTTP/1.1
   12 ObjResponse  c OK
   12 ObjHeader    c Date: Thu, 02 Jul 2015 08:27:38 GMT
   12 ObjHeader    c Server: Apache/2.2.15 (CentOS)
   12 ObjHeader    c Last-Modified: Wed, 24 Jun 2015 08:08:37 GMT
   12 ObjHeader    c ETag: "60009-af-5193f0390ab40"
   12 ObjHeader    c Content-Type: image/png
   12 VCL_call     c deliver deliver
   12 TxProtocol   c HTTP/1.1
   12 TxStatus     c 200
   12 TxResponse   c OK
   12 TxHeader     c Server: Apache/2.2.15 (CentOS)
   12 TxHeader     c Last-Modified: Wed, 24 Jun 2015 08:08:37 GMT
   12 TxHeader     c ETag: "60009-af-5193f0390ab40"
   12 TxHeader     c Content-Type: image/png
   12 TxHeader     c Content-Length: 175
   12 TxHeader     c Accept-Ranges: bytes
   12 TxHeader     c Date: Thu, 02 Jul 2015 08:27:38 GMT
   12 TxHeader     c X-Varnish: 722117073
   12 TxHeader     c Age: 0
   12 TxHeader     c Via: 1.1 varnish
   12 TxHeader     c Connection: keep-alive
   12 Length       c 175
   12 ReqEnd       c 722117073 1435825658.607635498 1435825658.608191013 0.003841162 0.000532389 0.000023127`

Now my question: how can i get these lines into a single line? Or how can I summarize this request?

Do I have to change something in the config-files? Or is there a tool that can help me?

Thanks cM

Config-file:

    DAEMON_OPTS="$DAEMON_OPTS -i RxStatus"

    # Configuration file for varnish
    #
    # /etc/init.d/varnish expects the variable $DAEMON_OPTS to be set from this
    # shell script fragment.
    #

    # Maximum number of open files (for ulimit -n)
    NFILES=131072

    # Locked shared memory (for ulimit -l)
    # Default log size is 82MB + header
    MEMLOCK=82000

    # Maximum number of threads (for ulimit -u)
    NPROCS="unlimited"

    # Maximum size of corefile (for ulimit -c). Default in Fedora is 0
    # DAEMON_COREFILE_LIMIT="unlimited"

    # Set this to 1 to make init script reload try to switch vcl without restart.
    # To make this work, you need to set the following variables
    # explicit: VARNISH_VCL_CONF, VARNISH_ADMIN_LISTEN_ADDRESS,
    # VARNISH_ADMIN_LISTEN_PORT, VARNISH_SECRET_FILE, or in short,
    # use Alternative 3, Advanced configuration, below
    RELOAD_VCL=1

    # This file contains 4 alternatives, please use only one.

    ## Alternative 1, Minimal configuration, no VCL
    #
    # Listen on port 7272, administration on localhost:6082, and forward to
    # content server on localhost:2727.  Use a fixed-size cache file.
    #
    #DAEMON_OPTS="-a :6081 \
    #             -T localhost:6082 \
    #             -b localhost:8080 \
    #             -u varnish -g varnish \
    #             -s file,/var/lib/varnish/varnish_storage.bin,1G"


    ## Alternative 2, Configuration with VCL
    #
    # Listen on port 6081, administration on localhost:6082, and forward to
    # one content server selected by the vcl file, based on the request.  Use a
    # fixed-size cache file.
    #
    #DAEMON_OPTS="-a :6081 \
    #             -T localhost:6082 \
    #             -f /etc/varnish/default.vcl \
    #             -u varnish -g varnish \
    #             -S /etc/varnish/secret \
    #             -s file,/var/lib/varnish/varnish_storage.bin,1G"


    ## Alternative 3, Advanced configuration
    #
    # See varnishd(1) for more information.
    #
    # # Main configuration file. You probably want to change it :)
    VARNISH_VCL_CONF=/etc/varnish/default.vcl
    #
    # # Default address and port to bind to
    # # Blank address means all IPv4 and IPv6 interfaces, otherwise specify
    # # a host name, an IPv4 dotted quad, or an IPv6 address in brackets.
    # VARNISH_LISTEN_ADDRESS=
    VARNISH_LISTEN_PORT=7272
    #
    # # Telnet admin interface listen address and port
    VARNISH_ADMIN_LISTEN_ADDRESS=127.0.0.1
    VARNISH_ADMIN_LISTEN_PORT=6082
    #
    # # Shared secret file for admin interface
    VARNISH_SECRET_FILE=/etc/varnish/secret
    #
    # # The minimum number of worker threads to start
    VARNISH_MIN_THREADS=50
    #
    # # The Maximum number of worker threads to start
    VARNISH_MAX_THREADS=1000
    #
    # # Idle timeout for worker threads
    VARNISH_THREAD_TIMEOUT=120
    #
    # # Cache file location
    VARNISH_STORAGE_FILE=/var/lib/varnish/varnish_storage.bin
    #
    # # Cache file size: in bytes, optionally using k / M / G / T suffix,
    # # or in percentage of available disk space using the % suffix.
    VARNISH_STORAGE_SIZE=1G
    #
    # # Backend storage specification
    VARNISH_STORAGE="file,${VARNISH_STORAGE_FILE},${VARNISH_STORAGE_SIZE}"
    #
    # # Default TTL used when the backend does not specify one
    VARNISH_TTL=120
    #
    # # DAEMON_OPTS is used by the init script.  If you add or remove options, make
    # # sure you update this section, too.
    DAEMON_OPTS="-a ${VARNISH_LISTEN_ADDRESS}:${VARNISH_LISTEN_PORT} \
                 -f ${VARNISH_VCL_CONF} \
                 -T ${VARNISH_ADMIN_LISTEN_ADDRESS}:${VARNISH_ADMIN_LISTEN_PORT} \
                 -t ${VARNISH_TTL} \
                 -w ${VARNISH_MIN_THREADS},${VARNISH_MAX_THREADS},${VARNISH_THREAD_TIMEOUT} \
                 -u varnish -g varnish \
                 -S ${VARNISH_SECRET_FILE} \
                 -s ${VARNISH_STORAGE}"
    #


    ## Alternative 4, Do It Yourself. See varnishd(1) for more information.
    #
    # DAEMON_OPTS=""

When I locate Varnishlog:

[elk@ecomxenvm01 ~]$ sudo locate varnishlog
/etc/rc.d/init.d/varnishlog
/etc/rc.d/rc0.d/K10varnishlog
/etc/rc.d/rc1.d/K10varnishlog
/etc/rc.d/rc2.d/K10varnishlog
/etc/rc.d/rc3.d/K10varnishlog
/etc/rc.d/rc4.d/K10varnishlog
/etc/rc.d/rc5.d/K10varnishlog
/etc/rc.d/rc6.d/K10varnishlog
/usr/bin/varnishlog
/usr/share/man/man1/varnishlog.1.gz
/usr/share/man/man8/varnishlog_selinux.8.gz

score 1 · Accepted Answer · answered Jul 03 '15 at 02:41

1

You should take a look at this. Specially options -I and -i.

Example with tags, shows RxStatus log entries only:

varnishlog -i RxStatus

Example with regex, shows both ReqStart and ReqEnd entries only:

varnishlog -I "Req[Start|End]"

answered Jul 03 '15 at 02:41

Redithion

986
1
19
32

Is there a possibility to integrate this options in the config-file? I don't only want to see this special logs, I want varnish to only give further this logs. And i need to combine some logs. For example the log with the response time from the server and the exactly place from where the reqest comes, so Kibana can visualize exactly this case. – cMonkey Jul 03 '15 at 06:59
Don't know if it works, but you can try something like `DAEMON_OPTS="$DAEMON_OPTS -i RxStatus"` right after `VARNISHLOG_ENABLED=1` – Redithion Jul 03 '15 at 19:20
I don't know why, but I get even more lines with this command. =/ – cMonkey Jul 06 '15 at 07:39
Let's see if I understand, you've tried the command directly (executing `varnishlog -i RxStatus`) and the output it's ok, but when you try to do the same by config file it prints more lines than before, Am I right? – Redithion Jul 06 '15 at 14:40
Yes, you are right. (Unfortunately I am just a trainee and I don't understand pretty much about these things... an no one can help me here) – cMonkey Jul 07 '15 at 07:24
Can you edit your post with your config-file so I can see it? – Redithion Jul 07 '15 at 12:25
Oh, I see it now, my mistake. You shouldn't edit that config-file. So, remove the first line of that config-file (it's being overridden anyway). Then open /etc/default/varnishlog (you may need sudo) and uncomment `VARNISHLOG_ENABLED=1`, in a new line write the `DAEMON_OPTS="$DAEMON_OPTS -i RxStatus" `line. Save the file. Not sure, but you may need to restart varnish. Let me know the results :) – Redithion Jul 07 '15 at 15:50
I have no file at /etc/default/varnishlog =/ I also can't find a file on Google, which I could download. Do you can send me the script of this file so I can create the file by myself? – cMonkey Jul 08 '15 at 08:01
Maybe I should edit, that i run CentOS 6 :) I don't know, but maybe my file is somewhere else. But I can't find anything else, when I try to locate it. I edited my location-results above. – cMonkey Jul 08 '15 at 08:07
I'm running out of ideas. Does [this](http://stackoverflow.com/questions/12705252/how-to-setup-varnish-logging) help? – Redithion Jul 08 '15 at 15:09
The problem with varnishncsa is that it doesn't log everything I need. =/ – cMonkey Jul 09 '15 at 06:53
Do you have this `/etc/default/varnishlog ` file? – cMonkey Jul 09 '15 at 13:42
Yes I do, but I run varnish in Ubuntu. What about doing something like `nohup varnishlog -w [path where you want the log file to be] -a -I [regex] &` -a is for appending instead of overwriting, -w is to log in a file instead of stdout and -I is to log whatever matches the regex given. Finally with [nohup](http://linux.die.net/man/1/nohup) you can logout (assuming you connect through ssh) and varnish will continue logging. I assume you already know but & is for running the command on background. – Redithion Jul 09 '15 at 22:01
I will try it this way :) I will let you know if it helps me :) – cMonkey Jul 10 '15 at 10:53
Hope so, if that works I will edit my answer and mention that as an alternative for future readers. – Redithion Jul 10 '15 at 13:02

score 0 · Answer 2 · answered Jul 03 '15 at 10:05

We use varnishncsa to create an apache like access log.

varnishncsa -a -w /var/log/varnish/varnishncsa.log -D -P /var/run/varnishncsa.pid -F"%{X-Forwarded-For}i %l %u %t \"%r\" %s %b \"%{Referer}i\" \"%{User-agent}i\" %D %{Varnish:hitmiss}x"

when adding this to log rotate make sure to use copy/truncate option.

more info https://www.varnish-cache.org/docs/trunk/reference/varnishncsa.html

score 0 · Answer 3 · answered Aug 28 '15 at 06:38

Here is a some background on how to set this up specifically for Varnish: https://www.section.io/varnish-logs-centralized-and-managed-by-elasticsearch-logstash-and-kibana/

The extension of the effort for varnishlog is exactly the same. Run varnishlog as a daemon, write to a file and then push all of the entries at logstash (potentially via syslog-ng).

Let me know if this helps, Happy to provide further specific information for your use case.

How to get a summarized Varnishlog

3 Answers3