Log request timing in every generated vhost

Per-app latency, error rate and cache status were invisible: the
vhosts logged plain combined lines. The serverkit_timed format keeps
the combined fields first so bandwidth accounting and the fail2ban
filters still match, and appends request/upstream time, cache status
and host. Legacy access_log lines read as equivalent for drift so an
upgrade doesn't flag every site.

backend/app/services/drift_service.py

@@ -47,6 +47,7 @@ import difflib
 import json
 import logging
 import os
+import re
 import sys
 from datetime import datetime
 
@@ -388,6 +389,23 @@ def _with_expected_waf(app_id, config):
     return injected if injected is not None else config
 
 
+# A vhost written before the timed log format (plan 86 §A1) has a bare
+# `access_log <path>;`. That is not drift: the format only changes what the log
+# records, and the next regeneration adopts it. Read such lines as the timed
+# form so an upgrade doesn't flag (and notify about) every existing site.
+_LEGACY_ACCESS_LOG_RE = re.compile(
+    r'^(\s*access_log /var/log/nginx/[^\s;]+\.access\.log);$', re.MULTILINE)
+
+
+def _nginx_read_actual(paths):
+    actual = _default_read_actual(paths)
+    return {
+        path: (_LEGACY_ACCESS_LOG_RE.sub(r'\1 serverkit_timed;', content)
+               if content is not None else None)
+        for path, content in actual.items()
+    }
+
+
 def _nginx_repair(app_id):
     from app.models.application import Application
     from app.services.nginx_service import NginxService
@@ -425,6 +443,7 @@ register_check({
     'supported': _linux_only,
     'list_resources': _nginx_list_resources,
     'render_expected': _nginx_render_expected,
+    'read_actual': _nginx_read_actual,
     'repair': _nginx_repair,
 })
 

backend/app/services/environment_domain_service.py

@@ -30,7 +30,7 @@ class EnvironmentDomainService:
     listen [::]:80;
     server_name {domain};
 
-    access_log /var/log/nginx/{site_name}.access.log;
+    access_log /var/log/nginx/{site_name}.access.log serverkit_timed;
     error_log /var/log/nginx/{site_name}.error.log;
 
 {extra_headers}

backend/app/services/nginx_service.py

@@ -58,7 +58,7 @@ class NginxService:
     root {root_path};
     index index.php index.html index.htm;
 
-    access_log /var/log/nginx/{name}.access.log;
+    access_log /var/log/nginx/{name}.access.log serverkit_timed;
     error_log /var/log/nginx/{name}.error.log;
 
     location / {{
@@ -101,7 +101,7 @@ class NginxService:
     listen [::]:80;
     server_name {domains};
 
-    access_log /var/log/nginx/{name}.access.log;
+    access_log /var/log/nginx/{name}.access.log serverkit_timed;
     error_log /var/log/nginx/{name}.error.log;
 
     location / {{
@@ -132,7 +132,7 @@ class NginxService:
     root {root_path};
     index index.html index.htm;
 
-    access_log /var/log/nginx/{name}.access.log;
+    access_log /var/log/nginx/{name}.access.log serverkit_timed;
     error_log /var/log/nginx/{name}.error.log;
 
     location / {{
@@ -152,7 +152,7 @@ class NginxService:
     listen [::]:80;
     server_name {domains};
 
-    access_log /var/log/nginx/{name}.access.log;
+    access_log /var/log/nginx/{name}.access.log serverkit_timed;
     error_log /var/log/nginx/{name}.error.log;
 
     location / {{
@@ -222,7 +222,7 @@ limit_req_zone $server_name$binary_remote_addr zone=serverkit_wp_xmlrpc:10m rate
     listen [::]:80;
     server_name {domains};
 
-    access_log /var/log/nginx/{name}.access.log;
+    access_log /var/log/nginx/{name}.access.log serverkit_timed;
     error_log /var/log/nginx/{name}.error.log;
 
     location / {{
@@ -360,6 +360,23 @@ location = /wordpress {{
     }}
 '''
 
+    # ==================== TIMED ACCESS LOG (plan 86 §A1) ====================
+    # Every vhost ServerKit writes logs in this format. The combined fields come
+    # first, unchanged, so every existing combined-format reader (bandwidth
+    # accounting, the fail2ban `^<HOST> -` filters) keeps matching; the timing
+    # fields are appended after them. The app id is the log file itself
+    # (/var/log/nginx/<app>.access.log) — a per-vhost `set` variable would make
+    # `nginx -t` warn on every server block that never sets it.
+    TIMED_LOG_FORMAT = 'serverkit_timed'
+    TIMED_LOG_CONF_NAME = 'serverkit-log-format.conf'
+    TIMED_LOG_FORMAT_SNIPPET = """# ServerKit timed access-log format (auto-generated; do not edit).
+# Combined fields first (compatible with combined parsers), then timing.
+log_format serverkit_timed '$remote_addr - $remote_user [$time_local] "$request" '
+                           '$status $body_bytes_sent "$http_referer" "$http_user_agent" '
+                           'rt=$request_time urt="$upstream_response_time" '
+                           'cs=$upstream_cache_status h=$host';
+"""
+
     # ==================== MICRO-CACHE (task #21) ====================
     # Opt-in per-site micro-cache: a very short (10s) full-page cache in front
     # of proxied/PHP sites, with hard bypasses for anything personalized.
@@ -757,6 +774,27 @@ location /p/ {{
         except Exception as e:
             return {'success': False, 'error': str(e)}
 
+    @classmethod
+    def ensure_log_format(cls) -> Dict:
+        """Write the ``serverkit_timed`` log_format to conf.d (idempotent).
+
+        ``log_format`` is http-context only, so like the micro-cache zone it is
+        a conf.d snippet, not part of any vhost. :meth:`write_vhost` calls this
+        before writing any vhost that references the format.
+        """
+        conf_path = os.path.join(cls.NGINX_CONF_DIR, 'conf.d', cls.TIMED_LOG_CONF_NAME)
+        try:
+            if os.path.isfile(conf_path):
+                with open(conf_path, 'r') as f:
+                    if f.read() == cls.TIMED_LOG_FORMAT_SNIPPET:
+                        return {'success': True, 'changed': False, 'path': conf_path}
+            written = write_privileged_file(conf_path, cls.TIMED_LOG_FORMAT_SNIPPET)
+            if not written['success']:
+                return {'success': False, 'error': written['error']}
+            return {'success': True, 'changed': True, 'path': conf_path}
+        except Exception as e:
+            return {'success': False, 'error': str(e)}
+
     @classmethod
     def purge_micro_cache(cls) -> Dict:
         """Wipe the shared micro-cache directory contents. Linux-only.
@@ -903,6 +941,14 @@ location /p/ {{
                 or name in ('.', '..') or '\x00' in name):
             return {'success': False, 'error': f'Invalid site name: {name!r}'}
 
+        # A vhost naming the timed format fails `nginx -t` until the
+        # http-level log_format exists — declare it first.
+        if f' {cls.TIMED_LOG_FORMAT};' in content:
+            fmt = cls.ensure_log_format()
+            if not fmt.get('success'):
+                return {'success': False,
+                        'error': f"log format setup failed: {fmt.get('error')}"}
+
         available_path = os.path.join(cls.SITES_AVAILABLE, name)
         enabled_path = os.path.join(cls.SITES_ENABLED, name)
         previous = cls.read_vhost(name)

backend/tests/test_nginx_timed_log.py

@@ -0,0 +1,129 @@
+"""The timed access-log format every generated vhost uses (plan 86 §A1).
+
+The format appends request/upstream timing and cache status AFTER the standard
+combined fields, so the readers that already parse these logs (bandwidth
+accounting, the fail2ban `^<HOST> -` filters) keep working on both the old and
+the new line shape. Asserted here from both ends: what the templates write, and
+what the existing parser still reads.
+"""
+import os
+from datetime import date
+
+import pytest
+
+from app.services.bandwidth_service import BandwidthService
+from app.services.drift_service import _nginx_read_actual
+from app.services.nginx_service import NginxService
+
+OLD_LINE = ('203.0.113.9 - - [03/Jul/2026:10:00:00 +0000] "GET / HTTP/1.1" '
+            '200 512 "-" "curl/8"')
+NEW_LINE = (OLD_LINE
+            + ' rt=0.042 urt="0.040" cs=HIT h=shop.example.com')
+
+
+@pytest.mark.parametrize('kwargs', [
+    dict(app_type='docker', port=8003),
+    dict(app_type='static', root_path='/var/www/shop'),
+    dict(app_type='php', root_path='/var/www/shop'),
+    dict(app_type='python', port=8004, root_path='/srv/shop'),
+    dict(app_type='remote', upstream='10.8.0.2:8080'),
+    dict(app_type='docker', port=8003, micro_cache=True,
+         ssl_cert='/c.pem', ssl_key='/k.pem'),
+])
+def test_every_vhost_flavor_logs_in_the_timed_format(kwargs):
+    rendered = NginxService.render_site_config(
+        'shop', domains=['shop.example.com'], **kwargs)
+    assert rendered['success'], rendered
+    assert ('access_log /var/log/nginx/shop.access.log serverkit_timed;'
+            in rendered['config'])
+
+
+def test_the_format_keeps_combined_fields_first():
+    snippet = NginxService.TIMED_LOG_FORMAT_SNIPPET
+    assert 'log_format serverkit_timed' in snippet
+    combined = ('$remote_addr - $remote_user [$time_local] "$request" '
+                "'\n                           '"
+                '$status $body_bytes_sent "$http_referer" "$http_user_agent"')
+    assert combined in snippet
+    for field in ('$request_time', '$upstream_response_time',
+                  '$upstream_cache_status', '$host'):
+        assert field in snippet
+        assert snippet.index(field) > snippet.index('$http_user_agent')
+
+
+@pytest.mark.parametrize('line', [OLD_LINE, NEW_LINE])
+def test_bandwidth_parser_reads_old_and_new_lines(tmp_path, line):
+    log = tmp_path / 'shop.access.log'
+    log.write_text(line + '\n')
+    per_host, plain, skipped = BandwidthService.parse_log_file(
+        str(log), date(2026, 7, 3))
+    assert plain == [512, 1]
+    assert skipped == 0
+    assert per_host == {}
+
+
+class TestWriteVhostDeclaresTheFormat:
+    @pytest.fixture
+    def nginx(self, tmp_path, monkeypatch, fake_subprocess):
+        from subprocess_stub import FakeProc
+
+        conf = tmp_path / 'nginx'
+        for d in ('sites-available', 'sites-enabled', 'conf.d'):
+            (conf / d).mkdir(parents=True)
+        monkeypatch.setattr(NginxService, 'NGINX_CONF_DIR', str(conf))
+        monkeypatch.setattr(NginxService, 'SITES_AVAILABLE', str(conf / 'sites-available'))
+        monkeypatch.setattr(NginxService, 'SITES_ENABLED', str(conf / 'sites-enabled'))
+        monkeypatch.setattr('app.services.nginx_service.is_command_available',
+                            lambda *a, **k: True)
+
+        def tee(argv, kwargs):
+            with open(argv[-1], 'w') as fh:
+                fh.write(kwargs.get('input', ''))
+            return FakeProc()
+
+        def ln(argv, kwargs):
+            open(argv[-1], 'w').close()
+            return FakeProc()
+
+        fake_subprocess.when(['tee'], tee)
+        fake_subprocess.when(['ln'], ln)
+        fake_subprocess.script(['cat'], returncode=1)
+        fake_subprocess.script(['nginx', '-t'])
+        fake_subprocess.script(['systemctl'])
+        return conf
+
+    def test_snippet_is_written_before_a_timed_vhost(self, nginx):
+        res = NginxService.write_vhost(
+            'shop', 'server { access_log /x.log serverkit_timed; }')
+        assert res['success'], res
+        snippet = nginx / 'conf.d' / NginxService.TIMED_LOG_CONF_NAME
+        assert snippet.read_text() == NginxService.TIMED_LOG_FORMAT_SNIPPET
+
+    def test_a_vhost_without_the_format_does_not_write_it(self, nginx):
+        assert NginxService.write_vhost('shop', 'server {}')['success']
+        assert not (nginx / 'conf.d' / NginxService.TIMED_LOG_CONF_NAME).exists()
+
+
+def test_drift_reads_a_legacy_access_log_line_as_the_timed_form(tmp_path):
+    """An upgrade must not flag every pre-§A1 vhost as drifted."""
+    vhost = tmp_path / 'shop'
+    vhost.write_text('server {\n'
+                     '    access_log /var/log/nginx/shop.access.log;\n'
+                     '    error_log /var/log/nginx/shop.error.log;\n'
+                     '}\n')
+    got = _nginx_read_actual([str(vhost)])[str(vhost)]
+    assert '    access_log /var/log/nginx/shop.access.log serverkit_timed;\n' in got
+    assert '    error_log /var/log/nginx/shop.error.log;\n' in got
+
+
+def test_drift_leaves_a_hand_edited_access_log_alone(tmp_path):
+    """Only the exact legacy line is equivalent; anything else is real drift."""
+    vhost = tmp_path / 'shop'
+    body = 'server {\n    access_log off;\n}\n'
+    vhost.write_text(body)
+    assert _nginx_read_actual([str(vhost)])[str(vhost)] == body
+
+
+def test_drift_reports_a_missing_file_as_none(tmp_path):
+    missing = str(tmp_path / 'nope')
+    assert _nginx_read_actual([missing]) == {missing: None}

backend/tests/test_nginx_write_vhost.py

@@ -27,6 +27,8 @@ def nginx(tmp_path, monkeypatch, fake_subprocess):
     enabled = tmp_path / 'sites-enabled'
     available.mkdir()
     enabled.mkdir()
+    (tmp_path / 'conf.d').mkdir()   # http-level snippets (timed log format)
+    monkeypatch.setattr(NginxService, 'NGINX_CONF_DIR', str(tmp_path))
     monkeypatch.setattr(NginxService, 'SITES_AVAILABLE', str(available))
     monkeypatch.setattr(NginxService, 'SITES_ENABLED', str(enabled))
     monkeypatch.setattr('app.services.nginx_service.is_command_available',

backend/tests/test_real_nginx_vhost_syntax.py

@@ -61,7 +61,7 @@ def _nginx_t(tmp_path, vhost_config):
     relies on: writable log/cache dirs, the fastcgi_params file that
     `include fastcgi_params;` resolves against the conf prefix (= tmp_path
     under `-c`), and the http-level micro-cache zones ServerKit installs
-    as a conf.d snippet.
+    and timed log format ServerKit installs as conf.d snippets.
     """
     (tmp_path / 'log').mkdir(exist_ok=True)
     # nginx -t mkdirs the *_cache_path leaf dirs itself, but not parents.
@@ -74,6 +74,7 @@ def _nginx_t(tmp_path, vhost_config):
     zones.write_text(
         _localize(NginxService.MICROCACHE_ZONE_SNIPPET, tmp_path)
         + NginxService.WORDPRESS_RATE_LIMIT_ZONE_SNIPPET
+        + NginxService.TIMED_LOG_FORMAT_SNIPPET
     )
     vhost = tmp_path / 'vhost.conf'
     vhost.write_text(_localize(vhost_config, tmp_path))