Django ASGI: Invalid ASGI message after request body: http.request

[codedoga]

Bug Overview

This is the regular django ASGI app with simple function based view.

If I try to send POST/PUT with body I will get this exception and 503 response:

2025/02/16 11:07:14 [error] 6#6 [unit] #9: Python failed to call 'future.result()'
Traceback (most recent call last):
  File "/usr/local/lib/python3.13/site-packages/django/core/handlers/asgi.py", line 162, in __call__
    await self.handle(scope, receive, send)
  File "/usr/local/lib/python3.13/site-packages/django/core/handlers/asgi.py", line 208, in handle
    task.result()
    ~~~~~~~~~~~^^
  File "/usr/local/lib/python3.13/site-packages/django/core/handlers/asgi.py", line 239, in listen_for_disconnect
    assert False, "Invalid ASGI message after request body: %s" % message["type"]
           ^^^^^
AssertionError: Invalid ASGI message after request body: http.request

This is the repo with example project:
https://github.com/codedoga/nginx_unit_asgi_django

Expected Behavior

The same code works perfectly well with uvicorn and granian so I would expect it to also work with Unit

Steps to Reproduce the Bug

1. Build and run docker container

curl --fail -X "PUT" "http://localhost:8000" -d "test"
curl --fail -X "POST" "http://localhost:8000" -d "test"

Environment Details

• Target deployment platform: any docker capable
• Target OS: Debian/Ubuntu/Alpine
• Version of this project or specific commit: 0.1
• Version of any relevant project languages: I tried with Unit versions from 1.29.1 to 1.34.1/Python 3.11 - 3.13
• django>=5

Additional Context

Debug log:

2025/02/16 11:27:33.426 [debug] 4#8 epoll_wait(20): 1
2025/02/16 11:27:33.426 [debug] 4#8 epoll: fd:14 ev:0001 d:FFFFAC001450 rd:5 wr:0
2025/02/16 11:27:33.426 [debug] 4#8 timer expire minimum: 485363883:398971315
2025/02/16 11:27:33.426 [debug] 4#8 work queue: accept
2025/02/16 11:27:33.426 [debug] 4#8 accept4(14): 48
2025/02/16 11:27:33.426 [debug] 4#8 client: 192.168.127.1
2025/02/16 11:27:33.426 [debug] 4#8 malloc(168): FFFFAC0028A0
2025/02/16 11:27:33.426 [debug] 4#8 posix_memalign(16, 464): FFFFAC002950
2025/02/16 11:27:33.426 [debug] 4#8 *20 connections: 2
2025/02/16 11:27:33.426 [debug] 4#8 work queue: accept
2025/02/16 11:27:33.426 [debug] 4#8 accept4(14) (11: Resource temporarily unavailable)
2025/02/16 11:27:33.426 [debug] 4#8 work queue: read
2025/02/16 11:27:33.426 [debug] 4#8 *9 http conn init
2025/02/16 11:27:33.426 [debug] 4#8 work queue: read
2025/02/16 11:27:33.426 [debug] 4#8 *9 conn read fd:48 rdy:0 cl:0 er:0 bl:0
2025/02/16 11:27:33.426 [debug] 4#8 *9 epoll 20 set event: fd:48 op:1 ev:80002001
I2025/02/16 11:27:33.426 [debug] 4#8 *9 timer add: 0±50 180000:399151315
E2025/02/16 11:27:33.426 [debug] 4#8 *9 timer change: 399151315±50:1
2025/02/16 11:27:33.426 [debug] 4#8 timers changes: 1
J2025/02/16 11:27:33.426 [debug] 4#8 *9 timer rbtree insert: 399151315±50
T2025/02/16 11:27:33.426 [debug] 4#8 *9 timer found minimum: 399151315±50:398971315
2025/02/16 11:27:33.426 [debug] 4#8 epoll 20 changes:1
2025/02/16 11:27:33.426 [debug] 4#8 *9 epoll_ctl(20): fd:48 op:1 ev:80002001
2025/02/16 11:27:33.426 [debug] 4#8 epoll_wait(20) timeout:180000
2025/02/16 11:27:33.426 [debug] 4#8 epoll_wait(20): 1
2025/02/16 11:27:33.426 [debug] 4#8 *9 epoll: fd:48 ev:0001 d:FFFFAC001600 rd:5 wr:0
2025/02/16 11:27:33.426 [debug] 4#8 timer expire minimum: 399151265:398971315
2025/02/16 11:27:33.426 [debug] 4#8 work queue: read
2025/02/16 11:27:33.426 [debug] 4#8 *9 conn read fd:48 rdy:1 cl:0 er:0 bl:0
2025/02/16 11:27:33.426 [debug] 4#8 posix_memalign(16, 2160): FFFFAC002B30
2025/02/16 11:27:33.426 [debug] 4#8 recvbuf: 0, FFFFAC002B78, 2048
2025/02/16 11:27:33.426 [debug] 4#8 *9 recv(48, FFFFAC002B78, 2048, 0x0): 150
2025/02/16 11:27:33.426 [debug] 4#8 *9 timer disable: 399151315
2025/02/16 11:27:33.426 [debug] 4#8 work queue: fast
2025/02/16 11:27:33.426 [debug] 4#8 *9 h1p conn proto init
2025/02/16 11:27:33.426 [debug] 4#8 malloc(136): FFFFAC002810
2025/02/16 11:27:33.426 [debug] 4#8 posix_memalign(128, 1024): FFFFAC003400
2025/02/16 11:27:33.426 [debug] 4#8 *9 h1p conn request init
2025/02/16 11:27:33.426 [debug] 4#8 malloc(184): FFFFAC003870
2025/02/16 11:27:33.426 [debug] 4#8 posix_memalign(16, 656): FFFFAC003930
2025/02/16 11:27:33.426 [debug] 4#8 malloc(232): FFFFAC003BD0
2025/02/16 11:27:33.426 [debug] 4#8 posix_memalign(128, 4096): FFFFAC003D00
2025/02/16 11:27:33.426 [debug] 4#8 *9 h1p conn header parse
2025/02/16 11:27:33.426 [debug] 4#8 *9 timer disable: 399151315
2025/02/16 11:27:33.426 [debug] 4#8 *9 h1p request body read 4 te:0
2025/02/16 11:27:33.426 [debug] 4#8 *9 h1p body rest: 0
2025/02/16 11:27:33.426 [debug] 4#8 *9 http application handler
2025/02/16 11:27:33.426 [debug] 4#8 posix_memalign(128, 128): FFFFAC004D80
2025/02/16 11:27:33.426 [debug] 4#8 *9 rpc: stream #9 registered
2025/02/16 11:27:33.426 [debug] 4#8 mp FFFFAC003870 retain: 2
2025/02/16 11:27:33.426 [debug] 4#8 pthread_mutex_lock(AAAAE6854200) enter
2025/02/16 11:27:33.426 [debug] 4#8 pthread_mutex_unlock(AAAAE6854200) exit
2025/02/16 11:27:33.426 [debug] 4#8 mp FFFFAC003870 retain: 3
2025/02/16 11:27:33.426 [debug] 4#8 *9 request 351 bytes shm buffer
2025/02/16 11:27:33.426 [debug] 4#8 mp FFFFAC000BC0 retain: 2
2025/02/16 11:27:33.426 [debug] 4#8 pthread_mutex_lock(AAAAE6854340) enter
2025/02/16 11:27:33.426 [debug] 4#8 malloc(24): FFFFAC0017E0
2025/02/16 11:27:33.426 [debug] 4#8 realloc(0, 8): FFFFAC000F60
2025/02/16 11:27:33.426 [debug] 4#8 *9 memfd_create(/unit.4.e79c731a): 49
2025/02/16 11:27:33.426 [debug] 4#8 mmap(0, 10489856, 3, 1, 49, 0): FFFFB06F7000
2025/02/16 11:27:33.426 [debug] 4#8 *9 new mmap #0 created for 4 -> ...
2025/02/16 11:27:33.426 [debug] 4#8 pthread_mutex_unlock(AAAAE6854340) exit
2025/02/16 11:27:33.426 [debug] 4#8 *9 outgoing mmap buf allocation: FFFFAC001880 [FFFFB06F8000,16384] 4->0,0,0
2025/02/16 11:27:33.426 [debug] 4#8 *9 fields_count=5
2025/02/16 11:27:33.426 [debug] 4#8 *9 add field 0xE6EB, 0, 4, FFFFAC002B89 : 14 FFFFAC002B8F
2025/02/16 11:27:33.426 [debug] 4#8 *9 add field 0x0220, 0, 10, FFFFAC002B9F : 10 FFFFAC002BAB
2025/02/16 11:27:33.426 [debug] 4#8 *9 add field 0xD871, 0, 6, FFFFAC002BB7 : 3 FFFFAC002BBF
2025/02/16 11:27:33.426 [debug] 4#8 *9 add field 0x1EA0, 0, 14, FFFFAC002BC4 : 1 FFFFAC002BD4
2025/02/16 11:27:33.426 [debug] 4#8 *9 add field 0x5F7D, 0, 12, FFFFAC002BD7 : 33 FFFFAC002BE5
2025/02/16 11:27:33.426 [debug] 4#8 *9 about to send 351 bytes buffer to app process port 12
2025/02/16 11:27:33.426 [debug] 4#8 pthread_mutex_lock(AAAAE682EA20) enter
2025/02/16 11:27:33.426 [debug] 4#8 pthread_mutex_unlock(AAAAE682EA20) exit
2025/02/16 11:27:33.426 [debug] 4#8 sendmsg(12, -1, -1, 1): 16
2025/02/16 11:27:33.426 [debug] 4#8 epoll_wait(20) timeout:-1
2025/02/16 11:27:33.428 [debug] 6#6 [unit] app_queue_recv: 28
2025/02/16 11:27:33.428 [debug] 6#6 [unit] #9: process message 23 fd[0] -1 fd[1] -1
2025/02/16 11:27:33.428 [debug] 6#6 [unit] get_mmap: 4 0
2025/02/16 11:27:33.428 [debug] 6#6 [unit] sendmsg(13, 20, 0): 20
2025/02/16 11:27:33.428 [debug] 6#6 [unit] port{4,0} sendmsg 20
2025/02/16 11:27:33.428 [debug] 6#6 [unit] asgi_port_read(0xaaaae7075340,0xaaaae694fd80): 0
2025/02/16 11:27:33.427 [debug] 4#4 epoll_wait(3): 1
2025/02/16 11:27:33.427 [debug] 4#4 epoll: fd:10 ev:0001 d:AAAAE68363A0 rd:5 wr:0
2025/02/16 11:27:33.427 [debug] 4#4 timer expire minimum: 485363883:398971316
2025/02/16 11:27:33.427 [debug] 4#4 work queue: fast
2025/02/16 11:27:33.427 [debug] 4#4 recvmsg(10, 2, 32): 20
2025/02/16 11:27:33.427 [debug] 4#4 port 10: message type:17 fds:-1,-1
2025/02/16 11:27:33.427 [debug] 4#4 process port (6, 0) found
2025/02/16 11:27:33.427 [debug] 4#4 pthread_mutex_lock(AAAAE6854340) enter
2025/02/16 11:27:33.427 [debug] 4#4 pthread_mutex_unlock(AAAAE6854340) exit
2025/02/16 11:27:33.427 [debug] 4#4 get mmap 6:0 found
2025/02/16 11:27:33.427 [debug] 4#4 port{6,0} 16: enqueue 1 notify 1, 0
2025/02/16 11:27:33.427 [debug] 4#4 pthread_mutex_lock(AAAAE6867120) enter
2025/02/16 11:27:33.427 [debug] 4#4 pthread_mutex_unlock(AAAAE6867120) exit
2025/02/16 11:27:33.427 [debug] 4#4 sendmsg(16, 49, -1, 1): 16
2025/02/16 11:27:33.427 [debug] 4#4 recvmsg(10, 2, 32): -1
2025/02/16 11:27:33.427 [debug] 4#4 recvmsg(10) not ready
2025/02/16 11:27:33.427 [debug] 4#4 epoll 3 set event: fd:10 op:3 ev:80002001
2025/02/16 11:27:33.428 [debug] 6#6 [unit] app_queue_recv: -1
2025/02/16 11:27:33.427 [debug] 4#4 epoll 3 changes:1
2025/02/16 11:27:33.427 [debug] 4#4 epoll_ctl(3): fd:10 op:3 ev:80002001
2025/02/16 11:27:33.427 [debug] 4#4 epoll_wait(3) timeout:-1
2025/02/16 11:27:33.428 [debug] 6#6 [unit] recvmsg(10): 16
2025/02/16 11:27:33.428 [debug] 6#6 [unit] port{6,65535} recv 16 read_queue
2025/02/16 11:27:33.428 [debug] 6#6 [unit] app_queue_recv: -1
2025/02/16 11:27:33.428 [debug] 6#6 [unit] recvmsg(10) failed: Resource temporarily unavailable (11)
2025/02/16 11:27:33.428 [debug] 6#6 [unit] asgi_port_read(0xaaaae7075340,0xaaaae694fd80): 2
2025/02/16 11:27:33.428 [debug] 6#6 [unit] app_queue_recv: -1
2025/02/16 11:27:33.428 [debug] 6#6 [unit] recvmsg(10) failed: Resource temporarily unavailable (11)
2025/02/16 11:27:33.428 [debug] 6#6 [unit] asgi_port_read(0xaaaae7075340,0xaaaae694fd80): 2
2025/02/16 11:27:33.428 [debug] 6#6 [unit] port{6,0} dequeue 1 read_socket 1
2025/02/16 11:27:33.429 [debug] 6#6 [unit] recvmsg(8): 16
2025/02/16 11:27:33.429 [debug] 6#6 [unit] port{6,0} recvmsg 16
2025/02/16 11:27:33.429 [debug] 6#6 [unit] #0: process message 16 fd[0] 11 fd[1] -1
2025/02/16 11:27:33.429 [debug] 6#6 [unit] incoming_mmap: fd 11 from process 4
2025/02/16 11:27:33.429 [debug] 6#6 [unit] close(11): 0
2025/02/16 11:27:33.429 [debug] 6#6 [unit] #9: process message 23 fd[0] -1 fd[1] -1
2025/02/16 11:27:33.429 [debug] 6#6 [unit] #9: mmap_read: [0xffffb1013000,351] 4->0,(0,0,351)
2025/02/16 11:27:33.429 [debug] 6#6 [unit] #9: POST / (4)
2025/02/16 11:27:33.429 [debug] 6#6 [unit] get_port: 4 3
2025/02/16 11:27:33.429 [debug] 6#6 [unit] sendmsg(13, 24, 0): 24
2025/02/16 11:27:33.429 [debug] 6#6 [unit] port{4,0} sendmsg 24
2025/02/16 11:27:33.429 [debug] 6#6 [unit] asgi_port_read(0xaaaae7075340,0xaaaae6bb2010): 0
2025/02/16 11:27:33.429 [debug] 6#6 [unit] recvmsg(8) failed: Resource temporarily unavailable (11)
2025/02/16 11:27:33.429 [debug] 6#6 [unit] port{6,0} recvmsg -1
2025/02/16 11:27:33.429 [debug] 6#6 [unit] asgi_port_read(0xaaaae7075340,0xaaaae6bb2010): 2
2025/02/16 11:27:33.428 [debug] 4#4 epoll_wait(3): 1
2025/02/16 11:27:33.428 [debug] 4#4 epoll: fd:10 ev:0001 d:AAAAE68363A0 rd:5 wr:0
2025/02/16 11:27:33.428 [debug] 4#4 timer expire minimum: 485371316:398971317
2025/02/16 11:27:33.428 [debug] 4#4 work queue: fast
2025/02/16 11:27:33.428 [debug] 4#4 recvmsg(10, 2, 32): 24
2025/02/16 11:27:33.428 [debug] 4#4 port 10: message type:14 fds:-1,-1
2025/02/16 11:27:33.428 [debug] 4#4 process port (6, 0) found
2025/02/16 11:27:33.428 [debug] 4#4 process port (4, 3) found
2025/02/16 11:27:33.428 [debug] 4#4 get port 4:3 found
2025/02/16 11:27:33.428 [debug] 4#4 malloc(136): AAAAE6847F20
2025/02/16 11:27:33.428 [debug] 4#4 posix_memalign(128, 1024): AAAAE6853000
2025/02/16 11:27:33.428 [debug] 4#4 mp AAAAE68210B0 retain: 2
2025/02/16 11:27:33.428 [debug] 4#4 send port 37 to process 6
2025/02/16 11:27:33.428 [debug] 4#4 port{6,0} 16: enqueue 1 notify 1, 0
2025/02/16 11:27:33.428 [debug] 4#4 pthread_mutex_lock(AAAAE6867120) enter
2025/02/16 11:27:33.428 [debug] 4#4 pthread_mutex_unlock(AAAAE6867120) exit
2025/02/16 11:27:33.428 [debug] 4#4 using plain mode
2025/02/16 11:27:33.428 [debug] 4#4 sendbuf: 0, AAAAE6853078, 32
2025/02/16 11:27:33.428 [debug] 4#4 sendmsg(16, 37, 38, 2): 48
2025/02/16 11:27:33.428 [debug] 4#4 recvmsg(10, 2, 32): -1
2025/02/16 11:27:33.428 [debug] 4#4 recvmsg(10) not ready
2025/02/16 11:27:33.428 [debug] 4#4 epoll 3 set event: fd:10 op:3 ev:80002001
2025/02/16 11:27:33.428 [debug] 4#4 work queue: fast
2025/02/16 11:27:33.428 [debug] 4#4 buf ts completion: AAAAE6853000 AAAAE6853078
2025/02/16 11:27:33.428 [debug] 4#4 free(AAAAE6847F20)
2025/02/16 11:27:33.428 [debug] 4#4 free(AAAAE6853000)
2025/02/16 11:27:33.428 [debug] 4#4 mp AAAAE68210B0 release: 1
2025/02/16 11:27:33.428 [debug] 4#4 epoll 3 changes:1
2025/02/16 11:27:33.428 [debug] 4#4 epoll_ctl(3): fd:10 op:3 ev:80002001
2025/02/16 11:27:33.428 [debug] 4#4 epoll_wait(3) timeout:-1
2025/02/16 11:27:33.429 [debug] 6#6 [unit] port{6,0} dequeue 1 read_socket 1
2025/02/16 11:27:33.429 [debug] 6#6 [unit] recvmsg(8): 48
2025/02/16 11:27:33.429 [debug] 6#6 [unit] port{6,0} recvmsg 48
2025/02/16 11:27:33.429 [debug] 6#6 [unit] #0: process message 13 fd[0] 11 fd[1] 15
2025/02/16 11:27:33.429 [debug] 6#6 [unit] #0: new_port: port{4,3} fd[0] 11 fd[1] 15
2025/02/16 11:27:33.429 [debug] 6#6 [unit] add_port: duplicate port{4,3} in_fd -1 out_fd 11 queue 0xffffb0f71000
2025/02/16 11:27:33.429 [debug] 6#6 [unit] close(15): 0
2025/02/16 11:27:33.429 [debug] 6#6 [unit] port{4,3} enqueue 16 notify 1
2025/02/16 11:27:33.429 [debug] 6#6 [unit] sendmsg(11, 16, 0): 16
2025/02/16 11:27:33.429 [debug] 6#6 [unit] port{4,3} send 16 read_queue
2025/02/16 11:27:33.429 [debug] 6#6 [unit] #9: Python call ASGI 3.0 application
2025/02/16 11:27:33.428 [debug] 4#8 epoll_wait(20): 1
2025/02/16 11:27:33.428 [debug] 4#8 epoll: fd:36 ev:0001 d:FFFFAC000D30 rd:5 wr:0
2025/02/16 11:27:33.428 [debug] 4#8 timer expire minimum: 485371315:398971317
2025/02/16 11:27:33.428 [debug] 4#8 work queue: fast
2025/02/16 11:27:33.428 [debug] 4#8 port{4,3} 36: dequeue 16
2025/02/16 11:27:33.428 [debug] 4#8 posix_memalign(16, 16496): FFFFAC004EC0
2025/02/16 11:27:33.428 [debug] 4#8 port 36: message type:24 fds:256,0
2025/02/16 11:27:33.428 [debug] 4#8 rpc: stream #9 handler, type 24
2025/02/16 11:27:33.428 [debug] 4#8 stream #9: got ack from 6:0
2025/02/16 11:27:33.430 [debug] 6#6 [unit] asgi_port_read(0xaaaae7075340,0xaaaae6bb2010): 0
2025/02/16 11:27:33.428 [debug] 4#8 posix_memalign(128, 128): FFFFAC008F80
2025/02/16 11:27:33.428 [debug] 4#8 rpc: stream #9 assigned uniq pid 6 (FFFFAC001088)
2025/02/16 11:27:33.428 [debug] 4#8 pthread_mutex_lock(AAAAE6854200) enter
2025/02/16 11:27:33.428 [debug] 4#8 process port (6, 0) found
2025/02/16 11:27:33.428 [debug] 4#8 app 'django_asgi' move port 6:0 out of spare_ports (ack)
2025/02/16 11:27:33.428 [debug] 4#8 pthread_mutex_unlock(AAAAE6854200) exit
2025/02/16 11:27:33.428 [debug] 4#8 mp FFFFAC003870 release: 2
2025/02/16 11:27:33.428 [debug] 4#8 port{4,3} 36: dequeue -1
2025/02/16 11:27:33.428 [debug] 4#8 recvmsg(36, 2, 32): 16
2025/02/16 11:27:33.428 [debug] 4#8 port{4,3} 36: recv 16 read_queue
2025/02/16 11:27:33.428 [debug] 4#8 port{4,3} 36: dequeue -1
2025/02/16 11:27:33.428 [debug] 4#8 recvmsg(36, 2, 32): -1
2025/02/16 11:27:33.428 [debug] 4#8 recvmsg(36) not ready
2025/02/16 11:27:33.428 [debug] 4#8 port{4,3} 36: recvmsg -2
2025/02/16 11:27:33.428 [debug] 4#8 epoll 20 set event: fd:36 op:3 ev:80002001
2025/02/16 11:27:33.428 [debug] 4#8 epoll 20 changes:1
2025/02/16 11:27:33.428 [debug] 4#8 epoll_ctl(20): fd:36 op:3 ev:80002001
2025/02/16 11:27:33.428 [debug] 4#8 epoll_wait(20) timeout:-1
2025/02/16 11:27:33.430 [debug] 6#6 [unit] #9: asgi_http_receive
2025/02/16 11:27:33.430 [debug] 6#6 [unit] recvmsg(8) failed: Resource temporarily unavailable (11)
2025/02/16 11:27:33.430 [debug] 6#6 [unit] port{6,0} recvmsg -1
2025/02/16 11:27:33.430 [debug] 6#6 [unit] asgi_port_read(0xaaaae7075340,0xaaaae6bb2010): 2
2025/02/16 11:27:33.433 [debug] 6#6 [unit] #9: asgi_http_receive
2025/02/16 11:27:33.434 [debug] 6#6 [unit] #9: asgi_http_done
2025/02/16 11:27:33.434 [error] 6#6 [unit] #9: Python failed to call 'future.result()'
Traceback (most recent call last):
  File "/usr/local/lib/python3.13/site-packages/django/core/handlers/asgi.py", line 162, in __call__
    await self.handle(scope, receive, send)
  File "/usr/local/lib/python3.13/site-packages/django/core/handlers/asgi.py", line 208, in handle
    task.result()
    ~~~~~~~~~~~^^
  File "/usr/local/lib/python3.13/site-packages/django/core/handlers/asgi.py", line 239, in listen_for_disconnect
    assert False, "Invalid ASGI message after request body: %s" % message["type"]
           ^^^^^
AssertionError: Invalid ASGI message after request body: http.request
2025/02/16 11:27:33.437 [debug] 6#6 [unit] #9: done: 1
2025/02/16 11:27:33.437 [debug] 6#6 [unit] port{4,3} enqueue 16 notify 1
2025/02/16 11:27:33.437 [debug] 6#6 [unit] sendmsg(11, 16, 0): 16
2025/02/16 11:27:33.437 [debug] 6#6 [unit] port{4,3} send 16 read_queue
2025/02/16 11:27:33.435 [debug] 4#8 epoll_wait(20): 1
2025/02/16 11:27:33.435 [debug] 4#8 epoll: fd:36 ev:0001 d:FFFFAC000D30 rd:5 wr:0
2025/02/16 11:27:33.435 [debug] 4#8 timer expire minimum: 485371317:398971324
2025/02/16 11:27:33.435 [debug] 4#8 work queue: fast
2025/02/16 11:27:33.435 [debug] 4#8 port{4,3} 36: dequeue 16
2025/02/16 11:27:33.435 [debug] 4#8 port 36: message type:1 fds:256,0
2025/02/16 11:27:33.435 [debug] 4#8 free(FFFFAC004D80)
2025/02/16 11:27:33.435 [debug] 4#8 rpc: stream #9 last handler, type 1
2025/02/16 11:27:33.435 [debug] 4#8 http request error: 503
2025/02/16 11:27:33.435 [debug] 4#8 realloc(FFFFAC000B70, 64): FFFFAC009080
2025/02/16 11:27:33.435 [debug] 4#8 malloc(29): FFFFAC000B70
2025/02/16 11:27:33.435 [debug] 4#8 h1p request header send
2025/02/16 11:27:33.435 [debug] 4#8 mp FFFFAC003870 retain: 3
2025/02/16 11:27:33.435 [debug] 4#8 mmap buf completion: FFFFAC001880 [FFFFB06F8000,16384] (sent=1), 4->0,0,1
2025/02/16 11:27:33.435 [debug] 4#8 mp FFFFAC000BC0 release: 1
2025/02/16 11:27:33.435 [debug] 4#8 app 'django_asgi' release port 6:0: -1 0
2025/02/16 11:27:33.435 [debug] 4#8 pthread_mutex_lock(AAAAE6854200) enter
2025/02/16 11:27:33.435 [debug] 4#8 app 'django_asgi' move port 6:0 to spare_ports
2025/02/16 11:27:33.435 [debug] 4#8 pthread_mutex_unlock(AAAAE6854200) exit
2025/02/16 11:27:33.435 [debug] 4#8 app 'django_asgi' AAAAE6854200 requests queue is empty, keep the port
A2025/02/16 11:27:33.435 [debug] 4#8 timer add: 0±50 0:398971324
B2025/02/16 11:27:33.435 [debug] 4#8 timer change: 398971324±50:1
2025/02/16 11:27:33.435 [debug] 4#8 pthread_mutex_lock(AAAAE6854200) enter
2025/02/16 11:27:33.435 [debug] 4#8 pthread_mutex_unlock(AAAAE6854200) exit
2025/02/16 11:27:33.435 [debug] 4#8 rpc: stream #9 remove first and last pid 6 registration (FFFFAC001088)
2025/02/16 11:27:33.435 [debug] 4#8 free(FFFFAC008F80)
2025/02/16 11:27:33.435 [debug] 4#8 rpc: stream #9 free registration
2025/02/16 11:27:33.435 [debug] 4#8 port{4,3} 36: dequeue -1
2025/02/16 11:27:33.435 [debug] 4#8 recvmsg(36, 2, 32): 16
2025/02/16 11:27:33.435 [debug] 4#8 port{4,3} 36: recv 16 read_queue
2025/02/16 11:27:33.435 [debug] 4#8 port{4,3} 36: dequeue -1
2025/02/16 11:27:33.435 [debug] 4#8 recvmsg(36, 2, 32): -1
2025/02/16 11:27:33.435 [debug] 4#8 recvmsg(36) not ready
2025/02/16 11:27:33.435 [debug] 4#8 port{4,3} 36: recvmsg -2
2025/02/16 11:27:33.435 [debug] 4#8 epoll 20 set event: fd:36 op:3 ev:80002001
2025/02/16 11:27:33.435 [debug] 4#8 work queue: fast
2025/02/16 11:27:33.435 [debug] 4#8 http request send error body
2025/02/16 11:27:33.435 [debug] 4#8 mp FFFFAC003870 retain: 4
2025/02/16 11:27:33.435 [debug] 4#8 h1p request send
2025/02/16 11:27:33.435 [debug] 4#8 work queue: write
2025/02/16 11:27:33.435 [debug] 4#8 *9 conn write fd:48 er:0 bl:0
2025/02/16 11:27:33.435 [debug] 4#8 *9 sendbuf: 0, FFFFAC004548, 139
2025/02/16 11:27:33.435 [debug] 4#8 *9 sendbuf: 1, FFFFAC003FC8, 54
192.168.127.1 - - [16/Feb/2025:11:27:33 +0000] "POST / HTTP/1.1" 503 54 "-" "curl/8.7.1"
2025/02/16 11:27:33.435 [debug] 4#8 *9 writev(48, 2): 193
2025/02/16 11:27:33.435 [debug] 4#8 *9 event conn: 193 sent:193
2025/02/16 11:27:33.435 [debug] 4#8 *9 timer disable: 0
2025/02/16 11:27:33.435 [debug] 4#8 work queue: fast
2025/02/16 11:27:33.435 [debug] 4#8 *9 h1p conn sent
2025/02/16 11:27:33.435 [debug] 4#8 work queue: fast
2025/02/16 11:27:33.435 [debug] 4#8 mp FFFFAC003870 release: 3
2025/02/16 11:27:33.435 [debug] 4#8 mp FFFFAC003870 release: 2
2025/02/16 11:27:33.435 [debug] 4#8 work queue: fast
2025/02/16 11:27:33.435 [debug] 4#8 *9 router http request done (rpc_data 0)
2025/02/16 11:27:33.436 [debug] 4#8 realloc(FFFFAC009080, 96): FFFFAC009080
2025/02/16 11:27:33.436 [debug] 4#8 malloc(26): FFFFAC001420
�2025/02/16 11:27:33.435 [debug] 4#8 *9 tstr query: "$remote_addr - - [$time_local] "$request_line" $status $body_bytes_sent "$header_referer" "$header_user_agent"
", result: "192.168.127.1 - - [16/Feb/2025:11:27:33 +0000] "POST / HTTP/1.1" 503 54 "-" "curl/8.7.1"
"
2025/02/16 11:27:33.435 [debug] 4#8 write(17, FFFFAC004362, 89): 89
2025/02/16 11:27:33.435 [debug] 4#8 *9 http request close handler
2025/02/16 11:27:33.435 [debug] 4#8 *9 h1p request close
2025/02/16 11:27:33.435 [debug] 4#8 *9 conf joint AAAAE6854040 count: 2
2025/02/16 11:27:33.435 [debug] 4#8 *9 h1p keepalive
2025/02/16 11:27:33.435 [debug] 4#8 *9 setsockopt(48, 6, TCP_NODELAY): 1
2025/02/16 11:27:33.435 [debug] 4#8 *9 h1p complete buffers
2025/02/16 11:27:33.435 [debug] 4#8 *9 buf completion: FFFFAC002B30 FFFFAC002B78
2025/02/16 11:27:33.435 [debug] 4#8 mp FFFFAC003870 release: 1
2025/02/16 11:27:33.435 [debug] 4#8 work queue: read
2025/02/16 11:27:33.435 [debug] 4#8 *9 conn read fd:48 rdy:0 cl:0 er:0 bl:0
Q2025/02/16 11:27:33.435 [debug] 4#8 *9 timer add: 399151315±50 180000:399151324
E2025/02/16 11:27:33.435 [debug] 4#8 *9 timer previous: 399151324±50
2025/02/16 11:27:33.435 [debug] 4#8 timers changes: 1
G2025/02/16 11:27:33.435 [debug] 4#8 timer rbtree insert: 398971324±50
Q2025/02/16 11:27:33.435 [debug] 4#8 timer found minimum: 398971324±50:398971324
2025/02/16 11:27:33.435 [debug] 4#8 epoll 20 changes:1
2025/02/16 11:27:33.435 [debug] 4#8 epoll_ctl(20): fd:36 op:3 ev:80002001
2025/02/16 11:27:33.435 [debug] 4#8 epoll_wait(20) timeout:0
2025/02/16 11:27:33.436 [debug] 4#8 epoll_wait(20): 0
2025/02/16 11:27:33.436 [debug] 4#8 timer expire minimum: 398971274:398971325
G2025/02/16 11:27:33.436 [debug] 4#8 timer expire delete: 398971324±50
2025/02/16 11:27:33.436 [debug] 4#8 work queue: fast
2025/02/16 11:27:33.436 [debug] 4#8 http request pool release
2025/02/16 11:27:33.436 [debug] 4#8 mp FFFFAC003870 release: 0
2025/02/16 11:27:33.436 [debug] 4#8 free(FFFFAC003930)
2025/02/16 11:27:33.436 [debug] 4#8 free(FFFFAC003BD0)
2025/02/16 11:27:33.436 [debug] 4#8 free(FFFFAC003D00)
2025/02/16 11:27:33.436 [debug] 4#8 free(FFFFAC003870)
T2025/02/16 11:27:33.436 [debug] 4#8 *9 timer found minimum: 399151315±50:398971325
2025/02/16 11:27:33.436 [debug] 4#8 epoll_wait(20) timeout:179990
2025/02/16 11:27:33.438 [debug] 4#8 epoll_wait(20): 1
2025/02/16 11:27:33.438 [debug] 4#8 *9 epoll: fd:48 ev:2001 d:FFFFAC001600 rd:5 wr:0
2025/02/16 11:27:33.438 [debug] 4#8 timer expire minimum: 399151265:398971327
2025/02/16 11:27:33.438 [debug] 4#8 work queue: read
2025/02/16 11:27:33.438 [debug] 4#8 *9 conn read fd:48 rdy:1 cl:0 er:0 bl:0
2025/02/16 11:27:33.438 [debug] 4#8 recvbuf: 0, FFFFAC002B78, 2048
2025/02/16 11:27:33.438 [debug] 4#8 *9 recv(48, FFFFAC002B78, 2048, 0x0): 0
2025/02/16 11:27:33.438 [debug] 4#8 *9 timer disable: 399151315
2025/02/16 11:27:33.438 [debug] 4#8 work queue: fast
2025/02/16 11:27:33.438 [debug] 4#8 *9 h1p conn close
2025/02/16 11:27:33.438 [debug] 4#8 *9 h1p shutdown
2025/02/16 11:27:33.438 [debug] 4#8 *9 h1p complete buffers
2025/02/16 11:27:33.438 [debug] 4#8 *9 h1p closing
2025/02/16 11:27:33.438 [debug] 4#8 *9 h1p conn closing
2025/02/16 11:27:33.438 [debug] 4#8 *9 conn close fd:48, to:0
2025/02/16 11:27:33.438 [debug] 4#8 work queue: close
2025/02/16 11:27:33.438 [debug] 4#8 *9 conn close handler fd:48
C2025/02/16 11:27:33.438 [debug] 4#8 *9 timer delete: 399151315±50
=2025/02/16 11:27:33.438 [debug] 4#8 *9 timer change: 0±50:2
;2025/02/16 11:27:33.438 [debug] 4#8 *9 timer delete: 0±50
2025/02/16 11:27:33.438 [debug] 4#8 *9 epoll 20 set event: fd:48 op:2 ev:0
D2025/02/16 11:27:33.438 [debug] 4#8 *9 timer add: 0±50 0:398971327
E2025/02/16 11:27:33.438 [debug] 4#8 *9 timer change: 398971327±50:1
2025/02/16 11:27:33.438 [debug] 4#8 timers changes: 2
J2025/02/16 11:27:33.438 [debug] 4#8 *9 timer rbtree delete: 399151315±50
J2025/02/16 11:27:33.438 [debug] 4#8 *9 timer rbtree insert: 398971327±50
T2025/02/16 11:27:33.438 [debug] 4#8 *9 timer found minimum: 398971327±50:398971327
2025/02/16 11:27:33.438 [debug] 4#8 epoll 20 changes:1
2025/02/16 11:27:33.438 [debug] 4#8 *9 epoll_ctl(20): fd:48 op:2 ev:0
2025/02/16 11:27:33.438 [debug] 4#8 epoll_wait(20) timeout:0
2025/02/16 11:27:33.438 [debug] 4#8 epoll_wait(20): 0
2025/02/16 11:27:33.438 [debug] 4#8 timer expire minimum: 398971277:398971327
J2025/02/16 11:27:33.438 [debug] 4#8 *9 timer expire delete: 398971327±50
2025/02/16 11:27:33.438 [debug] 4#8 work queue: fast
2025/02/16 11:27:33.438 [debug] 4#8 *9 conn close timer handler fd:48
2025/02/16 11:27:33.438 [debug] 4#8 *9 socket close(48)
2025/02/16 11:27:33.438 [debug] 4#8 work queue: fast
2025/02/16 11:27:33.438 [debug] 4#8 *9 h1p conn free
2025/02/16 11:27:33.438 [debug] 4#8 mp FFFFAC001550 release: 0
2025/02/16 11:27:33.438 [debug] 4#8 free(FFFFAC001600)
2025/02/16 11:27:33.438 [debug] 4#8 free(FFFFAC002810)
2025/02/16 11:27:33.438 [debug] 4#8 free(FFFFAC003400)
2025/02/16 11:27:33.438 [debug] 4#8 free(FFFFAC001550)
2025/02/16 11:27:33.438 [debug] 4#8 listen event count: 2
2025/02/16 11:27:33.438 [debug] 4#8 epoll_wait(20) timeout:-1
2025/02/16 11:27:33.447 [debug] 6#6 [unit] #9: asgi_http_send type is 'http.response.start'

[codedoga]

I also asked Django forum regarding this issue and this is a probable cause proposed by carltongibson:

This looks like Unit isn’t correctly handling the more_body key of the http.request event.
https://asgi.readthedocs.io/en/latest/specs/www.html#request-receive-event
After an http.request event where more_body is False the only permitted event is http.disconnect. Hence the assertion.

[ac000]

Hi, thanks for the report.

Managed to get your app (thanks for that!) running without docker, but it seems to be working fine.

$ curl -X PUT localhost:8000 -d test
ok
$ curl -X POST localhost:8000 -d test
ok

Using current Unit master from GitHub, but older versions should work, I'll check...

Python is 3.9.21 under RHEL 9. Django is 4.2.19 installed via pip

[codedoga]

Please try using Django version equal to or higher than 5.0 or with provided docker, I'm using unit:1.34.1-python3.13-slim image.

I also updated demo project to require django>=5

I don't know what else I might be missing. I purposefully created this because I have the same exact problem in one production project which is now switched to different app server. :(

[ac000]

Works under Fedora 41 with Python 3.13.2 and Django 4.2.16 (Unit master)

I'll see if I can try Django 5.x

[ac000]

OK, reproduced the issue with Django 5.1.6

[ac000]

I am also seeing this error (with both Django 4.x and 5.x)

2025/02/19 19:08:02 [info] 0#8703 [unit] ASGI Lifespan processing exception
Traceback (most recent call last):
  File "/home/andrew/.local/lib/python3.13/site-packages/django/core/handlers/asgi.py", line 157, in __call__
    raise ValueError(
        "Django can only handle ASGI/HTTP connections, not %s." % scope["type"]
    )
ValueError: Django can only handle ASGI/HTTP connections, not lifespan.

Though it doesn't seem to prevent things from working (with Django 4.x anyway)

Looking at the function call graph with Django 4.x we get

nxt_python_asgi_run: 
nxt_py_asgi_http_receive: 
nxt_py_asgi_http_read_msg: 
nxt_py_asgi_http_read_msg: body_buf [test]
nxt_py_asgi_http_receive: Got [more_body == false]
nxt_py_asgi_set_result_soon: 
nxt_py_asgi_set_result_soon: cleanup -> cleanup_result
nxt_py_asgi_http_send: 
nxt_py_asgi_http_send: 
nxt_py_asgi_http_response_body: 
nxt_py_asgi_http_response_body: nxt_py_asgi_http_emit_disconnect(http)
nxt_py_asgi_http_emit_disconnect: 
nxt_py_asgi_http_done: 

We call nxt_py_asgi_set_result_soon() then we call nxt_py_asgi_http_send() and everythings good.

With Django 5.x we see

nxt_python_asgi_run: 
nxt_py_asgi_http_receive: 
nxt_py_asgi_http_read_msg: 
nxt_py_asgi_http_read_msg: body_buf [test]
nxt_py_asgi_http_receive: Got [more_body == false]
nxt_py_asgi_set_result_soon: 
nxt_py_asgi_set_result_soon: cleanup -> cleanup_result
nxt_py_asgi_http_receive: 
nxt_py_asgi_http_read_msg: 
nxt_py_asgi_http_receive: Got [more_body == false]
nxt_py_asgi_set_result_soon: 
nxt_py_asgi_set_result_soon: cleanup -> cleanup_result
nxt_py_asgi_http_done: 
nxt_py_asgi_http_done: Python failed to call 'future.result()'
nxt_py_asgi_http_send: 

After calling nxt_py_asgi_set_result_soon() we go back to calling nxt_py_asgi_http_receive() again.

This decision to call nxt_py_asgi_http_send() vs nxt_py_asgi_http_receive() seems to happen deep down in Python, or maybe it's actually triggered by Django and with 5.x for some reason it thinks there is more data to read...

While we don't explicitly set more_body = false (we do set it to true if appropriate), AIUI it defaults to false if not set. Anyway explicitly setting it to false doesn't help.

This works with Django 4.x so something has obviously changed in 5.x. Looking at the commit log this looks a likely suspect, though I wonder if there more going on as if I comment out the assert the error goes away but we are still having the behaviour of calling _receive() again instead of _send()...

[ac000]

If I hack django/core/handlers/asgi.py thusly

diff --git ./django/core/handlers/asgi.py ./django/core/handlers/asgi.py
index bb6a6bfb3c..81e70567bd 100644
--- ./django/core/handlers/asgi.py
+++ ./django/core/handlers/asgi.py
@@ -198,7 +198,6 @@ class ASGIHandler(base.BaseHandler):
             # because it should not raise unexpected errors that would prevent
             # us from cancelling process_request().
-            asyncio.create_task(self.listen_for_disconnect(receive)),
             asyncio.create_task(process_request(request, send)),
         ]
         await asyncio.wait(tasks, return_when=asyncio.FIRST_COMPLETED)
         # Now wait on both tasks (they may have both finished by now).
@@ -222,7 +221,7 @@ class ASGIHandler(base.BaseHandler):
                     pass
 
         try:
-            response = tasks[1].result()
+            response = tasks[0].result()
         except asyncio.CancelledError:
             await signals.request_finished.asend(sender=self.__class__)
         else:

Things work as expected

$ curl -X POST -d test localhost:8000
ok

nxt_python_asgi_run: 
nxt_py_asgi_http_create: 
nxt_py_asgi_http_receive: 
nxt_py_asgi_http_read_msg: 
nxt_py_asgi_http_read_msg: body_buf [test]
nxt_py_asgi_http_receive: Got [more_body == false]
nxt_py_asgi_set_result_soon: 
nxt_py_asgi_set_result_soon: cleanup -> cleanup_result
nxt_py_asgi_http_send: 
nxt_py_asgi_http_send: 
nxt_py_asgi_http_response_body: 
nxt_py_asgi_http_response_body: nxt_py_asgi_http_emit_disconnect(http)
nxt_py_asgi_http_emit_disconnect: 
nxt_py_asgi_http_done: 

[codedoga]

In my debugging (mostly printing results) I noticed that last message from nxt_py_asgi_http_receive has type "http.request" whenever there is body involved hence the assertion fail. If request (no matter the verb) doesn't have body, then the last message will have type "http.disconnect" which is desired behaviour.

I would assume that this doesn't get called:
msg = nxt_py_asgi_new_msg(req, nxt_py_http_disconnect_str);

[codedoga]

I am also seeing this error (with both Django 4.x and 5.x)

2025/02/19 19:08:02 [info] 0#8703 [unit] ASGI Lifespan processing exception
Traceback (most recent call last):
  File "/home/andrew/.local/lib/python3.13/site-packages/django/core/handlers/asgi.py", line 157, in __call__
    raise ValueError(
        "Django can only handle ASGI/HTTP connections, not %s." % scope["type"]
    )
ValueError: Django can only handle ASGI/HTTP connections, not lifespan.

Though it doesn't seem to prevent things from working (with Django 4.x anyway)

Looking at the function call graph with Django 4.x we get

nxt_python_asgi_run: 
nxt_py_asgi_http_receive: 
nxt_py_asgi_http_read_msg: 
nxt_py_asgi_http_read_msg: body_buf [test]
nxt_py_asgi_http_receive: Got [more_body == false]
nxt_py_asgi_set_result_soon: 
nxt_py_asgi_set_result_soon: cleanup -> cleanup_result
nxt_py_asgi_http_send: 
nxt_py_asgi_http_send: 
nxt_py_asgi_http_response_body: 
nxt_py_asgi_http_response_body: nxt_py_asgi_http_emit_disconnect(http)
nxt_py_asgi_http_emit_disconnect: 
nxt_py_asgi_http_done: 

We call nxt_py_asgi_set_result_soon() then we call nxt_py_asgi_http_send() and everythings good.

With Django 5.x we see

nxt_python_asgi_run: 
nxt_py_asgi_http_receive: 
nxt_py_asgi_http_read_msg: 
nxt_py_asgi_http_read_msg: body_buf [test]
nxt_py_asgi_http_receive: Got [more_body == false]
nxt_py_asgi_set_result_soon: 
nxt_py_asgi_set_result_soon: cleanup -> cleanup_result
nxt_py_asgi_http_receive: 
nxt_py_asgi_http_read_msg: 
nxt_py_asgi_http_receive: Got [more_body == false]
nxt_py_asgi_set_result_soon: 
nxt_py_asgi_set_result_soon: cleanup -> cleanup_result
nxt_py_asgi_http_done: 
nxt_py_asgi_http_done: Python failed to call 'future.result()'
nxt_py_asgi_http_send: 

After calling nxt_py_asgi_set_result_soon() we go back to calling nxt_py_asgi_http_receive() again.

This decision to call nxt_py_asgi_http_send() vs nxt_py_asgi_http_receive() seems to happen deep down in Python, or maybe it's actually triggered by Django and with 5.x for some reason it thinks there is more data to read...

While we don't explicitly set more_body = false (we do set it to true if appropriate), AIUI it defaults to false if not set. Anyway explicitly setting it to false doesn't help.

This works with Django 4.x so something has obviously changed in 5.x. Looking at the commit log this looks a likely suspect, though I wonder if there more going on as if I comment out the assert the error goes away but we are still having the behaviour of calling _receive() again instead of _send()...

This is completely fine:

ValueError: Django can only handle ASGI/HTTP connections, not lifespan.

The main thing that is changed is now waiting for http.disconnect I guess.

[ac000]

So it comes down to the fact that nxt_py_asgi_http_receive() is being called due to asyncio.create_task(self.listen_for_disconnect(receive)), in ashi.py.

But of course there is no request data to read from the client, there is no message that needs to be sent to the application, we simply want to fall through to the end of nxt_py_asgi_http_receive() and return the future thing. As demonstrated by

index cdd6357e..e703c662 100644
--- ./src/python/nxt_python_asgi_http.c
+++ ./src/python/nxt_python_asgi_http.c
@@ -177,6 +192,8 @@ nxt_py_asgi_http_read_msg(nxt_py_asgi_http_t *http)
     }
 
     if (size == 0) {
+        Py_RETURN_NONE;
+
         if (http->empty_body_received) {
             Py_RETURN_NONE;
         }

While that fixes the POST case, it of course breaks it for things like GET. But at least we're on the right track...

[ac000]

Whether or not this is the right way to fix it, things seem to work... (ASGI and Python pytrests pass)

diff --git ./src/python/nxt_python_asgi_http.c ./src/python/nxt_python_asgi_http.c
index cdd6357e..79f387e3 100644
--- ./src/python/nxt_python_asgi_http.c
+++ ./src/python/nxt_python_asgi_http.c
@@ -28,6 +28,7 @@ typedef struct {
     uint8_t                  complete;
     uint8_t                  closed;
     uint8_t                  empty_body_received;
+    uint8_t                  request_received;
 } nxt_py_asgi_http_t;
 
 
@@ -103,6 +104,7 @@ nxt_py_asgi_http_create(nxt_unit_request_info_t *req)
         http->complete = 0;
         http->closed = 0;
         http->empty_body_received = 0;
+        http->request_received = 0;
     }
 
     return (PyObject *) http;
@@ -177,7 +179,7 @@ nxt_py_asgi_http_read_msg(nxt_py_asgi_http_t *http)
     }
 
     if (size == 0) {
-        if (http->empty_body_received) {
+        if (http->request_received || http->empty_body_received) {
             Py_RETURN_NONE;
         }
 
@@ -234,6 +236,8 @@ nxt_py_asgi_http_read_msg(nxt_py_asgi_http_t *http)
 
         Py_XDECREF(body);
 
+        http->request_received = 1;
+
         return msg;
     }
 

[codedoga]

Thank you for putting effort into this and quickly getting into the issue. Also I'm very happy with entire Unit project so far and want to thank the entire team. Best.