Terminplaner: Jobs lesen abgeschaltete Funktionen vor dem Löschen neu, Tagesbericht im Log

Co-Authored-By: Claude Sonnet 5.5 <noreply@anthropic.com>

server/index.js

@@ -23,7 +23,7 @@ import { purgeViewLog } from './services/customerViewLog.js'
 import { purgeUnclaimedNewsImages } from './services/newsImages.js'
 import { runActivation } from './services/siteFeatures.js'
 import { runAboCheck, runAnalyseReconcile } from './services/analyse.js'
-import { fuenfMinutenJob, minutenJob, taeglicherJob } from './services/termine/jobs.js'
+import { fuenfMinutenJob, minutenJob, tagesbericht, taeglicherJob } from './services/termine/jobs.js'
 import giteaWebhookRoutes from './routes/webhook/gitea.js'
 import pushTimeRoutes from './routes/pushTime.js'
 import adminGiteaRoutes from './routes/admin/gitea.js'
@@ -203,8 +203,14 @@ const server = app.listen(config.port, '0.0.0.0', () => {
   const termineFuenfMinutenJob = () =>
     fuenfMinutenJob(new Date()).catch((err) => console.warn('[termine] Fünf-Minuten-Job fehlgeschlagen:', err.message))
   setInterval(termineFuenfMinutenJob, 5 * 60 * 1000).unref()
+  // Nach dem Tagesjob steht eine Zeile mit den Zahlen der Loeschungen im Log (Spur unwiderruflicher Loeschungen, ohne Personendaten)
   const termineTagesJob = () =>
-    taeglicherJob(new Date()).catch((err) => console.warn('[termine] Tagesjob fehlgeschlagen:', err.message))
+    taeglicherJob(new Date())
+      .then((ergebnis) => {
+        const zeile = tagesbericht(ergebnis)
+        if (zeile) console.log(zeile)
+      })
+      .catch((err) => console.warn('[termine] Tagesjob fehlgeschlagen:', err.message))
   setTimeout(termineTagesJob, 180 * 1000).unref()
   setInterval(termineTagesJob, 24 * 60 * 60 * 1000).unref()
 

server/services/termine/jobs.js

@@ -1,5 +1,5 @@
 import { config } from '../../config.js'
-import { Query, deleteDocument, listAllDocuments } from '../appwriteAdmin.js'
+import { Query, deleteDocument, getDocument, listAllDocuments } from '../appwriteAdmin.js'
 import { withLocks } from '../keyedLock.js'
 import { gibFreiSicher, iso, vertragAm } from './ablauf.js'
 import {
@@ -68,7 +68,7 @@ function melde(lauf, was, err, bookingId = null) {
     const zuletzt = letzteWarnung.get(lauf.job)
     if (zuletzt !== undefined && lauf.nowMs - zuletzt < STUNDE_MS) return
     letzteWarnung.set(lauf.job, lauf.nowMs)
-    console.warn(`[termine-jobs] ${lauf.job}: ${err.type}, die Termine-Einrichtung ist unvollständig (Warnung höchstens einmal je Stunde)`)
+    console.warn(`[termine-jobs] ${lauf.job}, Schritt „${was}“: ${err.type}, die Termine-Einrichtung ist unvollständig (Warnung höchstens einmal je Stunde)`)
     return
   }
   const nummer = bookingId ? ` (${buchungsNummer(bookingId)})` : ''
@@ -314,9 +314,35 @@ async function loeschfristen(lauf, now) {
   return geloescht
 }
 
+/** So viele Buchungen einer abgeschalteten Funktion hoechstens, bevor ihr Zustand erneut gelesen wird. */
+const ABGESCHALTET_NEU_PRUEFEN_ALLE = 50
+
+/**
+ * Gilt die Funktion unmittelbar vor einem unwiderruflichen Loeschschritt noch als abgeschaltet? Frisch gelesen, weil ein Wieder-
+ * einschalten durch das Personal (siteFeatures.activate) weder sperrt noch disabledAt loescht: featureKey termine, state disabled
+ * und disabledAt vor der Grenze. Sonst false mit Log, ohne Wurf – auch bei einem Lesefehler: im Zweifel wird nichts geloescht.
+ */
+async function nochAbgeschaltet(lauf, funktionId, grenze) {
+  try {
+    const frisch = await getDocument(config.collections.portalFeatures, funktionId)
+    if (frisch.featureKey === 'termine' && frisch.state === 'disabled' && zeitMs(frisch.disabledAt) < grenze) return true
+    console.warn(`[termine-jobs] ${lauf.job}: eine Funktion ist inzwischen wieder aktiv oder neu abgeschaltet, die Löschung wird für sie abgebrochen`)
+  } catch (err) {
+    if (err?.status === 404 && !fehlendeCollection(err)) {
+      console.warn(`[termine-jobs] ${lauf.job}: eine Funktion wurde inzwischen entfernt, die Löschung wird für sie abgebrochen`)
+    } else {
+      melde(lauf, 'Funktion vor dem Löschen nicht gelesen', err)
+    }
+  }
+  return false
+}
+
 /**
  * Funktionen im Zustand `disabled` seit mehr als 30 Tagen (disabledAt): alle Buchungen mit Zellen und zuletzt die Einstellung
- * loeschen. Scheitert eine Buchung, bleibt die Einstellung bis zum naechsten Lauf. Zellen ohne Buchung raeumt danach der Tagesjob.
+ * loeschen. Vor der Buchungsliste, nach jeweils 50 Buchungen und vor dem Loeschen der Einstellung wird die Funktion frisch gelesen
+ * (nochAbgeschaltet); gilt sie nicht mehr als abgeschaltet, endet die Loeschung fuer diese Funktion sofort (Log, kein Wurf).
+ * Scheitert eine Buchung, bleibt die Einstellung bis zum naechsten Lauf. Zellen ohne Buchung raeumt danach der Tagesjob.
+ * funktionen zaehlt die Funktionen, bei denen etwas geloescht wurde (Buchungen oder Einstellung).
  */
 async function loescheAbgeschaltete(lauf) {
   const erg = { funktionen: 0, buchungen: 0 }
@@ -324,26 +350,42 @@ async function loescheAbgeschaltete(lauf) {
   const funktionen = await listAllDocuments(config.collections.portalFeatures, [Query.equal('featureKey', 'termine'), Query.equal('state', 'disabled')])
   for (const funktion of funktionen) {
     if (!(zeitMs(funktion.disabledAt) < grenze)) continue
-    erg.funktionen += 1
     const buchungen = await schritt(lauf, 'Buchungen abgeschalteter Funktion', () => listAllDocuments(config.collections.termineBookings, [Query.equal('featureId', funktion.$id)]), null)
-    if (buchungen === null) continue
+    if (buchungen === null || !(await nochAbgeschaltet(lauf, funktion.$id, grenze))) continue
+
+    let geloescht = 0
     let vollstaendig = true
-    for (const buchung of buchungen) {
+    for (const [i, buchung] of buchungen.entries()) {
+      if (i > 0 && i % ABGESCHALTET_NEU_PRUEFEN_ALLE === 0 && !(await nochAbgeschaltet(lauf, funktion.$id, grenze))) {
+        vollstaendig = false
+        break
+      }
       const weg = await loescheMitZellen(lauf, buchung.$id, null)
-      if (weg) erg.buchungen += 1
+      if (weg) geloescht += 1
       if (weg === undefined) vollstaendig = false
     }
+    erg.buchungen += geloescht
+
+    let einstellungWeg = false
     if (vollstaendig) {
-      await schritt(lauf, 'Einstellung abgeschalteter Funktion', () =>
-        withLocks([`termine-cfg:${funktion.$id}`], async () => {
-          try {
-            await deleteDocument(config.collections.termineConfig, funktion.$id)
-          } catch (err) {
-            if (err?.status !== 404) throw err
-          }
-        }),
+      einstellungWeg = await schritt(
+        lauf,
+        'Einstellung abgeschalteter Funktion',
+        () =>
+          withLocks([`termine-cfg:${funktion.$id}`], async () => {
+            if (!(await nochAbgeschaltet(lauf, funktion.$id, grenze))) return false
+            try {
+              await deleteDocument(config.collections.termineConfig, funktion.$id)
+              return true
+            } catch (err) {
+              if (err?.status === 404 && !fehlendeCollection(err)) return false // schon weg
+              throw err
+            }
+          }),
+        false,
       )
     }
+    if (geloescht > 0 || einstellungWeg) erg.funktionen += 1
   }
   return erg
 }
@@ -386,6 +428,25 @@ export async function taeglicherJob(now) {
   })
 }
 
+/**
+ * Eine Zeile fuers Log nach dem Tagesjob: nur Zahlen, keine personenbezogenen Daten und keine Buchungs- oder Funktions-IDs
+ * (Spur der unwiderruflichen Loeschungen). null, wenn der Job nicht gelaufen ist (Modus off, uebersprungen).
+ * @param {object} ergebnis Rueckgabe von taeglicherJob
+ * @returns {string|null}
+ */
+export function tagesbericht(ergebnis) {
+  if (!ergebnis || ergebnis.aus || ergebnis.uebersprungen) return null
+  const l = ergebnis.loeschfristen
+  const a = ergebnis.abgeschaltet
+  const gesamt = Object.values(l).reduce((summe, n) => summe + n, 0) + a.buchungen
+  return (
+    `[termine] Tagesjob: ${gesamt} Buchungen gelöscht (verfallen ${l.verfallen}, abgesagt ${l.abgesagt}, abgelehnt ${l.abgelehnt}, ` +
+    `erledigt ${l.erledigt}, nichterschienen ${l.nichterschienen}, abgeschaltete Funktionen ${a.buchungen}), ` +
+    `${a.funktionen} Funktionen bereinigt, ${ergebnis.zellen} Zellen, ${ergebnis.aufgeraeumt} Outbox, ` +
+    `${ergebnis.festgefahren} Mails nicht zugestellt, ${ergebnis.fehler} Fehler`
+  )
+}
+
 /** Nur fuer Tests: Ueberlappungsmerker und Warnungs-Zeitpunkte zuruecksetzen. */
 export function resetJobsForTests() {
   laufend.clear()

test/termineJobs.test.js

@@ -33,7 +33,7 @@ const { speichereEinstellung, resetKontextForTests } = await import('../server/s
 const { belegeZellen } = await import('../server/services/termine/zellen.js')
 const { bestaetige } = await import('../server/services/termine/ablauf.js')
 const J = await import('../server/services/termine/jobs.js')
-const { minutenJob, fuenfMinutenJob, taeglicherJob, wendeLoeschfristenAn, loescheAbgeschalteteFunktionen, resetJobsForTests } = J
+const { minutenJob, fuenfMinutenJob, taeglicherJob, tagesbericht, wendeLoeschfristenAn, loescheAbgeschalteteFunktionen, resetJobsForTests } = J
 after(() => setMailTransportForTests(null))
 
 const MIN = 60000
@@ -774,7 +774,7 @@ test('loescheAbgeschalteteFunktionen: disabled länger als 30 Tage ⇒ Buchungen
   assert.equal(buchungen().length, 8, 'die Buchungen der anderen vier Funktionen bleiben')
   for (const featureId of [F2, F3, 'f_p_projekt04_termine', 'f_p_projekt05_termine']) assert.ok(aw.docs('termineConfig').get(featureId), `${featureId}: Einstellung bleibt`)
   assert.ok(aw.docs('portalFeatures').get(F1), 'das Funktionsdokument selbst bleibt')
-  assert.deepEqual(await loescheAbgeschalteteFunktionen(JETZT), { funktionen: 1, buchungen: 0 }, 'zweiter Lauf: nichts mehr zu löschen')
+  assert.deepEqual(await loescheAbgeschalteteFunktionen(JETZT), { funktionen: 0, buchungen: 0 }, 'zweiter Lauf: nichts mehr zu löschen, die Funktion zählt nicht noch einmal')
 })
 
 test('loescheAbgeschalteteFunktionen: scheitert das Löschen einer Buchung, bleibt die Einstellung bis zum nächsten Lauf', async () => {
@@ -789,6 +789,79 @@ test('loescheAbgeschalteteFunktionen: scheitert das Löschen einer Buchung, blei
   assert.equal(aw.docs('termineConfig').get(F1), undefined)
 })
 
+/** Eine abgeschaltete Funktion (seit 40 Tagen) mit n Buchungen; mit zellen bekommt jede ihre Zellen. */
+async function abgeschaltetMitBuchungen(n, { zellen = true } = {}) {
+  await richteFunktionEin(F1, { state: 'disabled', disabledAt: iso(plus(JETZT, -40 * TAG)) })
+  for (let i = 0; i < n; i++) await legeBuchung(`b_ab${String(i).padStart(3, '0')}`, { start: plus(JETZT, TAG + i * 2 * STUNDE), zellen })
+}
+/** Das Personal schaltet die Funktion wieder ein: siteFeatures.activate sperrt nicht und lässt disabledAt stehen. */
+const schalteEin = () => aw.seed('portalFeatures', { ...aw.docs('portalFeatures').get(F1), state: 'active', enabled: true })
+/** Anfragen an die Buchungsliste einer Funktion bzw. an die Funktionsliste */
+const funktionsListe = (url, methode) => methode === 'GET' && /\/collections\/portalFeatures\/documents(\?|$)/.test(url)
+const buchungLoeschen = (url, methode) => methode === 'DELETE' && /\/collections\/termineBookings\/documents\/b_ab/.test(url)
+
+for (const [wann, passt] of [['zwischen Funktionsliste und Buchungsliste', funktionsListe], ['zwischen Buchungsliste und erster Löschung', listeVonBuchungen(/featureId/)]]) {
+  for (const [was, umschalten] of [
+    ['wieder eingeschaltet (disabledAt bleibt alt)', schalteEin],
+    ['frisch neu abgeschaltet', () => aw.seed('portalFeatures', { ...aw.docs('portalFeatures').get(F1), disabledAt: iso(plus(JETZT, -TAG)) })],
+  ]) {
+    test(`loescheAbgeschalteteFunktionen: ${was} ${wann} ⇒ nichts wird gelöscht`, async () => {
+      await abgeschaltetMitBuchungen(3)
+      const erg = await mitEinwurf(passt, async () => umschalten(), () => loescheAbgeschalteteFunktionen(JETZT))
+      assert.deepEqual(erg, { funktionen: 0, buchungen: 0 })
+      assert.equal(buchungen().length, 3, 'alle Buchungen bleiben')
+      assert.equal(aw.docs('termineClaims').size > 0, true)
+      for (const b of buchungen()) assert.ok(claims(b.$id).length > 0, `${b.$id}: Zellen bleiben`)
+      assert.ok(aw.docs('termineConfig').get(F1), 'Einstellung bleibt')
+      assert.ok(warnLog().some((zeile) => /inzwischen wieder aktiv oder neu abgeschaltet/.test(zeile)), 'Abbruch steht im Log')
+      assert.equal(fehlerLog().length, 0, 'kein Fehler, kein Wurf')
+    })
+  }
+}
+
+test('loescheAbgeschalteteFunktionen: wird die Funktion nach 50 Buchungen wieder eingeschaltet, endet die Löschung dort', async () => {
+  await abgeschaltetMitBuchungen(60, { zellen: false })
+  const echt = globalThis.fetch
+  let geloescht = 0
+  globalThis.fetch = async (url, optionen) => {
+    const antwort = await echt(url, optionen)
+    if (buchungLoeschen(String(url), optionen?.method ?? 'GET')) {
+      geloescht += 1
+      if (geloescht === 50) schalteEin()
+    }
+    return antwort
+  }
+  let erg
+  try {
+    erg = await loescheAbgeschalteteFunktionen(JETZT)
+  } finally {
+    globalThis.fetch = echt
+  }
+  assert.equal(geloescht, 50, 'nach dem Einschalten kommt keine Löschung mehr')
+  assert.deepEqual(erg, { funktionen: 1, buchungen: 50 })
+  assert.equal(buchungen().length, 10)
+  assert.ok(aw.docs('termineConfig').get(F1), 'Einstellung bleibt')
+})
+
+test('loescheAbgeschalteteFunktionen: wird die Funktion nach der letzten Buchung wieder eingeschaltet, bleibt die Einstellung', async () => {
+  await abgeschaltetMitBuchungen(2)
+  const erg = await mitEinwurf(buchungLoeschen, async () => schalteEin(), () => loescheAbgeschalteteFunktionen(JETZT))
+  // die erste Buchung ging noch vor dem Einschalten; die Funktion ist danach aktiv, ihre Einstellung muss bleiben
+  assert.ok(aw.docs('termineConfig').get(F1), 'Einstellung bleibt')
+  assert.equal(erg.funktionen, 1)
+  assert.equal(erg.buchungen, 2, 'beide Buchungen waren in einem Block von 50, vor der nächsten Prüfung gelöscht')
+})
+
+test('loescheAbgeschalteteFunktionen: kann die Funktion vor dem Löschen nicht gelesen werden, wird nichts gelöscht (Fehler im Log)', async () => {
+  await abgeschaltetMitBuchungen(2)
+  aw.failNext({ collection: 'portalFeatures', method: 'GET', status: 500, message: 'Nachbau kaputt', after: 1 }) // 1. GET = Liste, 2. = Neulesen
+  const erg = await loescheAbgeschalteteFunktionen(JETZT)
+  assert.deepEqual(erg, { funktionen: 0, buchungen: 0 })
+  assert.equal(buchungen().length, 2)
+  assert.ok(aw.docs('termineConfig').get(F1))
+  assert.equal(fehlerLog().length, 1)
+})
+
 // ---------------------------------------------------------------- Tagesjob
 
 test('taeglicherJob: Löschfristen, Warteschlange, festgefahrene Mails, verwaiste Zellen und abgeschaltete Funktionen in einem Lauf', async () => {
@@ -822,6 +895,20 @@ test('taeglicherJob: Löschfristen, Warteschlange, festgefahrene Mails, verwaist
   assert.equal(aw.docs('termineClaims').size, claims('b_zukunft').length, 'sonst bleibt keine Zelle übrig')
   assert.equal(aw.docs('termineOutbox').get('o_gesendet'), undefined)
   assert.equal(aw.docs('termineOutbox').get('o_festgefahren').status, 'fehler')
+
+  // eine Zeile fürs Log: nur Zahlen, keine IDs, keine Personendaten
+  const zeile = tagesbericht(erg)
+  assert.equal(
+    zeile,
+    `[termine] Tagesjob: 3 Buchungen gelöscht (verfallen 1, abgesagt 0, abgelehnt 0, erledigt 1, nichterschienen 0, abgeschaltete Funktionen 1), 1 Funktionen bereinigt, ${erg.zellen} Zellen, 1 Outbox, 1 Mails nicht zugestellt, 0 Fehler`,
+  )
+  assert.doesNotMatch(zeile, /\bb_|\bf_|@|Mustermann|Salon/)
+})
+
+test('tagesbericht: keine Zeile, wenn der Job nicht gelaufen ist', () => {
+  assert.equal(tagesbericht({ aus: true }), null)
+  assert.equal(tagesbericht({ uebersprungen: true }), null)
+  assert.equal(tagesbericht(undefined), null)
 })
 
 test('taeglicherJob: festgefahrene Mail wird fehler und erst 48 Stunden später gelöscht (nicht im selben Lauf)', async () => {
@@ -861,6 +948,8 @@ test('fehlende Collection: höchstens eine Warnung je Stunde und Job, kein Wurf'
     assert.equal(warnLog().filter((zeile) => /minutenJob/.test(zeile)).length, 2, 'nach einer Stunde wieder')
   })
   assert.match(warnLog()[0], /collection_not_found/)
+  assert.match(warnLog().find((zeile) => /minutenJob/.test(zeile)), /Schritt „Verfall“/, 'die Warnung nennt den Schritt')
+  assert.match(warnLog().find((zeile) => /fuenfMinutenJob/.test(zeile)), /Schritt „Erinnerungen“/)
 })
 
 test('fehlende Collection der Warteschlange: der Minutenjob verfällt trotzdem Haltungen', async () => {
@@ -921,10 +1010,15 @@ test('server/index.js: die drei Jobs laufen alle 60 s, alle 5 min und täglich (
   assert.match(index, /import \{[^}]*\bfuenfMinutenJob\b[^}]*\} from '\.\/services\/termine\/jobs\.js'/)
   assert.match(index, /import \{[^}]*\btaeglicherJob\b[^}]*\} from '\.\/services\/termine\/jobs\.js'/)
   for (const [job, takt] of [['minutenJob', '60 \\* 1000'], ['fuenfMinutenJob', '5 \\* 60 \\* 1000'], ['taeglicherJob', '24 \\* 60 \\* 60 \\* 1000']]) {
-    const lauf = new RegExp(`const (\\w+) = \\(\\) =>\\s*${job}\\(new Date\\(\\)\\)\\s*\\.catch\\(`)
+    const lauf = new RegExp(`const (\\w+) = \\(\\) =>\\s*${job}\\(new Date\\(\\)\\)([\\s\\S]*?)\\.catch\\(`)
     const treffer = lauf.exec(index)
     assert.ok(treffer, `${job} mit .catch eingebunden`)
     assert.match(index, new RegExp(`setInterval\\(${treffer[1]}, ${takt}\\)\\.unref\\(\\)`), `${job}: Intervall`)
-    if (job === 'taeglicherJob') assert.match(index, new RegExp(`setTimeout\\(${treffer[1]}, 180 \\* 1000\\)\\.unref\\(\\)`), 'täglicher Job: +180 s')
+    if (job === 'taeglicherJob') {
+      assert.match(index, new RegExp(`setTimeout\\(${treffer[1]}, 180 \\* 1000\\)\\.unref\\(\\)`), 'täglicher Job: +180 s')
+      assert.match(treffer[2], /\.then\(\(ergebnis\) => \{\s*const zeile = tagesbericht\(ergebnis\)\s*if \(zeile\) console\.log\(zeile\)\s*\}\)\s*$/, 'eine Zusammenfassung pro Tageslauf im Log')
+    } else {
+      assert.match(treffer[2], /^\s*$/, `${job}: direkt .catch`)
+    }
   }
 })