Open JasonGloverNZ opened 1 year ago
UPDATE: I had a theory that maybe the spawned processes were running under a different user space and that was causing the rotated files to be created with root
as the owner.
I tested that by emitting the uid and gid both in the parent process, but also in the stdout and stderr event handlers.
Same values.
following.
We also have this issue, though we are using systemctl to restart the node application.
Sep 28 19:37:53 raspberry systemd[1]: Started Frank.
Sep 28 19:37:54 raspberry start.sh[3653]: Added RotateFileTransport
Sep 28 19:37:54 raspberry start.sh[3653]: Error: EACCES: permission denied, open 'logs/frank-2023-09-28-19.log'
Sep 28 19:37:55 raspberry systemd[1]: frank.service: Main process exited, code=exited, status=1/FAILURE
Sep 28 19:37:55 raspberry systemd[1]: frank.service: Failed with result 'exit-code'.
Sep 28 19:37:55 raspberry systemd[1]: frank.service: Service RestartSec=100ms expired, scheduling restart.
Sep 28 19:37:55 raspberry systemd[1]: frank.service: Scheduled restart job, restart counter is at 5.
Sep 28 19:37:55 raspberry systemd[1]: Stopped Frank.
Sep 28 19:37:55 raspberry systemd[1]: frank.service: Start request repeated too quickly.
Sep 28 19:37:55 raspberry systemd[1]: frank.service: Failed with result 'exit-code'.
Sep 28 19:37:55 raspberry systemd[1]: Failed to start Frank.
Sep 28 19:38:11 raspberry systemd[1]: Started Frank.
-rw-r--r-- 1 pi pi 30K Sep 28 16:00 frank-2023-09-28-15.log.gz
-rw-r--r-- 1 pi pi 17K Sep 28 17:00 frank-2023-09-28-16.log.gz
-rw-r--r-- 1 pi pi 39K Sep 28 18:00 frank-2023-09-28-17.log.gz
-rw-r--r-- 1 root root 17K Sep 28 19:00 frank-2023-09-28-18.log.gz
-rw-r--r-- 1 root root 179K Sep 28 19:34 frank-2023-09-28-19.log
-rw-r--r-- 1 pi pi 7.2K Sep 29 00:00 frank-2023-09-28.log.gz
-rw-r--r-- 1 pi pi 1.9M Sep 29 09:52 frank-2023-09-29.log
We also have a python script doing some stuff
import { spawn } from 'child_process';
[..]
pythonPrint = (type) => {
logger.debug(PRINTER.PYTHON_PRINT, { type });
const spawnProcess = spawn('python3', ['./print.py', type]);
spawnProcess.stdout.on('data', (msg) => {
logger.debug(PRINTER.PYTHON_PRINT, { type, msg: msg.toString() });
});
spawnProcess.stderr.on('data', (msg) => {
logger.error(PRINTER.PYTHON_PRINT, { type, msg: msg.toString() });
});
spawnProcess.on('error', (msg) => {
logger.error(PRINTER.PYTHON_PRINT, { type, msg: msg.toString() });
});
};
workaround is set all log files (in folder ./logs) to current user (pi), so
sudo chown pi:pi ./logs -R
I'm running into a frustrating problem that was a little hard to track down. I have a background process that was trouble-free until a few weeks ago and then suddenly it developed the following error...
EACCES: permission denied, open '../logs/textract-prod/default-2023-06-07.log'
Once this error occurs the process enters a failed state. It is controlled by pm2, which will restart it, but as soon as it tries to log to the file (which it does on startup) it encounters the permission problem and it crashes, and gets restarted again.
I found that I could temporarily fix the problem by stopping the process and renaming the logging directory. When I restart the process it creates a new log file which has the correct permissions. I should mention at this point that I am running the process in user space, and the log directory is in the user's home directory.
User:
bigbird
Log directory:/home/bigbird/logs/textract-prod/
OS:Ubuntu 18.04.6 LTS
Looking at the logs I noticed a pattern: the file permission problem always starts at midnight UTC. Which led me to the log file rotator.
I confirmed this theory by checking the file permissions of a set of files:
So straight away I see the rotator has a random chance of creating the new log file with the current user as the owner, but sometimes
root
is the owner.What the ____ ?!
The only "odd" thing that we do in this process is we spawn some python processes. We capture the stdout and stderr from those processes in the parent process and write that to the log. I'm wondering if that has something to do with why we sometimes get a root-owner log file.
The reason I don't think this is the problem:
child_process.spawn
should be creating processes in the same user space as the parent process.I also note that we don't get this problem on other environments, OSes and architectures.