Re: Как лучше хранить логи

Vladimir Rusinov vladimir на greenmice.info
Вт Ноя 9 12:55:30 MSK 2010


2010/11/9 Vladimir Rusinov <vladimir at greenmice.info>
>
> А что в отладочном логе про редирект ?
>>
>
> Если собрано без дебага - ничего. Сейчас попробую собрать с дебагом,
> посмотрю.
>

2010/11/09 01:38:35 [debug] 15706#0: *11402 http proxy header:
"GET / HTTP/1.0
Host: splunk.wrike.com:8000
X-Real-IP: 91.204.22.9
X-Forwarded-For: 91.204.22.9
Connection: close
Accept:
application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5
User-Agent: Mozilla/5.0 (X11; U; Linux i686; en-US) AppleWebKit/534.7
(KHTML, like Gecko) Chrome/7.0.517.36 Safari/534.7
Accept-Encoding: gzip,deflate,sdch
Accept-Language: en-US,en;q=0.8,ru-RU;q=0.6,ru;q=0.4
Accept-Charset: windows-1251,utf-8;q=0.7,*;q=0.3
Cookie:
__utmz=193439723.1283187841.29.3.utmcsr=feedburner|utmccn=Feed:%20WrikeBlog%20(Wrike%20Blog)|utmcmd=feed;
__utmx=193439723.; __utmxx=193439723.;
__utma=193439723.1578913152.1283246862.1288345141.1289219304.13;
session_id_8000=2a5ef837d995064c48ce071154d103457ff888eb

"
<...>
2010/11/09 01:38:35 [debug] 15706#0: *11402 recv: fd:355 430 of 32768
2010/11/09 01:38:35 [debug] 15706#0: *11402 http proxy status 302 "302
Found"
2010/11/09 01:38:35 [debug] 15706#0: *11402 http proxy header: "Date: Tue,
09 Nov 2010 09:38:35 GMT"
2010/11/09 01:38:35 [debug] 15706#0: *11402 http proxy header:
"Content-Length: 123"
2010/11/09 01:38:35 [debug] 15706#0: *11402 http proxy header:
"Content-Type: text/html;charset=utf-8"
2010/11/09 01:38:35 [debug] 15706#0: *11402 http proxy header: "Location:
http://splunk.wrike.com:8000/en-US/"
2010/11/09 01:38:35 [debug] 15706#0: *11402 http proxy header: "Server:
CherryPy/3.1.2"
2010/11/09 01:38:35 [debug] 15706#0: *11402 http proxy header: "Set-Cookie:
session_id_8000=9415a7b9f0c34931c496d22cf309c1227ea36d80; expires=Wed, 10
Nov 2010 09:38:35 GMT; Path=/"
2010/11/09 01:38:35 [debug] 15706#0: *11402 http proxy header done
2010/11/09 01:38:35 [debug] 15706#0: *11402 uploadprogress error-tracker
error: 0
2010/11/09 01:38:35 [debug] 15706#0: *11402 HTTP/1.1 302 Found
Server: nginx
Date: Tue, 09 Nov 2010 09:38:35 GMT
Content-Type: text/html;charset=utf-8
Connection: keep-alive
Content-Length: 123
Location: http://splunk.wrike.com:8000/en-US/
Set-Cookie: session_id_8000=9415a7b9f0c34931c496d22cf309c1227ea36d80;
expires=Wed, 10 Nov 2010 09:38:35 GMT; Path=/

2010/11/09 01:38:35 [debug] 15706#0: *11402 write new buf t:1 f:0
000000000C3CC1E8, pos 000000000C3CC1E8, size: 322 file: 0, size: 0
2010/11/09 01:38:35 [debug] 15706#0: *11402 write new buf t:1 f:0
000000000C3CC1E8, pos 000000000C3CC1E8, size: 322 file: 0, size: 0
2010/11/09 01:38:35 [debug] 15706#0: *11402 http write filter: l:0 f:0 s:322
2010/11/09 01:38:35 [debug] 15706#0: *11402 http cacheable: 0
2010/11/09 01:38:35 [debug] 15706#0: *11402 http upstream process upstream
2010/11/09 01:38:35 [debug] 15706#0: *11402 pipe read upstream: 1
2010/11/09 01:38:35 [debug] 15706#0: *11402 pipe preread: 123
2010/11/09 01:38:35 [debug] 15706#0: *11402 readv: 1:32338
2010/11/09 01:38:35 [debug] 15706#0: *11402 readv() not ready (11: Resource
temporarily unavailable)
2010/11/09 01:38:35 [debug] 15706#0: *11402 pipe recv chain: -2
2010/11/09 01:38:35 [debug] 15706#0: *11402 pipe buf free s:0 t:1 f:0
000000000EC35AB0, pos 000000000EC35BE3, size: 123 file: 0, size: 0
2010/11/09 01:38:35 [debug] 15706#0: *11402 pipe write downstream: 1
2010/11/09 01:38:35 [debug] 15706#0: *11402 pipe write busy: 0
2010/11/09 01:38:35 [debug] 15706#0: *11402 pipe write:
out:0000000000000000, f:0
2010/11/09 01:38:35 [debug] 15706#0: *11402 pipe read upstream: 0
2010/11/09 01:38:35 [debug] 15706#0: *11402 pipe buf free s:0 t:1 f:0
000000000EC35AB0, pos 000000000EC35BE3, size: 123 file: 0, size: 0
2010/11/09 01:38:35 [debug] 15706#0: *11402 event timer: 355, old:
1289295635405, new: 1289295635409
2010/11/09 01:38:35 [debug] 15706#0: *11402 post event 000000000BF0CC20
2010/11/09 01:38:35 [debug] 15706#0: *11402 post event 000000000BE6D880
2010/11/09 01:38:35 [debug] 15706#0: *11402 delete posted event
000000000BE6D880
2010/11/09 01:38:35 [debug] 15706#0: *11402 http upstream request: "/?"
2010/11/09 01:38:35 [debug] 15706#0: *11402 http upstream dummy handler
2010/11/09 01:38:35 [debug] 15706#0: *11402 delete posted event
000000000BF0CC20
2010/11/09 01:38:35 [debug] 15706#0: *11402 http upstream request: "/?"
2010/11/09 01:38:35 [debug] 15706#0: *11402 http upstream process upstream
2010/11/09 01:38:35 [debug] 15706#0: *11402 pipe read upstream: 1
2010/11/09 01:38:35 [debug] 15706#0: *11402 readv: 1:32338
2010/11/09 01:38:35 [debug] 15706#0: *11402 pipe recv chain: 0
2010/11/09 01:38:35 [debug] 15706#0: *11402 pipe buf free s:0 t:1 f:0
000000000EC35AB0, pos 000000000EC35BE3, size: 123 file: 0, size: 0
2010/11/09 01:38:35 [debug] 15706#0: *11402 input buf #0
2010/11/09 01:38:35 [debug] 15706#0: *11402 pipe write downstream: 1
2010/11/09 01:38:35 [debug] 15706#0: *11402 pipe write downstream flush in
2010/11/09 01:38:35 [debug] 15706#0: *11402 http output filter "/?"
2010/11/09 01:38:35 [debug] 15706#0: *11402 copy filter: "/?"
2010/11/09 01:38:35 [debug] 15706#0: *11402 http postpone filter "/?"
000000000C3CC498
2010/11/09 01:38:35 [debug] 15706#0: *11402 write old buf t:1 f:0
000000000C3CC1E8, pos 000000000C3CC1E8, size: 322 file: 0, size: 0
2010/11/09 01:38:35 [debug] 15706#0: *11402 write new buf t:1 f:0
000000000EC35AB0, pos 000000000EC35BE3, size: 123 file: 0, size: 0
2010/11/09 01:38:35 [debug] 15706#0: *11402 http write filter: l:0 f:0 s:445
2010/11/09 01:38:35 [debug] 15706#0: *11402 copy filter: 0 "/?"
2010/11/09 01:38:35 [debug] 15706#0: *11402 pipe write downstream done
<....>


Если сделать proxy_set_header  Host  $host:443:

2010/11/09 01:42:41 [debug] 15848#0: *29433 http proxy header:
"GET / HTTP/1.0
Host: splunk.wrike.com:443
Connection: close
Accept:
application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5
User-Agent: Mozilla/5.0 (X11; U; Linux i686; en-US) AppleWebKit/534.7
(KHTML, like Gecko) Chrome/7.0.517.36 Safari/534.7
Accept-Encoding: gzip,deflate,sdch
Accept-Language: en-US,en;q=0.8,ru-RU;q=0.6,ru;q=0.4
Accept-Charset: windows-1251,utf-8;q=0.7,*;q=0.3
Cookie:
__utmz=193439723.1283187841.29.3.utmcsr=feedburner|utmccn=Feed:%20WrikeBlog%20(Wrike%20Blog)|utmcmd=feed;
__utmx=193439723.; __utmxx=193439723.;
__utma=193439723.1578913152.1283246862.1288345141.1289219304.13;
session_id_8000=9415a7b9f0c34931c496d22cf309c1227ea36d80

"
<...>
2010/11/09 01:42:41 [debug] 15848#0: *29433 http proxy status 302 "302
Found"
2010/11/09 01:42:41 [debug] 15848#0: *29433 http proxy header: "Date: Tue,
09 Nov 2010 09:42:41 GMT"
2010/11/09 01:42:41 [debug] 15848#0: *29433 http proxy header:
"Content-Length: 121"
2010/11/09 01:42:41 [debug] 15848#0: *29433 http proxy header:
"Content-Type: text/html;charset=utf-8"
2010/11/09 01:42:41 [debug] 15848#0: *29433 http proxy header: "Location:
http://splunk.wrike.com:443/en-US/"
2010/11/09 01:42:41 [debug] 15848#0: *29433 http proxy header: "Server:
CherryPy/3.1.2"
2010/11/09 01:42:41 [debug] 15848#0: *29433 http proxy header: "Set-Cookie:
session_id_8000=d26c5c64bfc6b530c399d132c1bdfcc9c03dac43; expires=Wed, 10
Nov 2010 09:42:41 GMT; Path=/"
2010/11/09 01:42:41 [debug] 15848#0: *29433 http proxy header done
2010/11/09 01:42:41 [debug] 15848#0: *29433 uploadprogress error-tracker
error: 0
2010/11/09 01:42:41 [debug] 15848#0: *29433 HTTP/1.1 302 Found
Server: nginx
Date: Tue, 09 Nov 2010 09:42:41 GMT
Content-Type: text/html;charset=utf-8
Connection: keep-alive
Content-Length: 121
Location: http://splunk.wrike.com:443/en-US/
Set-Cookie: session_id_8000=d26c5c64bfc6b530c399d132c1bdfcc9c03dac43;
expires=Wed, 10 Nov 2010 09:42:41 GMT; Path=/
<...>
2010/11/09 01:42:42 [info] 15848#0: *29481 client sent plain HTTP request to
HTTPS port while reading client request headers, client: 91.204.22.9,
server: splunk.wrike.com, request: "GET /en-US/ HTTP/1.1", host: "
splunk.wrike.com:443"
2010/11/09 01:42:42 [debug] 15848#0: *29481 http finalize request: 497,
"/en-US/?" 1
2010/11/09 01:42:42 [debug] 15848#0: *29481 event timer del: 272:
1289295822174
2010/11/09 01:42:42 [debug] 15848#0: *29481 http special response: 497,
"/en-US/?"
2010/11/09 01:42:42 [debug] 15848#0: *29481 http set discard body
2010/11/09 01:42:42 [debug] 15848#0: *29481 uploadprogress error-tracker
error: 400
2010/11/09 01:42:42 [debug] 15848#0: *29481 uploadprogress error-tracker not
tracking in this location
2010/11/09 01:42:42 [debug] 15848#0: *29481 HTTP/1.1 400 Bad Request
Server: nginx
Date: Tue, 09 Nov 2010 09:42:42 GMT
Content-Type: text/html
Content-Length: 666
Connection: close


если сделать proxy_set_header  Host  $host - самое интересное.

"GET / HTTP/1.0
Host: splunk.wrike.com
Connection: close
Cache-Control: max-age=0
Accept:
application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5
User-Agent: Mozilla/5.0 (X11; U; Linux i686; en-US) AppleWebKit/534.7
(KHTML, like Gecko) Chrome/7.0.517.36 Safari/534.7
Accept-Encoding: gzip,deflate,sdch
Accept-Language: en-US,en;q=0.8,ru-RU;q=0.6,ru;q=0.4
Accept-Charset: windows-1251,utf-8;q=0.7,*;q=0.3
Cookie:
__utmz=193439723.1283187841.29.3.utmcsr=feedburner|utmccn=Feed:%20WrikeBlog%20(Wrike%20Blog)|utmcmd=feed;
__utmx=193439723.; __utmxx=193439723.;
__utma=193439723.1578913152.1283246862.1288345141.1289219304.13;
session_id_8000=d26c5c64bfc6b530c399d132c1bdfcc9c03dac43

"
2010/11/09 01:46:03 [debug] 15987#0: *44256 http upstream request: "/?"
2010/11/09 01:46:03 [debug] 15987#0: *44256 http upstream dummy handler
2010/11/09 01:46:03 [debug] 15987#0: *44256 delete posted event
000000000BE6C2F8
2010/11/09 01:46:03 [debug] 15987#0: *44256 http upstream request: "/?"
2010/11/09 01:46:03 [debug] 15987#0: *44256 http upstream process header
2010/11/09 01:46:03 [debug] 15987#0: *44256 malloc: 000000000E7B0160:32768
2010/11/09 01:46:03 [debug] 15987#0: *44256 recv: fd:310 415 of 32768
2010/11/09 01:46:03 [debug] 15987#0: *44256 http proxy status 302 "302
Found"
2010/11/09 01:46:03 [debug] 15987#0: *44256 http proxy header: "Date: Tue,
09 Nov 2010 09:46:03 GMT"
2010/11/09 01:46:03 [debug] 15987#0: *44256 http proxy header:
"Content-Length: 113"
2010/11/09 01:46:03 [debug] 15987#0: *44256 http proxy header:
"Content-Type: text/html;charset=utf-8"
2010/11/09 01:46:03 [debug] 15987#0: *44256 http proxy header: "Location:
http://splunk.wrike.com/en-US/"
2010/11/09 01:46:03 [debug] 15987#0: *44256 http proxy header: "Server:
CherryPy/3.1.2"
2010/11/09 01:46:03 [debug] 15987#0: *44256 http proxy header: "Set-Cookie:
session_id_8000=4aa43c5af2930599ba0fb3b261c7f0a2782d4bd4; expires=Wed, 10
Nov 2010 09:46:03 GMT; Path=/"
2010/11/09 01:46:03 [debug] 15987#0: *44256 http proxy header done
2010/11/09 01:46:03 [debug] 15987#0: *44256 uploadprogress error-tracker
error: 0
2010/11/09 01:46:03 [debug] 15987#0: *44256 HTTP/1.1 302 Found
Server: nginx
Date: Tue, 09 Nov 2010 09:46:03 GMT
Content-Type: text/html;charset=utf-8
Connection: keep-alive
Content-Length: 113
Location: http://splunk.wrike.com/en-US/
Set-Cookie: session_id_8000=4aa43c5af2930599ba0fb3b261c7f0a2782d4bd4;
expires=Wed, 10 Nov 2010 09:46:03 GMT; Path=/
<....>
2010/11/09 01:46:05 [debug] 15987#0: *44385 http script copy: "Host: "
2010/11/09 01:46:05 [debug] 15987#0: *44385 http script var: "
splunk.wrike.com"
2010/11/09 01:46:05 [debug] 15987#0: *44385 http script copy: "
"
2010/11/09 01:46:05 [debug] 15987#0: *44385 http script copy: "Connection:
close
"
2010/11/09 01:46:05 [debug] 15987#0: *44385 http proxy header:
"Cache-Control: max-age=0"
2010/11/09 01:46:05 [debug] 15987#0: *44385 http proxy header: "Accept:
application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5"
2010/11/09 01:46:05 [debug] 15987#0: *44385 http proxy header: "User-Agent:
Mozilla/5.0 (X11; U; Linux i686; en-US) AppleWebKit/534.7 (KHTML, like
Gecko) Chrome/7.0.517.36 Safari/534.7"
2010/11/09 01:46:05 [debug] 15987#0: *44385 http proxy header:
"Accept-Encoding: gzip,deflate,sdch"
2010/11/09 01:46:05 [debug] 15987#0: *44385 http proxy header:
"Accept-Language: en-US,en;q=0.8,ru-RU;q=0.6,ru;q=0.4"
2010/11/09 01:46:05 [debug] 15987#0: *44385 http proxy header:
"Accept-Charset: windows-1251,utf-8;q=0.7,*;q=0.3"
2010/11/09 01:46:05 [debug] 15987#0: *44385 http proxy header: "Cookie:
__utmz=193439723.1283187841.29.3.utmcsr=feedburner|utmccn=Feed:%20WrikeBlog%20(Wrike%20Blog)|utmcmd=feed;
__utmx=193439723.; __utmxx=193439723.;
__utma=193439723.1578913152.1283246862.1288345141.1289219304.13;
session_id_8000=4aa43c5af2930599ba0fb3b261c7f0a2782d4bd4"
2010/11/09 01:46:05 [debug] 15987#0: *44385 http proxy header:
"GET /en-US/ HTTP/1.0
Host: splunk.wrike.com
Connection: close
Cache-Control: max-age=0
Accept:
application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5
User-Agent: Mozilla/5.0 (X11; U; Linux i686; en-US) AppleWebKit/534.7
(KHTML, like Gecko) Chrome/7.0.517.36 Safari/534.7
Accept-Encoding: gzip,deflate,sdch
Accept-Language: en-US,en;q=0.8,ru-RU;q=0.6,ru;q=0.4
Accept-Charset: windows-1251,utf-8;q=0.7,*;q=0.3
Cookie:
__utmz=193439723.1283187841.29.3.utmcsr=feedburner|utmccn=Feed:%20WrikeBlog%20(Wrike%20Blog)|utmcmd=feed;
__utmx=193439723.; __utmxx=193439723.;
__utma=193439723.1578913152.1283246862.1288345141.1289219304.13;
session_id_8000=4aa43c5af2930599ba0fb3b261c7f0a2782d4bd4

"
<...>
2010/11/09 01:46:05 [debug] 15987#0: *44385 http proxy status 302 "302
Found"
2010/11/09 01:46:05 [debug] 15987#0: *44385 http proxy header:
"Content-Length: 130"
2010/11/09 01:46:05 [debug] 15987#0: *44385 http proxy header:
"Content-Encoding: gzip"
2010/11/09 01:46:05 [debug] 15987#0: *44385 http proxy header: "Vary:
Accept-Encoding"
2010/11/09 01:46:05 [debug] 15987#0: *44385 http proxy header: "Server:
CherryPy/3.1.2"
2010/11/09 01:46:05 [debug] 15987#0: *44385 http proxy header: "Location:
http://127.0.0.1:8000/en-US/account/login?return_to=%2Fen-US%2F"
2010/11/09 01:46:05 [debug] 15987#0: *44385 http proxy header: "Date: Tue,
09 Nov 2010 09:46:05 GMT"
2010/11/09 01:46:05 [debug] 15987#0: *44385 http proxy header:
"Content-Type: text/html;charset=utf-8"
2010/11/09 01:46:05 [debug] 15987#0: *44385 http proxy header: "Set-Cookie:
session_id_8000=d121f2d4aafe7bb126562585a7af1c520e9f89cc; expires=Wed, 10
Nov 2010 09:46:05 GMT; Path=/"
2010/11/09 01:46:05 [debug] 15987#0: *44385 http proxy header done
2010/11/09 01:46:05 [debug] 15987#0: *44385 uploadprogress error-tracker
error: 0
2010/11/09 01:46:05 [debug] 15987#0: *44385 HTTP/1.1 302 Found
Server: nginx
Date: Tue, 09 Nov 2010 09:46:05 GMT
Content-Type: text/html;charset=utf-8
Connection: keep-alive
Content-Length: 130
Content-Encoding: gzip
Vary: Accept-Encoding
Location: http://127.0.0.1:8000/en-US/account/login?return_to=%2Fen-US%2F
Set-Cookie: session_id_8000=d121f2d4aafe7bb126562585a7af1c520e9f89cc;
expires=Wed, 10 Nov 2010 09:46:05 GMT; Path=/
<...>


Еще раз конифг:

server {
        listen 10.10.0.30:443;
        server_name splunk.wrike.com;

        ssl                  on;
        ssl_certificate      /etc/nginx/ssl/wrike.crt;
        ssl_certificate_key  /etc/nginx/ssl/wrike.key;
        ssl_session_cache    shared:SSL:10m;
        ssl_session_timeout  10m;

        access_log  /var/log/nginx/splunk.access.log  my_combined;
        error_log /var/log/nginx/splunk.error.log debug;

        location / {
                proxy_set_header  Host  $host;
                proxy_pass    http://10.10.0.17:8000;
                proxy_redirect default;
        }
}
server {
        listen 10.10.0.30:80;
        server_name splunk.wrike.com;

        access_log  /var/log/nginx/splunk.access.log  my_combined;
        error_log /var/log/nginx/splunk.error.log;

        rewrite (.*) https://splunk.wrike.com$1 permanent;
}

nginx version: nginx/0.7.67
built by gcc 4.1.2 20080704 (Red Hat 4.1.2-48)
TLS SNI support disabled
configure arguments: --user=nginx --group=nginx --prefix=/usr/share/nginx
--sbin-path=/usr/sbin/nginx --conf-path=/etc/nginx/nginx.conf
--error-log-path=/var/log/nginx/error.log
--http-log-path=/var/log/nginx/access.log
--http-client-body-temp-path=/var/lib/nginx/tmp/client_body
--http-proxy-temp-path=/var/lib/nginx/tmp/proxy
--http-fastcgi-temp-path=/var/lib/nginx/tmp/fastcgi
--pid-path=/var/run/nginx.pid --lock-path=/var/lock/subsys/nginx
--with-http_ssl_module --with-http_realip_module
--with-http_gzip_static_module --with-http_stub_status_module --with-debug
--with-cc-opt='-O2 -g -m64 -mtune=generic'
--add-module=/usr/src/redhat//BUILD/nginx-0.7.67/nginx-upstream-fair
--add-module=/usr/src/redhat//BUILD/nginx-0.7.67/nginx_uploadprogress_module
--add-module=/usr/src/redhat//BUILD/nginx-0.7.67/nginx_upload_module-2.0.10/

-- 
Vladimir Rusinov
http://greenmice.info/
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://nginx.org/pipermail/nginx-ru/attachments/20101109/f65b588e/attachment-0001.html>


Подробная информация о списке рассылки nginx-ru