diff --git a/.github/upstream-check/watch.json b/.github/upstream-check/watch.json index 1809d95e46..f30959f536 100644 --- a/.github/upstream-check/watch.json +++ b/.github/upstream-check/watch.json @@ -124,6 +124,13 @@ "keywords": ["SetMaxPower"], "paths": ["core/circuit/", "core/site.go", "server/"] }, + { + "name": "Log-Datei (Tagesdateien)", + "files": ["util/logstash/file_custom.go", "core/site_logfile.go"], + "prs": [32018], + "keywords": ["log file", "logfile", "LogFile", "logrotate", "lumberjack", "rotat"], + "paths": ["util/log.go", "util/logstash/"] + }, { "name": "Grundlagen, auf denen der Fork aufbaut", "files": ["core/loadpoint_lm.go"], diff --git a/assets/js/components/LogFile/LogFileButton.vue b/assets/js/components/LogFile/LogFileButton.vue new file mode 100644 index 0000000000..69337203de --- /dev/null +++ b/assets/js/components/LogFile/LogFileButton.vue @@ -0,0 +1,61 @@ + + + diff --git a/assets/js/components/LogFile/LogFileModal.vue b/assets/js/components/LogFile/LogFileModal.vue new file mode 100644 index 0000000000..27a3ebb4a0 --- /dev/null +++ b/assets/js/components/LogFile/LogFileModal.vue @@ -0,0 +1,200 @@ + + + + diff --git a/assets/js/types/evcc-lm.ts b/assets/js/types/evcc-lm.ts index 6b362d7d80..f98ca0ae64 100644 --- a/assets/js/types/evcc-lm.ts +++ b/assets/js/types/evcc-lm.ts @@ -257,3 +257,19 @@ export interface LmConfigLoadpoint { phaseScale3pDelay?: number; // ns before scaling up, 0/empty = enable delay phaseScale1pDelay?: number; // ns before scaling down, 0/empty = disable delay } + +/** Log file setting and state, see core/site_logfile.go. */ +export interface LogFileState { + enabled: boolean; + /** Level of the file: error, warn, info, debug or trace. */ + level: string; + /** Days the files are kept. */ + days: number; + /** Folder of the files, set by evcc. */ + dir: string; + files: number; + /** Bytes of all files. */ + size: number; + /** Why the file is off, empty = none. */ + error?: string; +} diff --git a/assets/js/views/Log.vue b/assets/js/views/Log.vue index 6e20ecb078..7b4dc97ae8 100644 --- a/assets/js/views/Log.vue +++ b/assets/js/views/Log.vue @@ -36,6 +36,8 @@ > + +
, default: () => [] }, diff --git a/cmd/root.go b/cmd/root.go index f602d9257f..f2e69fff9f 100644 --- a/cmd/root.go +++ b/cmd/root.go @@ -28,6 +28,7 @@ import ( "github.com/evcc-io/evcc/ui" "github.com/evcc-io/evcc/util" "github.com/evcc-io/evcc/util/auth" + "github.com/evcc-io/evcc/util/logstash" "github.com/evcc-io/evcc/util/pipe" "github.com/evcc-io/evcc/util/sponsor" "github.com/evcc-io/evcc/util/telemetry" @@ -556,6 +557,8 @@ func runRoot(cmd *cobra.Command, args []string) { case <-time.After(max(conf.Interval, 5*time.Second)): } + logstash.CloseFile() // custom: write out the log file, see util/logstash/file_custom.go + // exit code 1 on error os.Exit(cast.ToInt(err != nil)) } diff --git a/core/fork_hooks_test.go b/core/fork_hooks_test.go index 713928317c..661c6a816c 100644 --- a/core/fork_hooks_test.go +++ b/core/fork_hooks_test.go @@ -48,6 +48,8 @@ var forkHooks = []struct { {"api/globalconfig/types.go", "TariffRefs.IsConfigured", []string{"FeedInEeg"}}, {"api/globalconfig/types.go", "TariffRefs.Used", []string{"FeedInEeg"}}, {"charger/switchsocket.go", "NewSwitchSocketFromConfig", []string{"RatedPower"}}, + {"util/log.go", "newLogger", []string{"Output"}}, + {"cmd/root.go", "runRoot", []string{"CloseFile"}}, } // forkUiHooks lists the fork's mounts in evcc's ui files @@ -62,6 +64,7 @@ var forkUiHooks = []struct { {"assets/js/components/Config/LoadpointModal.vue", []string{" evcc , level ` +- the first line of a new day switches the file, the day before is compressed in + the background (`.log.gz`, streaming) and the original deleted; files left + unpacked by a stop are packed the same way +- the retention (1-90 days, default 14) counts today: older files are deleted + when switching on and at each new day. Over 1 GB for all files together the + oldest are deleted with a warning, also while today's file grows; today's file + is never deleted, if it alone reaches 1 GB it pauses with a note until the next day +- written buffered (64 KB) and flushed every 2 s, at once for warnings and errors, + when switching off and at the end of `runRoot`: a power cut or a kill loses at + most 2 s of info and debug lines +- a folder that cannot be created or a full disk switches the file off for this + run: logged once as an error (console and log page) and shown in the dialog. The + setting stays on, the next start tries again. A failing file never stops + the control loop + +``` +GET /api/logfile {enabled, level, days, dir, files, size, error} +POST /api/logfile json body {enabled, level, days}, answers like GET +``` + +The output sits between the loggers and the buffer (`logstash.Output`, hook in +`util/log.go`), the buffer and the log page stay as they are. evcc PR 32018 (open) +changes the logger underneath `util/log.go`; then the hook has to be set again and +checked whether evcc brings a file output itself. See `util/logstash/file_custom.go`, +`core/site_logfile.go`. + --- ## Rules @@ -459,11 +504,14 @@ Every change in an evcc file. Check these when merging a new evcc version. | `core/loadpoint/config.go`, `server/http_config_loadpoint_handler.go` | `PhaseSwitchConfig` in the dynamic config, applied after min/max current, read back for the ui | | `core/circuit/circuit.go` | over power logged via `overPowerLog()` (info, no ui notification) | | `charger/switchsocket.go` | `RatedPower` config field | +| `util/log.go` | `newLogger` writes to `logstash.Output` instead of `logstash.DefaultHandler`, which passes every line on to it and to the log file | +| `cmd/root.go` | `logstash.CloseFile()` at the end of `runRoot`, after the shutdown functions | | `templates/definition/charger/homeassistant-switch.yaml` | `ratedpower` parameter | | `api/globalconfig/types.go`, `tariff/tariffs.go`, `cmd/setup.go`, `server/http_config_device_handler.go` | `feedInEeg` tariff: ref field, `Used`/`IsConfigured`, one `configureTariff` call, cleared on delete | | `server/http.go` | `addCustomSiteRoutes`: a route colliding with an evcc route is left out and logged | | `assets/js/views/App.vue` | mounts `LoadManagement/GlobalModals.vue` | | `assets/js/views/Battery.vue` | mounts the battery cards and the profile selection | +| `assets/js/views/Log.vue` | mounts `LogFile/LogFileButton.vue` next to the download button | | `assets/js/views/Config.vue` | *Lastmanagement-Details* section, `LmConfigModals.vue`, EEG tariff card and add button | | `assets/js/components/BottomTabs/MoreMenu.vue` | mounts `LoadManagement/MoreMenuItems.vue` | | `assets/js/components/Config/LoadpointModal.vue` | mounts `PhaseSwitchFields.vue`, 3-phase labels and minimum while it is shown; default mode labels Aus/Smart/Ein for a heater in stages (`chargerIsStages`) | @@ -487,6 +535,7 @@ Every change in an evcc file. Check these when merging a new evcc version. | forecast | `core/site_load_weekday.go`, `core/site_load_manual.go`, `core/metrics/profile_custom.go` | | battery identification | `core/site_battery_ident.go`, `core/metrics/slots_custom.go` | | EEG | `core/site_feedin_eeg.go`, `core/metrics/feedin_eeg_custom.go`, `assets/js/components/Energy/feedInEeg.ts` | +| log file | `util/logstash/file_custom.go`, `core/site_logfile.go`, `assets/js/components/LogFile/` | | optimizer | `core/site_optimizer_lm.go`, `core/site_optimizer_reserve_pass.go`, `core/site_optimizer_soc_pass.go` | | api, keys | `core/site/api_custom.go`, `server/http_custom.go`, `core/keys/site_custom.go` | | ui | `assets/js/types/evcc-lm.ts`, `assets/js/utils/lmPriorityOrder.ts`, `assets/js/components/LoadManagement/`, `assets/js/components/PeakShaving/`, the battery cards in `assets/js/components/Battery/` (`BatterySocGridChargeCard`, `BatteryGridChargeOnce`, `BatteryPeakShavingCard`, `BatteryProfileCard`, `ProfileIcon`), the config components in `assets/js/components/Config/` (`PeakShavingConfig`, `LmConfigModals` and its dialogs, `FeedInEegSummary`, `PhaseSwitchFields`) | diff --git a/core/site/api_custom.go b/core/site/api_custom.go index 31db061b1b..13d221a6e5 100644 --- a/core/site/api_custom.go +++ b/core/site/api_custom.go @@ -4,6 +4,7 @@ import ( "time" "github.com/evcc-io/evcc/core/lm/profile" + "github.com/evcc-io/evcc/util/logstash" ) // CustomAPI is the part of the site api added by this fork. It lives in its own @@ -56,6 +57,10 @@ type CustomAPI interface { GetFeedInEegEntity() string SetFeedInEegEntity(string) error + // log in daily files, see core/site_logfile.go + LogFile() logstash.FileState + SetLogFile(logstash.FileConfig) error + // peak shaving, see core/site_peakshaving.go GetPeakShaving() bool SetPeakShaving(bool) error diff --git a/core/site_lm.go b/core/site_lm.go index 12161b9da0..058a125985 100644 --- a/core/site_lm.go +++ b/core/site_lm.go @@ -100,6 +100,7 @@ func (site *Site) restoreCustom() { site.restoreLmSettings() site.restorePeakSettings() site.restoreFeedInEeg() + site.restoreLogFile() } // updateCustom runs the fork's per cycle work once the meters are read, before diff --git a/core/site_logfile.go b/core/site_logfile.go new file mode 100644 index 0000000000..dcc15676a1 --- /dev/null +++ b/core/site_logfile.go @@ -0,0 +1,95 @@ +package core + +// Custom extension: the log in daily files, set in the ui on the log page. The +// writing is in util/logstash/file_custom.go, this holds the setting, the folder +// and the api. Without a stored setting nothing is written and no folder created. + +import ( + "os" + "path/filepath" + "strings" + "sync" + + "github.com/evcc-io/evcc/core/keys" + "github.com/evcc-io/evcc/db" + "github.com/evcc-io/evcc/db/settings" + "github.com/evcc-io/evcc/util" + "github.com/evcc-io/evcc/util/logstash" + jww "github.com/spf13/jwalterweatherman" +) + +// logFileMu serializes saving and applying the setting +var logFileMu sync.Mutex + +// logFileDir returns the folder of the log files, replaced in tests +var logFileDir = func() string { + return logFileDirFor("/config", db.FilePath()) +} + +// logFileDirFor returns /config/logs where /config is a folder (the add-on, reachable through +// its share), else logs next to the database file. Empty without either, e.g. an in-memory database. +func logFileDirFor(configDir, dbFile string) string { + if fi, err := os.Stat(configDir); err == nil && fi.IsDir() { + return filepath.Join(configDir, "logs") + } + + if dbFile == "" || strings.Contains(dbFile, ":memory:") || strings.Contains(dbFile, "mode=memory") { + return "" + } + + return filepath.Join(filepath.Dir(dbFile), "logs") +} + +// restoreLogFile applies the persisted setting, switched on again after a restart +func (site *Site) restoreLogFile() { + cfg := logstash.DefaultFileConfig + + if err := settings.Json(keys.LogFile, &cfg); err != nil || cfg.Validate() != nil { + cfg = logstash.DefaultFileConfig + } + + site.applyLogFile(cfg) +} + +// applyLogFile hands the setting to the writer +func (site *Site) applyLogFile(cfg logstash.FileConfig) { + log := util.NewLogger("logfil") + + cfg.Level = strings.ToLower(cfg.Level) + cfg.Dir = logFileDir() + cfg.Version = util.FormattedVersion() + cfg.Log = func(level jww.Threshold, msg string) { + if level >= jww.LevelError { + log.ERROR.Println(msg) + } else { + log.WARN.Println(msg) + } + } + + _, _ = logstash.SetFile(cfg) +} + +// LogFile returns the log file setting with folder, files and size +func (site *Site) LogFile() logstash.FileState { + return logstash.FileStatus() +} + +// SetLogFile saves the log file setting and applies it +func (site *Site) SetLogFile(cfg logstash.FileConfig) error { + if err := cfg.Validate(); err != nil { + return err + } + + cfg.Level = strings.ToLower(cfg.Level) + + logFileMu.Lock() + defer logFileMu.Unlock() + + if err := settings.SetJson(keys.LogFile, cfg); err != nil { + return err + } + + site.applyLogFile(cfg) + + return nil +} diff --git a/core/site_logfile_test.go b/core/site_logfile_test.go new file mode 100644 index 0000000000..f4c8e8e039 --- /dev/null +++ b/core/site_logfile_test.go @@ -0,0 +1,146 @@ +package core + +import ( + "os" + "path/filepath" + "testing" + + "github.com/evcc-io/evcc/core/keys" + "github.com/evcc-io/evcc/db/settings" + "github.com/evcc-io/evcc/util/logstash" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +// useLogFileDir points the log file at a folder of the test and switches it off afterwards +func useLogFileDir(t *testing.T) string { + t.Helper() + + dir := filepath.Join(t.TempDir(), "logs") + + prev := logFileDir + logFileDir = func() string { return dir } + t.Cleanup(func() { + logFileDir = prev + _, _ = logstash.SetFile(logstash.DefaultFileConfig) + }) + + return dir +} + +func TestLogFileDirFor(t *testing.T) { + root := t.TempDir() + file := filepath.Join(root, "file") + require.NoError(t, os.WriteFile(file, nil, 0o644)) + + // the add-on: /config is a folder and takes precedence over the database + assert.Equal(t, filepath.Join(root, "logs"), logFileDirFor(root, "/var/lib/evcc/evcc.db")) + + // /config missing or no folder: next to the database + assert.Equal(t, filepath.Join("/var/lib/evcc", "logs"), logFileDirFor(filepath.Join(root, "none"), "/var/lib/evcc/evcc.db")) + assert.Equal(t, filepath.Join("/var/lib/evcc", "logs"), logFileDirFor(file, "/var/lib/evcc/evcc.db")) + + // no place to write to + assert.Empty(t, logFileDirFor(root+"/none", "")) + assert.Empty(t, logFileDirFor(root+"/none", ":memory:")) + assert.Empty(t, logFileDirFor(root+"/none", "file::memory:?cache=shared")) +} + +// TestLogFileInertWhenUnused: without a stored setting nothing is written and +// no folder created +func TestLogFileInertWhenUnused(t *testing.T) { + noSettingsDB(t) + keepSettings(t) + dir := useLogFileDir(t) + + site := &Site{} + site.restoreLogFile() + + st := site.LogFile() + assert.False(t, st.Enabled) + assert.Equal(t, "debug", st.Level) + assert.Equal(t, 14, st.Days) + assert.Equal(t, dir, st.Dir) + assert.Zero(t, st.Files) + assert.NoDirExists(t, dir) +} + +// TestLogFileSettingSurvivesRestart: set through the api, switched on again by +// restoreLogFile, folder and version are not stored +func TestLogFileSettingSurvivesRestart(t *testing.T) { + noSettingsDB(t) + keepSettings(t) + dir := useLogFileDir(t) + + a := &Site{} + require.NoError(t, a.SetLogFile(logstash.FileConfig{Enabled: true, Level: "INFO", Days: 30})) + + st := a.LogFile() + assert.True(t, st.Enabled) + assert.Empty(t, st.Error) + assert.Equal(t, "info", st.Level) + assert.Equal(t, 30, st.Days) + assert.Equal(t, dir, st.Dir) + assert.DirExists(t, dir) + + stored, err := settings.String(keys.LogFile) + require.NoError(t, err) + assert.JSONEq(t, `{"enabled":true,"level":"info","days":30}`, stored) + + // restart: the writer starts from nothing + _, err = logstash.SetFile(logstash.DefaultFileConfig) + require.NoError(t, err) + require.NoError(t, os.RemoveAll(dir)) + + b := &Site{} + b.restoreLogFile() + + st = b.LogFile() + assert.True(t, st.Enabled) + assert.Equal(t, "info", st.Level) + assert.Equal(t, 30, st.Days) + assert.Empty(t, st.Error) + assert.DirExists(t, dir, "switched on again") + + // switched off: stays off after a restart, files stay + require.NoError(t, b.SetLogFile(logstash.FileConfig{Level: "info", Days: 30})) + assert.False(t, b.LogFile().Enabled) + assert.Equal(t, 1, b.LogFile().Files) + + _, err = logstash.SetFile(logstash.DefaultFileConfig) + require.NoError(t, err) + c := &Site{} + c.restoreLogFile() + assert.False(t, c.LogFile().Enabled) +} + +func TestLogFileInvalidSetting(t *testing.T) { + noSettingsDB(t) + keepSettings(t) + dir := useLogFileDir(t) + + site := &Site{} + + assert.Error(t, site.SetLogFile(logstash.FileConfig{Enabled: true, Level: "verbose", Days: 14})) + assert.Error(t, site.SetLogFile(logstash.FileConfig{Enabled: true, Level: "debug", Days: 0})) + assert.Error(t, site.SetLogFile(logstash.FileConfig{Enabled: true, Level: "debug", Days: 91})) + + assert.False(t, settings.Exists(keys.LogFile), "nothing stored") + assert.False(t, site.LogFile().Enabled) + assert.NoDirExists(t, dir) +} + +// TestLogFileStoredInvalidIsIgnored: a stored setting that no longer validates falls back to off +func TestLogFileStoredInvalidIsIgnored(t *testing.T) { + noSettingsDB(t) + keepSettings(t) + dir := useLogFileDir(t) + + settings.SetString(keys.LogFile, `{"enabled":true,"level":"loud","days":14}`) + + site := &Site{} + site.restoreLogFile() + + assert.False(t, site.LogFile().Enabled) + assert.NoDirExists(t, dir) +} diff --git a/core/site_restore_test.go b/core/site_restore_test.go index 84537981e9..eb0bd26088 100644 --- a/core/site_restore_test.go +++ b/core/site_restore_test.go @@ -9,6 +9,7 @@ import ( "github.com/evcc-io/evcc/db/settings" "github.com/evcc-io/evcc/util" "github.com/evcc-io/evcc/util/config" + "github.com/evcc-io/evcc/util/logstash" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) @@ -23,6 +24,8 @@ func TestRestoreCustomAfterRestart(t *testing.T) { config.Reset() t.Cleanup(config.Reset) + useLogFileDir(t) + main, err := circuit.New(util.NewLogger("test"), "main", 0, 10000, nil, 0) require.NoError(t, err) require.NoError(t, config.Circuits().Add(config.NewStaticDevice(config.Named{Name: "main"}, api.Circuit(main)))) @@ -50,6 +53,7 @@ func TestRestoreCustomAfterRestart(t *testing.T) { require.NoError(t, a.SetPeakFollowBuffer(1000)) require.NoError(t, a.SetPeakFollow(true)) require.NoError(t, a.SetPeakTariff("price", 40)) + require.NoError(t, a.SetLogFile(logstash.FileConfig{Enabled: true, Level: "info", Days: 30})) // set through Home Assistant in the ui, stored as names settings.SetString(keys.PeakShavingEntity, "input_number.peak") @@ -84,4 +88,7 @@ func TestRestoreCustomAfterRestart(t *testing.T) { assert.Equal(t, "input_number.charge", b.GetPeakShavingChargeEntity()) assert.Equal(t, "sensor.grid_import", b.GetPeakShavingEnergyEntity()) assert.Equal(t, "sensor.eeg_export", b.GetFeedInEegEntity()) + assert.True(t, b.LogFile().Enabled) + assert.Equal(t, "info", b.LogFile().Level) + assert.Equal(t, 30, b.LogFile().Days) } diff --git a/i18n/de.json b/i18n/de.json index 436c8dc86f..2b3e55b3cb 100644 --- a/i18n/de.json +++ b/i18n/de.json @@ -1802,6 +1802,21 @@ "title": "Logs", "update": "Aktualisieren" }, + "logFile": { + "daysLabel": "Aufbewahrung", + "daysUnit": "Tage", + "description": "Schreibt das Log in Tagesdateien, ältere werden gepackt. Im Add-on über die Samba-Freigabe unter addon_configs lesbar. Höchstens 1 GB.", + "enabledLabel": "Log-Datei schreiben", + "failed": "Fehler", + "files": "Dateien", + "folder": "Ordner", + "invalid": "Ungültige Einstellung.", + "invalidDays": "Aufbewahrung: ganze Tage von {min} bis {max}.", + "levelLabel": "Level", + "off": "aus", + "size": "Größe", + "title": "Log-Datei" + }, "loginModal": { "cancel": "Abbrechen", "demoMode": "Login ist im Demo-Modus nicht verfügbar.", diff --git a/i18n/en.json b/i18n/en.json index 3f5fd06bba..5c5cca0fff 100644 --- a/i18n/en.json +++ b/i18n/en.json @@ -1802,6 +1802,21 @@ "title": "Logs", "update": "Auto update" }, + "logFile": { + "daysLabel": "Retention", + "daysUnit": "days", + "description": "Writes the log to daily files, older ones are compressed. In the add-on readable via the Samba share under addon_configs. At most 1 GB.", + "enabledLabel": "Write log file", + "failed": "Error", + "files": "Files", + "folder": "Folder", + "invalid": "Invalid setting.", + "invalidDays": "Retention: whole days from {min} to {max}.", + "levelLabel": "Level", + "off": "off", + "size": "Size", + "title": "Log file" + }, "loginModal": { "cancel": "Cancel", "demoMode": "Login is not supported in demo mode.", diff --git a/server/http_custom.go b/server/http_custom.go index feb36a58d0..171ba8da93 100644 --- a/server/http_custom.go +++ b/server/http_custom.go @@ -18,6 +18,7 @@ import ( "github.com/evcc-io/evcc/core/metrics" "github.com/evcc-io/evcc/core/site" "github.com/evcc-io/evcc/util" + "github.com/evcc-io/evcc/util/logstash" "github.com/gorilla/mux" ) @@ -101,6 +102,10 @@ func customSiteRoutes(site site.API) map[string]route { "feedineegentitydelete": {"DELETE", "/feedineegentity", stringHandler(site.SetFeedInEegEntity, site.GetFeedInEegEntity)}, "feedinsplit": {"GET", "/feedinsplit", feedInSplitHandler}, + // log in daily files, see core/site_logfile.go + "logfile": {"GET", "/logfile", logFileHandler(site)}, + "logfileset": {"POST", "/logfile", logFileSetHandler(site)}, + // peak shaving, see core/site_peakshaving.go "peakshaving": {"POST", "/peakshaving/{value:[01truefalse]+}", boolHandler(site.SetPeakShaving, site.GetPeakShaving)}, "peakshavinglimit": {"POST", "/peakshavinglimit/{value:[0-9.]+}", floatHandler(site.SetPeakShavingLimit, site.GetPeakShavingLimit)}, @@ -120,6 +125,31 @@ func customSiteRoutes(site site.API) map[string]route { } } +// logFileHandler returns the log file setting and the state of the files +func logFileHandler(site site.API) http.HandlerFunc { + return func(w http.ResponseWriter, r *http.Request) { + jsonWrite(w, site.LogFile()) + } +} + +// logFileSetHandler saves the log file setting sent as json and answers like logFileHandler +func logFileSetHandler(site site.API) http.HandlerFunc { + return func(w http.ResponseWriter, r *http.Request) { + var cfg logstash.FileConfig + err := json.NewDecoder(http.MaxBytesReader(w, r.Body, 4<<10)).Decode(&cfg) + if err == nil { + err = site.SetLogFile(cfg) + } + + if err != nil { + jsonError(w, http.StatusBadRequest, err) + return + } + + jsonWrite(w, site.LogFile()) + } +} + // lmProfileSaveHandler creates or updates a battery profile sent as json func lmProfileSaveHandler(site site.API) http.HandlerFunc { return func(w http.ResponseWriter, r *http.Request) { diff --git a/server/http_custom_test.go b/server/http_custom_test.go index 48790c89ad..2a020b9d6e 100644 --- a/server/http_custom_test.go +++ b/server/http_custom_test.go @@ -10,6 +10,7 @@ import ( "github.com/evcc-io/evcc/core" "github.com/evcc-io/evcc/core/lm/profile" "github.com/evcc-io/evcc/core/site" + "github.com/evcc-io/evcc/util/logstash" "github.com/gorilla/mux" "github.com/stretchr/testify/assert" ) @@ -116,6 +117,8 @@ var customRouteSamples = map[string]string{ "feedineegentity": "/feedineegentity/sensor.eeg_export", "feedineegentitydelete": "/feedineegentity", "feedinsplit": "/feedinsplit?from=2026-09-01&to=2026-10-01&aggregate=day", + "logfile": "/logfile", + "logfileset": "/logfile", "peakshaving": "/peakshaving/false", "peakshavinglimit": "/peakshavinglimit/7000", "peakfollow": "/peakfollow/true", @@ -186,3 +189,40 @@ func must[T any](v T, err error) T { } return v } + +// TestLogFileRoutes: GET and POST answer the state, an invalid level or retention is a 400 +func TestLogFileRoutes(t *testing.T) { + r := mux.NewRouter() + for _, rt := range customSiteRoutes(core.NewSite()) { + r.Methods(rt.Methods()...).Path(rt.Pattern).Handler(rt.HandlerFunc) + } + + do := func(method, body string) *httptest.ResponseRecorder { + w := httptest.NewRecorder() + r.ServeHTTP(w, httptest.NewRequest(method, "/logfile", strings.NewReader(body))) + return w + } + + t.Cleanup(func() { _, _ = logstash.SetFile(logstash.DefaultFileConfig) }) + + w := do(http.MethodGet, "") + assert.Equal(t, http.StatusOK, w.Code) + assert.Contains(t, w.Body.String(), `"enabled":false`) + + // disabled: stored, nothing written + w = do(http.MethodPost, `{"enabled":false,"level":"WARN","days":7,"dir":"/ignored"}`) + assert.Equal(t, http.StatusOK, w.Code) + assert.Contains(t, w.Body.String(), `"level":"warn"`) + assert.Contains(t, w.Body.String(), `"days":7`) + assert.NotContains(t, w.Body.String(), "ignored") + + for _, body := range []string{ + `{"enabled":true,"level":"loud","days":7}`, + `{"enabled":true,"level":"info","days":0}`, + `{"enabled":true,"level":"info","days":91}`, + `{"enabled":true,"level":"info"}`, + `not json`, + } { + assert.Equal(t, http.StatusBadRequest, do(http.MethodPost, body).Code, body) + } +} diff --git a/util/log.go b/util/log.go index d77408eba2..697d00ed40 100644 --- a/util/log.go +++ b/util/log.go @@ -60,7 +60,7 @@ func newLogger(area string, lp int) *Logger { redactor := new(Redactor) notepad := jww.NewNotepad( level, jww.LevelTrace, - &redactWriter{os.Stdout, redactor}, &redactWriter{logstash.DefaultHandler, redactor}, + &redactWriter{os.Stdout, redactor}, &redactWriter{logstash.Output, redactor}, // custom: log file, see util/logstash/file_custom.go padded, log.Ldate|log.Ltime) logger := &Logger{ diff --git a/util/logstash/file_custom.go b/util/logstash/file_custom.go new file mode 100644 index 0000000000..ff5aedf72b --- /dev/null +++ b/util/logstash/file_custom.go @@ -0,0 +1,719 @@ +package logstash + +// Custom extension: the log in daily files, set in the ui on the log page. +// +// evcc keeps its log in a ring buffer for the log page, a few hours of debug. +// This writes the same stream (all areas and levels, already redacted) to +// /evcc-YYYY-MM-DD.log from a level of its own, independent of the console +// level. The first line of a new day switches the file, the day before is +// compressed in the background, older files are deleted by age and by a fixed +// size limit for the whole folder, also while today's file grows. Warnings and +// errors are written out at once, the rest every 2 s. +// +// Output sits between the loggers and the ring buffer. It hands every line +// to the buffer unchanged and, under the buffer's lock, to the file. Switching +// the file on dumps the buffer into it under the same lock, so there is neither +// a gap nor a line twice. Nothing is written, and no folder created, until +// SetFile switches it on. + +import ( + "bufio" + "bytes" + "compress/gzip" + "errors" + "fmt" + "io" + "os" + "path/filepath" + "regexp" + "slices" + "strings" + "sync" + "sync/atomic" + "time" + + jww "github.com/spf13/jwalterweatherman" +) + +const ( + fileSizeLimit = 1 << 30 // all files together + fileBufferSize = 64 << 10 + fileFlushEvery = 2 * time.Second + fileMinDays = 1 + fileMaxDays = 90 + + dayLayout = "2006-01-02" + timeLayout = "2006/01/02 15:04:05" // as the loggers write it +) + +// fileNameRE matches the files this writes, their date is the first group +var fileNameRE = regexp.MustCompile(`^evcc-(\d{4}-\d{2}-\d{2})\.log(\.gz)?$`) + +// maintainMu lets one folder clean-up run at a time, also across a switched off and on file +var maintainMu sync.Mutex + +// FileConfig is the log file setting +type FileConfig struct { + Enabled bool `json:"enabled"` + Level string `json:"level"` // error, warn, info, debug or trace + Days int `json:"days"` // retention + + // set by the caller, not part of the stored or posted setting + Dir string `json:"-"` // folder of the files + Version string `json:"-"` // evcc version for the header line + Log func(jww.Threshold, string) `json:"-"` // reports warnings and errors +} + +// DefaultFileConfig is what the ui starts with +var DefaultFileConfig = FileConfig{Level: "debug", Days: 14} + +// FileState is what the ui shows +type FileState struct { + Enabled bool `json:"enabled"` + Level string `json:"level"` + Days int `json:"days"` + Dir string `json:"dir"` + Files int `json:"files"` + Size int64 `json:"size"` + Error string `json:"error,omitempty"` +} + +// Validate checks level and retention +func (c FileConfig) Validate() error { + switch strings.ToLower(c.Level) { + case "error", "warn", "info", "debug", "trace": + default: + return fmt.Errorf("invalid log level: %q", c.Level) + } + + if c.Days < fileMinDays || c.Days > fileMaxDays { + return fmt.Errorf("invalid retention: %d days, allowed %d to %d", c.Days, fileMinDays, fileMaxDays) + } + + return nil +} + +// Output is where the loggers write to: the log buffer of the log page and, if switched on, the file +var Output io.Writer = out + +var out = newTee(DefaultHandler) + +// SetFile switches the log file on, off or to other settings. The error is one +// of the settings, a file that cannot be written is in the state. +func SetFile(cfg FileConfig) (FileState, error) { + return out.setFile(cfg) +} + +// FileStatus returns folder, files, size and the error that switched the file off +func FileStatus() FileState { + return out.status() +} + +// CloseFile writes out what is buffered and closes the file, on shutdown +func CloseFile() { + out.close() +} + +// tee hands every line to the log buffer and to the file +type tee struct { + l *logger + + // for tests + now func() time.Time + sizeLimit int64 + flushEvery time.Duration + + // guarded by l.mu + cfg FileConfig + sink *fileSink + err error // why the file is off, kept until the next setting + // seq of the last line handed to a file: switching on again or changing a + // setting dumps only the buffered lines after it, none twice + written uint64 +} + +var _ io.Writer = (*tee)(nil) + +func newTee(l *logger) *tee { + return &tee{l: l, now: time.Now, sizeLimit: fileSizeLimit, flushEvery: fileFlushEvery} +} + +func (t *tee) Write(p []byte) (int, error) { + return t.l.writeWith(p, t.toFile) +} + +// toFile runs under the lock of the log buffer +func (t *tee) toFile(e entry) { + if t.sink == nil { + return + } + + t.sink.write(e.text) + t.written = e.seq + + if err := t.sink.failure(); err != nil { + t.fail(err) + } +} + +// fail switches the file off for this run. The setting stays, the next start tries again. +func (t *tee) fail(err error) { + t.sink.close() + t.sink = nil + t.err = err + t.report(jww.LevelError, fmt.Sprintf("log file switched off: %v", err)) +} + +// report logs asynchronously: the caller holds the lock of the log buffer, which the log line needs +func (t *tee) report(level jww.Threshold, msg string) { + if log := t.cfg.Log; log != nil { + go log(level, msg) + } +} + +func (t *tee) setFile(cfg FileConfig) (FileState, error) { + if err := cfg.Validate(); err != nil { + return t.status(), err + } + + t.l.mu.Lock() + + if t.sink != nil { + t.sink.close() + t.sink = nil + } + + t.cfg = cfg + t.err = nil + + if cfg.Enabled { + s, err := newFileSink(cfg, t.now, t.sizeLimit, t.flushEvery) + if err == nil { + // the buffer first, then the lines that follow, nothing in between + t.l.merged(func(e entry) { + if e.seq > t.written { + s.write(e.text) + t.written = e.seq + } + }) + s.flush() // the folder shows the file as it is switched on + err = s.failure() + } + + if err != nil { + if s != nil { + s.close() + } + t.err = err + t.report(jww.LevelError, fmt.Sprintf("log file not written: %v", err)) + } else { + s.start() + s.maintainAsync() + t.sink = s + } + } + + t.l.mu.Unlock() + + return t.status(), nil +} + +func (t *tee) status() FileState { + t.l.mu.RLock() + cfg, sink, err := t.cfg, t.sink, t.err + t.l.mu.RUnlock() + + if cfg.Level == "" { + cfg.Level = DefaultFileConfig.Level + } + if cfg.Days == 0 { + cfg.Days = DefaultFileConfig.Days + } + + if err == nil && sink != nil { + err = sink.failure() + } + + res := FileState{Enabled: cfg.Enabled, Level: strings.ToLower(cfg.Level), Days: cfg.Days, Dir: cfg.Dir} + if err != nil { + res.Error = err.Error() + } + + if cfg.Dir != "" { + for _, f := range listFiles(cfg.Dir) { + res.Files++ + res.Size += f.size + } + } + + return res +} + +func (t *tee) close() { + t.l.mu.Lock() + defer t.l.mu.Unlock() + + if t.sink != nil { + t.sink.close() + t.sink = nil + } +} + +// writeWith is Write, additionally handing the stored entry to fn while the lock +// is held. It repeats Write's body, TestWriteWithIsWrite pins that both store the same. +func (l *logger) writeWith(p []byte, fn func(entry)) (int, error) { + if bytes.HasPrefix(p, []byte("[cache ]")) { + return len(p), nil + } + + e := element(p) + _, level := e.areaLevel() + + l.mu.Lock() + defer l.mu.Unlock() + + l.seq++ + en := entry{l.seq, e} + if level == jww.LevelTrace { + l.trace.add(en) + } else { + l.other.add(en) + } + + fn(en) + + return len(p), nil +} + +// merged calls fn for every stored entry in the order it was written. The caller holds the lock. +func (l *logger) merged(fn func(entry)) { + var trace, other []entry + l.trace.visit(func(e entry) { trace = append(trace, e) }) + l.other.visit(func(e entry) { other = append(other, e) }) + + for len(trace) > 0 || len(other) > 0 { + if len(other) == 0 || (len(trace) > 0 && trace[0].seq < other[0].seq) { + fn(trace[0]) + trace = trace[1:] + } else { + fn(other[0]) + other = other[1:] + } + } +} + +// fileSink writes the lines of one day to a file and switches at midnight +type fileSink struct { + dir, version string + level jww.Threshold + levelName string + days int + sizeLimit int64 + now func() time.Time + log func(jww.Threshold, string) + + mu sync.Mutex + f *os.File + w *bufio.Writer + next time.Time // start of the next day, the first line from then switches the file + full bool // today's file alone reached the size limit, paused until the next day + err error + + bytes atomic.Int64 // size of today's file including the buffer + others atomic.Int64 // size of the other files, as the last clean-up left them + pruning atomic.Bool // a clean-up for the size limit is running + + flushEvery time.Duration + stopC chan struct{} + ticker sync.WaitGroup + bg sync.WaitGroup // clean-up runs +} + +// newFileSink creates the folder and opens today's file with its header line +func newFileSink(cfg FileConfig, now func() time.Time, sizeLimit int64, flushEvery time.Duration) (*fileSink, error) { + if cfg.Dir == "" { + return nil, errors.New("no folder for the log files") + } + + s := &fileSink{ + dir: cfg.Dir, + version: cfg.Version, + level: LogLevelToThreshold(cfg.Level), + levelName: strings.ToLower(cfg.Level), + days: cfg.Days, + sizeLimit: sizeLimit, + now: now, + log: cfg.Log, + flushEvery: flushEvery, + stopC: make(chan struct{}), + } + + if err := os.MkdirAll(s.dir, 0o755); err != nil { + return nil, err + } + + s.mu.Lock() + defer s.mu.Unlock() + + if err := s.open(); err != nil { + return nil, err + } + + return s, nil +} + +func fileName(day string) string { + return "evcc-" + day + ".log" +} + +// open opens the file of the current day and writes the header line, the caller holds s.mu +func (s *fileSink) open() error { + now := s.now() + day := now.Format(dayLayout) + + f, err := os.OpenFile(filepath.Join(s.dir, fileName(day)), os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0o644) + if err != nil { + s.err = err + return err + } + + var size int64 + if fi, err := f.Stat(); err == nil { + size = fi.Size() + } + + s.f, s.w, s.full = f, bufio.NewWriterSize(f, fileBufferSize), false + s.next = time.Date(now.Year(), now.Month(), now.Day()+1, 0, 0, 0, 0, now.Location()) + s.bytes.Store(size) + s.line(fmt.Sprintf("[logfil] INFO %s evcc %s, level %s", now.Format(timeLayout), s.version, s.levelName)) + + return s.err +} + +// line writes a line to the buffer, the caller holds s.mu +func (s *fileSink) line(text string) { + if !strings.HasSuffix(text, "\n") { + text += "\n" + } + + n, err := s.w.WriteString(text) + s.bytes.Add(int64(n)) + if err != nil { + s.fail(err) + } +} + +// fail switches this file off, the caller holds s.mu +func (s *fileSink) fail(err error) { + if s.err == nil { + s.err = err + } + if s.f != nil { + _ = s.f.Close() + } + s.f, s.w = nil, nil +} + +// write adds a line from the level on, the first line of a new day switches the file +func (s *fileSink) write(e element) { + _, level := e.areaLevel() + if level < s.level { + return + } + + s.mu.Lock() + defer s.mu.Unlock() + + if s.w == nil { + return + } + + if !s.now().Before(s.next) { + s.rotate() + if s.w == nil { + return + } + } + + if s.full { + return + } + + s.line(string(e)) + s.limit() + + // warnings and errors at once: the lines before a crash are the ones that count + if level >= jww.LevelWarn && s.w != nil { + if err := s.w.Flush(); err != nil { + s.fail(err) + } + } +} + +// limit keeps the folder within the size limit while today's file grows, the caller holds s.mu +func (s *fileSink) limit() { + if s.w == nil || s.bytes.Load()+s.others.Load() <= s.sizeLimit { + return + } + + if s.bytes.Load() < s.sizeLimit { + // the older files make room, one clean-up at a time + if s.pruning.CompareAndSwap(false, true) { + s.maintainAsync() + } + return + } + + s.full = true + msg := fmt.Sprintf("log file reached %d MB, paused until the next day", s.sizeLimit>>20) + s.line(fmt.Sprintf("[logfil] WARN %s %s", s.now().Format(timeLayout), msg)) + if log := s.log; log != nil { + go log(jww.LevelWarn, msg) // the caller holds the lock of the log buffer + } +} + +// rotate closes the file of the day before and opens the next, the caller holds s.mu +func (s *fileSink) rotate() { + if err := s.w.Flush(); err != nil { + s.fail(err) + return + } + + if err := s.f.Close(); err != nil { + s.fail(err) + return + } + + if err := s.open(); err != nil { + s.fail(err) + return + } + + s.maintainAsync() +} + +// failure is what switched the file off +func (s *fileSink) failure() error { + s.mu.Lock() + defer s.mu.Unlock() + + return s.err +} + +// start flushes every flushEvery +func (s *fileSink) start() { + s.ticker.Add(1) + go func() { + defer s.ticker.Done() + + tick := time.NewTicker(s.flushEvery) + defer tick.Stop() + + for { + select { + case <-tick.C: + s.flush() + case <-s.stopC: + return + } + } + }() +} + +func (s *fileSink) flush() { + s.mu.Lock() + defer s.mu.Unlock() + + if s.w != nil { + if err := s.w.Flush(); err != nil { + s.fail(err) + } + } +} + +// close writes out what is buffered and closes the file +func (s *fileSink) close() { + select { + case <-s.stopC: + default: + close(s.stopC) + } + s.ticker.Wait() + + s.mu.Lock() + defer s.mu.Unlock() + + if s.w != nil { + if err := s.w.Flush(); err != nil { + s.fail(err) + } + } + + if s.f != nil { + _ = s.f.Close() + } + s.f, s.w = nil, nil +} + +func (s *fileSink) maintainAsync() { + s.bg.Add(1) + go func() { + defer s.bg.Done() + s.maintain() + }() +} + +// logFile is a file of the folder +type logFile struct { + name string + day time.Time + size int64 + gz bool +} + +// listFiles returns the files this writes, oldest first +func listFiles(dir string) []logFile { + entries, err := os.ReadDir(dir) + if err != nil { + return nil + } + + var res []logFile + for _, e := range entries { + m := fileNameRE.FindStringSubmatch(e.Name()) + if m == nil || e.IsDir() { + continue + } + + day, err := time.ParseInLocation(dayLayout, m[1], time.Local) + info, ierr := e.Info() + if err != nil || ierr != nil { + continue + } + + res = append(res, logFile{e.Name(), day, info.Size(), m[2] != ""}) + } + + slices.SortFunc(res, func(a, b logFile) int { + if c := a.day.Compare(b.day); c != 0 { + return c + } + return strings.Compare(a.name, b.name) + }) + + return res +} + +// maintain compresses the files of the days before, deletes those older than +// the retention and then the oldest ones while the folder is over its limit. +// Today's file stays. +func (s *fileSink) maintain() { + maintainMu.Lock() + defer maintainMu.Unlock() + + now := s.now() + today := time.Date(now.Year(), now.Month(), now.Day(), 0, 0, 0, 0, time.Local) + + // left by a run that was stopped while compressing + if tmp, err := filepath.Glob(filepath.Join(s.dir, "evcc-*.log.gz.tmp")); err == nil { + for _, f := range tmp { + _ = os.Remove(f) + } + } + + for _, f := range listFiles(s.dir) { + if f.gz || !f.day.Before(today) { + continue + } + if err := compress(filepath.Join(s.dir, f.name)); err != nil { + s.report(jww.LevelWarn, fmt.Sprintf("log file %s not compressed: %v", f.name, err)) + } + } + + // the retention counts today: 14 days are today and the 13 before + first := today.AddDate(0, 0, 1-s.days) + + var kept []logFile + for _, f := range listFiles(s.dir) { + if f.day.Before(first) { + if err := os.Remove(filepath.Join(s.dir, f.name)); err != nil { + s.report(jww.LevelWarn, fmt.Sprintf("log file %s not deleted: %v", f.name, err)) + kept = append(kept, f) + } + continue + } + kept = append(kept, f) + } + + // today's file as written, the disk lags by the buffer + var total, others int64 + for _, f := range kept { + if f.day.Before(today) { + others += f.size + } + } + total = others + s.bytes.Load() + + for _, f := range kept { + if total <= s.sizeLimit || !f.day.Before(today) { + break + } + + if err := os.Remove(filepath.Join(s.dir, f.name)); err != nil { + s.report(jww.LevelWarn, fmt.Sprintf("log file %s not deleted: %v", f.name, err)) + continue + } + + total -= f.size + others -= f.size + s.report(jww.LevelWarn, fmt.Sprintf("log files over %d MB, deleted %s", s.sizeLimit>>20, f.name)) + } + + s.others.Store(others) + s.pruning.Store(false) +} + +func (s *fileSink) report(level jww.Threshold, msg string) { + if s.log != nil { + s.log(level, msg) + } +} + +// compress packs a file to path.gz and deletes the original, streaming +func compress(path string) (err error) { + in, err := os.Open(path) + if err != nil { + return err + } + defer in.Close() + + tmp := path + ".gz.tmp" + out, err := os.Create(tmp) + if err != nil { + return err + } + + defer func() { + if err != nil { + _ = os.Remove(tmp) + } + }() + + zw := gzip.NewWriter(out) + if _, err = io.Copy(zw, in); err == nil { + err = zw.Close() + } + if cerr := out.Close(); err == nil { + err = cerr + } + if err != nil { + return err + } + + if err = os.Rename(tmp, path+".gz"); err != nil { + return err + } + + _ = in.Close() + return os.Remove(path) +} diff --git a/util/logstash/file_custom_test.go b/util/logstash/file_custom_test.go new file mode 100644 index 0000000000..292c4c85bc --- /dev/null +++ b/util/logstash/file_custom_test.go @@ -0,0 +1,666 @@ +package logstash + +import ( + "compress/gzip" + "fmt" + "io" + "os" + "path/filepath" + "slices" + "strings" + "sync" + "testing" + "time" + + jww "github.com/spf13/jwalterweatherman" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +// fileTest is a log buffer with a file output, a clock and a folder of its own +type fileTest struct { + *tee + dir string + + mu sync.Mutex + time time.Time + logs []string +} + +func newFileTest(t *testing.T) *fileTest { + t.Helper() + + f := &fileTest{ + tee: newTee(New(10000)), + dir: filepath.Join(t.TempDir(), "logs"), // does not exist yet + time: time.Date(2026, 10, 5, 12, 0, 0, 0, time.Local), + } + f.tee.now = f.clock + f.tee.flushEvery = time.Hour // flushed by close, unless a test wants the ticker + + t.Cleanup(f.tee.close) + + return f +} + +func (f *fileTest) clock() time.Time { + f.mu.Lock() + defer f.mu.Unlock() + return f.time +} + +func (f *fileTest) setTime(tm time.Time) { + f.mu.Lock() + defer f.mu.Unlock() + f.time = tm +} + +func (f *fileTest) config(level string, days int) FileConfig { + return FileConfig{ + Enabled: true, + Level: level, + Days: days, + Dir: f.dir, + Version: "0.1.2", + Log: func(l jww.Threshold, msg string) { + f.mu.Lock() + defer f.mu.Unlock() + f.logs = append(f.logs, fmt.Sprintf("%d %s", l, msg)) + }, + } +} + +func (f *fileTest) logged() []string { + f.mu.Lock() + defer f.mu.Unlock() + return slices.Clone(f.logs) +} + +// waitMaintain waits for the clean-up that switching on or a new day started +func (f *fileTest) waitMaintain() { + f.l.mu.RLock() + s := f.sink + f.l.mu.RUnlock() + + if s != nil { + s.bg.Wait() + } +} + +func (f *fileTest) read(t *testing.T, name string) string { + t.Helper() + b, err := os.ReadFile(filepath.Join(f.dir, name)) + require.NoError(t, err) + return string(b) +} + +func (f *fileTest) names(t *testing.T) []string { + t.Helper() + entries, err := os.ReadDir(f.dir) + require.NoError(t, err) + + var res []string + for _, e := range entries { + res = append(res, e.Name()) + } + return res +} + +func readGz(t *testing.T, path string) string { + t.Helper() + in, err := os.Open(path) + require.NoError(t, err) + defer in.Close() + + zr, err := gzip.NewReader(in) + require.NoError(t, err) + b, err := io.ReadAll(zr) + require.NoError(t, err) + return string(b) +} + +func (f *fileTest) write(lines ...string) { + for _, s := range lines { + _, _ = f.Write([]byte(s)) + } +} + +const header = "[logfil] INFO 2026/10/05 12:00:00 evcc 0.1.2, level " + +var ( + lTrace = "[mqtt ] TRACE 2026/10/05 12:00:01 trace" + lDebug = "[site ] DEBUG 2026/10/05 12:00:02 debug" + lInfo = "[site ] INFO 2026/10/05 12:00:03 info" + lWarn = "[site ] WARN 2026/10/05 12:00:04 warn" + lError = "[site ] ERROR 2026/10/05 12:00:05 error" +) + +// TestFileInert: without SetFile nothing is written and no folder created, the +// log buffer gets every line as without the output +func TestFileInert(t *testing.T) { + f := newFileTest(t) + ref := New(10000) + + for _, s := range []string{lTrace, lDebug, lInfo, "[cache ] DEBUG dropped", lWarn, lError, "no header"} { + f.write(s) + _, _ = ref.Write([]byte(s)) + } + + assert.Equal(t, ref.All(nil, jww.LevelTrace, 0), f.l.All(nil, jww.LevelTrace, 0), "same buffer as without the output") + assert.Len(t, f.l.All(nil, jww.LevelTrace, 0), 6) + + assert.NoDirExists(t, f.dir) + st := f.status() + assert.False(t, st.Enabled) + assert.Equal(t, "debug", st.Level) + assert.Equal(t, 14, st.Days) + assert.Empty(t, st.Dir) + assert.Zero(t, st.Files) + + f.close() // nothing to close + assert.NoDirExists(t, f.dir) +} + +// TestFileOutputIsBuffer: the package output reaches the buffer of the log +// page unchanged, the contract util.newLogger relies on +func TestFileOutputIsBuffer(t *testing.T) { + line := "[tstout] DEBUG 2026/10/05 12:00:00 reaches the log page" + + n, err := Output.Write([]byte(line)) + require.NoError(t, err) + assert.Equal(t, len(line), n) + + assert.Contains(t, All([]string{"tstout"}, jww.LevelTrace, 0), line) + + _, _ = Output.Write([]byte("[cache ] DEBUG dropped as in the buffer")) + assert.Empty(t, All([]string{"cache"}, jww.LevelTrace, 0)) +} + +func TestFileLevelFilter(t *testing.T) { + for level, want := range map[string][]string{ + "error": {lError}, + "warn": {lWarn, lError}, + "info": {lInfo, lWarn, lError}, + "debug": {lDebug, lInfo, lWarn, lError}, + "trace": {lTrace, lDebug, lInfo, lWarn, lError}, + } { + t.Run(level, func(t *testing.T) { + f := newFileTest(t) + + st, err := f.setFile(f.config(level, 14)) + require.NoError(t, err) + assert.True(t, st.Enabled) + assert.Empty(t, st.Error) + + f.write(lTrace, lDebug, lInfo, lWarn, lError) + f.close() + + exp := header + level + "\n" + for _, s := range want { + exp += s + "\n" + } + assert.Equal(t, exp, f.read(t, "evcc-2026-10-05.log")) + }) + } +} + +// TestFileDumpsBuffer: switching on writes the buffer in the order the lines +// came, trace and other lines mixed, filtered by level, without cache lines +func TestFileDumpsBuffer(t *testing.T) { + f := newFileTest(t) + + f.write(lTrace, lDebug, "[cache ] DEBUG dropped", lInfo, "[mqtt ] TRACE 2026/10/05 12:00:02 trace 2", lError) + + _, err := f.setFile(f.config("debug", 14)) + require.NoError(t, err) + + f.write(lWarn) + f.close() + + assert.Equal(t, header+"debug\n"+lDebug+"\n"+lInfo+"\n"+lError+"\n"+lWarn+"\n", f.read(t, "evcc-2026-10-05.log")) + + // switched on again: appended, with a header of its own, the lines already in the file not again + _, err = f.setFile(f.config("error", 14)) + require.NoError(t, err) + f.close() + + got := f.read(t, "evcc-2026-10-05.log") + assert.Equal(t, 2, strings.Count(got, "[logfil] INFO")) + assert.Equal(t, 1, strings.Count(got, lError)) + assert.True(t, strings.HasSuffix(got, lWarn+"\n"+header+"error\n")) +} + +// TestFileSettingChangeNoDuplicate: changing a setting while the file is on +// reopens it without writing the buffer a second time +func TestFileSettingChangeNoDuplicate(t *testing.T) { + f := newFileTest(t) + + _, err := f.setFile(f.config("debug", 14)) + require.NoError(t, err) + f.write(lDebug, lInfo) + + _, err = f.setFile(f.config("info", 30)) + require.NoError(t, err) + f.write(lWarn) + f.close() + + assert.Equal(t, header+"debug\n"+lDebug+"\n"+lInfo+"\n"+header+"info\n"+lWarn+"\n", f.read(t, "evcc-2026-10-05.log")) +} + +// TestFileReenableWritesMissed: lines that came while the file was off are +// written on switching on again, those already in the file are not +func TestFileReenableWritesMissed(t *testing.T) { + f := newFileTest(t) + + _, err := f.setFile(f.config("debug", 14)) + require.NoError(t, err) + f.write(lDebug) + + off := f.config("debug", 14) + off.Enabled = false + _, err = f.setFile(off) + require.NoError(t, err) + f.write(lInfo) + + _, err = f.setFile(f.config("debug", 14)) + require.NoError(t, err) + f.close() + + assert.Equal(t, header+"debug\n"+lDebug+"\n"+header+"debug\n"+lInfo+"\n", f.read(t, "evcc-2026-10-05.log")) +} + +// TestFileFlushesWarnAtOnce: warnings and errors are on disk right away, the +// lines before a crash are not lost in the buffer +func TestFileFlushesWarnAtOnce(t *testing.T) { + f := newFileTest(t) + + _, err := f.setFile(f.config("debug", 14)) + require.NoError(t, err) + + f.write(lInfo) + assert.NotContains(t, f.read(t, "evcc-2026-10-05.log"), lInfo, "info waits for the flush interval") + + f.write(lWarn) + got := f.read(t, "evcc-2026-10-05.log") + assert.Contains(t, got, lInfo+"\n"+lWarn+"\n") + + f.write(lError) + assert.Contains(t, f.read(t, "evcc-2026-10-05.log"), lError) +} + +// TestWriteWithIsWrite: writeWith stores exactly what evcc's Write stores, so +// a change of Write in an evcc update shows up here +func TestWriteWithIsWrite(t *testing.T) { + lines := []string{lTrace, lDebug, "[cache ] DEBUG dropped", lInfo, "no area at all", lWarn, lError} + + a, b := New(5), New(5) + for _, s := range lines { + na, ea := a.Write([]byte(s)) + nb, eb := b.writeWith([]byte(s), func(entry) {}) + assert.Equal(t, na, nb, s) + assert.Equal(t, ea, eb, s) + } + + for _, level := range []jww.Threshold{jww.LevelTrace, jww.LevelDebug, jww.LevelError} { + assert.Equal(t, a.All(nil, level, 0), b.All(nil, level, 0)) + } + assert.Equal(t, a.Areas(), b.Areas()) + assert.Equal(t, a.Size(), b.Size()) + assert.Equal(t, a.seq, b.seq) +} + +// TestFileDumpNoGapNoDuplicate: lines written by other goroutines while the +// file is switched on end up in the file exactly once, in order +func TestFileDumpNoGapNoDuplicate(t *testing.T) { + f := newFileTest(t) + + const writers, lines = 8, 1000 + + var wg sync.WaitGroup + start := make(chan struct{}) + for w := range writers { + wg.Go(func() { + <-start + for i := range lines { + f.write(fmt.Sprintf("[site ] INFO 2026/10/05 12:00:00 w%d-%04d", w, i)) + if i%100 == 0 { + time.Sleep(time.Millisecond) + } + } + }) + } + + close(start) + time.Sleep(2 * time.Millisecond) + _, err := f.setFile(f.config("info", 14)) + require.NoError(t, err) + + wg.Wait() + f.close() + + seen := make(map[string]int) + next := make(map[int]int) + for _, l := range strings.Split(strings.TrimSpace(f.read(t, "evcc-2026-10-05.log")), "\n")[1:] { + id := l[strings.LastIndex(l, " ")+1:] + seen[id]++ + + var w, i int + _, err := fmt.Sscanf(id, "w%d-%d", &w, &i) + require.NoError(t, err) + assert.Equal(t, next[w], i, "writer %d in order", w) + next[w] = i + 1 + } + + assert.Len(t, seen, writers*lines) + for id, n := range seen { + assert.Equal(t, 1, n, id) + } +} + +func TestFileDayRotation(t *testing.T) { + f := newFileTest(t) + + _, err := f.setFile(f.config("debug", 14)) + require.NoError(t, err) + f.write(lInfo) + + // the first line of the next day switches the file + f.setTime(time.Date(2026, 10, 6, 0, 0, 3, 0, time.Local)) + f.write(lError) + f.waitMaintain() + f.close() + + assert.ElementsMatch(t, []string{"evcc-2026-10-05.log.gz", "evcc-2026-10-06.log"}, f.names(t), "the day before is packed, the original gone") + assert.Equal(t, header+"debug\n"+lInfo+"\n", readGz(t, filepath.Join(f.dir, "evcc-2026-10-05.log.gz"))) + + day2 := f.read(t, "evcc-2026-10-06.log") + assert.True(t, strings.HasPrefix(day2, "[logfil] INFO 2026/10/06 00:00:03 evcc 0.1.2, level debug\n"), day2) + assert.True(t, strings.HasSuffix(day2, lError+"\n")) +} + +// TestFileRetention: older than the retention is deleted when switching on and +// at a new day; files the day before that were left unpacked get packed +func TestFileRetention(t *testing.T) { + f := newFileTest(t) + require.NoError(t, os.MkdirAll(f.dir, 0o755)) + + touch := func(name, content string) { + require.NoError(t, os.WriteFile(filepath.Join(f.dir, name), []byte(content), 0o644)) + } + touch("evcc-2026-09-20.log.gz", "old") // 15 days: deleted + touch("evcc-2026-09-29.log.gz", "old") // 7th day counting today: kept + touch("evcc-2026-09-28.log", "old") // 8th day: deleted + touch("evcc-2026-10-03.log", "left\n") // not packed yet + touch("evcc-2026-10-01.log.gz.tmp", "") // stopped while packing + touch("notes.txt", "not ours") + touch("evcc-x.log", "not ours") + + _, err := f.setFile(f.config("debug", 7)) + require.NoError(t, err) + f.waitMaintain() + + assert.ElementsMatch(t, []string{ + "evcc-2026-09-29.log.gz", "evcc-2026-10-03.log.gz", "evcc-2026-10-05.log", "notes.txt", "evcc-x.log", + }, f.names(t)) + assert.Equal(t, "left\n", readGz(t, filepath.Join(f.dir, "evcc-2026-10-03.log.gz"))) + + // a new day moves the window + f.setTime(time.Date(2026, 10, 6, 0, 0, 1, 0, time.Local)) + f.write(lInfo) + f.waitMaintain() + + assert.NotContains(t, f.names(t), "evcc-2026-09-29.log.gz") + assert.Contains(t, f.names(t), "evcc-2026-10-03.log.gz") + assert.Contains(t, f.names(t), "evcc-2026-10-05.log.gz") +} + +// TestFileSizeLimit: over the limit the oldest files go with a warning +func TestFileSizeLimit(t *testing.T) { + f := newFileTest(t) + f.sizeLimit = 150 + require.NoError(t, os.MkdirAll(f.dir, 0o755)) + + for _, d := range []string{"01", "02", "03"} { + require.NoError(t, os.WriteFile(filepath.Join(f.dir, "evcc-2026-10-"+d+".log.gz"), make([]byte, 60), 0o644)) + } + + _, err := f.setFile(f.config("debug", 14)) + require.NoError(t, err) + f.waitMaintain() + + // 180 and the header (58 bytes) over 150: the two oldest go + assert.ElementsMatch(t, []string{"evcc-2026-10-03.log.gz", "evcc-2026-10-05.log"}, f.names(t)) + + warns := f.logged() + require.Len(t, warns, 2) + for i, d := range []string{"01", "02"} { + assert.Contains(t, warns[i], fmt.Sprintf("%d ", jww.LevelWarn)) + assert.Contains(t, warns[i], "evcc-2026-10-"+d+".log.gz") + } +} + +// TestFileSizeLimitKeepsToday: today's file is never deleted; once it alone +// reaches the limit, writing pauses with a note until the next day +func TestFileSizeLimitKeepsToday(t *testing.T) { + f := newFileTest(t) + f.sizeLimit = 100 + + _, err := f.setFile(f.config("debug", 14)) + require.NoError(t, err) + f.waitMaintain() + + big := "[site ] INFO " + strings.Repeat("x", 300) + f.write(big, lError) + f.l.mu.RLock() + f.sink.flush() + f.l.mu.RUnlock() + f.sink.maintain() + + assert.Equal(t, []string{"evcc-2026-10-05.log"}, f.names(t)) + got := f.read(t, "evcc-2026-10-05.log") + assert.Contains(t, got, big+"\n[logfil] WARN 2026/10/05 12:00:00 log file reached 0 MB, paused until the next day\n") + assert.NotContains(t, got, lError, "paused") + assert.Eventually(t, func() bool { return len(f.logged()) == 1 }, time.Second, time.Millisecond) + + // the next day writes again + f.setTime(time.Date(2026, 10, 6, 0, 0, 1, 0, time.Local)) + f.write(lInfo) + f.waitMaintain() + f.close() + assert.Contains(t, f.read(t, "evcc-2026-10-06.log"), lInfo) +} + +// TestFileSizeLimitDuringDay: today's file growing over the limit removes the +// oldest files right away, not only at the next day +func TestFileSizeLimitDuringDay(t *testing.T) { + f := newFileTest(t) + f.sizeLimit = 300 + require.NoError(t, os.MkdirAll(f.dir, 0o755)) + + for _, d := range []string{"01", "02", "03"} { + require.NoError(t, os.WriteFile(filepath.Join(f.dir, "evcc-2026-10-"+d+".log.gz"), make([]byte, 60), 0o644)) + } + + _, err := f.setFile(f.config("debug", 14)) + require.NoError(t, err) + f.waitMaintain() + assert.Len(t, f.names(t), 4, "180 and the header within 300") + + // header 58 + 100 + 180 over 300: the oldest goes + f.write("[site ] INFO " + strings.Repeat("x", 85)) + f.waitMaintain() + + assert.ElementsMatch(t, []string{"evcc-2026-10-02.log.gz", "evcc-2026-10-03.log.gz", "evcc-2026-10-05.log"}, f.names(t)) +} + +// TestFileSizeLimitKeepsNewer: only as many of the oldest go as needed +func TestFileSizeLimitKeepsNewer(t *testing.T) { + f := newFileTest(t) + f.sizeLimit = 200 + require.NoError(t, os.MkdirAll(f.dir, 0o755)) + + for _, d := range []string{"01", "02", "03", "04"} { + require.NoError(t, os.WriteFile(filepath.Join(f.dir, "evcc-2026-10-"+d+".log.gz"), make([]byte, 60), 0o644)) + } + + _, err := f.setFile(f.config("debug", 14)) + require.NoError(t, err) + f.waitMaintain() + + // 240 and the header over 200: the two oldest go + assert.ElementsMatch(t, []string{"evcc-2026-10-03.log.gz", "evcc-2026-10-04.log.gz", "evcc-2026-10-05.log"}, f.names(t)) +} + +// TestFileErrorFolder: a folder that cannot be created is reported once, shown +// in the state, and the log buffer keeps working +func TestFileErrorFolder(t *testing.T) { + f := newFileTest(t) + + blocker := filepath.Join(t.TempDir(), "file") + require.NoError(t, os.WriteFile(blocker, nil, 0o644)) + + cfg := f.config("debug", 14) + cfg.Dir = filepath.Join(blocker, "logs") + + st, err := f.setFile(cfg) + require.NoError(t, err, "a file that cannot be written is no invalid setting") + assert.True(t, st.Enabled, "the setting stays on") + assert.NotEmpty(t, st.Error) + + f.write(lInfo) + assert.Equal(t, []string{lInfo}, f.l.All(nil, jww.LevelTrace, 0)) + + assert.Eventually(t, func() bool { return len(f.logged()) == 1 }, time.Second, time.Millisecond) + assert.Contains(t, f.logged()[0], fmt.Sprintf("%d ", jww.LevelError)) + + assert.NotEmpty(t, f.status().Error) + + // no folder at all + cfg.Dir = "" + st, err = f.setFile(cfg) + require.NoError(t, err) + assert.NotEmpty(t, st.Error) +} + +// TestFileErrorWriting: a file that fails while running switches itself off +// once, the buffer and the other outputs go on +func TestFileErrorWriting(t *testing.T) { + f := newFileTest(t) + + _, err := f.setFile(f.config("debug", 14)) + require.NoError(t, err) + + // the disk fails: the file is gone from under the writer + f.l.mu.RLock() + require.NoError(t, f.sink.f.Close()) + f.l.mu.RUnlock() + + line := "[site ] INFO 2026/10/05 12:00:00 " + strings.Repeat("x", 1000) + for range 100 { // more than the 64 KB buffer + f.write(line) + } + + assert.Len(t, f.l.All(nil, jww.LevelTrace, 0), 100, "the log page is not affected") + + st := f.status() + assert.True(t, st.Enabled) + assert.NotEmpty(t, st.Error) + + f.l.mu.RLock() + assert.Nil(t, f.sink, "off for this run") + f.l.mu.RUnlock() + + assert.Eventually(t, func() bool { return len(f.logged()) == 1 }, time.Second, time.Millisecond) + assert.Contains(t, f.logged()[0], fmt.Sprintf("%d ", jww.LevelError)) + + // a new setting tries again + st, err = f.setFile(f.config("debug", 14)) + require.NoError(t, err) + assert.Empty(t, st.Error) +} + +func TestFileDisable(t *testing.T) { + f := newFileTest(t) + + _, err := f.setFile(f.config("debug", 14)) + require.NoError(t, err) + f.write(lInfo) + + st, err := f.setFile(FileConfig{Level: "debug", Days: 14, Dir: f.dir}) + require.NoError(t, err) + assert.False(t, st.Enabled) + assert.Equal(t, 1, st.Files, "files stay") + assert.Positive(t, st.Size) + + f.write(lError) + assert.Equal(t, header+"debug\n"+lInfo+"\n", f.read(t, "evcc-2026-10-05.log"), "flushed on switching off, nothing after") +} + +func TestFileValidate(t *testing.T) { + f := newFileTest(t) + + for _, cfg := range []FileConfig{ + {Enabled: true, Level: "verbose", Days: 14, Dir: f.dir}, + {Enabled: true, Level: "", Days: 14, Dir: f.dir}, + {Enabled: true, Level: "debug", Days: 0, Dir: f.dir}, + {Enabled: true, Level: "debug", Days: 91, Dir: f.dir}, + } { + _, err := f.setFile(cfg) + assert.Error(t, err, "%+v", cfg) + } + assert.NoDirExists(t, f.dir) + assert.False(t, f.status().Enabled) + + for _, l := range []string{"error", "WARN", "Info", "debug", "trace"} { + assert.NoError(t, FileConfig{Level: l, Days: 90}.Validate(), l) + } +} + +// TestFileFlushes: written out every flush interval, not only on closing +func TestFileFlushes(t *testing.T) { + f := newFileTest(t) + f.flushEvery = 5 * time.Millisecond + + _, err := f.setFile(f.config("debug", 14)) + require.NoError(t, err) + f.write(lInfo) + + assert.Eventually(t, func() bool { + b, _ := os.ReadFile(filepath.Join(f.dir, "evcc-2026-10-05.log")) + return strings.Contains(string(b), lInfo) + }, 2*time.Second, 5*time.Millisecond) +} + +// TestFileLineWithoutNewline: every line ends in a newline in the file +func TestFileLineWithoutNewline(t *testing.T) { + f := newFileTest(t) + _, err := f.setFile(f.config("debug", 14)) + require.NoError(t, err) + + f.write(lInfo, lError+"\n", lWarn) + f.close() + + assert.Equal(t, header+"debug\n"+lInfo+"\n"+lError+"\n"+lWarn+"\n", f.read(t, "evcc-2026-10-05.log")) +} + +// TestFileStatus: folder, number and size of the files +func TestFileStatus(t *testing.T) { + f := newFileTest(t) + + st, err := f.setFile(f.config("info", 30)) + require.NoError(t, err) + assert.Equal(t, f.dir, st.Dir) + assert.Equal(t, "info", st.Level) + assert.Equal(t, 30, st.Days) + assert.Equal(t, 1, st.Files) + assert.EqualValues(t, len(header+"info\n"), st.Size, "the header is on disk right away") + + f.write(lInfo) + f.l.mu.RLock() + f.sink.flush() + f.l.mu.RUnlock() + + st = f.status() + assert.Equal(t, 1, st.Files) + assert.EqualValues(t, len(header+"info\n"+lInfo+"\n"), st.Size) +} diff --git a/util/logstash/file_hook_custom_test.go b/util/logstash/file_hook_custom_test.go new file mode 100644 index 0000000000..62b9aafe8d --- /dev/null +++ b/util/logstash/file_hook_custom_test.go @@ -0,0 +1,95 @@ +package logstash_test + +import ( + "os" + "path/filepath" + "strings" + "testing" + "time" + + "github.com/evcc-io/evcc/util" + "github.com/evcc-io/evcc/util/logstash" + jww "github.com/spf13/jwalterweatherman" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +// TestLoggerWritesToLogFile pins the hook in newLogger: every line of every +// level, redacted, reaches the log file as well as the log page. The buffer +// content before switching on is in the file. An external test, as the lines +// land in the global log buffer that the tests of util count. The secret is as +// long as its replacement: evcc drops a line from the log page if redaction +// changes its length (io.MultiWriter stops at the short write of the console). +func TestLoggerWritesToLogFile(t *testing.T) { + dir := filepath.Join(t.TempDir(), "logs") + + log := util.NewLogger("tstfile").Redact("pwd") + log.DEBUG.Print("before the file") + + // inert until switched on + assert.NoDirExists(t, dir) + + st, err := logstash.SetFile(logstash.FileConfig{Enabled: true, Level: "trace", Days: 14, Dir: dir, Version: "test"}) + require.NoError(t, err) + require.Empty(t, st.Error) + t.Cleanup(func() { + _, _ = logstash.SetFile(logstash.FileConfig{Level: "trace", Days: 14, Dir: dir}) + }) + + log.TRACE.Print("a trace line") + log.INFO.Print("password pwd") + log.ERROR.Print("an error") + + // the log page keeps its content + page := logstash.All([]string{"tstfile"}, jww.LevelTrace, 0) + assert.Len(t, page, 4) + + logstash.CloseFile() + + files, err := filepath.Glob(filepath.Join(dir, "evcc-*.log")) + require.NoError(t, err) + require.Len(t, files, 1) + + b, err := os.ReadFile(files[0]) + require.NoError(t, err) + got := string(b) + + assert.Contains(t, got, "before the file") + assert.Contains(t, got, "a trace line") + assert.Contains(t, got, "an error") + assert.NotContains(t, got, "pwd", "redacted before the file") + assert.Contains(t, got, "password") + + // the file holds what the log page holds + assert.Contains(t, got, strings.Join(page, "")) +} + +// TestCloseFileWritesOut: what the shutdown hook calls writes the buffered +// lines out, without waiting for the flush interval +func TestCloseFileWritesOut(t *testing.T) { + dir := filepath.Join(t.TempDir(), "logs") + + _, err := logstash.SetFile(logstash.FileConfig{Enabled: true, Level: "info", Days: 14, Dir: dir}) + require.NoError(t, err) + t.Cleanup(func() { + _, _ = logstash.SetFile(logstash.FileConfig{Level: "info", Days: 14, Dir: dir}) + }) + + util.NewLogger("tstclose").INFO.Print("last line before exit") + logstash.CloseFile() + + files, err := filepath.Glob(filepath.Join(dir, "evcc-*.log")) + require.NoError(t, err) + require.Len(t, files, 1) + + b, err := os.ReadFile(files[0]) + require.NoError(t, err) + assert.Contains(t, string(b), "last line before exit") + + // nothing is written after closing + util.NewLogger("tstclose").INFO.Print("after") + time.Sleep(10 * time.Millisecond) + b, err = os.ReadFile(files[0]) + require.NoError(t, err) + assert.NotContains(t, string(b), "after") +}