Добрый вечер!
У нас образовалось неприятная проблема при обработке запросов (в аттаче 2 примера).
Суть в том, что nginx начинает обрабатывать запрос – читает часть заголовков, потом сваливается с неким ивентом, пропускает остальные заголовки и пытается обработать body запроса как заголовки.
В аксесс логах при этом мы видим следующие записи:
10.0.0.1 - host.name - [15/Jul/2015:20:45:13 +0300] "\x12\x10U\xA6\x9C(\x00\x0E@/" 400 326 "-" "-" "-" 0.038 "-" "-" " " 33256046 - “host.name" "-" "-"
Помогите советом. Куда смотреть, что искать? Как решить эту проблему?
Про nginx:
$ nginx -V
nginx version: nginx/1.8.0
built by gcc 4.2.1 20070719 [FreeBSD]
built with OpenSSL 0.9.8q 2 Dec 2010
TLS SNI support enabled
configure arguments: --prefix=/usr/local/etc/nginx --with-cc-opt='-I /usr/local/include' --with-ld-opt='-L /usr/local/lib' --conf-path=/usr/local/etc/nginx/nginx.conf --sbin-path=/usr/local/sbin/nginx --pid-path=/var/run/nginx.pid --error-log-path=/var/log/nginx-error.log --user=www --group=www --with-file-aio --http-client-body-temp-path=/var/tmp/nginx/client_body_temp --http-fastcgi-temp-path=/var/tmp/nginx/fastcgi_temp --http-proxy-temp-path=/var/tmp/nginx/proxy_temp --http-scgi-temp-path=/var/tmp/nginx/scgi_temp --http-uwsgi-temp-path=/var/tmp/nginx/uwsgi_temp --http-log-path=/var/log/nginx-access.log --add-module=/root/echo-nginx-module --with-http_geoip_module --with-http_perl_module --with-http_stub_status_module --with-pcre --with-http_ssl_module --add-module=/root/ngx_http_pinba_module --add-module=/root/headers-more-nginx-module --with-debug
Заранее спасибо!
—
С уважением,
Клестов Александр2015/07/15 18:16:33 [debug] 72497#0: *15478189 accept: 52.2.105.4:42956 fd:288
2015/07/15 18:16:33 [debug] 72497#0: *15478189 post event 000000080CC058D0
2015/07/15 18:16:33 [debug] 72497#0: *15478189 delete posted event 000000080CC058D0
2015/07/15 18:16:33 [debug] 72497#0: *15478189 http wait request handler
2015/07/15 18:16:33 [debug] 72497#0: *15478189 malloc: 0000000802097000:8192
2015/07/15 18:16:33 [debug] 72497#0: *15478189 recv: eof:0, avail:1, err:0
2015/07/15 18:16:33 [debug] 72497#0: *15478189 recv: fd:288 1326 of 8192
2015/07/15 18:16:33 [debug] 72497#0: *15478189 reusable connection: 0
2015/07/15 18:16:33 [debug] 72497#0: *15478189 posix_memalign: 00000008021AA000:8192 @16
2015/07/15 18:16:33 [debug] 72497#0: *15478189 http process request line
2015/07/15 18:16:33 [debug] 72497#0: *15478189 http request line: "POST /?id=10046 HTTP/1.1"
2015/07/15 18:16:33 [debug] 72497#0: *15478189 http uri: "/"
2015/07/15 18:16:33 [debug] 72497#0: *15478189 http args: "id=10046"
2015/07/15 18:16:33 [debug] 72497#0: *15478189 http exten: ""
2015/07/15 18:16:33 [debug] 72497#0: *15478189 http process request header line
2015/07/15 18:16:33 [debug] 72497#0: *15478189 http header: "Content-Type: application/json; charset=utf-8"
2015/07/15 18:16:33 [debug] 72497#0: *15478189 http header: "x-openrtb-version: 2.0"
2015/07/15 18:16:33 [debug] 72497#0: *15478189 http header: "Content-Length: 1062"
2015/07/15 18:16:33 [debug] 72497#0: *15478189 post event 000000080CC058D0
2015/07/15 18:16:33 [debug] 72497#0: *15478189 delete posted event 000000080CC058D0
2015/07/15 18:16:33 [debug] 72497#0: *15478189 http process request line
2015/07/15 18:16:33 [debug] 72497#0: *15478189 http finalize request: 400, "?" a:1, c:1
2015/07/15 18:16:33 [debug] 72497#0: *15478189 http special response: 400, "?"
2015/07/15 18:16:33 [debug] 72497#0: *15478189 http set discard body
2015/07/15 18:16:33 [debug] 72497#0: *15478189 headers more header filter, uri ""
2015/07/15 18:16:33 [debug] 72497#0: *15478189 charset: "" > "utf-8"
2015/07/15 18:16:33 [debug] 72497#0: *15478189 HTTP/1.1 400 Bad Request
Server: nginx
Date: Wed, 15 Jul 2015 15:16:33 GMT
Content-Type: text/html; charset=utf-8
Content-Length: 166
Connection: close
2015/07/15 18:16:33 [debug] 72497#0: *15478189 write new buf t:1 f:0 00000008021AAFF0, pos 00000008021AAFF0, size: 160 file: 0, size: 0
2015/07/15 18:16:33 [debug] 72497#0: *15478189 http write filter: l:0 f:0 s:160
2015/07/15 18:16:33 [debug] 72497#0: *15478189 http output filter "?"
2015/07/15 18:16:33 [debug] 72497#0: *15478189 http copy filter: "?"
2015/07/15 18:16:33 [debug] 72497#0: *15478189 http postpone filter "?" 00000008021AB1D0
2015/07/15 18:16:33 [debug] 72497#0: *15478189 write old buf t:1 f:0 00000008021AAFF0, pos 00000008021AAFF0, size: 160 file: 0, size: 0
2015/07/15 18:16:33 [debug] 72497#0: *15478189 write new buf t:0 f:0 0000000000000000, pos 00000000005BFD20, size: 120 file: 0, size: 0
2015/07/15 18:16:33 [debug] 72497#0: *15478189 write new buf t:0 f:0 0000000000000000, pos 00000000005BF900, size: 46 file: 0, size: 0
2015/07/15 18:16:33 [debug] 72497#0: *15478189 http write filter: l:1 f:0 s:326
2015/07/15 18:16:33 [debug] 72497#0: *15478189 http write filter limit 0
2015/07/15 18:16:33 [debug] 72497#0: *15478189 writev: 326 of 326
2015/07/15 18:16:33 [debug] 72497#0: *15478189 http write filter 0000000000000000
2015/07/15 18:16:33 [debug] 72497#0: *15478189 http copy filter: 0 "?"
2015/07/15 18:16:33 [debug] 72497#0: *15478189 http finalize request: 0, "?" a:1, c:1
2015/07/15 18:16:33 [debug] 72497#0: *15478189 event timer add: 288: 5000:1436973398157
2015/07/15 18:16:33 [debug] 72497#0: *15478189 kevent: 288: ft:-1 fl:8020 ff:00000036 d:0 ud:000000080CC058D0
2015/07/15 18:16:33 [debug] 72497#0: *15478189 http lingering close handler
2015/07/15 18:16:33 [debug] 72497#0: *15478189 recv: eof:1, avail:0, err:54
2015/07/15 18:16:33 [debug] 72497#0: *15478189 lingering read: -1
2015/07/15 18:16:33 [debug] 72497#0: *15478189 http request count:1 blk:0
2015/07/15 18:16:33 [debug] 72497#0: *15478189 http close request
2015/07/15 18:16:33 [debug] 72497#0: *15478189 http log handler
2015/07/15 18:16:33 [debug] 72497#0: *15478189 http pinba handler
2015/07/15 18:16:33 [debug] 72497#0: *15478189 free: 00000008021AA000, unused: 1863
2015/07/15 18:16:33 [debug] 72497#0: *15478189 close http connection: 288
2015/07/15 18:16:33 [debug] 72497#0: *15478189 event timer del: 288: 1436973398157
2015/07/15 18:16:33 [debug] 72497#0: *15478189 reusable connection: 0
2015/07/15 18:16:33 [debug] 72497#0: *15478189 free: 0000000802097000
2015/07/15 18:16:33 [debug] 72497#0: *15478189 free: 000000080226F000, unused: 3712
2015/07/15 18:22:50 [debug] 91299#0: *16221160 accept: 52.2.105.4:36834 fd:115
2015/07/15 18:22:50 [debug] 91299#0: *16221160 post event 000000080CC00F50
2015/07/15 18:22:50 [debug] 91299#0: *16221160 delete posted event 000000080CC00F50
2015/07/15 18:22:50 [debug] 91299#0: *16221160 http wait request handler
2015/07/15 18:22:50 [debug] 91299#0: *16221160 malloc: 000000080235A000:8192
2015/07/15 18:22:50 [debug] 91299#0: *16221160 recv: eof:0, avail:1, err:0
2015/07/15 18:22:50 [debug] 91299#0: *16221160 recv: fd:115 1432 of 8192
2015/07/15 18:22:50 [debug] 91299#0: *16221160 reusable connection: 0
2015/07/15 18:22:50 [debug] 91299#0: *16221160 posix_memalign: 000000080235C000:8192 @16
2015/07/15 18:22:50 [debug] 91299#0: *16221160 http process request line
2015/07/15 18:22:50 [debug] 91299#0: *16221160 http request line: "POST /?id=10046 HTTP/1.1"
2015/07/15 18:22:50 [debug] 91299#0: *16221160 http uri: "/"
2015/07/15 18:22:50 [debug] 91299#0: *16221160 http args: "id=10046"
2015/07/15 18:22:50 [debug] 91299#0: *16221160 http exten: ""
2015/07/15 18:22:50 [debug] 91299#0: *16221160 http process request header line
2015/07/15 18:22:50 [debug] 91299#0: *16221160 http header: "Content-Type: application/json; charset=utf-8"
2015/07/15 18:22:50 [debug] 91299#0: *16221160 http header: "x-openrtb-version: 2.0"
2015/07/15 18:22:50 [debug] 91299#0: *16221160 http header: "Content-Length: 1168"
2015/07/15 18:22:50 [debug] 91299#0: *16221160 post event 000000080CC00F50
2015/07/15 18:22:50 [debug] 91299#0: *16221160 delete posted event 000000080CC00F50
2015/07/15 18:22:50 [debug] 91299#0: *16221160 http process request line
2015/07/15 18:22:50 [info] 91299#0: *16221160 client sent invalid method while reading client pipelined request line, client: 52.2.105.4, server: , request: "{"app":{"cat":["IAB1"],"domain":"www.amazon.com","id":"101001811","name":"A: Bubble Birds 3_A: Bubble Birds 3_Android_XXLARGE_320x50","publisher":{"id":"1001000147","name":"XIMAD INC"}},"at":2,"bcat":["IAB7-28","IAB17-18","IAB26","IAB25","IAB7-42","IAB9-9","IAB24","IAB23"],"device":{"carrier":"250-01","connectiontype":2,"devicetype":1,"didsha1":"e4017e11d4efe8e8f7d1ae481cde4f8730c9d480","dnt":0,"geo":{"country":"RUS","lat":55.124958,"lon":37.95398,"type":1},"ip":"109.188..126.8","js":1,"make":"Generic","model":"Android 4.4","os":"Android","osv":"4.4","ua":"Mozilla/5.0 (Linux; U; Android 4.4.4; ru-ru; HUAWEI G510-0010 Build/GRJ90) AppleWebKit/534.30 (KHTML, like Gecko) Version/4.0 Mobile Safari/534.30"},"ext":{"carriername":"unknown - probably WLAN","coppa":0,"operaminibrowser":0,"udi":{"googleadid":"7bae59c6-9640-491c-a494-14f09b106fdf","googlednt":0,"imei":"862074021400892"}},"id":"FI9WVKCpkS","imp":[{"banner":{"api":[3],"h":50,"mimes":["application/javascript","image/gif","image/jpeg","image/png","text/html","text/javascript","text/plain"],"pos":0,"w":320},"displaymanager":"SOMA","displaymanagerver":"sdkandroid_4-3-3","id":"1","instl":0}],"user":{}}"
2015/07/15 18:22:50 [debug] 91299#0: *16221160 http finalize request: 400, "?" a:1, c:1
2015/07/15 18:22:50 [debug] 91299#0: *16221160 http special response: 400, "?"
2015/07/15 18:22:50 [debug] 91299#0: *16221160 http set discard body
2015/07/15 18:22:50 [debug] 91299#0: *16221160 headers more header filter, uri ""
2015/07/15 18:22:50 [debug] 91299#0: *16221160 charset: "" > "utf-8"
2015/07/15 18:22:50 [debug] 91299#0: *16221160 HTTP/1.1 400 Bad Request
2015/07/15 18:22:50 [debug] 91299#0: *16221160 write new buf t:1 f:0 000000080235CFF0, pos 000000080235CFF0, size: 160 file: 0, size: 0
2015/07/15 18:22:50 [debug] 91299#0: *16221160 http write filter: l:0 f:0 s:160
2015/07/15 18:22:50 [debug] 91299#0: *16221160 http output filter "?"
2015/07/15 18:22:50 [debug] 91299#0: *16221160 http copy filter: "?"
2015/07/15 18:22:50 [debug] 91299#0: *16221160 http postpone filter "?" 000000080235D1D0
2015/07/15 18:22:50 [debug] 91299#0: *16221160 write old buf t:1 f:0 000000080235CFF0, pos 000000080235CFF0, size: 160 file: 0, size: 0
2015/07/15 18:22:50 [debug] 91299#0: *16221160 write new buf t:0 f:0 0000000000000000, pos 00000000005BFD20, size: 120 file: 0, size: 0
2015/07/15 18:22:50 [debug] 91299#0: *16221160 write new buf t:0 f:0 0000000000000000, pos 00000000005BF900, size: 46 file: 0, size: 0
2015/07/15 18:22:50 [debug] 91299#0: *16221160 http write filter: l:1 f:0 s:326
2015/07/15 18:22:50 [debug] 91299#0: *16221160 http write filter limit 0
2015/07/15 18:22:50 [debug] 91299#0: *16221160 writev: 326 of 326
2015/07/15 18:22:50 [debug] 91299#0: *16221160 http write filter 0000000000000000
2015/07/15 18:22:50 [debug] 91299#0: *16221160 http copy filter: 0 "?"
2015/07/15 18:22:50 [debug] 91299#0: *16221160 http finalize request: 0, "?" a:1, c:1
2015/07/15 18:22:50 [debug] 91299#0: *16221160 event timer add: 115: 5000:1436973775334
_______________________________________________
nginx-ru mailing list
nginx-ru@nginx.org
http://mailman.nginx.org/mailman/listinfo/nginx-ru
