Error on 21.04 LTS

[CAReeser]

trafficstars

Switched to 21.04 LTS with python 3.10.4

Get this:

May 22 07:04:05 tychocam authbind[7536]: --- Logging error --- May 22 07:04:05 tychocam authbind[7536]: Traceback (most recent call last): May 22 07:04:05 tychocam authbind[7536]: File "/usr/lib/python3.10/logging/handlers.py", line 73, in emit May 22 07:04:05 tychocam authbind[7536]: if self.shouldRollover(record): May 22 07:04:05 tychocam authbind[7536]: File "/usr/lib/python3.10/logging/handlers.py", line 197, in shouldRollover May 22 07:04:05 tychocam authbind[7536]: self.stream.seek(0, 2) #due to non-posix-compliant Windows feature May 22 07:04:05 tychocam authbind[7536]: ValueError: I/O operation on closed file. May 22 07:04:05 tychocam authbind[7536]: Call stack: May 22 07:04:05 tychocam authbind[7536]: File "/usr/lib/python3.10/threading.py", line 966, in _bootstrap May 22 07:04:05 tychocam authbind[7536]: self._bootstrap_inner() May 22 07:04:05 tychocam authbind[7536]: File "/usr/lib/python3.10/threading.py", line 1009, in _bootstrap_inner May 22 07:04:05 tychocam authbind[7536]: self.run() May 22 07:04:05 tychocam authbind[7536]: File "/usr/lib/python3.10/threading.py", line 946, in run May 22 07:04:05 tychocam authbind[7536]: self._target(*self._args, **self._kwargs) May 22 07:04:05 tychocam authbind[7536]: File "/var/www/FlaskApp/main_program/mainApp/cloud_processing/app_cloud.py", line 127, in start_cloud_app May 22 07:04:05 tychocam authbind[7536]: with get_context("fork").Pool(3) as pl: May 22 07:04:05 tychocam authbind[7536]: File "/usr/lib/python3.10/multiprocessing/context.py", line 119, in Pool May 22 07:04:05 tychocam authbind[7536]: return Pool(processes, initializer, initargs, maxtasksperchild, May 22 07:04:05 tychocam authbind[7536]: File "/usr/lib/python3.10/multiprocessing/pool.py", line 212, in init May 22 07:04:05 tychocam authbind[7536]: self._repopulate_pool() May 22 07:04:05 tychocam authbind[7536]: File "/usr/lib/python3.10/multiprocessing/pool.py", line 303, in _repopulate_pool May 22 07:04:05 tychocam authbind[7536]: return self._repopulate_pool_static(self._ctx, self.Process, May 22 07:04:05 tychocam authbind[7536]: File "/usr/lib/python3.10/multiprocessing/pool.py", line 326, in _repopulate_pool_static May 22 07:04:05 tychocam authbind[7536]: w.start() May 22 07:04:05 tychocam authbind[7536]: File "/usr/lib/python3.10/multiprocessing/process.py", line 121, in start May 22 07:04:05 tychocam authbind[7536]: self._popen = self._Popen(self) May 22 07:04:05 tychocam authbind[7536]: File "/usr/lib/python3.10/multiprocessing/context.py", line 277, in _Popen May 22 07:04:05 tychocam authbind[7536]: return Popen(process_obj) May 22 07:04:05 tychocam authbind[7536]: File "/usr/lib/python3.10/multiprocessing/popen_fork.py", line 19, in init May 22 07:04:05 tychocam authbind[7536]: self._launch(process_obj) May 22 07:04:05 tychocam authbind[7536]: File "/usr/lib/python3.10/multiprocessing/popen_fork.py", line 71, in _launch May 22 07:04:05 tychocam authbind[7536]: code = process_obj._bootstrap(parent_sentinel=child_r) May 22 07:04:05 tychocam authbind[7536]: File "/usr/lib/python3.10/multiprocessing/process.py", line 315, in _bootstrap May 22 07:04:05 tychocam authbind[7536]: self.run() May 22 07:04:05 tychocam authbind[7536]: File "/usr/lib/python3.10/multiprocessing/process.py", line 108, in run May 22 07:04:05 tychocam authbind[7536]: self._target(*self._args, **self._kwargs) May 22 07:04:05 tychocam authbind[7536]: File "/usr/lib/python3.10/multiprocessing/pool.py", line 125, in worker May 22 07:04:05 tychocam authbind[7536]: result = (True, func(*args, **kwds)) May 22 07:04:05 tychocam authbind[7536]: File "/usr/lib/python3.10/multiprocessing/pool.py", line 48, in mapstar May 22 07:04:05 tychocam authbind[7536]: return list(map(*args)) May 22 07:04:05 tychocam authbind[7536]: File "/var/www/FlaskApp/main_program/mainApp/cloud_processing/app_cloud.py", line 396, in process_image May 22 07:04:05 tychocam authbind[7536]: logger.debug('saving plot to cloud_stack: ' + filename) May 22 07:04:05 tychocam authbind[7536]: Message: 'saving plot to cloud_stack: 1653221036'

[jruere]

Could you reduce this to a smaller reproducible case?

There's a suspicious record near the top: May 22 07:04:05 tychocam authbind[7536]: ValueError: I/O operation on closed file.

[CAReeser]

I cannot reduce unless you can tell me how. Does you MPL use locks? The error seems to happen more often when DEBUG is turned on, probably because of the increased volume of logging traffic. I will comment out the debug statements in different parts of the code to see if that matters. I have a pool starting every 30 seconds, and another MP running continuously. Would an unresolved lock on a file write/read interfere with your program? Especially when pool starts. It is possible that a file is being served to the UI during a write operation, but I use atomic functions for read/write. My files are 2-4 megabytes.

[jruere]

It does not use locks explicitly but undoubtedly locks are being used.

I suspect that at the moment of the fork, some locks remain held and are never released. If you remove this library but continue using "fork", you should be able to reproduce this problem as well, although with lower probability.

Could you check?

[jruere]

I suspect this is related to #49.

[jruere]

I'll consider it a duplicate.