diff --git a/docs/TROUBLESHOOTING.md b/docs/TROUBLESHOOTING.md index 1a1102e057..60109b2dc8 100644 --- a/docs/TROUBLESHOOTING.md +++ b/docs/TROUBLESHOOTING.md @@ -289,15 +289,51 @@ Continue checking delivery activity for destination failures. ## 🛠️ Advanced Diagnostics ### Correlate Logs with Requests -Every API response has an `X-Request-ID` header. Use it to find the exact log entry: + +For a failed HTTP API request, inspect its response in your authenticated +browser's **Developer tools → Network** panel. Copy only the `X-Request-ID` +response header, if present, and keep the HTTP status and time. Do not copy a +session cookie, **Copy as cURL** command or full network export into a report. +WebSocket upgrades do not pass through this request-ID middleware. + +Service logs normally use JSON (`"request_id":"abc123"`); console logs may use +`request_id=abc123`. Search for the literal ID value so both formats work. +Replace `abc123` below with the response's ID. Run only the command for your +deployment, on the Pulse host using an account authorised to read its logs. +These examples limit collection to the last 15 minutes and 1,000 lines; adjust +the time window to the original incident rather than repeating the failed action. + ```bash # systemd / Proxmox LXC -journalctl -u pulse --no-pager | grep "request_id=abc123" - -# Docker -docker logs pulse 2>&1 | grep "request_id=abc123" +set -o pipefail +REQUEST_ID='abc123' +journalctl -u pulse --since '15 minutes ago' --lines 1000 --no-pager | + grep -F -- "$REQUEST_ID" ``` +```bash +# Docker +REQUEST_ID='abc123' +if pulse_logs=$(docker logs --since 15m --tail 1000 pulse 2>&1); then + printf '%s\n' "$pulse_logs" | grep -F -- "$REQUEST_ID" +else + printf '%s\n' "$pulse_logs" >&2 + false +fi +``` + +A log-reader failure is not an empty search result: resolve any access or +container/service error locally first. Even a successful read with no match +does not prove the request succeeded. At the default log level, this middleware +logs HTTP 5xx failures but not successful requests; HTTP 4xx failures are logged +at debug level. The selected window, retained logs or deployment may also differ. +Keep the original response status, time and ID even when there is no matching log; +do not enable debug logging or retry a state-changing request just to fill that gap. + +These local excerpts are **not sanitised**. Before sharing a relevant line, +remove credentials, cookies, secret URLs and private host, network or personal +information. See [Getting Help](#-getting-help) for safe evidence collection. + ### Check Permissions (Proxmox) If Pulse can't see VMs or storage, check the user permissions on Proxmox: ```bash diff --git a/frontend-modern/public/docs/TROUBLESHOOTING.md b/frontend-modern/public/docs/TROUBLESHOOTING.md index 1a1102e057..60109b2dc8 100644 --- a/frontend-modern/public/docs/TROUBLESHOOTING.md +++ b/frontend-modern/public/docs/TROUBLESHOOTING.md @@ -289,15 +289,51 @@ Continue checking delivery activity for destination failures. ## 🛠️ Advanced Diagnostics ### Correlate Logs with Requests -Every API response has an `X-Request-ID` header. Use it to find the exact log entry: + +For a failed HTTP API request, inspect its response in your authenticated +browser's **Developer tools → Network** panel. Copy only the `X-Request-ID` +response header, if present, and keep the HTTP status and time. Do not copy a +session cookie, **Copy as cURL** command or full network export into a report. +WebSocket upgrades do not pass through this request-ID middleware. + +Service logs normally use JSON (`"request_id":"abc123"`); console logs may use +`request_id=abc123`. Search for the literal ID value so both formats work. +Replace `abc123` below with the response's ID. Run only the command for your +deployment, on the Pulse host using an account authorised to read its logs. +These examples limit collection to the last 15 minutes and 1,000 lines; adjust +the time window to the original incident rather than repeating the failed action. + ```bash # systemd / Proxmox LXC -journalctl -u pulse --no-pager | grep "request_id=abc123" - -# Docker -docker logs pulse 2>&1 | grep "request_id=abc123" +set -o pipefail +REQUEST_ID='abc123' +journalctl -u pulse --since '15 minutes ago' --lines 1000 --no-pager | + grep -F -- "$REQUEST_ID" ``` +```bash +# Docker +REQUEST_ID='abc123' +if pulse_logs=$(docker logs --since 15m --tail 1000 pulse 2>&1); then + printf '%s\n' "$pulse_logs" | grep -F -- "$REQUEST_ID" +else + printf '%s\n' "$pulse_logs" >&2 + false +fi +``` + +A log-reader failure is not an empty search result: resolve any access or +container/service error locally first. Even a successful read with no match +does not prove the request succeeded. At the default log level, this middleware +logs HTTP 5xx failures but not successful requests; HTTP 4xx failures are logged +at debug level. The selected window, retained logs or deployment may also differ. +Keep the original response status, time and ID even when there is no matching log; +do not enable debug logging or retry a state-changing request just to fill that gap. + +These local excerpts are **not sanitised**. Before sharing a relevant line, +remove credentials, cookies, secret URLs and private host, network or personal +information. See [Getting Help](#-getting-help) for safe evidence collection. + ### Check Permissions (Proxmox) If Pulse can't see VMs or storage, check the user permissions on Proxmox: ```bash diff --git a/scripts/tests/test_troubleshooting_logs.py b/scripts/tests/test_troubleshooting_logs.py new file mode 100644 index 0000000000..c3ba031f70 --- /dev/null +++ b/scripts/tests/test_troubleshooting_logs.py @@ -0,0 +1,134 @@ +#!/usr/bin/env python3 +"""Exercise copied log-correlation recipes with synthetic service log readers. + +This checks shell behaviour, not an installed Pulse service or Docker daemon. +""" + +from __future__ import annotations + +import json +import os +from pathlib import Path +import re +import subprocess +import tempfile +import unittest + + +ROOT = Path(__file__).resolve().parents[2] +DOC = ROOT / "docs/TROUBLESHOOTING.md" +REQUEST_ID = "trace.123:abc" +JSON_LOG = json.dumps({ + "level": "warn", "request_id": REQUEST_ID, "status": 503, + "message": "Request failed", +}, separators=(",", ":")) + "\n" +CONSOLE_LOG = f"WRN Request failed request_id={REQUEST_ID} status=503\n" +DECOY_LOG = "WRN Request failed request_id=traceX123:abc status=503\n" + + +def section() -> str: + return DOC.read_text(encoding="utf-8").split( + "### Correlate Logs with Requests\n", 1 + )[1].split("\n### ", 1)[0] + + +def recipes() -> dict[str, str]: + blocks = re.findall(r"```bash\n(.*?)```", section(), re.DOTALL) + return {"docker" if "# Docker" in block else "journalctl": block + for block in blocks} + + +READER = '''#!/usr/bin/env python3 +import json, os, pathlib, sys +name = pathlib.Path(sys.argv[0]).name +expected = (['-u', 'pulse', '--since', '15 minutes ago', '--lines', '1000', '--no-pager'] + if name == 'journalctl' else ['logs', '--since', '15m', '--tail', '1000', 'pulse']) +pathlib.Path(os.environ['READER_ARGV']).write_text(json.dumps(sys.argv[1:])) +if sys.argv[1:] != expected: + print('unexpected log-reader arguments', file=sys.stderr) + sys.exit(64) +sys.stdout.write(os.environ.get('LOG_STDOUT', '')) +sys.stderr.write(os.environ.get('LOG_STDERR', '')) +sys.exit(int(os.environ.get('READER_EXIT', '0'))) +''' + + +class TroubleshootingLogRecipesTest(unittest.TestCase): + def exercise(self, reader: str, *, stdout: str = "", stderr: str = "", + exit_code: int = 0, recipe: str | None = None): + with tempfile.TemporaryDirectory() as temporary: + directory = Path(temporary) + command = directory / reader + command.write_text(READER, encoding="utf-8") + command.chmod(0o700) + argv = directory / "argv.json" + env = dict(os.environ, PATH=f"{directory}:{os.environ['PATH']}", + READER_ARGV=str(argv), LOG_STDOUT=stdout, LOG_STDERR=stderr, + READER_EXIT=str(exit_code)) + copied = (recipe if recipe is not None else recipes()[reader]).replace( + "REQUEST_ID='abc123'", f"REQUEST_ID='{REQUEST_ID}'" + ) + result = subprocess.run(["bash", "-c", copied], env=env, + capture_output=True, text=True, timeout=10) + self.assertTrue(argv.exists(), "copied recipe did not invoke its log reader") + self.assertNotEqual(result.returncode, 64, result.stderr) + return result + + def test_shipped_document_is_the_same_guide(self): + self.assertEqual(DOC.read_bytes(), + (ROOT / "frontend-modern/public/docs/TROUBLESHOOTING.md").read_bytes()) + self.assertEqual(set(recipes()), {"journalctl", "docker"}) + + def test_literal_id_matches_json_and_console_without_regex_false_matches(self): + for reader in recipes(): + for log in (JSON_LOG, CONSOLE_LOG): + with self.subTest(reader=reader, format=log): + result = self.exercise(reader, stdout=DECOY_LOG + log) + self.assertEqual(result.returncode, 0, result.stderr) + self.assertEqual(result.stdout, log) + self.assertEqual(result.stderr, "") + + def test_docker_logs_written_to_stderr_are_searchable(self): + result = self.exercise("docker", stdout=DECOY_LOG, stderr=JSON_LOG) + self.assertEqual(result.returncode, 0, result.stderr) + self.assertEqual(result.stdout, JSON_LOG) + + def test_no_match_is_nonzero_and_does_not_print_unrelated_logs(self): + for reader in recipes(): + with self.subTest(reader=reader): + result = self.exercise(reader, stdout=DECOY_LOG) + self.assertEqual(result.returncode, 1) + self.assertEqual(result.stdout, "") + self.assertEqual(result.stderr, "") + + def test_log_reader_failure_remains_failure_even_with_a_matching_partial_log(self): + error = "synthetic log-reader access failure\n" + for reader in recipes(): + with self.subTest(reader=reader): + result = self.exercise(reader, stdout=JSON_LOG, stderr=error, exit_code=2) + self.assertNotEqual(result.returncode, 0) + self.assertIn(error, result.stderr) + + def test_console_only_selector_is_a_negative_control_for_json(self): + copied = recipes()["journalctl"].replace( + 'grep -F -- "$REQUEST_ID"', 'grep -F -- "request_id=$REQUEST_ID"' + ) + result = self.exercise("journalctl", stdout=JSON_LOG, recipe=copied) + self.assertEqual(result.returncode, 1) + self.assertEqual(result.stdout, "") + + def test_guidance_keeps_browser_credentials_and_missing_logs_in_context(self): + guide = " ".join(section().split()) + for boundary in ("Copy only the `X-Request-ID`", "Copy as cURL", + "WebSocket upgrades", "not sanitised", "HTTP 5xx", + "HTTP 4xx", "not successful requests", "debug level", + "does not prove the request succeeded", + "rather than repeating the failed action", + "do not enable debug logging or retry a state-changing request"): + self.assertIn(boundary, guide) + self.assertNotRegex("\n".join(recipes().values()), + r"curl\b|--follow\b|\s-f\b|--token\b|--api-token\b") + + +if __name__ == "__main__": + unittest.main()