Error while fetching store files: EPERM #2937

jriker1 · 2023-02-01T17:16:56Z

Checklist

I am not using Home Assistant. Or: a developer has told me to come here.
I have checked the troubleshooting section and my problem is not described there.
I have read the changelog and my problem is not mentioned there.

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 · 2023-02-02T07:24:54Z

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 · 2023-02-02T14:16:09Z

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:

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 · 2023-02-03T13:50:27Z

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 · 2023-02-03T13:53:57Z

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.

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 · 2024-09-12T13:54:10Z

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 · 2024-09-13T06:23:50Z

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 · 2024-09-13T10:45:58Z

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

robertsLando · 2024-09-16T08:21:24Z

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

AlCalzone · 2024-09-16T12:16:32Z

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 · 2024-09-16T13:06:57Z

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

…original package Fixes #2937

AlCalzone · 2024-09-16T15:17:59Z

I don't know. @Apollon77 does it?

Apollon77 · 2024-09-16T15:48:52Z

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

robertsLando · 2024-09-16T16:08:28Z

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 · 2024-09-27T13:05:43Z

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 · 2024-09-27T13:24:47Z

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

spudwebb · 2024-09-27T13:36:01Z

When I try to see the permissions of that file it says I don't have read permissions on that file

Then if I click Advanced and continue to attempt to see the permissions as Administrator it still says I don' t have permissions:

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

robertsLando · 2024-09-27T13:42:02Z

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 · 2024-09-27T13:44:09Z

Seems there is an open issue on nodejs related to this: nodejs/node#35853

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

AlCalzone · 2024-09-27T13:45:07Z

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

robertsLando · 2024-09-27T13:47:54Z

@AlCalzone Just as reference, I delete the files using this script:

zwave-js-ui/api/lib/logger.ts

Line 209 in d8c1f7b

export function setupCleanJob(settings: DailyRotateFileTransportOptions) {

In order to fix the issue with log files never deleted

spudwebb · 2024-09-27T14:47:03Z

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 · 2024-09-27T14:53:15Z

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 · 2024-10-04T17:13:32Z

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 · 2024-10-05T08:02:46Z

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.

Fixes #2937

robertsLando · 2024-10-07T08:06:07Z

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

jriker1 added the bug Something isn't working label Feb 1, 2023

robertsLando closed this as completed in 589e172 Feb 3, 2023

robertsLando reopened this Sep 13, 2024

robertsLando added a commit that referenced this issue Sep 16, 2024

fix: remove obsolete @zwave-js/winston-daily-rotate-file in favor of …

6807350

…original package Fixes #2937

robertsLando mentioned this issue Sep 16, 2024

fix: remove obsolete @zwave-js/winston-daily-rotate-file in favor of original package #3897

Merged

robertsLando closed this as completed in #3897 Sep 16, 2024

robertsLando reopened this Sep 16, 2024

robertsLando added a commit that referenced this issue Oct 7, 2024

fix: re-use file transport instance when setup loggers

d42b6fd

Fixes #2937

robertsLando mentioned this issue Oct 7, 2024

fix: re-use file transport instance when setup loggers #3928

Merged

robertsLando closed this as completed in #3928 Oct 17, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Error while fetching store files: EPERM #2937

Error while fetching store files: EPERM #2937

jriker1 commented Feb 1, 2023

robertsLando commented Feb 2, 2023

jriker1 commented Feb 2, 2023 •

edited

Loading

robertsLando commented Feb 3, 2023

jriker1 commented Feb 3, 2023 •

edited

Loading

spudwebb commented Sep 12, 2024

robertsLando commented Sep 13, 2024

AlCalzone commented Sep 13, 2024 •

edited

Loading

robertsLando commented Sep 16, 2024

AlCalzone commented Sep 16, 2024 •

edited

Loading

robertsLando commented Sep 16, 2024

AlCalzone commented Sep 16, 2024

Apollon77 commented Sep 16, 2024

robertsLando commented Sep 16, 2024

spudwebb commented Sep 27, 2024

robertsLando commented Sep 27, 2024 •

edited

Loading

spudwebb commented Sep 27, 2024

robertsLando commented Sep 27, 2024

robertsLando commented Sep 27, 2024

AlCalzone commented Sep 27, 2024

robertsLando commented Sep 27, 2024

spudwebb commented Sep 27, 2024

robertsLando commented Sep 27, 2024

spudwebb commented Oct 4, 2024

AlCalzone commented Oct 5, 2024

robertsLando commented Oct 7, 2024

Error while fetching store files: EPERM #2937

Error while fetching store files: EPERM #2937

Comments

jriker1 commented Feb 1, 2023

Checklist

Deploy method

Z-Wave JS UI version

ZwaveJS version

Describe the bug

To Reproduce

Expected behavior

Additional context

robertsLando commented Feb 2, 2023

jriker1 commented Feb 2, 2023 • edited Loading

robertsLando commented Feb 3, 2023

jriker1 commented Feb 3, 2023 • edited Loading

spudwebb commented Sep 12, 2024

robertsLando commented Sep 13, 2024

AlCalzone commented Sep 13, 2024 • edited Loading

robertsLando commented Sep 16, 2024

AlCalzone commented Sep 16, 2024 • edited Loading

robertsLando commented Sep 16, 2024

AlCalzone commented Sep 16, 2024

Apollon77 commented Sep 16, 2024

robertsLando commented Sep 16, 2024

spudwebb commented Sep 27, 2024

robertsLando commented Sep 27, 2024 • edited Loading

spudwebb commented Sep 27, 2024

robertsLando commented Sep 27, 2024

robertsLando commented Sep 27, 2024

AlCalzone commented Sep 27, 2024

robertsLando commented Sep 27, 2024

spudwebb commented Sep 27, 2024

robertsLando commented Sep 27, 2024

spudwebb commented Oct 4, 2024

AlCalzone commented Oct 5, 2024

robertsLando commented Oct 7, 2024

jriker1 commented Feb 2, 2023 •

edited

Loading

jriker1 commented Feb 3, 2023 •

edited

Loading

AlCalzone commented Sep 13, 2024 •

edited

Loading

AlCalzone commented Sep 16, 2024 •

edited

Loading

robertsLando commented Sep 27, 2024 •

edited

Loading