search

GrahamDumpleton / mod_wsgi

Source code for Apache/mod_wsgi.
Apache License 2.0
1.03k stars 269 forks source link

RuntimeError: log object has expired in mod_wsgi 5.0.1 with Django 5.0.9 python 3.13.0 #912

Open bdr-sara opened 1 month ago

bdr-sara commented 1 month ago

Summary

I'm encountering a RuntimeError: log object has expired when using mod_wsgi with Django 5.0.9. The issue appears in the Apache logs when rendering certain pages.

Environment

Steps to Reproduce

  1. Set up a Django 5.0.9 application with mod_wsgi and Apache.
  2. Visit a specific page or make an API request.
  3. Check the Apache error log.

Error Log

[Tue Oct 15 11:55:47.997506 2024] [wsgi ] [pid 8404 1060] [client xx:43833] File "C:\Apache24\htdocs\ERPapp.venv\Lib\site-packages\django\template\engine.py", line 20, in init [Tue Oct 15 11:55:47.997506 2024] [wsgi ] [pid 8404 1060] [client xx:43833] RuntimeError: log object has expired

GrahamDumpleton commented 1 month ago

This error indicates that something has cached the wsgi.errors object from the WSGI request environ dictionary beyond the lifetime of the HTTP request and has then tried to write to it after the request has finished.

It is very strange that something is actually trying to use the wsgi.errors object and not just using Python logging module and/or stderr instead. Don't thinkI have ever seen any framework use wsgi.errors even though it exists.

Would need the complete stack trace for the error to try and better understand what is trying to use it.

bdr-sara commented 1 month ago

it is apear on every API request and it is the partialstack trace: [Tue Oct 15 12:25:51.364043 2024] [wsgi:error] [pid 6868:tid 1220] [client xxx:36116] File "C:\Apache24\htdocs\ERPapp\.venv\Lib\site-packages\django\template\base.py", line 339, in init\r, referer: https://wishproglobal.com:portX/ [Tue Oct 15 12:25:51.364043 2024] [wsgi:error] [pid 6868:tid 1220] [client xxx:36116] def init(self, template_string):\r, referer: https://wishproglobal.com:portX/ [Tue Oct 15 12:25:51.364043 2024] [wsgi:error] [pid 6868:tid 1220] [client xxx:36116] RuntimeError: log object has expired\r, referer: https://wishproglobal.com:portX/ [Tue Oct 15 12:25:51.364043 2024] [wsgi:error] [pid 6868:tid 1220] [client xxx:36116] Exception ignored in: <_io.TextIOWrapper name='' encoding='utf-8'>\r, referer: https://wishproglobal.com:portX/ [Tue Oct 15 12:25:51.364043 2024] [wsgi:error] [pid 6868:tid 1220] [client xxx:36116] Traceback (most recent call last):\r, referer: https://wishproglobal.com:portX/ [Tue Oct 15 12:25:51.364043 2024] [wsgi:error] [pid 6868:tid 1220] [client xxx:36116] File "C:\Apache24\htdocs\ERPapp\.venv\Lib\site-packages\django\template\base.py", line 339, in init\r, referer: https://wishproglobal.com:portX/ [Tue Oct 15 12:25:51.364043 2024] [wsgi:error] [pid 6868:tid 1220] [client xxx:36116] def init(self, template_string):\r, referer: https://wishproglobal.com:portX/ [Tue Oct 15 12:25:51.364043 2024] [wsgi:error] [pid 6868:tid 1220] [client xxx:36116] RuntimeError: log object has expired\r, referer: https://wishproglobal.com:portX/ [Tue Oct 15 12:25:51.364043 2024] [wsgi:error] [pid 6868:tid 1220] [client xxx:36116] Exception ignored in: <_io.TextIOWrapper name='' encoding='utf-8'>\r, referer: https://wishproglobal.com:portX/ [Tue Oct 15 12:25:51.364043 2024] [wsgi:error] [pid 6868:tid 1220] [client xxx:36116] Traceback (most recent call last):\r, referer: https://wishproglobal.com:portX/ [Tue Oct 15 12:25:51.364043 2024] [wsgi:error] [pid 6868:tid 1220] [client xxx:36116] File "C:\Apache24\htdocs\ERPapp\.venv\Lib\site-packages\django\template\base.py", line 339, in init\r, referer: https://wishproglobal.com:portX/ [Tue Oct 15 12:25:51.364940 2024] [wsgi:error] [pid 6868:tid 1220] [client xxx:36116] def init(self, template_string):\r, referer: https://wishproglobal.com:portX/ [Tue Oct 15 12:25:51.364940 2024] [wsgi:error] [pid 6868:tid 1220] [client xxx:36116] RuntimeError: log object has expired\r, referer: https://wishproglobal.com:portX/

GrahamDumpleton commented 1 month ago

Do the pages which have this issue use an on transaction commit callback, or other callback which is processed upon completion of a request, to do something? This is probably what is happening, and it is trying to access the now invalid wsgi.errors object somehow, possibly by trying to print on the WSGI environ dictionary inadvertently.

bdr-sara commented 1 month ago

Thanks for taking the time This happens to me on every API request I feel like I had a version compatibility issue when installing the django pyodbc,mod_wsgi library I addressed this bug https://github.com/mkleehammer/pyodbc/issues/1382 And i did as pip install git+https://github.com/mkleehammer/pyodbc.git

That could be causing me a problem Maybe it's better for me to go down to old versions in everything

GrahamDumpleton commented 1 month ago

Oh, didn't pick up that you were using Python 3.13. I wonder what has changed in that version. 🤔

bdr-sara commented 4 weeks ago

i installed new versions of pip install pyodbc==5.2.0
but the errors still appear as: [Tue Oct 29 12:30:08.522311 2024] [wsgi:error] [pid 8468:tid 1188] [client xxx:22113] File "C:\Apache24\htdocs\ERPapp\.venv\Lib\site-packages\pyasn1\codec\ber\decoder.py", line 47, in _createComponent\r [Tue Oct 29 12:30:08.522311 2024] [wsgi:error] [pid 8468:tid 1188] [client xxx:22113] def _createComponent(self, asn1Spec, tagSet, value, options):\r [Tue Oct 29 12:30:08.522311 2024] [wsgi:error] [pid 8468:tid 1188] [client xxx:22113] RuntimeError: log object has expired\r [Tue Oct 29 12:30:08.522311 2024] [wsgi:error] [pid 8468:tid 1188] [client xxx:22113] Exception ignored in: <_io.TextIOWrapper name='' encoding='utf-8'>\r [Tue Oct 29 12:30:08.522311 2024] [wsgi:error] [pid 8468:tid 1188] [client xxx:22113] Traceback (most recent call last):\r [Tue Oct 29 12:30:08.522311 2024] [wsgi:error] [pid 8468:tid 1188] [client xxx:22113] File "C:\Apache24\htdocs\ERPapp\.venv\Lib\site-packages\pyasn1\codec\ber\decoder.py", line 47, in _createComponent\r [Tue Oct 29 12:30:08.522311 2024] [wsgi:error] [pid 8468:tid 1188] [client xxx:22113] def _createComponent(self, asn1Spec, tagSet, value, options):\r [Tue Oct 29 12:30:08.522311 2024] [wsgi:error] [pid 8468:tid 1188] [client xxx:22113] RuntimeError: log object has expired\r

GrahamDumpleton commented 4 weeks ago

My best guess at the moment is that you are using a WSGI middleware that doesn't call close() properly on the nested WSGI application resulting in things not being cleaned up immediately when the request finishes and before the log object is invalidated. Instead what is happening is things are only being cleaned up when the garbage collection later kicks in. In Python 3.13 it appears that garbage collection behaviour has changed such that it can take multiple passes of the garbage collector to clean up everything whereas before it would all be done on the first pass. This delay results in code trying to access the log object after it is invalidated.

I have written a blog post about this problem with close() in the past for other reasons.

Do you know if you are using any WSGI middlewares?

bdr-sara commented 4 weeks ago

Yes i am using mod wsgi version 5.0.1

I just transferred my server computer to an updated virtual machine and required me to update a version of a certain library and since then I have not been able to finish updating versions of everything pyodbc==5.2.0 mssql-django==1.5 mod_wsgi==5.0.1 wfastcgi==3.0.0 Django==5.0.9 djangorestframework==3.15.2

so what is the solution??

בתאריך יום ג׳, 29 באוק׳ 2024, 13:26, מאת Graham Dumpleton ‏< @.***>:

My best guess at the moment is that you are using a WSGI middleware that doesn't call close() properly on the nested WSGI application resulting in things not being cleaned up immediately when the request finishes and before the log object is invalidated. Instead what is happening is things are only being cleaned up when the garbage collection later kicks in. In Python 3.13 it appears that garbage collection behaviour has changed such that it can take multiple passes of the garbage collector to clean up everything whereas before it would all be done on the first pass. This delay results in code trying to access the log object after it is invalidated.

I have written a blog post about this problem with close() in the past for other reasons.

- http://blog.dscpl.com.au/2012/10/obligations-for-calling-close-on.html

Do you know if you are using any WSGI middlewares?

— Reply to this email directly, view it on GitHub https://github.com/GrahamDumpleton/mod_wsgi/issues/912#issuecomment-2443950338, or unsubscribe https://github.com/notifications/unsubscribe-auth/BD3BHS3CNI2YQ2A2726ZZHTZ55WHXAVCNFSM6AAAAABP6U5G4WVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDINBTHE2TAMZTHA . You are receiving this because you authored the thread.Message ID: @.***>

GrahamDumpleton commented 4 weeks ago

The mod_wsgi module provides the WSGI server, it is not a WSGI middleware.

In the list above you mention wfastcgi. Are you actually using wfastcgi? It is a strange module to be using given what I think it does.

Can you provide the output from running pip freeze so I can see all packages which are installed.

Also, as I note, this is possibly due to changes in Python 3.13. Can you go back to using Python 3.12 instead?

Finally, are they complete tracebacks you are supplying for errors, or are they actually partial stack traces which previous post suggests? I need to see one clean complete error stack trace for one request.

bdr-sara commented 4 weeks ago

(.venv) PS C:\Apache24\htdocs\ERPapp> pip list Package Version

asgiref 3.8.1 CacheControl 0.14.0 cachetools 5.5.0 certifi 2024.8.30 cffi 1.17.1 charset-normalizer 3.4.0 cryptography 43.0.1 Django 5.0.9 djangorestframework 3.15.2 et-xmlfile 1.1.0 firebase-admin 6.5.0 gcloud 0.18.3 google-api-core 2.21.0 google-api-python-client 2.149.0 google-auth 2.35.0 google-auth-httplib2 0.2.0 google-cloud-core 2.4.1 google-cloud-firestore 2.19.0 google-cloud-storage 2.18.2 google-crc32c 1.6.0 google-resumable-media 2.7.2 googleapis-common-protos 1.65.0 grpcio 1.66.2 grpcio-status 1.66.2 httplib2 0.22.0 idna 3.10 jwcrypto 1.5.6 mod_wsgi 5.0.1 msgpack 1.1.0 mssql-django 1.5 oauth2client 4.1.3 openpyxl 3.1.5 packaging 24.1 pip 24.2 pipdeptree 2.23.4 proto-plus 1.24.0 protobuf 5.28.2 pyasn1 0.6.1 pyasn1_modules 0.4.1 pycparser 2.22 pycryptodome 3.21.0 PyJWT 2.9.0 pyodbc 5.2.0 pyparsing 3.2.0 python-jwt 4.1.0 pytz 2024.2 requests 2.32.3 requests-toolbelt 1.0.0 rsa 4.9 setuptools 75.1.0 six 1.16.0 sqlparse 0.5.1 typing_extensions 4.12.2 tzdata 2024.2 uritemplate 4.1.1 urllib3 2.2.3 wfastcgi 3.0.0 wheel 0.44.0 I now have Python 3.13 installed I prefer to avoid going down to Python 3.12 but maybe I have no choice In every call from the application to the DJANGO server I get a RuntimeError: log object has expired error [Wed Oct 30 09:37:18.317286 2024] [wsgi:error] [pid 8112:tid 1244] [client xx:41427] RuntimeError: log object has expired\r [Wed Oct 30 09:37:18.317286 2024] [wsgi:error] [pid 8112:tid 1244] [client xx:41427] Exception ignored in: <_io.TextIOWrapper name='' encoding='utf-8'>\r [Wed Oct 30 09:37:18.317286 2024] [wsgi:error] [pid 8112:tid 1244] [client xx:41427] Traceback (most recent call last):\r [Wed Oct 30 09:37:18.317286 2024] [wsgi:error] [pid 8112:tid 1244] [client xx:41427] File "C:\Apache24\htdocs\ERPapp\.venv\Lib\site-packages\pyasn1\type\base.py", line 50, in init\r [Wed Oct 30 10:03:03.714371 2024] [wsgi:error] [pid 9144:tid 1232] [client xxx:23803] Traceback (most recent call last):\r [Wed Oct 30 10:03:03.714371 2024] [wsgi:error] [pid 9144:tid 1232] [client xxx:23803] File "C:\Users\servero\AppData\Local\Programs\ Python\Python313\Lib\re\_parser.py", line 255, in match\r [Wed Oct 30 10:03:03.730038 2024] [wsgi:error] [pid 9144:tid 1232] [client xxx:23803] def match(self, char):\r [Wed Oct 30 10:03:03.730038 2024] [wsgi:error] [pid 9144:tid 1232] [client xxx:23803] RuntimeError: log object has expired\r [Wed Oct 30 10:03:03.730038 2024] [wsgi:error] [pid 9144:tid 1232] [client xxx:23803] Exception ignored in: <_io.TextIOWrapper name='' encoding='utf -8'>\r [Wed Oct 30 10:03:03.730038 2024] [wsgi:error] [pid 9144:tid 1232] [client xxx:23803] Traceback (most recent call last):\r [Wed Oct 30 10:03:03.730038 2024] [wsgi:error] [pid 9144:tid 1232] [client xxx:23803] File "C:\Users\servero\AppData\Local\Programs\ Python\Python313\Lib\re\_parser.py", line 255, in match\r [Wed Oct 30 10:03:03.730038 2024] [wsgi:error] [pid 9144:tid 1232] [client xxx:23803] def match(self, char):\r [Wed Oct 30 10:03:03.730038 2024] [wsgi:error] [pid 9144:tid 1232] [client xxx:23803] RuntimeError: log object has expired\r [Wed Oct 30 10:03:03.730038 2024] [wsgi:error] [pid 9144:tid 1232] [client xxx:23803] Exception ignored in: <_io.TextIOWrapper name='' encoding='utf -8'>\r [Wed Oct 30 10:03:03.730038 2024] [wsgi:error] [pid 9144:tid 1232] [client xxx:23803] Traceback (most recent call last):\r [Wed Oct 30 10:03:03.730038 2024] [wsgi:error] [pid 9144:tid 1232] [client xxx:23803] File "C:\Users\servero\AppData\Local\Programs\ Python\Python313\Lib\re\_parser.py", line 255, in match\r [Wed Oct 30 10:03:03.730038 2024] [wsgi:error] [pid 9144:tid 1232] [client xxx:23803] def match(self, char):\r [Wed Oct 30 10:03:03.730038 2024] [wsgi:error] [pid 9144:tid 1232] [client xxx:23803] RuntimeError: log object has expired\r [Wed Oct 30 10:03:03.730038 2024] [wsgi:error] [pid 9144:tid 1232] [client xxx:23803] Exception ignored in: <_io.TextIOWrapper name='' encoding='utf -8'>\r [Wed Oct 30 10:03:03.730038 2024] [wsgi:error] [pid 9144:tid 1232] [client xxx:23803] Traceback (most recent call last):\r [Wed Oct 30 10:03:03.730038 2024] [wsgi:error] [pid 9144:tid 1232] [client xxx:23803] File "C:\Users\servero\AppData\Local\Programs\ Python\Python313\Lib\re\_parser.py", line 255, in match\r [Wed Oct 30 10:03:03.730038 2024] [wsgi:error] [pid 9144:tid 1232] [client xxx:23803] def match(self, char):\r [Wed Oct 30 10:03:03.730038 2024] [wsgi:error] [pid 9144:tid 1232] [client xxx:23803] RuntimeError: log object has expired\r [Wed Oct 30 10:03:03.730038 2024] [wsgi:error] [pid 9144:tid 1232] [client xxx:23803] Exception ignored in: <_io.TextIOWrapper name='' encoding='utf -8'>\r [Wed Oct 30 10:03:03.730038 2024] [wsgi:error] [pid 9144:tid 1232] [client xxx:23803] Traceback (most recent call last):\r [Wed Oct 30 10:03:03.730038 2024] [wsgi:error] [pid 9144:tid 1232] [client xxx:23803] File "C:\Users\servero\AppData\Local\Programs\ Python\Python313\Lib\re\_parser.py", line 255, in match\r [Wed Oct 30 10:03:03.730038 2024] [wsgi:error] [pid 9144:tid 1232] [client xxx:23803] def match(self, char):\r [Wed Oct 30 10:03:03.730038 2024] [wsgi:error] [pid 9144:tid 1232] [client xxx:23803] RuntimeError: log object has expired\r [Wed Oct 30 10:03:03.730038 2024] [wsgi:error] [pid 9144:tid 1232] [client xxx:23803]

I generally use these libraries only when importing does not make any changes What can help me with these errors? Can it be ignored?

GrahamDumpleton commented 3 weeks ago

Whether this is a serious problem to worry about (besides the noise in the logs), depends on what object is being deleted by the garbage collector and the consequences of an exception being thrown at that point.

What it likely comes down to is that a Python object has the special __del__() method for running actions when the object is being deleted. This cleanup method is trying to log something. If it tries to log something before running an important step, such as releasing some resource (file etc), then that an exception occurs would cause that important step to not run.

I don't know what happens if an exception occurs in a __del__() method, whether Python just ignores or not. If it doesn't just ignore it and still delete the object, then possibly you might end up with these dead objects for which the memory doesn't properly get released and so process memory could grow over time.

abompard commented 1 week ago

I'm getting the same error with mod_wsgi 5.0.0 and Python 3.13 but no Django:

[Wed Nov 20 08:00:20.636851 2024] [wsgi:error] [pid 396702:tid 396702] Exception ignored in: <_io.TextIOWrapper name='<wsgi.errors>' encoding='utf-8'>
[Wed Nov 20 08:00:20.636888 2024] [wsgi:error] [pid 396702:tid 396702] RuntimeError: log object has expired
GrahamDumpleton commented 1 week ago

@abompard Can you explain what WSGI framework you are using then? I need to be able to isolate this down to as small an example as possible to try and work out what is the problematic WSGI middleware/component.

abompard commented 1 week ago

We are not using a wsgi framework at all: https://pagure.io/koji/blob/master/f/kojihub/kojixmlrpc.py#_792

GrahamDumpleton commented 6 days ago

Trigger is likely due to the complete WSGI environ dictionary being stored in thread local storage but where the storage is not cleared at the end of the request, but only when a subsequent request arrives.

What I am not sure about is why something may be trying to access internals of wsgi.errors after the request has completed. I will need to check source code, but just deleting it after the request had completed I thought wouldn't log the warning.

Anyway, still all comes down to differences in garbage collector in Python 3.13. The access pattern under that version may be different and it may try to access internals somehow.

GrahamDumpleton commented 5 days ago

Try with equivalent of:

pip install https://github.com/GrahamDumpleton/mod_wsgi/archive/refs/heads/develop.zip

Or if manually installing from source code use:

https://github.com/GrahamDumpleton/mod_wsgi/archive/refs/heads/develop.zip

See if that solves the problems for your use cases.

GrahamDumpleton commented 5 days ago

Change with hopeful fix released in mod_wsgi 5.0.2.