Neel
Reputation: 21315
enable socket level logging in uwsgi server
Applicaiton is running on uwsgi+DJango rest framework and there is httpd server in front of the uwsgi service.
httpd server forward the request to 127.0.0.1:9000 ProxyPass /myapi uwsgi://127.0.0.1:9000
There is uwsgi configuration in ini file.
myapi.ini
[uwsgi]
module=my.package.app.wsgi:application
master=True
pidfile=/tmp/uwsgi.pid
vacuum=True
max-requests=5000
socket=:9000
env=my.package.app.settings
processes=1
threads=1
buffer-size=16384
When we start service, we are able to get the response when we access direct 9000 port.
% curl -X GET http://my.domain.com:9000/api/v1/url/ -s -I
HTTP/1.1 200 OK
Content-Type: application/json
Allow: GET, HEAD, OPTIONS
Access-Control-Allow-Methods: GET, PUT, POST, DELETE, OPTIONS
Access-Control-Allow-Credentials: true
X-Frame-Options: DENY
Vary: Cookie
Content-Length: 18160
X-Content-Type-Options: nosniff
Referrer-Policy: same-origin
Cross-Origin-Opener-Policy: same-origin
Set-Cookie: csrftoken=XXXXXXXXX; Domain=.domain.com; expires=Thu, 22 Jan 2026 13:04:09 GMT; Max-Age=31449600; Path=/; SameSite=Lax
Set-Cookie: sessionid=YYYYYYYYY; expires=Thu, 06 Feb 2025 13:04:09 GMT; HttpOnly; Max-Age=1209600; Path=/; SameSite=Lax
I can see the uwsgi server log and see that, it get request for url.
$ sudo LOG_DIR=/tmp/ CONF_FILE_PATH=/home/user/sandy_conf.json ./myvirtualenv/bin/uwsgi --http-socket :9000 --honour-stdin --ini /home/user/sandy_corp.ini
[uWSGI] getting INI configuration from /home/user/myapi.ini
*** Starting uWSGI 2.0.27 (64bit) on [Thu Jan 23 13:04:01 2025] ***
compiled with version: 8.5.0 20210514 (Red Hat 8.5.0-22) on 22 January 2025 18:28:27
os: Linux-4.18.0-553.5.1.el8_10.x86_64 #1 SMP Tue May 21 03:13:04 EDT 2024
nodename: my.domain.com
machine: x86_64
clock source: unix
detected number of CPU cores: 2
current working directory: /home/user/virtualenvs
writing pidfile to /tmp/uwsgi.pid
detected binary path: /home/user/virtualenvs/myvirtualenv/bin/uwsgi
!!! no internal routing support, rebuild with pcre support !!!
uWSGI running as root, you can use --uid/--gid/--chroot options
*** WARNING: you are running uWSGI as root !!! (use the --uid flag) ***
your processes number limit is 30635
your memory page size is 4096 bytes
detected max file descriptor number: 1024
lock engine: pthread robust mutexes
thunder lock: disabled (you can enable it with --thunder-lock)
uwsgi socket 0 bound to TCP address :9000 fd 3
uWSGI running as root, you can use --uid/--gid/--chroot options
*** WARNING: you are running uWSGI as root !!! (use the --uid flag) ***
Python version: 3.12.1 (main, Feb 21 2024, 00:19:28) [GCC 8.5.0 20210514 (Red Hat 8.5.0-20)]
Python main interpreter initialized at 0x7f89ba9ba708
uWSGI running as root, you can use --uid/--gid/--chroot options
*** WARNING: you are running uWSGI as root !!! (use the --uid flag) ***
python threads support enabled
your server socket listen backlog is limited to 100 connections
your mercy for graceful operations on workers is 60 seconds
mapped 170384 bytes (166 KB) for 1 cores
*** Operational MODE: single process ***
WSGI app 0 (mountpoint='') ready in 2 seconds on interpreter 0x7f89ba9ba708 pid: 339122 (default app)
uWSGI running as root, you can use --uid/--gid/--chroot options
*** WARNING: you are running uWSGI as root !!! (use the --uid flag) ***
*** uWSGI is running in multiple interpreter mode ***
spawned uWSGI master process (pid: 339122)
spawned uWSGI worker 1 (pid: 339129, cores: 1)
DEBUG:my.package.api.authentication.middleware:Adding user user to the current request
DEBUG:my.package.api.authentication.middleware:Calling login() to set the django cookie
[pid: 339129|app: 0|req: 1/1] 10.42.149.46 () {24 vars in 339 bytes} [Thu Jan 23 13:04:09 2025] GET /api/v1/url/ => generated 18160 bytes in 630 msecs (HTTP/1.1 200) 12 headers in 645 bytes (1 switches on core 0)
httpd configure to validate SSL and its running on 443 so we have to send https request when we have to go through httpd.
That gives 500 error.
% curl -X GET --cert ~/.athenz/cert --key ~/.athenz/key https://my.domain.com/myapi/api/v1/url/ -s -I
HTTP/1.1 500 Internal Server Error
Date: Thu, 23 Jan 2025 13:06:34 GMT
P3P: policyref="https://policies.domain.com/w3c/p3p.xml", CP="CAO DSP COR CUR ADM DEV TAI PSA PSD IVAi IVDi CONi TELo OTPi OUR DELi SAMi OTRi UNRi PUBi IND PHY ONL UNI PUR FIN COM NAV INT DEM CNT STA POL HEA PRE LOC GOV"
Content-Length: 2983
Connection: close
Content-Type: text/html; charset=iso-8859-1
I enable the httpd-dumpio to see that, whats going on.
[Thu Jan 23 15:40:37.196107 2025] [ssl:info] [pid 347838:tid 347838] [client 127.0.0.1:59334] AH01964: Connection to child 0 established (server my.domain.com:443)
[Thu Jan 23 15:40:37.196565 2025] [dumpio:trace7] [pid 347838:tid 347838] mod_dumpio.c(135): [client 127.0.0.1:59334] mod_dumpio: dumpio_in [init-blocking] 0 readbytes
[Thu Jan 23 15:40:37.196796 2025] [ssl:debug] [pid 347838:tid 347838] ssl_engine_kernel.c(2391): [client 127.0.0.1:59334] AH02043: SSL virtual host for servername my.domain.com found
[Thu Jan 23 15:40:37.515885 2025] [ssl:debug] [pid 347838:tid 347838] ssl_engine_kernel.c(2251): [client 127.0.0.1:59334] AH02041: Protocol: TLSv1.2, Cipher: ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
[Thu Jan 23 15:40:37.516065 2025] [dumpio:trace7] [pid 347838:tid 347838] mod_dumpio.c(135): [client 127.0.0.1:59334] mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Thu Jan 23 15:40:37.830577 2025] [dumpio:trace7] [pid 347838:tid 347838] mod_dumpio.c(58): [client 127.0.0.1:59334] mod_dumpio: dumpio_in (data-TRANSIENT): 35 bytes
[Thu Jan 23 15:40:37.830677 2025] [dumpio:trace7] [pid 347838:tid 347838] mod_dumpio.c(100): [client 127.0.0.1:59334] mod_dumpio: dumpio_in (data-TRANSIENT): GET /myapi/api/v1/url/ HTTP/1.1
[Thu Jan 23 15:40:37.830761 2025] [dumpio:trace7] [pid 347838:tid 347838] mod_dumpio.c(135): [client 127.0.0.1:59334] mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Thu Jan 23 15:40:37.830792 2025] [dumpio:trace7] [pid 347838:tid 347838] mod_dumpio.c(58): [client 127.0.0.1:59334] mod_dumpio: dumpio_in (data-TRANSIENT): 48 bytes
[Thu Jan 23 15:40:37.830806 2025] [dumpio:trace7] [pid 347838:tid 347838] mod_dumpio.c(100): [client 127.0.0.1:59334] mod_dumpio: dumpio_in (data-TRANSIENT): Host: my.domain.com
[Thu Jan 23 15:40:37.830821 2025] [dumpio:trace7] [pid 347838:tid 347838] mod_dumpio.c(135): [client 127.0.0.1:59334] mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Thu Jan 23 15:40:37.830835 2025] [dumpio:trace7] [pid 347838:tid 347838] mod_dumpio.c(58): [client 127.0.0.1:59334] mod_dumpio: dumpio_in (data-TRANSIENT): 24 bytes
[Thu Jan 23 15:40:37.830848 2025] [dumpio:trace7] [pid 347838:tid 347838] mod_dumpio.c(100): [client 127.0.0.1:59334] mod_dumpio: dumpio_in (data-TRANSIENT): User-Agent: curl/8.7.1
[Thu Jan 23 15:40:37.830884 2025] [dumpio:trace7] [pid 347838:tid 347838] mod_dumpio.c(135): [client 127.0.0.1:59334] mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Thu Jan 23 15:40:37.830899 2025] [dumpio:trace7] [pid 347838:tid 347838] mod_dumpio.c(58): [client 127.0.0.1:59334] mod_dumpio: dumpio_in (data-TRANSIENT): 13 bytes
[Thu Jan 23 15:40:37.830913 2025] [dumpio:trace7] [pid 347838:tid 347838] mod_dumpio.c(100): [client 127.0.0.1:59334] mod_dumpio: dumpio_in (data-TRANSIENT): Accept: */*
[Thu Jan 23 15:40:37.830945 2025] [dumpio:trace7] [pid 347838:tid 347838] mod_dumpio.c(135): [client 127.0.0.1:59334] mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Thu Jan 23 15:40:37.830960 2025] [dumpio:trace7] [pid 347838:tid 347838] mod_dumpio.c(58): [client 127.0.0.1:59334] mod_dumpio: dumpio_in (data-TRANSIENT): 2 bytes
[Thu Jan 23 15:40:37.830974 2025] [dumpio:trace7] [pid 347838:tid 347838] mod_dumpio.c(100): [client 127.0.0.1:59334] mod_dumpio: dumpio_in (data-TRANSIENT):
[Thu Jan 23 15:40:37.832282 2025] [ssl:debug] [pid 347838:tid 347838] ssl_engine_kernel.c(415): [client 127.0.0.1:59334 {YRA:127.0.0.1:59334, YPA:127.0.0.1:59334}] AH02034: Initial (No.1) HTTPS request received for child 0 (server my.domain.com:443)
[Thu Jan 23 15:40:37.833054 2025] [proxy:trace2] [pid 347838:tid 347838] mod_proxy.c(848): [client 127.0.0.1:59334 {YRA:127.0.0.1:59334, YPA:127.0.0.1:59334}] AH03461: attempting to match URI path '/myapi/api/v1/url/' against prefix '/myapi' for proxying
[Thu Jan 23 15:40:37.833129 2025] [proxy:trace1] [pid 347838:tid 347838] mod_proxy.c(969): [client 127.0.0.1:59334 {YRA:127.0.0.1:59334, YPA:127.0.0.1:59334}] AH03464: URI path '/myapi/api/v1/url/' matches proxy handler 'proxy:uwsgi://127.0.0.1:9000/api/v1/url/'
[Thu Jan 23 15:40:37.836705 2025] [proxy:trace2] [pid 347838:tid 347838] proxy_util.c(2609): [client 127.0.0.1:59334 {YRA:127.0.0.1:59334, YPA:127.0.0.1:59334}] uwsgi: found worker uwsgi://127.0.0.1:9000 for uwsgi://127.0.0.1:9000/api/v1/url/
[Thu Jan 23 15:40:37.836797 2025] [proxy:debug] [pid 347838:tid 347838] mod_proxy.c(1465): [client 127.0.0.1:59334 {YRA:127.0.0.1:59334, YPA:127.0.0.1:59334}] AH01143: Running scheme uwsgi handler (attempt 0)
[Thu Jan 23 15:40:37.836851 2025] [proxy:debug] [pid 347838:tid 347838] proxy_util.c(2802): AH00942: uwsgi: has acquired connection for (127.0.0.1:9000)
[Thu Jan 23 15:40:37.836876 2025] [proxy:debug] [pid 347838:tid 347838] proxy_util.c(3247): [client 127.0.0.1:59334 {YRA:127.0.0.1:59334, YPA:127.0.0.1:59334}] AH00944: connecting uwsgi://127.0.0.1:9000/api/v1/url/ to 127.0.0.1:9000
[Thu Jan 23 15:40:37.837111 2025] [proxy:debug] [pid 347838:tid 347838] proxy_util.c(2910): [client 127.0.0.1:59334 {YRA:127.0.0.1:59334, YPA:127.0.0.1:59334}] AH10479: uwsgi: 127.0.0.1 resolved to 127.0.0.1:9000
[Thu Jan 23 15:40:37.837190 2025] [proxy:debug] [pid 347838:tid 347838] proxy_util.c(3455): [client 127.0.0.1:59334 {YRA:127.0.0.1:59334, YPA:127.0.0.1:59334}] AH00947: connecting /api/v1/url/ to 127.0.0.1:9000 (127.0.0.1:9000)
[Thu Jan 23 15:40:37.837302 2025] [proxy:trace2] [pid 347838:tid 347838] proxy_util.c(3904): uwsgi: fam 2 socket created for 127.0.0.1:9000 (127.0.0.1:9000)
[Thu Jan 23 15:40:37.837519 2025] [proxy:debug] [pid 347838:tid 347838] proxy_util.c(3961): AH02824: uwsgi: connection established with 127.0.0.1:9000 (127.0.0.1:9000)
[Thu Jan 23 15:40:37.837580 2025] [proxy:debug] [pid 347838:tid 347838] proxy_util.c(4149): AH00962: uwsgi: connection complete to 127.0.0.1:9000 (127.0.0.1)
[Thu Jan 23 15:40:37.837901 2025] [dumpio:trace7] [pid 347838:tid 347838] mod_dumpio.c(135): [remote 127.0.0.1:9000] mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Thu Jan 23 15:40:41.842664 2025] [proxy:debug] [pid 347838:tid 347838] proxy_util.c(2818): AH00943: uwsgi: has released connection for (127.0.0.1:9000)
[Thu Jan 23 15:40:41.843168 2025] [dumpio:trace7] [pid 347838:tid 347838] mod_dumpio.c(164): [client 127.0.0.1:59334] mod_dumpio: dumpio_out
[Thu Jan 23 15:40:41.843187 2025] [dumpio:trace7] [pid 347838:tid 347838] mod_dumpio.c(58): [client 127.0.0.1:59334] mod_dumpio: dumpio_out (data-HEAP): 73 bytes
[Thu Jan 23 15:40:41.843193 2025] [dumpio:trace7] [pid 347838:tid 347838] mod_dumpio.c(100): [client 127.0.0.1:59334] mod_dumpio: dumpio_out (data-HEAP): HTTP/1.1 500 Internal Server Error
Date: Thu, 23 Jan 2025 15:40:37 GMT
[Thu Jan 23 15:40:41.843206 2025] [dumpio:trace7] [pid 347838:tid 347838] mod_dumpio.c(58): [client 127.0.0.1:59334] mod_dumpio: dumpio_out (data-HEAP): 309 bytes
[Thu Jan 23 15:40:41.843210 2025] [dumpio:trace7] [pid 347838:tid 347838] mod_dumpio.c(100): [client 127.0.0.1:59334] mod_dumpio: dumpio_out (data-HEAP): P3P: policyref="https://policies.company.com/w3c/p3p.xml", CP="CAO DSP COR CUR ADM DEV TAI PSA PSD IVAi IVDi CONi TELo OTPi OUR DELi SAMi OTRi UNRi PUBi IND PHY ONL UNI PUR FIN COM NAV INT DEM CNT STA POL HEA PRE LOC GOV"
Content-Length: 2983
Connection: close
Content-Type: text/html; charset=iso-8859-1
[Thu Jan 23 15:40:41.843236 2025] [dumpio:trace7] [pid 347838:tid 347838] mod_dumpio.c(164): [client 127.0.0.1:59334] mod_dumpio: dumpio_out
[Thu Jan 23 15:40:41.843240 2025] [dumpio:trace7] [pid 347838:tid 347838] mod_dumpio.c(58): [client 127.0.0.1:59334] mod_dumpio: dumpio_out (data-HEAP): 2983 bytes
[Thu Jan 23 15:40:41.843244 2025] [dumpio:trace7] [pid 347838:tid 347838] mod_dumpio.c(100): [client 127.0.0.1:59334] mod_dumpio: dumpio_out (data-HEAP): <!doctype html public "-//W3C//DTD HTML 4.01//EN" "http://www.w3.org/TR/html4/strict.dtd">
<html><head><title>Company - 500 Internal Server Error</title><style>
BIGHTML</html>
[Thu Jan 23 15:40:41.843259 2025] [dumpio:trace7] [pid 347838:tid 347838] mod_dumpio.c(58): [client 127.0.0.1:59334] mod_dumpio: dumpio_out (metadata-EOS): 0 bytes
[Thu Jan 23 15:40:41.843339 2025] [dumpio:trace7] [pid 347838:tid 347838] mod_dumpio.c(164): [client 127.0.0.1:59334] mod_dumpio: dumpio_out
[Thu Jan 23 15:40:41.843346 2025] [dumpio:trace7] [pid 347838:tid 347838] mod_dumpio.c(58): [client 127.0.0.1:59334] mod_dumpio: dumpio_out (metadata-EOR): 0 bytes
E 23-154041.856997 347838 ks keyname='tcookie-validate.ks-secret', kt keyname='tcookie-validate.kt-secret', ku keyname='tcookie-validate.ku-secret' - lookup failed no key found
[Thu Jan 23 15:40:41.857099 2025] [dumpio:trace7] [pid 347838:tid 347838] mod_dumpio.c(164): [client 127.0.0.1:59334] mod_dumpio: dumpio_out
[Thu Jan 23 15:40:41.857108 2025] [dumpio:trace7] [pid 347838:tid 347838] mod_dumpio.c(58): [client 127.0.0.1:59334] mod_dumpio: dumpio_out (metadata-FLUSH): 0 bytes
[Thu Jan 23 15:40:41.857126 2025] [dumpio:trace7] [pid 347838:tid 347838] mod_dumpio.c(164): [client 127.0.0.1:59334] mod_dumpio: dumpio_out
[Thu Jan 23 15:40:41.857130 2025] [dumpio:trace7] [pid 347838:tid 347838] mod_dumpio.c(58): [client 127.0.0.1:59334] mod_dumpio: dumpio_out (metadata-FLUSH): 0 bytes
[Thu Jan 23 15:40:41.857134 2025] [dumpio:trace7] [pid 347838:tid 347838] mod_dumpio.c(58): [client 127.0.0.1:59334] mod_dumpio: dumpio_out (metadata-EOC): 0 bytes
==> /var/log/httpd/access <==
0a2a9555679262f9003d3a8100000ba7/myapi/api/v1/url/Z34bAB59334wmy.domain.comgcurl/8.7.1Ktext/html; charset=iso-8859-1mGETvdnt!s500e500 Internal Server ErrorVPon
==> /var/log/httpd/error <==
[Thu Jan 23 15:40:41.857190 2025] [ssl:debug] [pid 347838:tid 347838] ssl_engine_io.c(1150): [client 127.0.0.1:59334] AH02001: Connection closed to child 0 with standard shutdown (server my.domain.com:443)
From the log, we can see that, it establish the connection to 127.0.0.1:9000
[Thu Jan 23 15:40:37.836851 2025] [proxy:debug] [pid 347838:tid 347838] proxy_util.c(2802): AH00942: uwsgi: has acquired connection for (127.0.0.1:9000)
[Thu Jan 23 15:40:37.836876 2025] [proxy:debug] [pid 347838:tid 347838] proxy_util.c(3247): [client 127.0.0.1:59334 {YRA:127.0.0.1:59334, YPA:127.0.0.1:59334}] AH00944: connecting uwsgi://127.0.0.1:9000/api/v1/url/ to 127.0.0.1:9000
[Thu Jan 23 15:40:37.837111 2025] [proxy:debug] [pid 347838:tid 347838] proxy_util.c(2910): [client 127.0.0.1:59334 {YRA:127.0.0.1:59334, YPA:127.0.0.1:59334}] AH10479: uwsgi: 127.0.0.1 resolved to 127.0.0.1:9000
[Thu Jan 23 15:40:37.837190 2025] [proxy:debug] [pid 347838:tid 347838] proxy_util.c(3455): [client 127.0.0.1:59334 {YRA:127.0.0.1:59334, YPA:127.0.0.1:59334}] AH00947: connecting /api/v1/url/ to 127.0.0.1:9000 (127.0.0.1:9000)
But after that it return 500 error.
[Thu Jan 23 15:40:41.843187 2025] [dumpio:trace7] [pid 347838:tid 347838] mod_dumpio.c(58): [client 127.0.0.1:59334] mod_dumpio: dumpio_out (data-HEAP): 73 bytes
[Thu Jan 23 15:40:41.843193 2025] [dumpio:trace7] [pid 347838:tid 347838] mod_dumpio.c(100): [client 127.0.0.1:59334] mod_dumpio: dumpio_out (data-HEAP): HTTP/1.1 500 Internal Server Error
I check the uwsgi server log, there is no logging on uwsgi server side. Means its establish the connection, but not reach to the point where it log the message.
I also get the tcpdump using tcpdump -i lo -w /tmp/dump.out port 9000 command.
We can see that it get connection.
15:15:59.963640 IP localhost.33654 > localhost.cslistener: Flags [P.], seq 1:3150, ack 1, win 342, options [nop,nop,TS val 812262926 ecr 812262926], length 3149
ACK data
15:15:59.963668 IP localhost.cslistener > localhost.33654: Flags [.], ack 3150, win 1365, options [nop,nop,TS val 812262926 ecr 812262926], length 0
But then close the connection.
15:16:03.968266 IP localhost.cslistener > localhost.33654: Flags [F.], seq 1, ack 3150, win 1365, options [nop,nop,TS val 812266931 ecr 812262926], length 0
Is there any way to enable loggin on uwsgi side to know that, packets reach to the uwsgi server?
Upvotes: 0
Views: 17