Forums

My two web-apps are being used a lot more this past month, which is good. However, as a result I noticed in the PythonAnywhere Dashboard that my file-storage had reached 98% of my allowance, so on Friday (22 June 2022 at about 11pm), I increased the allowance so that it was at 80% of capacity. (I know I should have kept an eye on the storage usage and increased it sooner).

However, since that file-storage allowance increase, I've noticed the apps sometimes are slow to respond, and there are many thousands of on-going "Logging error ..." messages in my server logs (eg: "/var/log/www.madapps.uk.server.log", etc), so that the recent server log files are 320 Mbytes, 515 Mbytes, and 850Mbytes (whereas in the past these logs were up to a hundred Kbytes at most).

However, in my error log files (eg: "/var/log/www.madapps.uk.error.log"), the last message was "2022-06-23 18:58" (which was after I increased my storage allowance):

2022-06-23 18:58:26,935:   File "/home/sbridgett/madapps/webedit/views_editor.py", line 108, in <module>
2022-06-23 18:58:26,935:     from webedit.views_teamup import get_teamup_events

I know there should have been several messages written to these error logs since.

I haven't made significant changes to my scripts, and my scripts still run on my localhost at home okay, and I've also disabled some logging messages, but I haven't been able to fix this problem so far.

I think that when my app does produce an uncaught exception error, or an imported module logs to the error log, then it can't currently write to the error log, so instead the system recursively writes thousands of lines to the server log about "Traceback,.... OSError: [Errno 9] Bad file descriptor, ... etc", as shown below. (I assume the "Bad file descriptor," refers to the error log file), as it tries to write to error log, which raises another exception, which tries again to write to the error log file, etc:

"2022-06-27 16:29:25 ('web_error:', '.............')
2022-06-27 16:29:30 --- Logging error ---
2022-06-27 16:29:30 Traceback (most recent call last):
2022-06-27 16:29:30   File "/usr/local/lib/python3.7/logging/handlers.py", line 940, in emit#012    self.socket.sendto(msg, self.address)
2022-06-27 16:29:30 OSError: [Errno 9] Bad file descriptor
2022-06-27 16:29:30 #012During handling of the above exception, another exception occurred:
2022-06-27 16:29:30 Traceback (most recent call last):
2022-06-27 16:29:30   File "/usr/local/lib/python3.7/logging/handlers.py", line 940, in emit#012    self.socket.sendto(msg, self.address)
2022-06-27 16:29:30 OSError: [Errno 9] Bad file descriptor
2022-06-27 16:29:30 #012During handling of the above exception, another exception occurred:
2022-06-27 16:29:30 Traceback (most recent call last):
2022-06-27 16:29:30   File "/usr/local/lib/python3.7/logging/handlers.py", line 940, in emit#012    self.socket.sendto(msg, self.address)
2022-06-27 16:29:30 OSError: [Errno 9] Bad file descriptor
2022-06-27 16:29:30 #012During handling of the above exception, another exception occurred:
2022-06-27 16:29:30 Traceback (most recent call last):
2022-06-27 16:29:30   File "/usr/local/lib/python3.7/logging/handlers.py", line 940, in emit#012    self.socket.sendto(msg, self.address)
2022-06-27 16:29:30 OSError: [Errno 9] Bad file descriptor
2022-06-27 16:29:30 #012During handling of the above exception, another exception occurred:
2022-06-27 16:29:30 Traceback (most recent call last):
2022-06-27 16:29:30   File "/usr/local/lib/python3.7/logging/handlers.py", line 940, in emit#012    self.socket.sendto(msg, self.address)
2022-06-27 16:29:30 OSError: [Errno 9] Bad file descriptor
2022-06-27 16:29:30 #012During handling of the above exception, another exception occurred:
2022-06-27 16:29:30 Traceback (most recent call last):
2022-06-27 16:29:30   File "/usr/local/lib/python3.7/logging/handlers.py", line 940, in emit#012    self.socket.sendto(msg, self.address)
2022-06-27 16:29:30 OSError: [Errno 9] Bad file descriptor
2022-06-27 16:29:30 #012During handling of the above exception, another exception occurred:
2022-06-27 16:29:30 Traceback (most recent call last):
2022-06-27 16:29:30   File "/usr/local/lib/python3.7/logging/handlers.py", line 940, in emit#012    self.socket.sendto(msg, self.address)
2022-06-27 16:29:30 OSError: [Errno 9] Bad file descriptor
etc....."

Until it finally stops writing to the log when it reaches max recursion depth:

2022-06-27 04:34:04   File "/usr/local/lib/python3.7/logging/__init__.py", line 1451, in findCaller#012    f = currentframe()
2022-06-27 04:34:04 RecursionError: maximum recursion depth exceeded

For example, here are counts of the numbers of messages written to the server log counted by time:

cut -f1,2 -d' ' /var/log/www.madapps.uk.server.log | uniq -c
      .....
      4 2022-06-27 16:29:25
     83 2022-06-27 16:29:30
    914 2022-06-27 16:29:31
  10082 2022-06-27 16:29:32
  13600 2022-06-27 16:29:33
  10945 2022-06-27 16:29:34
  13750 2022-06-27 16:29:35
   5653 2022-06-27 16:29:36
      2 2022-06-27 16:30:50
      3 2022-06-27 16:30:51
      4 2022-06-27 16:30:52
      4 2022-06-27 16:34:12
      .....etc

I've restarted the apps four times, and have further increased my file storage allowance, and deleted some old unused files, and added more exception catches to the scripts, but still haven't managed to stop this happening :(

That sort of thing is usually caused by calling django.setup in your web app, which closes all open file handles (including the one we need for the logs). It can also be caused by some other code that closes open file handles, though.

Thank you for explaining about the django.setup as the possible cause. I remember now that I had added a django.setup() line in one script to test the script locally at the command-line. I've removed that django.setup() line now, uploaded the script, restarted the webapps and the apps are logging messages to the error log again okay, and have stopped those 'Traceback .... OSError ...' messages. I hadn't realised the django.set() would close the log file handles, but that makes sense now. Thank you very much for your help.

Hey Guys, I am having the same issue. I called django.setup at some stage and now I have been getting these same logging errors. I have since removed the django.setup line from the script and restarted the webapp but these logging errors still persist. Is there something I can do to maybe reinitialise the logging system or to get the logging system back on track? Thanks

Reload fixes it. Are you sure that you do not have another instance of django.setup?

OK I double checked and I cannot find any other instances of django.setup. I went through the list of common issues in the link below and none of them seem to be the cause of the problem. It really looks like the issue described above but django.setup has been removed and the app has been restarted multiple times. Any other ideas of what could be causing this or how to resolve it? Thanks.
https://help.pythonanywhere.com/pages/502BadGateway/

The perhaps there is some other code in your web app that is closing all the file handles in the same way that django.setup does. The only way to track that down would be to remove installed apps one-by-one until the web app works. Then you have probably identified the code that is causing the problem.

I think I got to the bottom of the issue. We imported a script which called “application = get_wsgi_application()” into a django view. get_wsgi_application() calls django.setup() and because this being called inside an application it was generating the errors. Anyway it's all sorted now. Thanks for the help guys appreciate it, you are always super responsive across the forum and SO. Cheers.

Great! Glad you found it.