search

nginx / unit

NGINX Unit - universal web app server - a lightweight and versatile open source server that simplifies the application stack by natively executing application code across eight different programming language runtimes.
https://unit.nginx.org
Apache License 2.0
5.4k stars 327 forks source link

Problem with POST's #10

Closed gummiboll closed 7 years ago

gummiboll commented 7 years ago

Did a vanilla nginx/unit/php7/wordpress install on a fresh Ubuntu Xenial and noticed that I couldn't log in to wp-admin or post comments. Seems like $_POST doesn't get populated[1]?

Not sure if its a known issue, if it is you can just go ahead and close this. :)

[1]: Did a simple test to verify:

test.php: <?php print_r($_POST); ?>

$ curl --data "foo=bar" http://host/test.php

Array
(
)
vladkras commented 6 years ago

So, what was wrong? I'm expiriencing same problem. NGINX Unit is installed from latest source from this repo (0.4 so far) and no proxies are used

VBart commented 6 years ago

@vladkras that was broken recently and fixed again in b09227fa5c5f4b509d9e57da67b0ee79780a9877. Have you checked this revision?

vladkras commented 6 years ago

Yes, I'm using latest master (and I checked this file too). This what I've got in log with curl -v --data 'foo=bar' 127.0.0.1:8300

2018/01/12 13:11:59.332 [debug] 2490#2491 epoll_wait(12): 1
2018/01/12 13:11:59.332 [debug] 2490#2493 epoll_wait(16): 1
2018/01/12 13:11:59.332 [debug] 2490#2492 epoll_wait(14): 1
2018/01/12 13:11:59.332 [debug] 2490#2494 epoll_wait(18): 1
2018/01/12 13:11:59.332 [debug] 2490#2491 epoll: fd:11 ev:0001 d:561B8C32B680 rd:5 wr:0
2018/01/12 13:11:59.332 [debug] 2490#2493 epoll: fd:11 ev:0001 d:561B8C32DE80 rd:5 wr:0
2018/01/12 13:11:59.332 [debug] 2490#2492 epoll: fd:11 ev:0001 d:561B8C32B4C0 rd:5 wr:0
2018/01/12 13:11:59.332 [debug] 2490#2494 epoll: fd:11 ev:0001 d:561B8C32F360 rd:5 wr:0
2018/01/12 13:11:59.332 [debug] 2490#2491 timer expire minimum: 367409685:281090155
2018/01/12 13:11:59.332 [debug] 2490#2493 timer expire minimum: 367409689:281090155
2018/01/12 13:11:59.332 [debug] 2490#2492 timer expire minimum: 367409685:281090155
2018/01/12 13:11:59.332 [debug] 2490#2494 timer expire minimum: 367409685:281090155
2018/01/12 13:11:59.332 [debug] 2490#2491 work queue: accept
2018/01/12 13:11:59.332 [debug] 2490#2493 work queue: accept
2018/01/12 13:11:59.332 [debug] 2490#2492 work queue: accept
2018/01/12 13:11:59.332 [debug] 2490#2494 work queue: accept
2018/01/12 13:11:59.332 [debug] 2490#2491 accept4(11): 28
2018/01/12 13:11:59.332 [debug] 2490#2493 accept4(11) (11: Resource temporarily unavailable)
2018/01/12 13:11:59.332 [debug] 2490#2492 accept4(11) (11: Resource temporarily unavailable)
2018/01/12 13:11:59.332 [debug] 2490#2491 client: 127.0.0.1
2018/01/12 13:11:59.332 [debug] 2490#2494 accept4(11) (11: Resource temporarily unavailable)
2018/01/12 13:11:59.332 [debug] 2490#2493 epoll_wait(16) timeout:-1
2018/01/12 13:11:59.332 [debug] 2490#2492 epoll_wait(14) timeout:-1
2018/01/12 13:11:59.332 [debug] 2490#2491 malloc(168): 561B8C334940
2018/01/12 13:11:59.332 [debug] 2490#2494 epoll_wait(18) timeout:-1
2018/01/12 13:11:59.332 [debug] 2490#2491 posix_memalign(16, 464): 561B8C32DF80
2018/01/12 13:11:59.332 [debug] 2490#2491 *16 connections: 2
2018/01/12 13:11:59.332 [debug] 2490#2491 work queue: accept
2018/01/12 13:11:59.332 [debug] 2490#2491 accept4(11) (11: Resource temporarily unavailable)
2018/01/12 13:11:59.332 [debug] 2490#2491 work queue: read
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 http conn init
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 conn wait fd:28 rdy:0
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 timer add: 0:0 65000:281155155
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 timer change: 281155155:0
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 epoll 12 set event: fd:28 op:1 ev:80002001
2018/01/12 13:11:59.332 [debug] 2490#2491 timers changes: 1
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 timer rbtree insert: 281155155
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 timer found minimum: 281155155:281090155
2018/01/12 13:11:59.332 [debug] 2490#2491 epoll 12 changes:1
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 epoll_ctl(12): fd:28 op:1 ev:80002001
2018/01/12 13:11:59.332 [debug] 2490#2491 epoll_wait(12) timeout:65000
2018/01/12 13:11:59.332 [debug] 2490#2491 epoll_wait(12): 1
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 epoll: fd:28 ev:0001 d:561B8C2FE0C0 rd:5 wr:0
2018/01/12 13:11:59.332 [debug] 2490#2491 timer expire minimum: 281155155:281090155
2018/01/12 13:11:59.332 [debug] 2490#2491 work queue: accept
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 h1p read header
2018/01/12 13:11:59.332 [debug] 2490#2491 posix_memalign(16, 2160): 561B8C33F020
2018/01/12 13:11:59.332 [debug] 2490#2491 work queue: read
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 conn read fd:28 rdy:1 cl:0
2018/01/12 13:11:59.332 [debug] 2490#2491 recvbuf: 0, 561B8C33F068, 2048
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 recv(28, 561B8C33F068, 2048, 0x0): 154
2018/01/12 13:11:59.332 [debug] 2490#2491 work queue: fast
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 h1p header parse
2018/01/12 13:11:59.332 [debug] 2490#2491 malloc(136): 561B8C32E160
2018/01/12 13:11:59.332 [debug] 2490#2491 posix_memalign(128, 1024): 561B8C335780
2018/01/12 13:11:59.332 [debug] 2490#2491 malloc(168): 561B8C335BC0
2018/01/12 13:11:59.332 [debug] 2490#2491 malloc(136): 561B8C2FE2A0
2018/01/12 13:11:59.332 [debug] 2490#2491 posix_memalign(128, 1024): 561B8C33F900
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 h1p body read 7 te:0
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 h1p body rest: 0
2018/01/12 13:11:59.332 [debug] 2490#2491 work queue: fast
2018/01/12 13:11:59.332 [debug] 2490#2491 posix_memalign(16, 712): 561B8C339D60
2018/01/12 13:11:59.332 [debug] 2490#2491 mp 561B8C335BC0 retain: 2
2018/01/12 13:11:59.332 [debug] 2490#2491 malloc(136): 561B8C2FE340
2018/01/12 13:11:59.332 [debug] 2490#2491 posix_memalign(128, 1024): 561B8C33A080
2018/01/12 13:11:59.332 [debug] 2490#2491 posix_memalign(128, 128): 561B8C2FE400
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 rpc: stream #5 registered
2018/01/12 13:11:59.332 [debug] 2490#2491 pthread_mutex_lock(561B8C2FE760) enter
2018/01/12 13:11:59.332 [debug] 2490#2491 pthread_mutex_unlock(561B8C2FE760) exit
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 already have port for app 'default' 561B8C2FE760 
2018/01/12 13:11:59.332 [debug] 2490#2491 posix_memalign(128, 128): 561B8C33FD80
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 rpc: stream #5 assigned uniq pid 2501 (561B8C32AB88)
2018/01/12 13:11:59.332 [debug] 2490#2491 pthread_mutex_lock(561B8C2FDAA0) enter
2018/01/12 13:11:59.332 [debug] 2490#2491 process port (2490, 1) found
2018/01/12 13:11:59.332 [debug] 2490#2491 pthread_mutex_unlock(561B8C2FDAA0) exit
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 request 6 bytes shm buffer
2018/01/12 13:11:59.332 [debug] 2490#2491 mp 561B8C32A400 retain: 2
2018/01/12 13:11:59.332 [debug] 2490#2491 pthread_mutex_lock(561B8C2FDA68) enter
2018/01/12 13:11:59.332 [debug] 2490#2491 pthread_mutex_unlock(561B8C2FDA68) exit
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 outgoing mmap buf allocation: 561B8C330980 [7F192B668000,16384] 2490->2501,0,0
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 nxt_app_msg_write: 4 POST
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 nxt_app_msg_write: 1 /
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 nxt_app_msg_write: NULL
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 nxt_app_msg_write: 8 HTTP/1.1
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 nxt_app_msg_write: 9 127.0.0.1
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 nxt_app_msg_write: 9 127.0.0.1
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 nxt_app_msg_write: 14 127.0.0.1:8300
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 nxt_app_msg_write: NULL
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 nxt_app_msg_write: 33 application/x-www-form-urlencoded
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 nxt_app_msg_write: 1 7
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 nxt_app_msg_write_raw: 7
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 nxt_app_msg_write: 14 127.0.0.1:8300
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 nxt_app_msg_write: 11 curl/7.57.0
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 nxt_app_msg_write: 3 */*
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 nxt_app_msg_write: 1 7
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 nxt_app_msg_write: 33 application/x-www-form-urlencoded
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 nxt_app_msg_write: NULL
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 about to send 261 bytes buffer to worker port 29
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 request tracking for stream #5
2018/01/12 13:11:59.332 [debug] 2490#2491 pthread_mutex_lock(561B8C2FDA68) enter
2018/01/12 13:11:59.332 [debug] 2490#2491 pthread_mutex_unlock(561B8C2FDA68) exit
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 outgoing tracking allocation: 2490->2501,0,0
2018/01/12 13:11:59.332 [debug] 2490#2491 pthread_mutex_lock(561B8C334C50) enter
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 using mmap mode
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 sendbuf: 0, 7F192B668000, 261
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 prepare 261 bytes message for transfer to process 2501 via shared memory
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 mmap_msg={0, 0, 261} to 2501
2018/01/12 13:11:59.332 [debug] 2490#2491 sendmsg(29, -1, 2): 36
2018/01/12 13:11:59.332 [debug] 2490#2491 pthread_mutex_unlock(561B8C334C50) exit
2018/01/12 13:11:59.332 [debug] 2490#2491 pthread_mutex_lock(561B8C2FE760) enter
2018/01/12 13:11:59.332 [debug] 2501#2501 epoll_wait(3): 1
2018/01/12 13:11:59.332 [debug] 2490#2491 pthread_mutex_unlock(561B8C2FE760) exit
2018/01/12 13:11:59.332 [debug] 2501#2501 epoll: fd:10 ev:0001 d:561B8C2FFC40 rd:5 wr:0
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 app 'default' 561B8C2FE760 requests queue is empty, keep the port
2018/01/12 13:11:59.332 [debug] 2501#2501 timer expire minimum: 367409685:281090155
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 ra stream #5 update peer
2018/01/12 13:11:59.332 [debug] 2501#2501 work queue: fast
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 ra stream #5 release
2018/01/12 13:11:59.332 [debug] 2490#2491 work queue: fast
2018/01/12 13:11:59.332 [debug] 2501#2501 recvmsg(10, -1, 2): 36
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 timer found minimum: 281155155:281090155
2018/01/12 13:11:59.332 [debug] 2501#2501 pthread_mutex_lock(7F192CF361D0) enter
2018/01/12 13:11:59.332 [debug] 2490#2491 epoll_wait(12) timeout:65000
2018/01/12 13:11:59.332 [debug] 2501#2501 pthread_mutex_unlock(7F192CF361D0) exit
2018/01/12 13:11:59.332 [debug] 2501#2501 pthread_mutex_lock(561B8C3D9DB0) enter
2018/01/12 13:11:59.332 [debug] 2501#2501 pthread_mutex_unlock(561B8C3D9DB0) exit
2018/01/12 13:11:59.332 [debug] 2501#2501 tracking for stream #5 received
2018/01/12 13:11:59.332 [debug] 2501#2501 mmap_msg={0, 0, 261} from 2490
2018/01/12 13:11:59.332 [debug] 2501#2501 pthread_mutex_lock(7F192CF361D0) enter
2018/01/12 13:11:59.332 [debug] 2501#2501 pthread_mutex_unlock(7F192CF361D0) exit
2018/01/12 13:11:59.332 [debug] 2501#2501 pthread_mutex_lock(561B8C3D9DB0) enter
2018/01/12 13:11:59.332 [debug] 2501#2501 pthread_mutex_unlock(561B8C3D9DB0) exit
2018/01/12 13:11:59.332 [debug] 2501#2501 mp 561B8C2F8640 retain: 2
2018/01/12 13:11:59.332 [debug] 2501#2501 incoming mmap buf allocation: 561B8C2F8D80 [7F192AA00000,16384] 2490->2501,0,0
2018/01/12 13:11:59.332 [debug] 2501#2501 port 10: message type:12
2018/01/12 13:11:59.332 [debug] 2501#2501 app data: POST/  HTTP/1.1
127.0.0.1
127.0.0.1127.0.0.1:8300"application/x-www-form-urlencoded7foo=bar
HTTP_HOST127.0.0.1:8300HTTP_USER_AGENT
                                       curl/7.57.0
                                                  HTTP_ACCEPT*/*HTTP_CONTENT_LENGTH7HTTP_CONTENT_TYPE"application/x-www-form-urlencoded ...
2018/01/12 13:11:59.332 [debug] 2501#2501 process port (2490, 1) found
2018/01/12 13:11:59.332 [debug] 2501#2501 nxt_read_str: 4 POST
2018/01/12 13:11:59.332 [debug] 2501#2501 nxt_read_str: 1 /
2018/01/12 13:11:59.332 [debug] 2501#2501 nxt_read_str: NULL
2018/01/12 13:11:59.332 [debug] 2501#2501 nxt_read_size: 0
2018/01/12 13:11:59.332 [debug] 2501#2501 malloc(22): 561B8C2F89A0
2018/01/12 13:11:59.332 [debug] 2501#2501 nxt_read_str: 8 HTTP/1.1
2018/01/12 13:11:59.332 [debug] 2501#2501 nxt_read_str: 9 127.0.0.1
2018/01/12 13:11:59.332 [debug] 2501#2501 nxt_read_str: 9 127.0.0.1
2018/01/12 13:11:59.332 [debug] 2501#2501 nxt_read_str: 14 127.0.0.1:8300
2018/01/12 13:11:59.332 [debug] 2501#2501 nxt_read_str: NULL
2018/01/12 13:11:59.332 [debug] 2501#2501 nxt_read_str: 33 application/x-www-form-urlencoded
2018/01/12 13:11:59.332 [debug] 2501#2501 nxt_read_str: 1 7
2018/01/12 13:11:59.332 [debug] 2501#2501 nxt_read_size: 0
2018/01/12 13:11:59.332 [debug] 2501#2501 nxt_read_size: 7
2018/01/12 13:11:59.332 [debug] 2501#2501 handle.filename = '/app/default/index.php'
2018/01/12 13:11:59.332 [debug] 2501#2501 run script /app/default/index.php
2018/01/12 13:11:59.332 [debug] 2501#2501 nxt_php_read_post 0
2018/01/12 13:11:59.332 [debug] 2501#2501 nxt_php_read_cookies
2018/01/12 13:11:59.332 [debug] 2501#2501 nxt_app_msg_write_raw: 8
2018/01/12 13:11:59.332 [debug] 2501#2501 request 8 bytes shm buffer
2018/01/12 13:11:59.332 [debug] 2501#2501 malloc(136): 561B8C3BDF40
2018/01/12 13:11:59.332 [debug] 2501#2501 posix_memalign(128, 1024): 561B8C3BE000
2018/01/12 13:11:59.332 [debug] 2501#2501 mp 7F192CF36D20 retain: 2
2018/01/12 13:11:59.332 [debug] 2501#2501 pthread_mutex_lock(561B8C3D9DE8) enter
2018/01/12 13:11:59.332 [debug] 2501#2501 pthread_mutex_unlock(561B8C3D9DE8) exit
2018/01/12 13:11:59.332 [debug] 2501#2501 outgoing mmap buf allocation: 561B8C3BE000 [7F1929FFF000,16384] 2501->2490,0,0
2018/01/12 13:11:59.332 [debug] 2501#2501 nxt_app_msg_write_raw: 3
2018/01/12 13:11:59.332 [debug] 2501#2501 nxt_app_msg_write_raw: 2
2018/01/12 13:11:59.332 [debug] 2501#2501 nxt_app_msg_write_raw: 23
2018/01/12 13:11:59.332 [debug] 2501#2501 nxt_app_msg_write_raw: 2
2018/01/12 13:11:59.332 [debug] 2501#2501 nxt_app_msg_write_raw: 38
2018/01/12 13:11:59.332 [debug] 2501#2501 nxt_app_msg_write_raw: 2
2018/01/12 13:11:59.332 [debug] 2501#2501 nxt_app_msg_write_raw: 2
2018/01/12 13:11:59.332 [debug] 2501#2501 pthread_mutex_lock(561B8C2F8810) enter
2018/01/12 13:11:59.332 [debug] 2501#2501 using mmap mode
2018/01/12 13:11:59.332 [debug] 2501#2501 sendbuf: 0, 7F1929FFF000, 80
2018/01/12 13:11:59.332 [debug] 2501#2501 prepare 80 bytes message for transfer to process 2490 via shared memory
2018/01/12 13:11:59.332 [debug] 2501#2501 mmap_msg={0, 0, 80} to 2490
2018/01/12 13:11:59.332 [debug] 2501#2501 sendmsg(8, -1, 2): 28
2018/01/12 13:11:59.332 [debug] 2490#2491 epoll_wait(12): 1
2018/01/12 13:11:59.332 [debug] 2501#2501 pthread_mutex_unlock(561B8C2F8810) exit
2018/01/12 13:11:59.332 [debug] 2490#2491 epoll: fd:20 ev:0001 d:561B8C32A5A0 rd:5 wr:0
2018/01/12 13:11:59.332 [debug] 2501#2501 nxt_app_msg_write_raw: 13
2018/01/12 13:11:59.332 [debug] 2490#2491 timer expire minimum: 281155155:281090155
2018/01/12 13:11:59.332 [debug] 2501#2501 request 13 bytes shm buffer
2018/01/12 13:11:59.332 [debug] 2490#2491 work queue: fast
2018/01/12 13:11:59.332 [debug] 2501#2501 mp 7F192CF36D20 retain: 3
2018/01/12 13:11:59.332 [debug] 2501#2501 pthread_mutex_lock(561B8C3D9DE8) enter
2018/01/12 13:11:59.332 [debug] 2490#2491 recvmsg(20, -1, 2): 28
2018/01/12 13:11:59.332 [debug] 2501#2501 pthread_mutex_unlock(561B8C3D9DE8) exit
2018/01/12 13:11:59.332 [debug] 2490#2491 mmap_msg={0, 0, 80} from 2501
2018/01/12 13:11:59.332 [debug] 2501#2501 outgoing mmap buf allocation: 561B8C3BE080 [7F192A003000,16384] 2501->2490,0,1
2018/01/12 13:11:59.332 [debug] 2490#2491 pthread_mutex_lock(7F192CF361D0) enter
2018/01/12 13:11:59.332 [debug] 2501#2501 pthread_mutex_lock(561B8C2F8810) enter
2018/01/12 13:11:59.332 [debug] 2490#2491 pthread_mutex_unlock(7F192CF361D0) exit
2018/01/12 13:11:59.332 [debug] 2501#2501 using mmap mode
2018/01/12 13:11:59.332 [debug] 2490#2491 pthread_mutex_lock(561B8C2FDA30) enter
2018/01/12 13:11:59.332 [debug] 2501#2501 sendbuf: 0, 7F192A003000, 13
2018/01/12 13:11:59.332 [debug] 2490#2491 pthread_mutex_unlock(561B8C2FDA30) exit
2018/01/12 13:11:59.332 [debug] 2501#2501 prepare 13 bytes message for transfer to process 2490 via shared memory
2018/01/12 13:11:59.332 [debug] 2490#2491 mp 561B8C32A4E0 retain: 2
2018/01/12 13:11:59.332 [debug] 2501#2501 mmap_msg={0, 1, 13} to 2490
2018/01/12 13:11:59.332 [debug] 2490#2491 incoming mmap buf allocation: 561B8C32AA80 [7F192AC67000,16384] 2501->2490,0,0
2018/01/12 13:11:59.332 [debug] 2501#2501 sendmsg(8, -1, 2): 28
2018/01/12 13:11:59.332 [debug] 2490#2491 port 20: message type:12
2018/01/12 13:11:59.332 [debug] 2501#2501 pthread_mutex_unlock(561B8C2F8810) exit
2018/01/12 13:11:59.332 [debug] 2490#2491 rpc: stream #5 handler, type 12
2018/01/12 13:11:59.332 [debug] 2490#2491 router app data (80): Status: 200
X-Powered-By: PHP/7.1.9
Content-type: text/html; charset=UTF-8

2018/01/12 13:11:59.332 [debug] 2490#2491 h1p request header send
2018/01/12 13:11:59.332 [debug] 2490#2491 recvmsg(20, -1, 2): 28
2018/01/12 13:11:59.332 [debug] 2501#2501 pthread_mutex_lock(561B8C2F8810) enter
2018/01/12 13:11:59.332 [debug] 2490#2491 mmap_msg={0, 1, 13} from 2501
2018/01/12 13:11:59.332 [debug] 2501#2501 sendmsg(8, -1, 1): 16
2018/01/12 13:11:59.332 [debug] 2490#2491 pthread_mutex_lock(7F192CF361D0) enter
2018/01/12 13:11:59.332 [debug] 2501#2501 pthread_mutex_unlock(561B8C2F8810) exit
2018/01/12 13:11:59.332 [debug] 2490#2491 pthread_mutex_unlock(7F192CF361D0) exit
2018/01/12 13:11:59.332 [debug] 2501#2501 free(561B8C2F89A0)
2018/01/12 13:11:59.332 [debug] 2490#2491 pthread_mutex_lock(561B8C2FDA30) enter
2018/01/12 13:11:59.332 [debug] 2501#2501 complete buffer 561B8C2F8D80
2018/01/12 13:11:59.332 [debug] 2490#2491 pthread_mutex_unlock(561B8C2FDA30) exit
2018/01/12 13:11:59.332 [debug] 2501#2501 recvmsg(10, -1, 2): -1
2018/01/12 13:11:59.332 [debug] 2490#2491 mp 561B8C32A4E0 retain: 3
2018/01/12 13:11:59.332 [debug] 2501#2501 recvmsg(10) not ready
2018/01/12 13:11:59.332 [debug] 2490#2491 incoming mmap buf allocation: 561B8C32AB00 [7F192AC6B000,16384] 2501->2490,0,1
2018/01/12 13:11:59.332 [debug] 2501#2501 epoll 3 set event: fd:10 op:3 ev:80002001
2018/01/12 13:11:59.332 [debug] 2490#2491 port 20: message type:12
2018/01/12 13:11:59.332 [debug] 2501#2501 work queue: fast
2018/01/12 13:11:59.332 [debug] 2490#2491 rpc: stream #5 handler, type 12
2018/01/12 13:11:59.332 [debug] 2501#2501 mmap buf completion: 561B8C3BE000 [7F1929FFF000,16384] (sent=1), 2501->2490,0,1
2018/01/12 13:11:59.332 [debug] 2490#2491 router app data (13): array(0) {
}

2018/01/12 13:11:59.332 [debug] 2501#2501 mp 7F192CF36D20 release: 2
2018/01/12 13:11:59.332 [debug] 2490#2491 h1p request send
2018/01/12 13:11:59.332 [debug] 2501#2501 work queue: fast
2018/01/12 13:11:59.332 [debug] 2490#2491 recvmsg(20, -1, 2): 16
2018/01/12 13:11:59.332 [debug] 2501#2501 mmap buf completion: 561B8C3BE080 [7F192A003000,16384] (sent=1), 2501->2490,0,2
2018/01/12 13:11:59.332 [debug] 2490#2491 port 20: message type:12
2018/01/12 13:11:59.332 [debug] 2501#2501 free(561B8C3BDF40)
2018/01/12 13:11:59.332 [debug] 2490#2491 free(561B8C2FE400)
2018/01/12 13:11:59.332 [debug] 2501#2501 free(561B8C3BE000)
2018/01/12 13:11:59.332 [debug] 2490#2491 rpc: stream #5 last handler, type 12
2018/01/12 13:11:59.332 [debug] 2501#2501 mp 7F192CF36D20 release: 1
2018/01/12 13:11:59.332 [debug] 2490#2491 last router app data (0): 
2018/01/12 13:11:59.332 [debug] 2501#2501 work queue: fast
2018/01/12 13:11:59.332 [debug] 2490#2491 router data create last buf
2018/01/12 13:11:59.332 [debug] 2501#2501 buf completion: 561B8C3DA300 0
2018/01/12 13:11:59.332 [debug] 2490#2491 pthread_mutex_lock(561B8C2FE760) enter
2018/01/12 13:11:59.332 [debug] 2501#2501 work queue: fast
2018/01/12 13:11:59.332 [debug] 2490#2491 pthread_mutex_unlock(561B8C2FE760) exit
2018/01/12 13:11:59.332 [debug] 2501#2501 mmap buf completion: 561B8C2F8D80 [7F192AA00000,16384] (sent=0), 2490->2501,0,0
2018/01/12 13:11:59.332 [debug] 2490#2491 app 'default' 561B8C2FE760 requests queue is empty, keep the port
2018/01/12 13:11:59.332 [debug] 2501#2501 mp 561B8C2F8640 release: 1
2018/01/12 13:11:59.332 [debug] 2490#2491 failed to cancel tracking for stream #5
2018/01/12 13:11:59.332 [debug] 2501#2501 epoll 3 changes:1
2018/01/12 13:11:59.332 [debug] 2490#2491 mmap buf completion: 561B8C330980 [7F192B668000,16384] (sent=1), 2490->2501,0,1
2018/01/12 13:11:59.332 [debug] 2501#2501 epoll_ctl(3): fd:10 op:3 ev:80002001
2018/01/12 13:11:59.332 [debug] 2490#2491 mp 561B8C32A400 release: 1
2018/01/12 13:11:59.332 [debug] 2501#2501 epoll_wait(3) timeout:-1
2018/01/12 13:11:59.332 [debug] 2490#2491 timer add: 0:0 0:281090155
2018/01/12 13:11:59.332 [debug] 2490#2491 timer change: 281090155:0
2018/01/12 13:11:59.332 [debug] 2490#2491 h1p request send
2018/01/12 13:11:59.332 [debug] 2490#2491 rpc: stream #5 remove first and last pid 2501 registration (561B8C32AB88)
2018/01/12 13:11:59.332 [debug] 2490#2491 free(561B8C33FD80)
2018/01/12 13:11:59.332 [debug] 2490#2491 rpc: stream #5 free registration
2018/01/12 13:11:59.332 [debug] 2490#2491 recvmsg(20, -1, 2): -1
2018/01/12 13:11:59.332 [debug] 2490#2491 recvmsg(20) not ready
2018/01/12 13:11:59.332 [debug] 2490#2491 epoll 12 set event: fd:20 op:3 ev:80002001
2018/01/12 13:11:59.332 [debug] 2490#2491 work queue: fast
2018/01/12 13:11:59.332 [debug] 2490#2491 mmap buf completion: 561B8C32AA80 [7F192AC67000,16384] (sent=0), 2501->2490,0,0
2018/01/12 13:11:59.332 [debug] 2490#2491 mp 561B8C32A4E0 release: 2
2018/01/12 13:11:59.332 [debug] 2490#2491 work queue: fast
2018/01/12 13:11:59.332 [debug] 2490#2491 work queue: write
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 conn write fd:28
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 sendbuf: 0, 561B8C33A1C8, 128
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 sendbuf: 1, 561B8C33FCC8, 5
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 sendbuf: 2, 7F192AC6B000, 13
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 sendbuf: 3, 561B8C33A348, 7
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 writev(28, 4): 153
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 event conn: 153 sent:153
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 timer disable: 0:0
2018/01/12 13:11:59.332 [debug] 2490#2491 work queue: fast
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 h1p sent
2018/01/12 13:11:59.332 [debug] 2490#2491 work queue: fast
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 buf completion: 561B8C33A180 561B8C33A1C8
2018/01/12 13:11:59.332 [debug] 2490#2491 work queue: fast
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 buf completion: 561B8C33FC80 561B8C33FCC8
2018/01/12 13:11:59.332 [debug] 2490#2491 work queue: fast
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 mmap buf completion: 561B8C32AB00 [7F192AC6B000,16384] (sent=0), 2501->2490,0,1
2018/01/12 13:11:59.332 [debug] 2490#2491 mp 561B8C32A4E0 release: 1
2018/01/12 13:11:59.332 [debug] 2490#2491 work queue: fast
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 buf completion: 561B8C33A300 561B8C33A348
2018/01/12 13:11:59.332 [debug] 2490#2491 work queue: fast
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 http request done
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 http request close handler
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 http request log: "127.0.0.1 "POST / HTTP/1.1" 200"
2018/01/12 13:11:59.332 [debug] 2490#2491 mp 561B8C335BC0 release: 1
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 h1p request close
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 h1p keepalive
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 setsockopt(28, 6, TCP_NODELAY): 1
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 conn wait fd:28 rdy:0
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 timer previous: 281155155:2
2018/01/12 13:11:59.332 [debug] 2490#2491 timers changes: 1
2018/01/12 13:11:59.332 [debug] 2490#2491 timer rbtree insert: 281090155
2018/01/12 13:11:59.332 [debug] 2490#2491 timer found minimum: 281090155:281090155
2018/01/12 13:11:59.332 [debug] 2490#2491 epoll 12 changes:1
2018/01/12 13:11:59.332 [debug] 2490#2491 epoll_ctl(12): fd:20 op:3 ev:80002001
2018/01/12 13:11:59.332 [debug] 2490#2491 epoll_wait(12) timeout:0
2018/01/12 13:11:59.332 [debug] 2490#2491 epoll_wait(12): 1
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 epoll: fd:28 ev:2001 d:561B8C2FE0C0 rd:5 wr:0
2018/01/12 13:11:59.332 [debug] 2490#2491 timer expire minimum: 281090155:281090155
2018/01/12 13:11:59.332 [debug] 2490#2491 timer expire delete: 281090155:2
2018/01/12 13:11:59.332 [debug] 2490#2491 work queue: fast
2018/01/12 13:11:59.332 [debug] 2490#2491 http app release
2018/01/12 13:11:59.332 [debug] 2490#2491 mp 561B8C335BC0 release: 0
2018/01/12 13:11:59.332 [debug] 2490#2491 free(561B8C339D60)
2018/01/12 13:11:59.332 [debug] 2490#2491 free(561B8C2FE340)
2018/01/12 13:11:59.332 [debug] 2490#2491 free(561B8C33A080)
2018/01/12 13:11:59.332 [debug] 2490#2491 free(561B8C2FE2A0)
2018/01/12 13:11:59.332 [debug] 2490#2491 free(561B8C33F900)
2018/01/12 13:11:59.332 [debug] 2490#2491 free(561B8C335BC0)
2018/01/12 13:11:59.332 [debug] 2490#2491 work queue: read
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 h1p read header
2018/01/12 13:11:59.332 [debug] 2490#2491 work queue: read
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 conn read fd:28 rdy:1 cl:0
2018/01/12 13:11:59.332 [debug] 2490#2491 recvbuf: 0, 561B8C33F068, 2048
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 recv(28, 561B8C33F068, 2048, 0x0): 0
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 timer disable: 281155155:2
2018/01/12 13:11:59.332 [debug] 2490#2491 work queue: fast
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 h1p conn close
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 h1p close
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 conn close fd:28, to:0
2018/01/12 13:11:59.332 [debug] 2490#2491 work queue: close
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 conn close handler fd:28
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 timer delete: 281155155:0
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 timer change: 0:2
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 epoll 12 set event: fd:28 op:2 ev:0
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 timer add: 0:0 0:281090155
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 timer change: 281090155:0
2018/01/12 13:11:59.332 [debug] 2490#2491 timers changes: 2
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 timer rbtree delete: 281155155:1
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 timer rbtree insert: 281090155
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 timer found minimum: 281090155:281090155
2018/01/12 13:11:59.332 [debug] 2490#2491 epoll 12 changes:1
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 epoll_ctl(12): fd:28 op:2 ev:0
2018/01/12 13:11:59.332 [debug] 2490#2491 epoll_wait(12) timeout:0
2018/01/12 13:11:59.332 [debug] 2490#2491 epoll_wait(12): 0
2018/01/12 13:11:59.332 [debug] 2490#2491 timer expire minimum: 281090155:281090155
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 timer expire delete: 281090155:2
2018/01/12 13:11:59.332 [debug] 2490#2491 work queue: fast
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 conn close timer handler fd:28
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 socket close(28)
2018/01/12 13:11:59.332 [debug] 2490#2491 work queue: fast
2018/01/12 13:11:59.332 [debug] 2490#2491 *14 router conn close done
2018/01/12 13:11:59.332 [debug] 2490#2491 free(561B8C2FE0C0)
2018/01/12 13:11:59.332 [debug] 2490#2491 mp 561B8C2F93C0 release: 0
2018/01/12 13:11:59.332 [debug] 2490#2491 conf joint 561B8C331C00 count: 2
2018/01/12 13:11:59.332 [debug] 2490#2491 free(561B8C32E160)
2018/01/12 13:11:59.332 [debug] 2490#2491 free(561B8C335780)
2018/01/12 13:11:59.332 [debug] 2490#2491 free(561B8C33F020)
2018/01/12 13:11:59.332 [debug] 2490#2491 free(561B8C2F93C0)
2018/01/12 13:11:59.332 [debug] 2490#2491 epoll_wait(12) timeout:-1

as you can see data was recieved but result was empty

array(0) {
}

PS I use: Alpine Linux 3.7 with Docker https://github.com/vladkras/nginx-unit-php7

vladkras commented 6 years ago

I added logging to that part

    if (r->body != NULL) {
    nxt_debug(task, "body: %*s\n", 100, r->body);
        ar->r.body.buf = r->body;
        ar->r.body.preread_size = r->content_length_n;
    } else {
        nxt_debug(task, "no body"); 
    }

I'm not sure how to set length correctly but now I see 

2018/01/12 15:01:52.454 [debug] 21541#21544 *11 body: @3�u�U��7t�UȊ�u�Uϊ�u�UȊ�u�Uϊ�u�Ufoo=bar

in log. So that patch works but everything else is still like in my previous post.

VBart commented 6 years ago

@vladkras it seems the previous attempt to fix isn't complete, please try the following patch:

--- a/src/nxt_http_request.c    Fri Jan 12 16:37:42 2018 +0300
+++ b/src/nxt_http_request.c    Fri Jan 12 16:39:18 2018 +0300
@@ -221,6 +221,7 @@ nxt_http_app_request(nxt_task_t *task, v
     if (r->body != NULL) {
         ar->r.body.buf = r->body;
         ar->r.body.preread_size = r->content_length_n;
+        ar->r.header.parsed_content_length = r->content_length_n;
     }

     ar->r.body.done = 1;
vladkras commented 6 years ago

@VBart yes, this line helps

/unit # curl -d 'foo=bar' 127.0.0.1:8300
2018/01/12 15:34:59.757 [debug] 23960#23961 router app data (43): array(1) {
  ["foo"]=>
  string(3) "bar"
}

I'll try to send more data and files too.