Add detailed debug logging for the login flow

The login flow was near-silent: three info lines with no way to see why a session was considered expired or what happened to the cookies. Debugging a failing login meant guessing. Every login step now logs on debug level with a `phase` field: the login page fetch, the extracted nonce, the POST to /login/api/login.php, the session check, and any request retried after a re-login. Each of those requests is bracketed by a cookie snapshot taken before it is sent and one taken after, plus a delta of added/changed/removed cookies. The "before" snapshot is logged prior to sending, so it survives a hanging request. isLoginRequiredResponse() is split so the criterion that matched (status-401, login-markup, ...) can be reported instead of just a boolean. Secrets stay out of the log: the password is replaced by ***, and cookie values - including those in the raw Set-Cookie header - are truncated to their first four characters plus length. That still shows whether a session id changed without putting the session itself in the log. Detail logging is strictly debug-level via logLoginDetail(); the existing logDebug() falls back to info, which would flood a plain info logger. When no debug logger is attached, no snapshot is taken and nothing is serialized. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
2026-09-07 20:05:02 +02:00
parent b844b772b8
commit 4cd0da4a8a
7 changed files with 674 additions and 22 deletions
@@ -0,0 +1,183 @@
+const assert = require('node:assert/strict');
+const http = require('node:http');
+const test = require('node:test');
+
+const { AgrarmonitorConnector, MemoryCookieStore } = require('../dist');
+
+const PASSWORT = 'sup3rgeheim-passwort';
+const SESSION_VALUE = 'abcdef0123456789abcdef';
+
+const loginPage = `
+  <html>
+    <head><title>Anmeldung - AGRARMONITOR</title></head>
+    <body>
+      <form>
+        <input name="nonce" value="test-nonce" />
+        <button>Einloggen</button>
+      </form>
+    </body>
+  </html>
+`;
+
+function createServer() {
+  let loggedIn = false;
+  const requests = [];
+
+  const server = http.createServer((req, res) => {
+    requests.push({ method: req.method, url: req.url });
+
+    if (req.method === 'GET' && req.url === '/') {
+      res.writeHead(200, { 'Content-Type': 'text/html; charset=utf-8' });
+      res.end(loggedIn ? '<html><body>Mein AM</body></html>' : loginPage);
+      return;
+    }
+
+    // Laeuft die Session ab, liefert die Seite wieder das Login-Markup aus.
+    if (req.method === 'GET' && req.url === '/geschuetzt') {
+      if (!loggedIn) {
+        res.writeHead(200, { 'Content-Type': 'text/html; charset=utf-8' });
+        res.end(loginPage);
+        return;
+      }
+
+      res.writeHead(200, { 'Content-Type': 'text/html; charset=utf-8' });
+      res.end('<html><body>Geschuetzter Inhalt</body></html>');
+      return;
+    }
+
+    if (req.method === 'POST' && req.url === '/login/api/login.php') {
+      let body = '';
+      req.on('data', chunk => {
+        body += chunk;
+      });
+      req.on('end', () => {
+        loggedIn = true;
+        res.writeHead(200, {
+          'Content-Type': 'application/json',
+          'Set-Cookie': `agrar_session=${SESSION_VALUE}; Path=/`,
+        });
+        res.end(JSON.stringify({ success: true }));
+      });
+      return;
+    }
+
+    res.writeHead(404);
+    res.end('not found');
+  });
+
+  return {
+    server,
+    requests,
+    expireSession() {
+      loggedIn = false;
+    },
+  };
+}
+
+function createRecordingLogger() {
+  const entries = [];
+
+  const record = level => (message, meta) => entries.push({ level, message, meta });
+
+  return {
+    entries,
+    debug: record('debug'),
+    info: record('info'),
+    warn: record('warn'),
+    error: record('error'),
+    debugEntries: () => entries.filter(entry => entry.level === 'debug'),
+    text: () => entries.map(entry => `${entry.message} ${JSON.stringify(entry.meta ?? null)}`).join('\n'),
+  };
+}
+
+async function startConnector(t, { logger } = {}) {
+  const harness = createServer();
+
+  await new Promise(resolve => harness.server.listen(0, '127.0.0.1', resolve));
+  t.after(() => new Promise(resolve => harness.server.close(resolve)));
+
+  const connector = new AgrarmonitorConnector({
+    baseUrl: `http://127.0.0.1:${harness.server.address().port}`,
+    username: 'demo',
+    password: PASSWORT,
+    cookieStore: new MemoryCookieStore(),
+    logger,
+  });
+
+  await connector.init();
+
+  return { connector, ...harness };
+}
+
+function loginPostEntries(logger) {
+  return logger.debugEntries().filter(entry => entry.meta?.url === '/login/api/login.php');
+}
+
+test('logs cookie snapshots before and after the login request', async t => {
+  const logger = createRecordingLogger();
+  await startConnector(t, { logger });
+
+  const [request, response, ...rest] = loginPostEntries(logger);
+
+  assert.equal(rest.length, 0, 'genau ein Request- und ein Response-Eintrag fuer den Login-POST');
+  assert.equal(request?.meta.phase, 'request');
+  assert.equal(request?.meta.method, 'POST');
+  assert.ok(Array.isArray(request?.meta.cookies), 'Cookies vor dem Request werden protokolliert');
+
+  assert.equal(response?.meta.phase, 'response');
+  assert.equal(response?.meta.status, 200);
+
+  const cookieNames = response.meta.cookies.map(cookie => cookie.name);
+  assert.ok(cookieNames.includes('agrar_session'), 'Cookies nach dem Request enthalten die neue Session');
+  assert.deepEqual(response.meta.cookieChanges.added, ['agrar_session']);
+});
+
+test('masks cookie values and never logs the password', async t => {
+  const logger = createRecordingLogger();
+  await startConnector(t, { logger });
+
+  const text = logger.text();
+
+  assert.ok(!text.includes(PASSWORT), 'das Passwort darf in keinem Log-Eintrag stehen');
+  assert.ok(!text.includes(SESSION_VALUE), 'der volle Cookie-Wert darf nicht im Log stehen');
+
+  const response = loginPostEntries(logger).at(-1);
+  const session = response.meta.cookies.find(cookie => cookie.name === 'agrar_session');
+
+  assert.equal(session.value, `abcd…(len=${SESSION_VALUE.length})`);
+  assert.equal(session.path, '/');
+});
+
+test('logs the re-login triggered by an expired session', async t => {
+  const logger = createRecordingLogger();
+  const { connector, expireSession } = await startConnector(t, { logger });
+
+  logger.entries.length = 0;
+  expireSession();
+
+  const response = await connector.http.get('/geschuetzt');
+  assert.equal(response.status, 200);
+  assert.match(response.data, /Geschuetzter Inhalt/);
+
+  const retry = logger
+    .debugEntries()
+    .find(entry => entry.meta?.phase === 'retry' && entry.meta?.url === '/geschuetzt');
+
+  assert.ok(retry, 'der wiederholte Request wird protokolliert');
+  assert.equal(retry.meta.method, 'GET');
+  assert.ok(Array.isArray(retry.meta.cookies), 'Cookies des Wiederholungs-Requests werden protokolliert');
+  assert.ok(loginPostEntries(logger).length >= 2, 'der erneute Login wird ebenfalls protokolliert');
+});
+
+test('stays silent when the logger has no debug method', async t => {
+  const entries = [];
+  const logger = { info: (message, meta) => entries.push({ message, meta }) };
+
+  await startConnector(t, { logger });
+
+  assert.ok(entries.length > 0, 'info-Meldungen bleiben erhalten');
+  assert.ok(
+    entries.every(entry => entry.meta?.phase === undefined),
+    'ohne debug-Methode werden keine Request-Details ausgegeben'
+  );
+});