Gilles has uploaded a new change for review. ( https://gerrit.wikimedia.org/r/395076 )
Change subject: Smarter Varnish slow log ...................................................................... Smarter Varnish slow log Bug: T181315 Using python-logstash allows us to send structured data to ELK. Additionally, we can leverage varnishlog, which has more options than varnishncsa. Change-Id: I789c21c9764f6689e7c3cb4111dd1f11092e1249 --- M puppet/modules/varnish/files/build-varnish.sh A puppet/modules/varnish/files/varnishslowlog.py M puppet/modules/varnish/manifests/init.pp A puppet/modules/varnish/templates/systemd/varnishslowlog.erb 4 files changed, 199 insertions(+), 1 deletion(-) git pull ssh://gerrit.wikimedia.org:29418/mediawiki/vagrant refs/changes/76/395076/1 diff --git a/puppet/modules/varnish/files/build-varnish.sh b/puppet/modules/varnish/files/build-varnish.sh index fd66dae..ddf8acc 100644 --- a/puppet/modules/varnish/files/build-varnish.sh +++ b/puppet/modules/varnish/files/build-varnish.sh @@ -3,4 +3,5 @@ ./autogen.sh ./configure make -make install \ No newline at end of file +make install +ldconfig /usr/local/lib diff --git a/puppet/modules/varnish/files/varnishslowlog.py b/puppet/modules/varnish/files/varnishslowlog.py new file mode 100644 index 0000000..cfdde25 --- /dev/null +++ b/puppet/modules/varnish/files/varnishslowlog.py @@ -0,0 +1,166 @@ +#!/usr/bin/env python +# -*- coding: utf-8 -*- +""" + VarnishSlowLog + ~~~~~~~~~~ + VarnishSlowLog is responsible for gathering slow requests from varnishlog + and sending them to logstash. + + Copyright 2016-2017 Emanuele Rocca <[email protected]> + Copyright 2017 Gilles Dubuc <[email protected]> + Copyright 2014 Bernardo Heynemann <[email protected]> + + Licensed under the Apache License, Version 2.0 (the "License"); + you may not use this file except in compliance with the License. + You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + + Unless required by applicable law or agreed to in writing, software + distributed under the License is distributed on an "AS IS" BASIS, + WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + See the License for the specific language governing permissions and + limitations under the License. + +""" + +import argparse +import logging +import logstash +import os +import sys +import urlparse + +from subprocess import PIPE, Popen + + +def parse_logstash_server_string(server_string): + """Convert logstash server string into (hostname, port) tuple.""" + parsed = urlparse.urlparse('//' + server_string) + return parsed.hostname, parsed.port or 12202 + + +class VarnishSlowLog(object): + cmd = [] + description = 'Varnish slow log logstash logger' + logger = logging.getLogger('varnishslowlog') + logger.setLevel(logging.DEBUG) + tx = {} + + def __init__(self, argument_list): + """Parse CLI arguments. + + argument_list is a list such as ['--foo', 'FOO', '--bar', 'BAR']""" + ap = argparse.ArgumentParser( + description=self.description, + epilog='If no logstash server is specified, ' + 'prints log entries to stdout instead.') + + ap.add_argument('--logstash-server', help='logstash server', + type=parse_logstash_server_string, default=None) + + ap.add_argument('--slow-threshold', help='varnish fetch duration threshold', + type=float, default=10.0) + + ap.add_argument('--transaction-timeout', help='varnish transaction timeout', + type=int, default=600) + + ap.add_argument('--varnishd-instance-name', help='varnishd instance name', + default=None) + + self.args = ap.parse_args(argument_list) + + self.cmd = [self.which('varnishlog'), + # VSL query matching anything but purges + '-q', 'ReqMethod ne "PURGE" and Timestamp:Fetch[3] > %f' % self.args.slow_threshold, + # Set maximum Varnish transaction duration to track + '-T', '%d' % self.args.transaction_timeout] + + if self.args.varnishd_instance_name: + self.cmd.extend(['-n', self.args.varnishd_instance_name]) + + if self.args.logstash_server: + handler = logstash.LogstashHandler( + self.args.logstash_server[0], + port=self.args.logstash_server[1], + version=1, + message_type='varnishslowlog' + ) + else: + handler = logging.StreamHandler(sys.stdout) + + handler.setLevel(logging.DEBUG) + self.logger.addHandler(handler) + + # Borrowed from Thumbor, written by Bernardo Heynemann + def which(self, program): + """Finds the full path of a command according to the OS PATH""" + def is_exe(fpath): + return os.path.isfile(fpath) and os.access(fpath, os.X_OK) + + fpath, fname = os.path.split(program) + if fpath: + if is_exe(program): + return program + else: + for path in os.environ["PATH"].split(os.pathsep): + path = path.strip('"') + exe_file = os.path.join(path, program) + if is_exe(exe_file): + return exe_file + + return None + + def handle_line(self, line): + splitline = line.split(None, 2) + + if len(splitline) < 2: + return + + if splitline[0] != '-': + return + + if splitline[1] == 'Begin': + splitagain = splitline[2].split() + self.tx = {'id' : splitagain[1]} + elif splitline[1] == 'End': + if self.tx.has_key('request-Host') and self.tx.has_key('http-url'): + self.logger.info(self.tx['request-Host'] + self.tx['http-url'], extra=self.tx) + self.tx = {} + elif splitline[1] == 'ReqMethod': + self.tx['http-method'] = splitline[2] + elif splitline[1] == 'ReqURL': + self.tx['http-url'] = splitline[2] + elif splitline[1] == 'ReqProtocol': + self.tx['http-protocol'] = splitline[2] + elif splitline[1] == 'RespStatus': + self.tx['http-status'] = splitline[2] + elif splitline[1] == 'Timestamp': + splitagain = splitline[2].split() + ts_name = splitagain[0][:-1].lower() + self.tx['time-' + ts_name ] = float(splitagain[3]) + elif splitline[1] == 'ReqHeader': + splitagain = splitline[2].split(None, 1) + header_name = splitagain[0][:-1] + header_value = splitagain[1] + self.tx['request-' + header_name] = header_value + elif splitline[1] == 'RespHeader': + splitagain = splitline[2].split(None, 1) + header_name = splitagain[0][:-1] + header_value = splitagain[1] + self.tx['response-' + header_name] = header_value + + def main(self): + """Execute the command specified in self.cmd and call handle_record for + each output line produced by the command""" + p = Popen(self.cmd, stdout=PIPE, bufsize=-1) + + try: + while True: + line = p.stdout.readline().rstrip('\n') + self.handle_line(line) + except KeyboardInterrupt: + os.waitpid(p.pid, 0) + +if __name__ == "__main__": + VarnishSlowLog(sys.argv[1:]).main() \ No newline at end of file diff --git a/puppet/modules/varnish/manifests/init.pp b/puppet/modules/varnish/manifests/init.pp index 235ecb3..e3c2041 100644 --- a/puppet/modules/varnish/manifests/init.pp +++ b/puppet/modules/varnish/manifests/init.pp @@ -11,6 +11,8 @@ # See https://www.varnish-cache.org/docs/3.0/reference/vcl.html#multiple-subroutines # class varnish { + require ::role::elk + group { 'varnish': ensure => present, } @@ -41,6 +43,7 @@ require_package('libncurses-dev') require_package('libpcre3-dev') require_package('libedit-dev') + require_package('python-logstash') # We need to build from source because the tbf vmod needs the # built source, can't rely only on the headers @@ -243,6 +246,21 @@ user => 'root', } + file { '/usr/local/bin/varnishslowlog': + source => 'puppet:///modules/varnish/varnishslowlog.py', + owner => 'root', + group => 'root', + mode => '0555', + } + + systemd::service { 'varnishslowlog': + ensure => 'present', + require => File['/usr/local/bin/varnishslowlog'], + service_params => { + subscribe => File['/usr/local/bin/varnishslowlog'], + }, + } + systemd::service { 'varnish': ensure => 'present', require => [ diff --git a/puppet/modules/varnish/templates/systemd/varnishslowlog.erb b/puppet/modules/varnish/templates/systemd/varnishslowlog.erb new file mode 100644 index 0000000..d76cfa2 --- /dev/null +++ b/puppet/modules/varnish/templates/systemd/varnishslowlog.erb @@ -0,0 +1,13 @@ +[Unit] +Description=Varnish slow log logger +After=varnish.service + +[Service] +User=varnish +Group=varnish +ExecStart=/usr/local/bin/varnishslowlog --slow-threshold 0.0 --logstash-server=127.0.0.1:12202 +Restart=always +RestartSec=5s + +[Install] +WantedBy=multi-user.target -- To view, visit https://gerrit.wikimedia.org/r/395076 To unsubscribe, visit https://gerrit.wikimedia.org/r/settings Gerrit-MessageType: newchange Gerrit-Change-Id: I789c21c9764f6689e7c3cb4111dd1f11092e1249 Gerrit-PatchSet: 1 Gerrit-Project: mediawiki/vagrant Gerrit-Branch: master Gerrit-Owner: Gilles <[email protected]> _______________________________________________ MediaWiki-commits mailing list [email protected] https://lists.wikimedia.org/mailman/listinfo/mediawiki-commits
