[Bug]: Rotation of log files seems to crash plugin/homebridge

[fab7282]

What happened?

Hi, every night when temporary backup from Homebridge runs ... Homebridge server crashes because of missing log file of the plugin. Could you please help me what did I configure wrong? Loglevel Variable is set to"0". I tried reinstallation of Beta and current release but nothing helped. Thank you for your efforts.

BR,

fab

Device Type

Station (Supported)

Plugin Version

v2.0.x (Supported)

HomeBridge Version

v1.4.x (Supported)

NodeJS Version

v16 (Supported)

Operating System

Raspbian 10+ (Supported)

Relevant log output

[30/05/2022, 01:29:25] [Homebridge UI] Running scheduled instance backup...
[30/05/2022, 01:29:25] [Homebridge UI] Creating temporary backup archive at /tmp/homebridge-backup-dtjy9z/homebridge-backup-0E8159FAB9F8.tar.gz
[30/05/2022, 02:00:00] Error: ENOENT: no such file or directory, rename '/var/lib/homebridge/eufysecurity/log-lib.log' -> '/var/lib/homebridge/eufysecurity/log-lib.log.0'
[30/05/2022, 02:00:00] Got SIGTERM, shutting down Homebridge...
[5/30/2022, 2:00:00 AM] [EufySecurity-2.0.0] WARN:  Push Closed!
[5/30/2022, 2:00:00 AM] [EufySecurity-2.0.0] INFO:  Finished shutdown!
[30/05/2022, 02:00:06] [HB Supervisor] Homebridge Process Ended. Code: 143, Signal: null
[30/05/2022, 02:00:11] [HB Supervisor] Restarting Homebridge...
[30/05/2022, 02:00:11] [HB Supervisor] Starting Homebridge with extra flags: -I

[github-actions[bot]]

Did you check this Common Issues pages ?

[fab7282]

Yes, I did. ....

[thieren]

Hi @fab7282

does the directory /var/lib/homebridge/eufysecurity exist? And if so what contents are listed in this directory?

[fab7282]

Hi, last night I had the same issue: Homebridge Log says: [31/05/2022, 01:10:25] [Homebridge UI] Running job to cleanup config.json backup files older than 60 days... [31/05/2022, 01:29:25] [Homebridge UI] Running scheduled instance backup... [31/05/2022, 01:29:25] [Homebridge UI] Creating temporary backup archive at /tmp/homebridge-backup-rmFxHx/homebridge-backup-0E8159FAB9F8.tar.gz [31/05/2022, 02:00:00] Error: ENOENT: no such file or directory, rename '/var/lib/homebridge/eufysecurity/log-lib.log' -> '/var/lib/homebridge/eufysecurity/log-lib.log.0' [31/05/2022, 02:00:00] Got SIGTERM, shutting down Homebridge... [5/31/2022, 2:00:00 AM] [EufySecurity-2.0.0] WARN: Push Closed! [5/31/2022, 2:00:00 AM] [EufySecurity-2.0.0] INFO: Finished shutdown! [31/05/2022, 02:00:06] [HB Supervisor] Homebridge Process Ended. Code: 143, Signal: null [31/05/2022, 02:00:11] [HB Supervisor] Restarting Homebridge... [31/05/2022, 02:00:11] [HB Supervisor] Starting Homebridge with extra flags: -I

The folder /var/lib/homebridge/eufysecurity $ ls -la total 32 drwxr-xr-x 2 pi pi 4096 May 31 02:00 . drwxr-xr-x 6 pi pi 4096 May 29 09:04 .. -rw-r--r-- 1 pi pi 1180 May 31 02:00 log-lib.log -rw-r--r-- 1 pi pi 1455 May 30 02:00 log-lib.log.0 -rw-r--r-- 1 pi pi 4382 May 29 09:10 log-lib.log.1 -rw-r--r-- 1 pi pi 1793 May 31 02:00 persistent.json -rw-r--r-- 1 pi pi 292 May 29 09:03 stations.json

... has the given content.

I estimate, that eufyplugin wants to write something in the given files but they do not exist anymore due to backup. Is there a way to manually start the backup? Thank you for your efforts. BR fab.

[thieren]

So firstly this doesn't seem to have something to do with the backup process of the homebridge-ui. Look at the timestamps. There are over 30 minutes between the backup and the error.

I suspect that this has something to do with the file-rotation feature of the log library this plugin is using (it's buyan by the way). The fact that this error keeps occurring at exactly 2:00 am supports this I think. (buyan will rotate the log files every day at midnight. I suppose that the exact 2 hour difference is due to your time zone). I'll rename the issue accordingly.

Anyway, I just looked through my own logs and couldn't find the same behavior. So it's hard to reproduce.

1. the files in the directory are owned by the user pi can you confirm that the homebridge process is also run by this user? I'd be surprised if not, but by default this should be the user homebridge - but of course this depends on your method of installation.
2. Do you have enableDetailedLoggingenabled? If so, does disabling this prevent the error from happening?

[njuart]

Hey, I experience something similar

[fab7282]

Dear all, thank you for your help. @thieren referring to your questions.

1. ps -u pi PID TTY TIME CMD 838 ? 00:09:52 hb-service 1023 ? 00:05:35 homebridge

2. According to my current configuration I did not configure "enableDetailedLogging". Shall I add it to my configuration? Thank you very much for your efforts. BR fab

[thieren]

According to my current configuration I did not configure "enableDetailedLogging". Shall I add it to my configuration?

No, for now this is not necessary.

I did find a possible bug in the code that I suspect to be the cause. But I need to test this first in order not to break anything more for you guys.

Bear with me....

[fab7282]

Hi thieren, thanks a lot. Please let me know if I can test something for you or do some changes or install a beta version ... BR fab

[thieren]

Seen this in some other logs too now.

Should be fixed in 2.0.1-beta.4

Please test and report if this still happens.

[fab7282]

Hi thieren,

thank you very much for your work. Your fix seems to work fine. :) see Log below ...

[04/06/2022, 01:10:59] [Homebridge UI] Running job to cleanup config.json backup files older than 60 days... [04/06/2022, 02:12:19] [Homebridge UI] Running scheduled instance backup... [04/06/2022, 02:12:19] [Homebridge UI] Creating temporary backup archive at /tmp/homebridge-backup-Te2Yxd/homebridge-backup-0E8159FAB9F8.tar.gz [04/06/2022, 03:39:47] [RPi] warning: heartbeat 23892, drift 397

Thank you very much for your efforts. BR fab

[thieren]

Hey @fab7282

Thanks for the feedback.

Closing this as fixed.