Errors when trying to log to `stdout` or `stderr` from a function implementing an action

[kszys]

I have an issue with logging in py4web app (does not seem to be related to #874 ) - this is with logging to stdout or stderr. Here is a minimal example:

# __init__.py
import sys
import logging
from py4web import action

log = logging.getLogger("py4web:TEST")
log.setLevel(logging.DEBUG)
handler = logging.StreamHandler(sys.stderr)
log.addHandler(handler)

log.debug("Logger has been initialized")

@action('time')
def time():
    log.debug('test')
    return None

While the first logging command correctly prints Logger has been initialized to the console (during loading of the app), the HTTP request to /time very consistently produces an error in the console -ValueError: I/O operation on closed file:

2024-07-20 23:11:19 --- Logging error ---
2024-07-20 23:11:19 Traceback (most recent call last):
2024-07-20 23:11:19   File "/usr/local/lib/python3.12/logging/__init__.py", line 1163, in emit
2024-07-20 23:11:19     stream.write(msg + self.terminator)
2024-07-20 23:11:19 ValueError: I/O operation on closed file
2024-07-20 23:11:19 Call stack:
2024-07-20 23:11:19   File "/usr/local/lib/python3.12/threading.py", line 1030, in _bootstrap
2024-07-20 23:11:19     self._bootstrap_inner()
2024-07-20 23:11:19   File "/usr/local/lib/python3.12/threading.py", line 1073, in _bootstrap_inner
2024-07-20 23:11:19     self.run()
2024-07-20 23:11:19   File "/usr/local/lib/python3.12/site-packages/rocket3/__init__.py", line 1191, in run
2024-07-20 23:11:19     self.run_app(conn)
2024-07-20 23:11:19   File "/usr/local/lib/python3.12/site-packages/rocket3/__init__.py", line 1689, in run_app
2024-07-20 23:11:19     output = self.app(environ, self.start_response)
2024-07-20 23:11:19   File "/usr/local/lib/python3.12/site-packages/ombott/ombott.py", line 418, in __call__
2024-07-20 23:11:19     return self.wsgi(environ, start_response)
2024-07-20 23:11:19   File "/usr/local/lib/python3.12/site-packages/ombott/ombott.py", line 386, in wsgi
2024-07-20 23:11:19     out = self._cast(self._handle(environ))
2024-07-20 23:11:19   File "/usr/local/lib/python3.12/site-packages/ombott/ombott.py", line 281, in _handle
2024-07-20 23:11:19     return self.handler(self, route, kwargs, route_hooks, error404_405)
2024-07-20 23:11:19   File "/usr/local/lib/python3.12/site-packages/ombott/ombott.py", line 256, in handler
2024-07-20 23:11:19     return route(**kwargs)
2024-07-20 23:11:19   File "/usr/local/lib/python3.12/site-packages/ombott/router/radirouter.py", line 35, in __call__
2024-07-20 23:11:19     return self.handler(*a, **kw)
2024-07-20 23:11:19   File "/usr/local/lib/python3.12/site-packages/py4web/core.py", line 1040, in wrapper
2024-07-20 23:11:19     ret = func(*func_args, **func_kwargs)
2024-07-20 23:11:19   File "/apps/d44.be_en/__init__.py", line 19, in time
2024-07-20 23:11:19     log.debug('test')
2024-07-20 23:11:19 Message: 'test'
2024-07-20 23:11:19 Arguments: ()
2024-07-20 23:11:19 test > Thread-3 > 21:11:19.208

Running in Docker (not sure if this matters), version:

# py4web version
py4web: 1.20240713.1

[mbelletti]

Similar problem using the scheduler:

with USE_SCHEDULER = True the logger complain that the log file is closed.

My setting options in settings.py (but got same error using a file):

LOGGERS = [
    "debug:stdout"
]

--- Logging error ---
Traceback (most recent call last):
  File "/Users/max/.pyenv/versions/3.10.2/lib/python3.10/logging/__init__.py", line 1103, in emit
    stream.write(msg + self.terminator)
ValueError: I/O operation on closed file
Call stack:
  File "/Users/max/.pyenv/versions/3.10.2/lib/python3.10/threading.py", line 966, in _bootstrap
    self._bootstrap_inner()
  File "/Users/max/.pyenv/versions/3.10.2/lib/python3.10/threading.py", line 1009, in _bootstrap_inner
    self.run()
  File "/Users/max/.pyenv/versions/3.10.2/lib/python3.10/threading.py", line 946, in run
    self._target(*self._args, **self._kwargs)
  File "/Users/max/.pyenv/versions/py4web_3.10.2/lib/python3.10/site-packages/pydal/tools/scheduler.py", line 183, in loop
    if not self.step():
  File "/Users/max/.pyenv/versions/py4web_3.10.2/lib/python3.10/site-packages/pydal/tools/scheduler.py", line 228, in step
    self.logger.info("no new tasks")
Message: 'no new tasks'

[mbelletti]

It seems that the last version w/o the problem was version 1.20240518.3

[kszys]

Hmm... the version you mention do not seem to exist in https://pypi.org/project/py4web/#history

[mbelletti]

I checked it out on git. git checkout v1.20240518.3

In any case you can try 1.20240509.1 that is downloadable

[mdipierro]

Thanks! I was able to reproduce.

[mdipierro]

I believe this is now fixed. Thanks.