Forums

Don't understand those server logs

Hi,

I am new into this world, so please accept my apologies if my question is dumb. I have a dash app set up on pythonAnywhere. The app has to do a lot of processing on the dataset when it starts - which is alright as long as it stays "on".

Today I visited the app after a day without any visit, but the page took more than 1 min to load, and I can see in the server log that it had to do all the data processing again, meaning that the python script ran again when I accessed the page.

Why isn't my app staying active ? I don't want to have to wait for the python script to be executed to be able to visit the website after some time without any visit.

Here is the log for my connection this afternoon :

2022-11-22 08:35:55 announcing my loyalty to the Emperor...
2022-11-23 10:36:03 workers have been inactive for more than 93600 seconds (1669199757-1669106156)
2022-11-23 10:36:03 cheap mode enabled: waiting for socket connection...
2022-11-23 13:48:20 *** Starting uWSGI 2.0.20 (64bit) on [Wed Nov 23 13:46:21 2022] ***
2022-11-23 13:48:20 compiled with version: 9.4.0 on 22 July 2022 18:35:26
2022-11-23 13:48:20 os: Linux-5.15.0-1015-aws #19~20.04.1-Ubuntu SMP Wed Jun 22 19:07:51 UTC 2022
2022-11-23 13:48:20 nodename: blue-euweb2
2022-11-23 13:48:20 machine: x86_64
2022-11-23 13:48:20 clock source: unix
2022-11-23 13:48:20 pcre jit disabled
2022-11-23 13:48:20 detected number of CPU cores: 4
2022-11-23 13:48:20 current working directory: /home/albanpuech
2022-11-23 13:48:20 detected binary path: /usr/local/bin/uwsgi
2022-11-23 13:48:20 *** dumping internal routing table ***
2022-11-23 13:48:20 [rule: 0] subject: path_info regexp: \.svgz$ action: addheader:Content-Encoding:gzip
2022-11-23 13:48:20 *** end of the internal routing table ***
2022-11-23 13:48:20 chdir() to /home/albanpuech/
2022-11-23 13:48:20 your processes number limit is 256
2022-11-23 13:48:20 your memory page size is 4096 bytes
2022-11-23 13:48:20 detected max file descriptor number: 123456
2022-11-23 13:48:20 building mime-types dictionary from file /etc/mime.types...
2022-11-23 13:48:20 567 entry found
2022-11-23 13:48:20 lock engine: pthread robust mutexes
2022-11-23 13:48:20 thunder lock: disabled (you can enable it with --thunder-lock)
2022-11-23 13:48:20 uwsgi socket 0 bound to UNIX address /var/sockets/albanpuech.eu.pythonanywhere.com/socket fd 3
2022-11-23 13:48:20 Python version: 3.10.5 (main, Jul 22 2022, 17:09:35) [GCC 9.4.0]
2022-11-23 13:48:20 PEP 405 virtualenv detected: /home/albanpuech/.virtualenvs/dashappenv/
2022-11-23 13:48:20 Set PythonHome to /home/albanpuech/.virtualenvs/dashappenv/
2022-11-23 13:48:20 *** Python threads support is disabled. You can enable it with --enable-threads ***
2022-11-23 13:48:20 Python main interpreter initialized at 0x55cb62db8e70
2022-11-23 13:48:20 your server socket listen backlog is limited to 100 connections
2022-11-23 13:48:20 your mercy for graceful operations on workers is 60 seconds
2022-11-23 13:48:20 setting request body buffering size to 65536 bytes
2022-11-23 13:48:20 mapped 501384 bytes (489 KB) for 2 cores
2022-11-23 13:48:20 *** Operational MODE: preforking ***
2022-11-23 13:48:20 initialized 54 metrics
2022-11-23 13:48:20 /home/albanpuech/dashboard.py:73: FutureWarning: The default value of numeric_only in DataFrameGroupBy.mean is deprecated. In a future version, numeric_only will default to False. Either specify numeric_only or select only columns which should be valid for the function.#012  df_daily_cp = df_daily_cp[["country", "day", "capacity_factor", "timestamp"]].groupby(["country", "timestamp"]).mean().reset_index()
2022-11-23 13:48:20 /home/albanpuech/dashboard.py:81: FutureWarning: The default value of numeric_only in DataFrameGroupBy.mean is deprecated. In a future version, numeric_only will default to False. Either specify numeric_only or select only columns which should be valid for the function.#012  daily_cp_eu = df_daily_cp.groupby("timestamp").mean().reset_index()
2022-11-23 13:48:20 WSGI app 0 (mountpoint='') ready in 118 seconds on interpreter 0x55cb62db8e70 pid: 1 (default app)
2022-11-23 13:48:20 *** uWSGI is running in multiple interpreter mode ***
2022-11-23 13:48:20 gracefully (RE)spawned uWSGI master process (pid: 1)
2022-11-23 13:48:20 spawned uWSGI worker 1 (pid: 5, cores: 1)
2022-11-23 13:48:20 spawned 2 offload threads for uWSGI worker 1
2022-11-23 13:48:20 spawned uWSGI worker 2 (pid: 8, cores: 1)
2022-11-23 13:48:20 metrics collector thread started
2022-11-23 13:48:20 spawned 2 offload threads for uWSGI worker 2
2022-11-23 13:48:21 Wed Nov 23 13:48:21 2022 - SIGPIPE: writing to a closed pipe/socket/fd (probably the client disconnected) on request / (ip 10.0.0.49) !!!
2022-11-23 13:48:21 Wed Nov 23 13:48:21 2022 - uwsgi_response_writev_headers_and_body_do(): Broken pipe [core/writer.c line 306] during GET / (10.0.0.49)
2022-11-23 13:48:21 announcing my loyalty to the Emperor...
2022-11-23 13:48:21 Wed Nov 23 13:48:21 2022 - SIGPIPE: writing to a closed pipe/socket/fd (probably the client disconnected) on request / (ip 10.0.0.49) !!!
2022-11-23 13:48:21 Wed Nov 23 13:48:21 2022 - uwsgi_response_writev_headers_and_body_do(): Broken pipe [core/writer.c line 306] during GET / (10.0.0.49)
2022-11-23 13:48:21 announcing my loyalty to the Emperor...

Can you please help me to make sure that the app always stays active and that I don't need to wait for it to load when I visit the page after a period of inactivity ?

Thank you very much in advance.

Alban

Hi Alban -- sometimes websites have to be restarted; for example, they might have to be moved from one server to another due to load, or the server itself might have problems. Normally one would write a website so that restarting it isn't an expensive operation -- for example, the data that it presents to users would be calculated outside the website itself, and perhaps cached in a file or a database.

Hi Giles, thanks for your answer.

I understand that the website sometimes has to be restarted. However, I don't understand why my website has to start when I access it. This is what the server log file looks like when I tried to access my website this evening :

2022-11-24 18:57:30 *** Starting uWSGI 2.0.20 (64bit) on [Thu Nov 24 18:56:23 2022] ***
2022-11-24 18:57:30 compiled with version: 9.4.0 on 22 July 2022 18:35:26
2022-11-24 18:57:30 os: Linux-5.15.0-1015-aws #19~20.04.1-Ubuntu SMP Wed Jun 22 19:07:51 UTC 2022
2022-11-24 18:57:30 nodename: blue-euweb2
2022-11-24 18:57:30 machine: x86_64
2022-11-24 18:57:30 clock source: unix
2022-11-24 18:57:30 pcre jit disabled
2022-11-24 18:57:30 detected number of CPU cores: 4
2022-11-24 18:57:30 current working directory: /home/albanpuech
2022-11-24 18:57:30 detected binary path: /usr/local/bin/uwsgi
2022-11-24 18:57:30 *** dumping internal routing table ***
2022-11-24 18:57:30 [rule: 0] subject: path_info regexp: \.svgz$ action: addheader:Content-Encoding:gzip
2022-11-24 18:57:30 *** end of the internal routing table ***
2022-11-24 18:57:30 chdir() to /home/albanpuech/
2022-11-24 18:57:30 your processes number limit is 256
2022-11-24 18:57:30 your memory page size is 4096 bytes
2022-11-24 18:57:30 detected max file descriptor number: 123456
2022-11-24 18:57:30 building mime-types dictionary from file /etc/mime.types...
2022-11-24 18:57:30 567 entry found
2022-11-24 18:57:30 lock engine: pthread robust mutexes
2022-11-24 18:57:30 thunder lock: disabled (you can enable it with --thunder-lock)
2022-11-24 18:57:30 uwsgi socket 0 bound to UNIX address /var/sockets/albanpuech.eu.pythonanywhere.com/socket fd 3
2022-11-24 18:57:30 Python version: 3.10.5 (main, Jul 22 2022, 17:09:35) [GCC 9.4.0]
2022-11-24 18:57:30 PEP 405 virtualenv detected: /home/albanpuech/.virtualenvs/dashappenv/
2022-11-24 18:57:30 Set PythonHome to /home/albanpuech/.virtualenvs/dashappenv/
2022-11-24 18:57:30 *** Python threads support is disabled. You can enable it with --enable-threads ***
2022-11-24 18:57:30 Python main interpreter initialized at 0x556828a5ee70
2022-11-24 18:57:30 your server socket listen backlog is limited to 100 connections
2022-11-24 18:57:30 your mercy for graceful operations on workers is 60 seconds
2022-11-24 18:57:30 setting request body buffering size to 65536 bytes
2022-11-24 18:57:30 mapped 501384 bytes (489 KB) for 2 cores
2022-11-24 18:57:30 *** Operational MODE: preforking ***
2022-11-24 18:57:30 initialized 54 metrics
2022-11-24 18:57:30 /home/albanpuech/dashboard.py:73: FutureWarning: The default value of numeric_only in DataFrameGroupBy.mean is deprecated. In a future version, numeric_only will default to False. Either specify numeric_only or select only columns which should be valid for the function.#012  df_daily_cp = df_daily_cp[["country", "day", "capacity_factor", "timestamp","year"]].groupby(["country", "timestamp"]).mean().reset_index()
2022-11-24 18:57:30 /home/albanpuech/dashboard.py:81: FutureWarning: The default value of numeric_only in DataFrameGroupBy.mean is deprecated. In a future version, numeric_only will default to False. Either specify numeric_only or select only columns which should be valid for the function.#012  daily_cp_eu_entire_period = df_daily_cp.groupby("timestamp").mean().reset_index()
2022-11-24 18:57:30 WSGI app 0 (mountpoint='') ready in 66 seconds on interpreter 0x556828a5ee70 pid: 1 (default app)
2022-11-24 18:57:30 *** uWSGI is running in multiple interpreter mode ***
2022-11-24 18:57:30 gracefully (RE)spawned uWSGI master process (pid: 1)
2022-11-24 18:57:30 spawned uWSGI worker 1 (pid: 5, cores: 1)
2022-11-24 18:57:30 spawned 2 offload threads for uWSGI worker 1
2022-11-24 18:57:30 spawned uWSGI worker 2 (pid: 8, cores: 1)
2022-11-24 18:57:30 metrics collector thread started
2022-11-24 18:57:30 spawned 2 offload threads for uWSGI worker 2
2022-11-24 18:57:30 Thu Nov 24 18:57:30 2022 - SIGPIPE: writing to a closed pipe/socket/fd (probably the client disconnected) on request / (ip 10.0.0.49) !!!
2022-11-24 18:57:30 Thu Nov 24 18:57:30 2022 - uwsgi_response_writev_headers_and_body_do(): Broken pipe [core/writer.c line 306] during GET / (10.0.0.49)
2022-11-24 18:57:30 announcing my loyalty to the Emperor...
2022-11-24 18:57:30 Thu Nov 24 18:57:30 2022 - SIGPIPE: writing to a closed pipe/socket/fd (probably the client disconnected) on request / (ip 10.0.0.49) !!!

This is the error log :

2022-11-24 18:57:30,748: OSError: write error
2022-11-24 18:57:32,427: /home/albanpuech/dashboard.py:358: FutureWarning:
2022-11-24 18:57:32,427: 
2022-11-24 18:57:32,427: The default value of numeric_only in DataFrameGroupBy.mean is deprecated. In a future version, numeric_only will default to False. Either specify numeric_only or select only columns which should be valid for the function.
2022-11-24 18:57:32,427:

As you can see there is an "OSError: write error" when I access the website and I am pretty sure that it doesn't come from the code.

Thanks in advance for your help

If there's no much traffic on a web app, after a server reboot it waits for a first hit to be loaded -- it could've been the case when you accessed your web app on yesterday evening. You could try hitting the web app again and check if the uWSGI process restarts (it shouldn't). The writing to a closed pipe/socket/fd message means that the client disconnected -- did you reload the browser tab while waiting for the web app to load?

Yes I did reload it - I guess that's why I got this message. Is there a way I can automatically load the website after a server reboot so that it is already loaded when someone tries to access it ?

There's no way to do that specifically, but you could perhaps create a schedule task to hit it periodically?

I would suggest that you change the code to make it start up faster, though. It's generally regarded as best practice to make server-side code start quickly.