Skip to content

Problem with POST's #10

New issue
New issue
Closed
Closed
Problem with POST's#10
Assignees
mar0x
@gummiboll

Description

@gummiboll
gummiboll
opened on Sep 7, 2017

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
(
)

Activity

mar0x
self-assigned this
on Sep 7, 2017
fblr
added a commit that references this issue on Sep 7, 2017

Moving body data before headers for PHP POST.

d87a4fb
fblr
closed this as completedin d87a4fbon Sep 7, 2017
mar0x
mentioned this on Sep 22, 2017
vladkras

vladkras commented on Jan 12, 2018

@vladkras
vladkras
on Jan 12, 2018

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

VBart commented on Jan 12, 2018

@VBart
VBart
on Jan 12, 2018
Contributor

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

vladkras

vladkras commented on Jan 12, 2018

@vladkras
vladkras
on Jan 12, 2018 · edited by vladkras

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-urlencoded�7foo=bar
HTTP_HOST127.0.0.1:8300�HTTP_USER_AGENT
                                       curl/7.57.0
                                                  HTTP_ACCEPT�*/*�HTTP_CONTENT_LENGTH�7�HTTP_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

vladkras commented on Jan 12, 2018

@vladkras
vladkras
on Jan 12, 2018

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

VBart commented on Jan 12, 2018

@VBart
VBart
on Jan 12, 2018 · edited by VBart
Contributor

@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

vladkras commented on Jan 12, 2018

@vladkras
vladkras
on Jan 12, 2018 · edited by vladkras

@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.

kkzetAM
mentioned this on Jun 22, 2022
nginx-hg-mirror
added a commit that references this issue on May 18, 2023

Python: Fix ASGI applications accessed over IPv6.

47683c4
ac000
added 2 commits that reference this issue on Nov 8, 2023

Ruby: Allow empty response headers.

ebf31d2

Ruby: Allow empty response headers.

5a82c9b
andrey-zelenkov
added a commit that references this issue on Jan 31, 2024

NJS: avoiding arithmetic ops with NULL pointer in r->args.

79a9a60

19 remaining items

Loading
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

No labels
No labels

Type

No type

Projects

No projects

Milestone

No milestone

Relationships

None yet

    Development

    No branches or pull requests

      Participants

      @gummiboll@VBart@vladkras@mar0x

      Issue actions
        Problem with POST's · Issue #10 · nginx/unit