Logging

README.md

@@ -35,18 +35,22 @@ Steuerungen → appRobotDriver → appRobotFileservice
 
 ## Dateiformat
 
-`.gcode` sieht aus wie Standard-G-Code; Zeitstempel und Cursor stehen im
+`.gcode` ist die **einzige verbindliche Positions-Abfolge** — reiner Standard-G-Code,
-**Kommentarfeld** (`;…`, standardkonform):
+nur der Aufnahme-Zeitstempel steht im **Kommentarfeld** (`;…`, standardkonform):
 
 ```
 G90 G1 x0 y300 z0 a90.00 b-90.00 c0.00 e0.00 f1000 ;1759566014
-G90 G1 x310 y444 z0.5 a90.00 b-90.00 c0.00 e6.88 f1000 ;1759566112!   <- Cursor (!)
+G90 G1 x310 y444 z0.5 a90.00 b-90.00 c0.00 e6.88 f1000 ;1759566112
 ```
 
-- `;<epoch>` = Aufnahme-Zeitstempel · abschließendes `!` = Cursor-Zeile.
+- `;<epoch>` = Aufnahme-Zeitstempel. Sonst nichts Service-Internes in der `.gcode`.
+- `<id>.json` ist ein Sidecar mit **Zusatz-Infos**: Name, Zeiten, `lineCount`,
+  `angleUnit` und der **`cursor`** (Index der zuletzt angefahrenen Zeile).
 - Der Cursor lebt zur Laufzeit als In-Memory-Index (schnelles Stepping ohne
-  Neuschreiben) und wird beim Speichern/Entladen als `!` zurückgeschrieben.
+  Neuschreiben) und wird beim Speichern/Entladen ins `.json` geschrieben — die
-- `<id>.json` ist ein Sidecar mit Metadaten (Name, Zeiten, `lineCount`, `angleUnit`).
+  `.gcode` bleibt sauber.
+- Migration: alte `.gcode`-Dateien mit `!`-Cursor-Marker werden beim ersten Lesen
+  automatisch übernommen (Marker raus, Cursor ins `.json`).
 
 ## Start
 

src/active/activeState.js

@@ -11,6 +11,7 @@
 const store = require('../store/fileStore');
 const units = require('../gcode/units');
 const cfg   = require('../config');
+const log   = require('../log');
 const { ApiError } = require('../errors');
 
 class ActiveState {
@@ -32,6 +33,20 @@ class ActiveState {
     if (!this.programId) throw new ApiError(409, 'NO_ACTIVE_PROGRAM', 'no active program');
   }
 
+  /**
+   * Stellt sicher, dass ein Programm aktiv ist. Ist keines geladen, wird das
+   * Default-Programm (cfg.defaultProgramId, i. d. R. 'log') geladen — exakt das
+   * alte Verhalten, bei dem log.gcode immer implizit aktiv war. Gilt für Lesen
+   * (Stepping/Play) UND Schreiben (FPoint), damit nach einem Neustart sofort
+   * gearbeitet werden kann, ohne vorher FLoad zu senden.
+   */
+  async _ensureActive() {
+    if (!this.programId) {
+      log.info(`kein aktives Programm → lade Default '${cfg.defaultProgramId}'`);
+      await this.load(cfg.defaultProgramId);
+    }
+  }
+
   /** API-Repräsentation (ActiveState). currentLine = driver-nativ (Radian). */
   getState() {
     const currentLine = this.lines.length ? units.toExecutable(this.lines[this.cursor]) : null;
@@ -61,6 +76,7 @@ class ActiveState {
       this.cursor = 0;
       this.playing = false;
       this._touch();
+      log.info(`load '${id}' → neu (leer angelegt)`);
       return this.getState();
     }
 
@@ -71,12 +87,13 @@ class ActiveState {
     this.cursor = Math.min(prog.cursor ?? 0, Math.max(0, prog.lines.length - 1));
     this.playing = false;
     this._touch();
+    log.info(`load '${id}' → ${prog.lines.length} Zeilen von Disk, cursor ${this.cursor}`);
     return this.getState();
   }
 
   /** Leert das aktive Programm (FClear). */
   async clear() {
-    this._requireActive();
+    await this._ensureActive();
     this.lines = [];
     this.cursor = 0;
     this.playing = false;
@@ -88,7 +105,6 @@ class ActiveState {
   // ---- Stepping (reine Cursor-Bewegung, gibt die ausführbare Zeile zurück) ----
 
   _gotoIndex(index) {
-    this._requireActive();
     if (!this.lines.length) throw new ApiError(409, 'EMPTY_PROGRAM', 'active program is empty');
     if (index < 0 || index >= this.lines.length) {
       throw new ApiError(
@@ -102,30 +118,32 @@ class ActiveState {
     return { cursor: this.cursor, line: units.toExecutable(this.lines[this.cursor]) };
   }
 
-  next() { return this._gotoIndex(this.cursor + 1); }
+  // Stepping lädt bei Bedarf das Default-Programm (Lesen mit implizitem log).
-  prev() { return this._gotoIndex(this.cursor - 1); }
+  async next()      { await this._ensureActive(); return this._gotoIndex(this.cursor + 1); }
-  first() { return this._gotoIndex(0); }
+  async prev()      { await this._ensureActive(); return this._gotoIndex(this.cursor - 1); }
-  last() { return this._gotoIndex(this.lines.length - 1); }
+  async first()     { await this._ensureActive(); return this._gotoIndex(0); }
-  goto(index) { return this._gotoIndex(Number(index)); }
+  async last()      { await this._ensureActive(); return this._gotoIndex(this.lines.length - 1); }
+  async goto(index) { await this._ensureActive(); return this._gotoIndex(Number(index)); }
 
   // ---- Teaching / Editieren (persistiert) ----
 
   /** Hängt die aktuelle Pose als G-Code-Zeile an (FPoint). pose: a/b/c/e in RADIAN.
    *  Kein aktives Programm → Default-Programm auto-laden (backward-compat. mit log.gcode). */
   async appendPoint(pose, feedrate) {
-    if (!this.programId) await this.load(cfg.defaultProgramId);
+    await this._ensureActive();
     if (!pose) throw new ApiError(400, 'FILE_ERROR', 'pose required');
     const line = units.formatPointLine(pose, feedrate);
     this.lines.push(line);
     this.cursor = this.lines.length - 1;
     this._touch();
     await this._persist();
+    log.info(`FPoint → '${this.programId}' index ${this.cursor}: ${line}`);
     return { index: this.cursor, line };
   }
 
   /** Hängt eine rohe Zeile an oder fügt sie an atIndex ein. */
   async appendLine(line, atIndex) {
-    this._requireActive();
+    await this._ensureActive();
     if (!line) throw new ApiError(400, 'FILE_ERROR', 'line required');
     const clean = units.removeCursorMarker(String(line));
     if (atIndex == null) {
@@ -169,8 +187,8 @@ class ActiveState {
   // ---- Playback (passiv: der Driver führt die Zeilen aus) ----
 
   /** Liefert die ausführbaren Zeilen ab Cursor (bzw. ab 0). Setzt playing. */
-  play({ mode = 'run', fromStart = false } = {}) {
+  async play({ mode = 'run', fromStart = false } = {}) {
-    this._requireActive();
+    await this._ensureActive();
     if (!this.lines.length) throw new ApiError(409, 'EMPTY_PROGRAM', 'active program is empty');
     if (fromStart) this.cursor = 0;
     this.playing = true;

src/errors.js

@@ -1,5 +1,6 @@
 // Fehler-Modell — Envelope konsistent mit dem Driver (doc/ToDo_5_API.md):
 //   { type: 'error', code, message, input }
+const log = require('./log');
 
 /** Fehler mit HTTP-Status + maschinenlesbarem Code. */
 class ApiError extends Error {
@@ -19,13 +20,15 @@ function envelope(code, message, input = null) {
 /** Express-Fehler-Middleware. */
 function errorMiddleware(err, req, res, _next) {
   if (err instanceof ApiError) {
+    log.warn(`${err.code} (${err.status}): ${err.message}`);
     return res.status(err.status).json(envelope(err.code, err.message));
   }
   // Ungültiger JSON-Body (vom express.json-Parser)
   if (err && err.type === 'entity.parse.failed') {
+    log.warn('FILE_ERROR: invalid JSON body');
     return res.status(400).json(envelope('FILE_ERROR', 'invalid JSON body'));
   }
-  console.error(err);
+  log.error(err.stack || err.message || err);
   return res.status(500).json(envelope('FILE_ERROR', err.message || 'internal error'));
 }
 

src/log.js

@@ -0,0 +1,18 @@
+// Schlanker, konsistenter Logger. Alle Ausgaben mit Zeitstempel + [fsvc]-Präfix,
+// damit man im Container-Log Fileservice-Zeilen sofort erkennt.
+// Im Test (NODE_ENV=test) still, damit die Jest-Ausgabe sauber bleibt.
+const silent = process.env.NODE_ENV === 'test';
+
+const ts = () => new Date().toISOString();
+
+function info(...args) {
+  if (!silent) console.log(`${ts()} [fsvc]`, ...args);
+}
+function warn(...args) {
+  if (!silent) console.warn(`${ts()} [fsvc] ⚠`, ...args);
+}
+function error(...args) {
+  if (!silent) console.error(`${ts()} [fsvc] ✖`, ...args);
+}
+
+module.exports = { info, warn, error };

src/routes/active.js

@@ -26,12 +26,12 @@ router.put(
 // POST /api/active/clear  (FClear)
 router.post('/clear', requireAuth, asyncH(async (req, res) => res.json(await active.clear())));
 
-// Stepping (synchron; ApiError wird von Express an die Fehler-Middleware gereicht)
+// Stepping (lädt bei Bedarf das Default-Programm; ApiError → Fehler-Middleware)
-router.post('/next', requireAuth, (req, res) => res.json(active.next()));
+router.post('/next', requireAuth, asyncH(async (req, res) => res.json(await active.next())));
-router.post('/prev', requireAuth, (req, res) => res.json(active.prev()));
+router.post('/prev', requireAuth, asyncH(async (req, res) => res.json(await active.prev())));
-router.post('/first', requireAuth, (req, res) => res.json(active.first()));
+router.post('/first', requireAuth, asyncH(async (req, res) => res.json(await active.first())));
-router.post('/last', requireAuth, (req, res) => res.json(active.last()));
+router.post('/last', requireAuth, asyncH(async (req, res) => res.json(await active.last())));
-router.post('/goto', requireAuth, (req, res) => res.json(active.goto((req.body || {}).index)));
+router.post('/goto', requireAuth, asyncH(async (req, res) => res.json(await active.goto((req.body || {}).index))));
 
 // Teaching / Editieren
 router.post(
@@ -66,7 +66,7 @@ router.delete(
 );
 
 // Playback
-router.post('/play', requireAuth, (req, res) => res.json(active.play(req.body || {})));
+router.post('/play', requireAuth, asyncH(async (req, res) => res.json(await active.play(req.body || {}))));
 router.post('/stop', requireAuth, (req, res) => res.json(active.stop()));
 
 module.exports = router;

src/server.js

@@ -3,11 +3,24 @@ const express = require('express');
 const programsRouter = require('./routes/programs');
 const activeRouter = require('./routes/active');
 const { errorMiddleware, envelope } = require('./errors');
+const log = require('./log');
 
 function createApp() {
   const app = express();
   app.use(express.json({ limit: '5mb' }));
 
+  // Request-Logging: jede Anfrage mit Methode, Pfad, Status und Dauer. So sieht man
+  // im Container-Log sofort, ob der Driver durchkommt und wie der Service antwortet.
+  app.use((req, res, next) => {
+    const t0 = Date.now();
+    res.on('finish', () => {
+      const ms = Date.now() - t0;
+      const mark = res.statusCode >= 400 ? '✖' : '→';
+      log.info(`${mark} ${req.method} ${req.originalUrl} ${res.statusCode} (${ms}ms)`);
+    });
+    next();
+  });
+
   app.get('/api/health', (req, res) => res.json({ ok: true, service: 'appRobotFileservice' }));
   app.use('/api/programs', programsRouter);
   app.use('/api/active', activeRouter);

src/store/fileStore.js

@@ -10,6 +10,7 @@ const fsp = require('fs/promises');
 const path = require('path');
 const cfg = require('../config');
 const units = require('../gcode/units');
+const log = require('../log');
 const { ApiError } = require('../errors');
 
 const ID_RE = /^[a-z0-9_]+$/;
@@ -107,6 +108,7 @@ async function write(id, { name, lines, cursor = 0 }) {
   const body = lines.join('\n') + (lines.length ? '\n' : '');
   await fsp.writeFile(gcodePath(id), body, 'utf8');
   await fsp.writeFile(jsonPath(id), JSON.stringify(meta, null, 2) + '\n', 'utf8');
+  log.info(`write ${gcodePath(id)} (${lines.length} Zeilen, cursor ${cursor})`);
   return meta;
 }
 

test/activeState.test.js

@@ -42,14 +42,14 @@ test('Playback: stepping liefert driver-native (Radian) Zeilen, Grenzen werfen',
   const a = new ActiveState();
   await a.load('play_1');
 
-  const first = a.first();
+  const first = await a.first();
   expect(first.cursor).toBe(0);
   expect(first.line).not.toMatch(/;/);
   const aVal = Number(first.line.split(/\s+/).find((t) => t.startsWith('a')).slice(1));
   expect(aVal).toBeCloseTo(Math.PI / 2, 4);
 
-  expect(a.next().cursor).toBe(1);
+  expect((await a.next()).cursor).toBe(1);
-  expect(() => a.next()).toThrow(); // über das Ende → CURSOR_OUT_OF_RANGE
+  await expect(a.next()).rejects.toThrow(); // über das Ende → CURSOR_OUT_OF_RANGE
 });
 
 test('Cursor liegt im .json-Sidecar, .gcode bleibt sauber (kein !-Marker)', async () => {
@@ -62,7 +62,7 @@ test('Cursor liegt im .json-Sidecar, .gcode bleibt sauber (kein !-Marker)', asyn
   });
   const a = new ActiveState();
   await a.load('cur_1');
-  a.next(); // cursor → 1 (kein Persist)
+  await a.next(); // cursor → 1 (kein Persist)
   await a.appendLine('G4 P0.1'); // persistiert, cursor → 2
 
   const prog = await store.read('cur_1');
@@ -75,9 +75,28 @@ test('Cursor liegt im .json-Sidecar, .gcode bleibt sauber (kein !-Marker)', asyn
   expect(units.splitComment(prog.lines[2]).code).toBe('G4 P0.1');
 });
 
-test('Stepping ohne aktives Programm → NO_ACTIVE_PROGRAM', async () => {
+test('Stepping ohne aktives Programm → auto-lädt Default (leer → EMPTY_PROGRAM)', async () => {
   const a = new ActiveState();
-  expect(() => a.next()).toThrow(); // NO_ACTIVE_PROGRAM
+  // next() lädt automatisch das Default-Programm; da es (im tmp) leer ist → EMPTY_PROGRAM
+  await expect(a.next()).rejects.toMatchObject({ code: 'EMPTY_PROGRAM' });
+  expect(a.programId).toBe(cfg.defaultProgramId); // Default wurde geladen
+});
+
+test('Stepping nach Neustart liest Default-Programm von Disk (FFirst ohne FLoad)', async () => {
+  // Simuliert: log.gcode liegt auf Disk, frischer ActiveState (wie nach Container-Neustart)
+  await store.write(cfg.defaultProgramId, {
+    name: 'log',
+    lines: [
+      'G90 G1 x0 y300 z0 a90.00 b-90.00 c0.00 e0.00 f1000 ;1',
+      'G90 G1 x10 y300 z0 a0.00 b-90.00 c0.00 e0.00 f1000 ;2',
+    ],
+    cursor: 1,
+  });
+  const a = new ActiveState();
+  const r = await a.first(); // ohne vorheriges FLoad → Default wird geladen
+  expect(a.programId).toBe(cfg.defaultProgramId);
+  expect(r.cursor).toBe(0);
+  expect(a.getState().lineCount).toBe(2);
 });
 
 test('FPoint ohne aktives Programm → auto-lädt Default-Programm (log)', async () => {