search

zwave-js / zwave-js-ui

Full featured Z-Wave Control Panel UI and MQTT gateway. Built using Nodejs, and Vue/Vuetify
https://zwave-js.github.io/zwave-js-ui
MIT License
984 stars 201 forks source link

Error while fetching store files: EPERM #2937

Closed jriker1 closed 1 month ago

jriker1 commented 1 year ago

Checklist

Deploy method

PKG executable

Z-Wave JS UI version

8.8.0

ZwaveJS version

10.4.0

Describe the bug

Not sure if it was when archiving but have Z-WaveJS UI running on Windows 2022 with Hyper-V role. There is a log from teh 29th in the log folder as of 2/1 and ther eis also a tar.gz file for that day. I can't access that log file or change ownership. When I go to the Store tab I get:

Error while fetching store files: EPERM: operation not permitted, lstat 'E:\Z-WaveJSUI\store\logs\zwavejs_2023-01-29.log'

I have since deleted that log file but the system is still complaining about it when I open up the Z-WaveJS UI > Store location again fresh in a browser.

To Reproduce

Launch Z-WaveJS UI and click on Store.

Expected behavior

It shows a tree of files/folders.

Additional context

No response

robertsLando commented 1 year ago

I'm not a windows expert but how did you start zui? It could be you runned it with admin privileges and that created that file, try to right click on the file to check its ownership and fix it. Also be sure you are not running zui as administrator

jriker1 commented 1 year ago

I am running the application as a domain admin so anything being done with that executable would be with that account. It's running with NMMS and set to run as my domain user. That file is a log file that ZUI creates and looks like when it archives it at night to a GZ file it does something to the original file and it fails to be removed. When I try and view the permissions on that file it says there is no owner. Happened again when I tried to look at the logs thru the GUI today.

Some images if it helps any:

Error message on ZUI GUI: error

You know maybe that's not the root problem. If you look at the above image, that is yesterday's file, which guess is now a zwavejs_2023-02-01.log.gz file. Looks like it's still trying to find yesterday's log? Note I did notice the logs seem to be in GMT so not sure if there is anything there. Not sure how ZUI parses that folder and why it's erroring vs displaying what's there.

When I posted the original issue the .log file was still there just not accessible.

robertsLando commented 1 year ago

I have submitted a fix for this, at least it should not throw, the problem is that file seems is still present but when I try to get stats that error is thrown, no clue why BTW, maybe the log rotation delete doesn't completely delete the file and a dead reference remains in memory, no clue as cannot repro this on linux system

jriker1 commented 1 year ago

Odd, next day it's still complaining about the 2023-02-01.log file. Figured it would start complaining about 2023-02-02 but looks like there are no new log files being generated. Below is what I see at 7:53AM on 2/3/2023 CST. image

Note I am on the following releases now.

zwave-js-ui: 8.8.3 zwave-js: 10.5.5

The above may have fixed some other issues I was having but not this one. Don't want to say for sure as I'm superstitious that way.

spudwebb commented 2 months ago

I'm having the same problem, ZWave JS UI running on windows as admin. Everyday at midnight I get the following error, which then repeats itself every hour:

2024-09-11 23:18:03.519 DEBUG APP: [session-file-store] Deleting expired sessions
2024-09-11 23:18:03.566 INFO LOGGER: Cleaning up log files...
2024-09-11 23:59:59.697 INFO Z-WAVE: Next update scheduled for: Thu Sep 12 2024 00:00:00 GMT-0400 (Eastern Daylight Time)
Logging to file:
        C:\Program Files (x86)\HomeSeer HS4\Data\ZWavePlus\zwave-js-ui\store_7e62acad-7dac-4c20-b383-5d1008aaac93\logs\zwavejs_2024-09-12.log
2024-09-12 00:00:00.229 INFO Z-WAVE: Next update scheduled for: Fri Sep 13 2024 00:00:00 GMT-0400 (Eastern Daylight Time)
2024-09-12 00:18:03.417 DEBUG APP: [session-file-store] Deleting expired sessions
2024-09-12 00:18:03.479 INFO LOGGER: Cleaning up log files...
2024-09-12 00:18:03.487 ERROR LOGGER: Error getting file stats: EPERM: operation not permitted, stat 'C:\Program Files (x86)\HomeSeer HS4\Data\ZWavePlus\zwave-js-ui\store_7e62acad-7dac-4c20-b383-5d1008aaac93\logs\z-ui_2024-09-11.log'
Error: EPERM: operation not permitted, stat 'C:\Program Files (x86)\HomeSeer HS4\Data\ZWavePlus\zwave-js-ui\store_7e62acad-7dac-4c20-b383-5d1008aaac93\logs\z-ui_2024-09-11.log'
2024-09-12 01:18:03.374 DEBUG APP: [session-file-store] Deleting expired sessions
2024-09-12 01:18:03.437 INFO LOGGER: Cleaning up log files...
2024-09-12 01:18:03.440 ERROR LOGGER: Error getting file stats: EPERM: operation not permitted, stat 'C:\Program Files (x86)\HomeSeer HS4\Data\ZWavePlus\zwave-js-ui\store_7e62acad-7dac-4c20-b383-5d1008aaac93\logs\z-ui_2024-09-11.log'
Error: EPERM: operation not permitted, stat 'C:\Program Files (x86)\HomeSeer HS4\Data\ZWavePlus\zwave-js-ui\store_7e62acad-7dac-4c20-b383-5d1008aaac93\logs\z-ui_2024-09-11.log

It seems that after ZUI archives the z-ui log file as a gz file, it fails to delete the log file and messes up the permissions on it. I cannot open it (z-ui_2004-09-11.log) from windows explorer, but I can open the log file for the current day (z-ui_2024-09-12.log) just fine.

Also, note that it only happens for the z-ui log files, the zwavejs log files don't have this problem.

Can this issue be reopened?

robertsLando commented 2 months ago

hi @spudwebb, the log rotation is automatically handeld by another library @zwave-js/winston-daily-rotate-file and I'm aware of some issues related to that expecially when it comes to delete files, in fact I have integrated my own handler to clean up files. no clue if this is a known one.

cc @AlCalzone @Apollon77

AlCalzone commented 2 months ago

@robertsLando zwave-js has switched the file rotator back to the official version a while back. 5.0.0 should be fixed AFAIK.

robertsLando commented 2 months ago

@AlCalzone Latest version on NPM is still 4.5.6-1: https://www.npmjs.com/package/@zwave-js/winston-daily-rotate-file

AlCalzone commented 2 months ago

Not the scoped/forked package. The original one: https://www.npmjs.com/package/winston-daily-rotate-file The forked repo is obsoleted/archived now.

robertsLando commented 2 months ago

LOL nice to know 😆 Does it fixes the bug related to files not being deleted? I know it used to loose the track of files on every startup so they remain there forever

AlCalzone commented 2 months ago

I don't know. @apollon77 does it?

Apollon77 commented 2 months ago

I think not. I did not found time to look into it.

robertsLando commented 2 months ago

For now I have merged my pr to remove the obsolete @zwave-js package, let's see if the bug reported here is fixed then or not

spudwebb commented 1 month ago

I'm still seeing the same errors with ZWave JS UI v9.20.0

2024-09-27 00:00:00.111 INFO Z-WAVE: Next update scheduled for: Sat Sep 28 2024 00:00:00 GMT-0400 (Eastern Daylight Time)
2024-09-27 00:31:36.110 DEBUG APP: [session-file-store] Deleting expired sessions
2024-09-27 00:31:36.157 INFO LOGGER: Cleaning up log files...
2024-09-27 00:31:36.179 ERROR LOGGER: Error getting file stats: EPERM: operation not permitted, stat 'C:\Program Files (x86)\HomeSeer HS4\Data\ZWavePlus\zwave-js-ui\store_7e62acad-7dac-4c20-b383-5d1008aaac93\logs\z-ui_2024-09-26.log'
Error: EPERM: operation not permitted, stat 'C:\Program Files (x86)\HomeSeer HS4\Data\ZWavePlus\zwave-js-ui\store_7e62acad-7dac-4c20-b383-5d1008aaac93\logs\z-ui_2024-09-26.log'
2024-09-27 01:31:36.092 DEBUG APP: [session-file-store] Deleting expired sessions
2024-09-27 01:31:36.139 INFO LOGGER: Cleaning up log files...
2024-09-27 01:31:36.143 ERROR LOGGER: Error getting file stats: EPERM: operation not permitted, stat 'C:\Program Files (x86)\HomeSeer HS4\Data\ZWavePlus\zwave-js-ui\store_7e62acad-7dac-4c20-b383-5d1008aaac93\logs\z-ui_2024-09-26.log'
Error: EPERM: operation not permitted, stat 'C:\Program Files (x86)\HomeSeer HS4\Data\ZWavePlus\zwave-js-ui\store_7e62acad-7dac-4c20-b383-5d1008aaac93\logs\z-ui_2024-09-26.log'
2024-09-27 02:31:36.077 DEBUG APP: [session-file-store] Deleting expired sessions
robertsLando commented 1 month ago

could you tell me the permissions of that file? Is it empty? Corrupted?

spudwebb commented 1 month ago

When I try to see the permissions of that file it says I don't have read permissions on that file image Then if I click Advanced and continue to attempt to see the permissions as Administrator it still says I don' t have permissions: image

I can' t open it, but it' s not empty, windows says it is 56KB

robertsLando commented 1 month ago

wow cool, I have no idea how this is possible, I have a feel this is something strictly related to windows as the main issue is referencing to windows paths as well...

robertsLando commented 1 month ago

Seems there is an open issue on nodejs related to this: https://github.com/nodejs/node/issues/35853

The question anyway could be also why the hell that file has those permissions...

AlCalzone commented 1 month ago

How is the process executed? With any special user account or permissions? Does the issue happen every night?

robertsLando commented 1 month ago

@AlCalzone Just as reference, I delete the files using this script: https://github.com/zwave-js/zwave-js-ui/blob/d8c1f7b71c15a0aaec470e88b0b7e6c2bae28a7d/api/lib/logger.ts#L209

In order to fix the issue with log files never deleted

spudwebb commented 1 month ago

How is the process executed? With any special user account or permissions? Does the issue happen every night?

The process is executed as a child process of HomeSeer which is run with Administrator rights.
The issue happen every night but only for the z-ui log file, the zwavejs log file is fine.

robertsLando commented 1 month ago

yeah because actually the trick to delete the old files runs only on zui files, it's something I had to add in order to fix another issue related to the daily rotate module that doesn't delete log files under certain conditions and users ended up with tons of log files causing memory issues

spudwebb commented 1 month ago

to investigate this issue without having to wait one day for the log file to rotate I made the logs to rotate at a one minute frequency, and added some console logging:

                const options: DailyRotateFileTransportOptions = {
                    filename: config.filePath,
                    auditFile: joinPath(logsDir, 'zui-logs.audit.json'),
                    datePattern: 'YYYY-MM-DD_HH-mm',
                    frequency: 'test',
                    createSymlink: true,
                    symlinkName: path
                        .basename(config.filePath)
                        .replace(`_%DATE%`, '_current'),
                    zippedArchive: true,
                    maxFiles: process.env.ZUI_LOG_MAXFILES || '7d',
                    maxSize: process.env.ZUI_LOG_MAXSIZE || '50m',
                    level: config.level,
                    format: customFormat(config, true),
                }
                fileTransport = new DailyRotateFile(options)
                fileTransport.on("new", (newFilename: string) => {
                    console.log(`Logging to file: ${newFilename}`);
                });
                fileTransport.on("error", (err: Error) => {
                    console.error(`Error in file stream rotator: ${err.message}`);
                });
                fileTransport.on("rotate",  (oldFile: string, newFile:string) => {
                    console.log(`Rotate log file, old: ${oldFile}, new: ${newFile}`);
                });

This shows that the transports for logging are created multiple times for ZUI (once for each module), which I think is wrong, they should be created only once like for ZWaveJS, and only re-created if the config changes.

2024-10-04 12:57:02.668 INFO LOGGER: Cleaning up log files...
Logging to file: C:\temp\zwave-js-ui\store\logs\z-ui_2024-10-04_12-57.log
Logging to file: C:\temp\zwave-js-ui\store\logs\z-ui_2024-10-04_12-57.log
Logging to file: C:\temp\zwave-js-ui\store\logs\z-ui_2024-10-04_12-57.log
Logging to file: C:\temp\zwave-js-ui\store\logs\z-ui_2024-10-04_12-57.log
Logging to file: C:\temp\zwave-js-ui\store\logs\z-ui_2024-10-04_12-57.log
Logging to file: C:\temp\zwave-js-ui\store\logs\z-ui_2024-10-04_12-57.log
Logging to file: C:\temp\zwave-js-ui\store\logs\z-ui_2024-10-04_12-57.log
Logging to file: C:\temp\zwave-js-ui\store\logs\z-ui_2024-10-04_12-57.log
Logging to file: C:\temp\zwave-js-ui\store\logs\z-ui_2024-10-04_12-57.log
2024-10-04 12:57:02.706 INFO APP: Listening on port 8091 protocol HTTP
2024-10-04 12:57:02.733 INFO ZNIFFERMANAGER: Zniffer is DISABLED
2024-10-04 12:57:02.734 INFO MQTT: MQTT is disabled
2024-10-04 12:57:02.736 WARN BACKUP: Store backup is disabled
2024-10-04 12:57:02.738 WARN BACKUP: Nvm backup is disabled
2024-10-04 12:57:02.747 INFO Z-WAVE: Connecting to COM8
Logging to file:
        C:\temp\zwave-js-ui\store\logs\zwavejs_2024-10-04.log
2024-10-04 12:57:02.805 INFO Z-WAVE: Zwavejs usage statistics ENABLED

If I force the fileTransport to be created only once by making it a global variable it fixes the original problem I have on windows. Obviously a proper fix would need to re-create the transports when the config changes like what is done in ZWaveJS but it's a bit above my typescript skills.

AlCalzone commented 1 month ago

Obviously a proper fix would need to re-create the transports when the config changes like what is done in ZWaveJS but it's a bit above my typescript skills.

Good find! I can work with @robertsLando on that next week.

robertsLando commented 1 month ago

@spudwebb thanks so much for the detailed issue! I have submit #3928, could you give it a try?