Alyx log rotation

[k1o0]

The Alyx logs are not working correctly on any of the instances on which it runs. There is a problem with permissions when trying to create a new log file.

On the production Alyx instance the access_alyx.log file is >1.2 GB and the error_alyx.log file is polluted with constant permissions errors:

[Mon Jun 12 09:48:57.243507 2023] [wsgi:error] [pid 8:tid 139694986295040] [remote 205.175.118.226:52550] --- Logging error ---
[Mon Jun 12 09:48:57.243572 2023] [wsgi:error] [pid 8:tid 139694986295040] [remote 205.175.118.226:52550] Traceback (most recent call last):
[Mon Jun 12 09:48:57.243596 2023] [wsgi:error] [pid 8:tid 139694986295040] [remote 205.175.118.226:52550]   File "/usr/lib/python3.8/logging/handlers.py", line 70, in emit
[Mon Jun 12 09:48:57.243600 2023] [wsgi:error] [pid 8:tid 139694986295040] [remote 205.175.118.226:52550]     self.doRollover()
[Mon Jun 12 09:48:57.243610 2023] [wsgi:error] [pid 8:tid 139694986295040] [remote 205.175.118.226:52550]   File "/usr/lib/python3.8/logging/handlers.py", line 171, in doRollover
[Mon Jun 12 09:48:57.243614 2023] [wsgi:error] [pid 8:tid 139694986295040] [remote 205.175.118.226:52550]     self.rotate(self.baseFilename, dfn)
[Mon Jun 12 09:48:57.243624 2023] [wsgi:error] [pid 8:tid 139694986295040] [remote 205.175.118.226:52550]   File "/usr/lib/python3.8/logging/handlers.py", line 111, in rotate
[Mon Jun 12 09:48:57.243628 2023] [wsgi:error] [pid 8:tid 139694986295040] [remote 205.175.118.226:52550]     os.rename(source, dest)
[Mon Jun 12 09:48:57.243643 2023] [wsgi:error] [pid 8:tid 139694986295040] [remote 205.175.118.226:52550] PermissionError: [Errno 13] Permission denied: '/var/log/alyx.log' -> '/var/log/alyx.log.1'
[Mon Jun 12 09:48:57.243656 2023] [wsgi:error] [pid 8:tid 139694986295040] [remote 205.175.118.226:52550] Call stack:
[Mon Jun 12 09:48:57.243881 2023] [wsgi:error] [pid 8:tid 139694986295040] [remote 205.175.118.226:52550]   File "/var/www/alyx/venv/lib/python3.8/site-packages/django/core/handlers/wsgi.py", line 131, in __call__
[Mon Jun 12 09:48:57.243893 2023] [wsgi:error] [pid 8:tid 139694986295040] [remote 205.175.118.226:52550]     response = self.get_response(request)
[Mon Jun 12 09:48:57.243905 2023] [wsgi:error] [pid 8:tid 139694986295040] [remote 205.175.118.226:52550]   File "/var/www/alyx/venv/lib/python3.8/site-packages/django/core/handlers/base.py", line 143, in get_response
[Mon Jun 12 09:48:57.243909 2023] [wsgi:error] [pid 8:tid 139694986295040] [remote 205.175.118.226:52550]     log_response(
[Mon Jun 12 09:48:57.243919 2023] [wsgi:error] [pid 8:tid 139694986295040] [remote 205.175.118.226:52550]   File "/var/www/alyx/venv/lib/python3.8/site-packages/django/utils/log.py", line 241, in log_response
[Mon Jun 12 09:48:57.243922 2023] [wsgi:error] [pid 8:tid 139694986295040] [remote 205.175.118.226:52550]     getattr(logger, level)(

This same issue occurs on mbox, the test instance, and cortexlab Alyx. I notice that in the Alyx set up instructions someone writes that a /var/log/alyx directory should be created within which all log files should be written, however we don't do this. Perhaps creating such a folder with the correct permissions would work?

[juhuntenburg]

@k1o0 @oliche I recall that this might have been solved already?

[k1o0]

No it hasn't. Olivier added a 'delay' arg to the log config but it didn't solve the issue. Here's what Olivier tried:

    'handlers': {
        'file': {
            'level': 'DEBUG',
            'class': 'logging.handlers.RotatingFileHandler',
            'filename': '/var/log/alyx.log',
            'maxBytes': 16777216,
            'backupCount': 1,
            'formatter': 'simple',
            'delay': True  # added in attempt to solve new file permissions error
        },

The production instance settings file had this delay arg yet when I restarted apache recently I encountered the same permissions error. We don't have any other leads at the moment.

[k1o0]

We never found a good solution to this but I noticed someone added a cron to periodically chmod the log files. Not ideal or secure but at least we're not having so much down time as a result...

[oliche]

This happens on the log rotation. This happened on the main alyx during the IBL meeting, so this needs to get looked into further, as this is still a problem even outside of the docker

[oliche]

This doesn't make sense as all the permissions are solid. I think what may happen is the following:

• the log is written by the wsgi process as the www-data user

• the log is rotated by the wsgi process using the logrotate daemon as root.

So the new file is created as root and this creates permissions errors.

To test this I would run a local Alyx server using unicorn as a web server and a small log rotate size, all of the above on a Linux machine.