bundles/nginx: add anonymous timing logging for http requests

bundles/grafana/dashboard-rows/nginx.py

@@ -1,6 +1,7 @@
 def dashboard_row_nginx(panel_id, node):
     queries_through = []
     queries_conn = []
+    queries_timing = []
 
     for measurement in [
         'accepted',
@@ -62,6 +63,40 @@ def dashboard_row_nginx(panel_id, node):
             "tags": []
         })
 
+    for measurement in [
+        'request_time',
+        'upstream_response_time',
+    ]:
+        queries_timing.append({
+            'groupBy': [
+                {'type': 'time', 'params': ['$__interval']},
+                {'type': 'fill', 'params': ['linear']},
+            ],
+            'orderByTime': "ASC",
+            'policy': "default",
+            'query': f"""from(bucket: "telegraf")
+    |> range(start: v.timeRangeStart, stop: v.timeRangeStop)
+    |> filter(fn: (r) =>
+        r["_measurement"] == "nginx_timing" and
+        r["_field"] == "{measurement}" and
+        r["host"] == "{node.name}"
+    )
+    |> map(fn: (r) => ({{
+            r with
+            _field: "{measurement}"
+        }})
+    )
+    |> group(columns: ["path", "_field"])
+    |> aggregateWindow(every: v.windowPeriod, fn: mean, createEmpty: false)
+    |> yield(name: "{measurement}")""",
+            'resultFormat': 'time_series',
+            'select': [[
+                {'type': 'field', 'params': ['value']},
+                {'type': 'mean', 'params': []},
+            ]],
+            "tags": []
+        })
+
     return {
         'title': 'nginx',
         'collapse': False,
@@ -236,5 +271,106 @@ def dashboard_row_nginx(panel_id, node):
                     'alignLevel': None
                 }
             },
+            {
+                'aliasColors': {},
+                'bars': False,
+                'dashLength': 10,
+                'dashes': False,
+                'datasource': None,
+                'fieldConfig': {
+                    'defaults': {
+                        'displayName': '${__field.name} ${__field.labels.path}'
+                    },
+                    'overrides': []
+                },
+                'fill': 0,
+                'fillGradient': 0,
+                'hiddenSeries': False,
+                'id': next(panel_id),
+                'legend': {
+                    'alignAsTable': True,
+                    'avg': False,
+                    'current': False,
+                    'max': False,
+                    'min': False,
+                    'rightSide': True,
+                    'show': True,
+                    'total': False,
+                    'values': False
+                },
+                'lines': False,
+                'linewidth': 1,
+                'NonePointMode': 'None',
+                'options': {
+                    'alertThreshold': True
+                },
+                'percentage': False,
+                'pluginVersion': '7.5.5',
+                'pointradius': 2,
+                'points': True,
+                'renderer': 'flot',
+                'seriesOverrides': [],
+                'spaceLength': 10,
+                'span': 12,
+                'stack': False,
+                'steppedLine': False,
+                'targets': queries_timing,
+                'thresholds': [
+                    {
+                        'colorMode': 'warning',
+                        'fill': False,
+                        'line': True,
+                        'op': 'gt',
+                        'value': 5,
+                        'yaxis': 'left'
+                    },
+                    {
+                        'colorMode': 'critical',
+                        'fill': False,
+                        'line': True,
+                        'op': 'gt',
+                        'value': 15,
+                        'yaxis': 'left'
+                    }
+                ],
+                'timeRegions': [],
+                'title': 'nginx timing',
+                'tooltip': {
+                    'shared': True,
+                    'sort': 0,
+                    'value_type': 'individual'
+                },
+                'type': 'graph',
+                'xaxis': {
+                    'buckets': None,
+                    'mode': 'time',
+                    'name': None,
+                    'show': True,
+                    'values': []
+                },
+                'yaxes': [
+                    {
+                        'format': 's',
+                        'label': 'request time',
+                        'logBase': 2,
+                        'max': None,
+                        'min': 0,
+                        'show': True,
+                        'decimals': 0,
+                    },
+                    {
+                        'format': 'short',
+                        'label': None,
+                        'logBase': 1,
+                        'max': None,
+                        'min': None,
+                        'show': False,
+                    }
+                ],
+                'yaxis': {
+                    'align': False,
+                    'alignLevel': None
+                }
+            },
         ],
     }

bundles/nginx/files/logrotate.conf

@@ -0,0 +1,28 @@
+/var/log/nginx/*.log {
+    compress
+    copytruncate
+    create 0640 www-data adm
+    daily
+    dateext
+    missingok
+    notifempty
+    rotate ${node.metadata.get('nginx/log_retention_days', 7)}
+    sharedscripts
+    prerotate
+        if [ -d /etc/logrotate.d/httpd-prerotate ]; then \
+            run-parts /etc/logrotate.d/httpd-prerotate; \
+        fi
+    endscript
+}
+
+/var/log/nginx-timing/*.log {
+    compress
+    copytruncate
+    create 0644 www-data adm
+    dateext
+    missingok
+    notifempty
+    rotate 3
+    sharedscripts
+    size 1M
+}

bundles/nginx/files/nginx.conf

@@ -50,9 +50,12 @@ http {
         default 0.0.0.0;
         "~(?P<ip>.*)" $ip;
     }
+
     log_format gdpr '$ip_anonymized - $remote_user [$time_local] '
         '"$request" $status $body_bytes_sent '
         '"<stripped>" "$http_user_agent"';
 
+    log_format anon_timing '[$time_local] $request_time $upstream_response_time "$request" $status';
+
     include /etc/nginx/sites/*;
 }

bundles/nginx/files/site_template

@@ -54,6 +54,12 @@ server {
     resolver 8.8.8.8 8.8.4.4 valid=300s;
     resolver_timeout 5s;
 
+% if create_access_log:
+    access_log /var/log/nginx/access-${vhost}.log gdpr;
+% endif
+    access_log /var/log/nginx-timing/${vhost}.log anon_timing;
+    # error_log is disabled globally
+
 % if max_body_size:
     client_max_body_size ${max_body_size};
 % elif proxy or php:

bundles/nginx/items.py

@@ -23,10 +23,19 @@ directories = {
             'svc_systemd:nginx:restart',
         },
     },
+    '/var/log/nginx-timing': {
+        'owner': username,
+        'needs': {
+            package,
+        },
+    },
     '/var/www': {},
 }
 
 files = {
+    '/etc/logrotate.d/nginx': {
+        'source': 'logrotate.conf',
+    },
     '/etc/nginx/nginx.conf': {
         'content_type': 'mako',
         'context': {
@@ -77,6 +86,7 @@ svc_systemd = {
     'nginx': {
         'needs': {
             'action:nginx-generate-dhparam',
+            'directory:/var/log/nginx-timing',
             package,
         },
     },
@@ -112,6 +122,7 @@ for vhost, config in node.metadata.get('nginx/vhosts', {}).items():
         'source': 'site_template',
         'content_type': 'mako',
         'context': {
+            'create_access_log': config.get('access_log', node.metadata.get('nginx/access_log', False)),
             'php_version': node.metadata.get('php/version', ''),
             'security_txt': security_txt_enabled,
             'vhost': vhost,

bundles/nginx/metadata.py

@@ -181,3 +181,29 @@ def firewall(metadata):
             },
         },
     }
+
+
+@metadata_reactor.provides(
+    'telegraf/input_plugins/tail',
+)
+def telegraf_anon_timing(metadata):
+    result = {}
+
+    for vhost in metadata.get('nginx/vhosts', {}):
+        result[f'nginx-{vhost}'] = {
+            'files': [f'/var/log/nginx-timing/{vhost}.log'],
+            'from_beginning': False,
+            'grok_patterns': ['%{LOGPATTERN}'],
+            'grok_custom_patterns': 'LOGPATTERN \[%{HTTPDATE:ts:ts-httpd}\] %{NUMBER:request_time:float} (?:%{NUMBER:upstream_response_time:float}|-) "%{WORD:verb:tag} %{NOTSPACE:request} HTTP/%{NUMBER:http_version:float}" %{NUMBER:resp_code:tag}',
+            'data_format': 'grok',
+            'name_override': 'nginx_timing',
+        }
+
+    return {
+        'telegraf': {
+            'input_plugins': {
+                'tail': result,
+            },
+        },
+    }
+

bundles/telegraf/items.py

@@ -71,6 +71,12 @@ for config in sorted(node.metadata.get('telegraf/input_plugins/execd', {}).value
 
     telegraf_config['inputs']['execd'].append(config)
 
+for name, config in sorted(node.metadata.get('telegraf/input_plugins/tail', {}).items()):
+    if 'tail' not in telegraf_config['inputs']:
+        telegraf_config['inputs']['tail'] = []
+
+    telegraf_config['inputs']['tail'].append(config)
+
 files = {
     '/etc/telegraf/telegraf.conf': {
         'content_type': 'mako',