Re: SOAP POST request lag

[Vitaliy Okulov <vitaliy.okulov@xxxxxxxxx>]

Не правила как раз написано нормально. Ситуация в том, что сервер, куда уходит запрос имеет 2-а IP: 1 - real ip, а 2-ой - из тойже подсетки, что и сервер, откуда идет запрос.
То есть через firewall проходит только трафик от 2-го сервера, а первый сервер отвечает напрямую, то есть без участия firewall сервера.
Соотвественно соединение висит на firewall сервере в состоянии CLOSED:SYN_SENT положенное в tcp.opening время и сбрасывает его.
Так что проблему локализовали и сейчас решаем.

21 мая 2009 г. 14:03 пользователь Alexey V. Karagodov <kav@xxxxxxxxxxxxxx> написал:

правила пф кривые
на шлюзе:
netstat -rn
cat /etc/rc.conf
cat /etc/pf.conf
traceroute -n 81.222.111.222
traceroute -n внешний_ип

на внутреннем сервере:
что там?
traceroute -n 81.222.111.222
traceroute -n внешний_ип

если нечто слушает на шлюзовом сервере и приходит запрос на внешний ИП из внутренней сети, то ответ всё равно должен уходить куда надо и как надо
что за сервис? хттп?
как внутренний сервер достигает интернета? нат?

On 21.05.2009, at 11:53, Vitaliy Okulov wrote:

Докопался, у меня 2-а сервера, на 1-ом - 1 real ip, 1 lan ip. На 2-м сервере
1 lan ip. Соотвественно, когда 2-ой сервер делает запрос на real ip адрес
первого сервера, то данный сервер отправляет ответные пакеты не через шлюз,
а напрямую на 2-ой сервер, но с real ip адресом, как адрес отправителя.
То есть получается такой треугольник при запросе.

Шлюзовому оборудованию видимо это не нравится. Пойду посмотрю может быть в
pf дело.

20 мая 2009 г. 16:39 пользователь Igor Sysoev <is@xxxxxxxxxxxxx> написал:

On Sun, May 17, 2009 at 06:56:55PM +0400, Vitaliy Okulov wrote:

Коллеги, кто может подсказать почему возникает лаг в 50 секунд при POST
запросе от SOAP клиента, может ли в этом виноват nginx? При томже запросе
напрямую (то есть без nginx сервера) все работает без проблем.

Насколько я могу судить из приведённого лога, ядро в первом случае не
присылает новые события в течение 50 секунд, а потом и 60 (после второго
таймаута соединение закрывается). То есть, nginx вроде отрабатывает
нормально.

Debug лог:

2009/05/17 18:43:15 [debug] 20128#0: *598 event timer del: 206:
1242571455407
2009/05/17 18:43:15 [debug] 20128#0: *598 generic phase: 0
2009/05/17 18:43:15 [debug] 20128#0: *598 generic phase: 1
2009/05/17 18:43:15 [debug] 20128#0: *598 find location for
"/webservices.php/user_content"
2009/05/17 18:43:15 [debug] 20128#0: *598 find location: "/"
2009/05/17 18:43:15 [debug] 20128#0: *598 using configuration "/"
2009/05/17 18:43:15 [debug] 20128#0: *598 http cl:258589 max:62914560
2009/05/17 18:43:15 [debug] 20128#0: *598 generic phase: 3
2009/05/17 18:43:15 [debug] 20128#0: *598 post rewrite phase: 4
2009/05/17 18:43:15 [debug] 20128#0: *598 generic phase: 5
2009/05/17 18:43:15 [debug] 20128#0: *598 generic phase: 6
2009/05/17 18:43:15 [debug] 20128#0: *598 access phase: 7
2009/05/17 18:43:15 [debug] 20128#0: *598 access phase: 8
2009/05/17 18:43:15 [debug] 20128#0: *598 access phase: 9
2009/05/17 18:43:15 [debug] 20128#0: *598 post access phase: 10
2009/05/17 18:43:15 [debug] 20128#0: *598 malloc: 000000000094B000:4096
2009/05/17 18:43:15 [debug] 20128#0: *598 http client request body

preread

819
2009/05/17 18:43:15 [debug] 20128#0: *598 malloc: 000000000118B000:131072
2009/05/17 18:43:15 [debug] 20128#0: *598 http read client request body
2009/05/17 18:43:15 [debug] 20128#0: *598 recv: eof:0, avail:3320, err:0
2009/05/17 18:43:15 [debug] 20128#0: *598 recv: fd:206 7664 of 131072
2009/05/17 18:43:15 [debug] 20128#0: *598 http client request body recv

7664

2009/05/17 18:43:15 [debug] 20128#0: *598 http client request body rest
250106
2009/05/17 18:43:15 [debug] 20128#0: *598 event timer add: 206:
60000:1242571455407
2009/05/17 18:43:15 [debug] 20128#0: *598 post event 0000000000D2B690
2009/05/17 18:43:15 [debug] 20128#0: *598 delete posted event
0000000000D2B690
2009/05/17 18:43:15 [debug] 20128#0: *598 http read client request body
2009/05/17 18:43:15 [debug] 20128#0: *598 recv: eof:0, avail:8688, err:0
2009/05/17 18:43:15 [debug] 20128#0: *598 recv: fd:206 8688 of 123408
2009/05/17 18:43:15 [debug] 20128#0: *598 http client request body recv

8688

2009/05/17 18:43:15 [debug] 20128#0: *598 http client request body rest
241418
2009/05/17 18:43:15 [debug] 20128#0: *598 event timer: 206, old:
1242571455407, new: 1242571455408
2009/05/17 18:43:15 [debug] 20128#0: *598 post event 0000000000D2B690
2009/05/17 18:43:15 [debug] 20128#0: *598 delete posted event
0000000000D2B690
2009/05/17 18:43:15 [debug] 20128#0: *598 http read client request body
2009/05/17 18:43:15 [debug] 20128#0: *598 recv: eof:0, avail:4344, err:0
2009/05/17 18:43:15 [debug] 20128#0: *598 recv: fd:206 13032 of 114720
2009/05/17 18:43:15 [debug] 20128#0: *598 http client request body recv
13032
2009/05/17 18:43:15 [debug] 20128#0: *598 http client request body rest
228386
2009/05/17 18:43:15 [debug] 20128#0: *598 event timer: 206, old:
1242571455407, new: 1242571455409
2009/05/17 18:43:15 [debug] 20128#0: *598 post event 0000000000D2B690
2009/05/17 18:43:15 [debug] 20128#0: *598 delete posted event
0000000000D2B690
2009/05/17 18:43:15 [debug] 20128#0: *598 http read client request body
2009/05/17 18:43:15 [debug] 20128#0: *598 recv: eof:0, avail:8688, err:0
2009/05/17 18:43:15 [debug] 20128#0: *598 recv: fd:206 20272 of 101688
2009/05/17 18:43:15 [debug] 20128#0: *598 http client request body recv
20272
2009/05/17 18:43:15 [debug] 20128#0: *598 http client request body rest
208114
2009/05/17 18:43:15 [debug] 20128#0: *598 event timer: 206, old:
1242571455407, new: 1242571455409
2009/05/17 18:43:15 [debug] 20128#0: *598 post event 0000000000D2B690
2009/05/17 18:43:15 [debug] 20128#0: *598 delete posted event
0000000000D2B690
2009/05/17 18:43:15 [debug] 20128#0: *598 http read client request body
2009/05/17 18:43:15 [debug] 20128#0: *598 recv: eof:0, avail:11584, err:0
2009/05/17 18:43:15 [debug] 20128#0: *598 recv: fd:206 11584 of 81416
2009/05/17 18:43:15 [debug] 20128#0: *598 http client request body recv
11584
2009/05/17 18:43:15 [debug] 20128#0: *598 http client request body rest
196530
2009/05/17 18:43:15 [debug] 20128#0: *598 event timer: 206, old:
1242571455407, new: 1242571455409
2009/05/17 18:43:15 [debug] 20128#0: *598 post event 0000000000D2B690
2009/05/17 18:43:15 [debug] 20128#0: *598 delete posted event
0000000000D2B690
2009/05/17 18:43:15 [debug] 20128#0: *598 http read client request body
2009/05/17 18:43:15 [debug] 20128#0: *598 recv: eof:0, avail:4344, err:0
2009/05/17 18:43:15 [debug] 20128#0: *598 recv: fd:206 4344 of 69832
2009/05/17 18:43:15 [debug] 20128#0: *598 http client request body recv

4344

2009/05/17 18:43:15 [debug] 20128#0: *598 http client request body rest
192186
2009/05/17 *18:43:15* [debug] 20128#0: *598 event timer: 206, old:
1242571455407, new: 1242571455409
2009/05/17 *18:44:06* [debug] 20128#0: *598 http read client request body
2009/05/17 18:44:06 [debug] 20128#0: *598 recv: eof:0, avail:1448, err:0
2009/05/17 18:44:06 [debug] 20128#0: *598 recv: fd:206 1448 of 65488
2009/05/17 18:44:06 [debug] 20128#0: *598 http client request body recv

1448

2009/05/17 18:44:06 [debug] 20128#0: *598 http client request body rest
190738
2009/05/17 18:44:06 [debug] 20128#0: *598 event timer del: 206:
1242571455407
2009/05/17 18:44:06 [debug] 20128#0: *598 event timer add: 206:
60000:1242571506913
2009/05/17 18:44:07 [debug] 20128#0: *598 http read client request body
2009/05/17 18:44:07 [debug] 20128#0: *598 recv: eof:0, avail:2896, err:0
2009/05/17 18:44:07 [debug] 20128#0: *598 recv: fd:206 2896 of 64040
2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body recv

2896

2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body rest
187842
2009/05/17 18:44:07 [debug] 20128#0: *598 event timer: 206, old:
1242571506913, new: 1242571507013
2009/05/17 18:44:07 [debug] 20128#0: *598 http read client request body
2009/05/17 18:44:07 [debug] 20128#0: *598 recv: eof:0, avail:2896, err:0
2009/05/17 18:44:07 [debug] 20128#0: *598 recv: fd:206 4344 of 61144
2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body recv

4344

2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body rest
183498
2009/05/17 18:44:07 [debug] 20128#0: *598 event timer: 206, old:
1242571506913, new: 1242571507014
2009/05/17 18:44:07 [debug] 20128#0: *598 http read client request body
2009/05/17 18:44:07 [debug] 20128#0: *598 recv: eof:0, avail:5792, err:0
2009/05/17 18:44:07 [debug] 20128#0: *598 recv: fd:206 5792 of 56800
2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body recv

5792

2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body rest
177706
2009/05/17 18:44:07 [debug] 20128#0: *598 event timer: 206, old:
1242571506913, new: 1242571507014
2009/05/17 18:44:07 [debug] 20128#0: *598 http read client request body
2009/05/17 18:44:07 [debug] 20128#0: *598 recv: eof:0, avail:1448, err:0
2009/05/17 18:44:07 [debug] 20128#0: *598 recv: fd:206 1448 of 51008
2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body recv

1448

2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body rest
176258
2009/05/17 18:44:07 [debug] 20128#0: *598 event timer: 206, old:
1242571506913, new: 1242571507014
2009/05/17 18:44:07 [debug] 20128#0: *598 http read client request body
2009/05/17 18:44:07 [debug] 20128#0: *598 recv: eof:0, avail:5792, err:0
2009/05/17 18:44:07 [debug] 20128#0: *598 recv: fd:206 5792 of 49560
2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body recv

5792

2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body rest
170466
2009/05/17 18:44:07 [debug] 20128#0: *598 event timer: 206, old:
1242571506913, new: 1242571507014
2009/05/17 18:44:07 [debug] 20128#0: *598 http read client request body
2009/05/17 18:44:07 [debug] 20128#0: *598 recv: eof:0, avail:2896, err:0
2009/05/17 18:44:07 [debug] 20128#0: *598 recv: fd:206 2896 of 43768
2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body recv

2896

2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body rest
167570
2009/05/17 18:44:07 [debug] 20128#0: *598 event timer: 206, old:
1242571506913, new: 1242571507014
2009/05/17 18:44:07 [debug] 20128#0: *598 http read client request body
2009/05/17 18:44:07 [debug] 20128#0: *598 recv: eof:0, avail:5296, err:0
2009/05/17 18:44:07 [debug] 20128#0: *598 recv: fd:206 5296 of 40872
2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body recv

5296

2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body rest
162274
2009/05/17 18:44:07 [debug] 20128#0: *598 event timer: 206, old:
1242571506913, new: 1242571507014
2009/05/17 18:44:07 [debug] 20128#0: *598 http read client request body
2009/05/17 18:44:07 [debug] 20128#0: *598 recv: eof:0, avail:8688, err:0
2009/05/17 18:44:07 [debug] 20128#0: *598 recv: fd:206 8688 of 35576
2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body recv

8688

2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body rest
153586
2009/05/17 18:44:07 [debug] 20128#0: *598 event timer: 206, old:
1242571506913, new: 1242571507014
2009/05/17 18:44:07 [debug] 20128#0: *598 http read client request body
2009/05/17 18:44:07 [debug] 20128#0: *598 recv: eof:0, avail:1448, err:0
2009/05/17 18:44:07 [debug] 20128#0: *598 recv: fd:206 7240 of 26888
2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body recv

7240

2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body rest
146346
2009/05/17 18:44:07 [debug] 20128#0: *598 event timer: 206, old:
1242571506913, new: 1242571507015
2009/05/17 18:44:07 [debug] 20128#0: *598 http read client request body
2009/05/17 18:44:07 [debug] 20128#0: *598 recv: eof:0, avail:2896, err:0
2009/05/17 18:44:07 [debug] 20128#0: *598 recv: fd:206 7240 of 19648
2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body recv

7240

2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body rest
139106
2009/05/17 18:44:07 [debug] 20128#0: *598 event timer: 206, old:
1242571506913, new: 1242571507015
2009/05/17 18:44:07 [debug] 20128#0: *598 http read client request body
2009/05/17 18:44:07 [debug] 20128#0: *598 recv: eof:0, avail:1448, err:0
2009/05/17 18:44:07 [debug] 20128#0: *598 recv: fd:206 8688 of 12408
2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body recv

8688

2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body rest
130418
2009/05/17 18:44:07 [debug] 20128#0: *598 event timer: 206, old:
1242571506913, new: 1242571507015
2009/05/17 18:44:07 [debug] 20128#0: *598 http read client request body
2009/05/17 18:44:07 [debug] 20128#0: *598 recv: eof:0, avail:5792, err:0
2009/05/17 18:44:07 [debug] 20128#0: *598 recv: fd:206 3720 of 3720
2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body recv

3720

2009/05/17 18:44:07 [debug] 20128#0: *598 add cleanup: 000000000094B238
2009/05/17 18:44:07 [debug] 20128#0: *598 hashed path:
/var/nginx/client_body_temp/0000000003
2009/05/17 18:44:07 [debug] 20128#0: *598 temp fd:211
2009/05/17 18:44:07 [warn] 20128#0: *598 a client request body is

buffered

to a temporary file /var/nginx/client_body_temp/0000000003, client:

x.x.x.x,

server: example.com, request: "POST /webservices.php/user_content

HTTP/1.1",

host: "example.com"
2009/05/17 18:44:07 [debug] 20128#0: *598 write: 211, 000000000118B000,
131072, 0
2009/05/17 18:44:07 [debug] 20128#0: *598 recv: eof:0, avail:2072, err:0
2009/05/17 18:44:07 [debug] 20128#0: *598 recv: fd:206 2072 of 126698
2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body recv

2072

2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body rest
124626
2009/05/17 18:44:07 [debug] 20128#0: *598 event timer: 206, old:
1242571506913, new: 1242571507015
2009/05/17 18:45:06 [debug] 20128#0: *598 event timer del: 206:
1242571506913
2009/05/17 18:45:06 [debug] 20128#0: *598 http finalize request: 408,
"/webservices.php/user_content?"
2009/05/17 18:45:06 [debug] 20128#0: *598 http close request
2009/05/17 18:45:06 [debug] 20128#0: *598 http log handler
2009/05/17 18:45:06 [debug] 20128#0: *598 run cleanup: 000000000094B238
2009/05/17 18:45:06 [debug] 20128#0: *598 file cleanup: fd:211
2009/05/17 18:45:06 [debug] 20128#0: *598 free: 000000000118B000
2009/05/17 18:45:06 [debug] 20128#0: *598 free: 000000000094A000, unused:

8

2009/05/17 18:45:06 [debug] 20128#0: *598 free: 000000000094B000, unused:
3344
2009/05/17 18:45:06 [debug] 20128#0: *598 close http connection: 206
2009/05/17 18:45:06 [debug] 20128#0: *598 free: 00000000005EA400
2009/05/17 18:45:06 [debug] 20128#0: *598 free: 00000000005E2800
2009/05/17 18:45:06 [debug] 20128#0: *598 free: 0000000000918600, unused:

8

2009/05/17 18:45:06 [debug] 20128#0: *598 free: 0000000000918700, unused:
112

--
Игорь Сысоев
http://sysoev.ru