Project

General

Profile

Download (15.1 KB)

Defect #17928 ยป error2.log

Jonathan Heng, 2014-09-22 15:42

 
1 
[Mon Sep 22 08:49:05.183359 2014] [core:trace5] [pid 2636:tid 1076] protocol.c(616): [client 10.1.59.68:63213] Request received from client: GET /redmine/groups HTTP/1.1
2 
[Mon Sep 22 08:49:05.183359 2014] [http:trace4] [pid 2636:tid 1076] http_request.c(300): [client 10.1.59.68:63213] Headers received from client:, referer: http://RedmineServer001/redmine/admin
3 
[Mon Sep 22 08:49:05.183359 2014] [http:trace4] [pid 2636:tid 1076] http_request.c(303): [client 10.1.59.68:63213]   Host: RedmineServer001, referer: http://RedmineServer001/redmine/admin
4 
[Mon Sep 22 08:49:05.183359 2014] [http:trace4] [pid 2636:tid 1076] http_request.c(303): [client 10.1.59.68:63213]   Connection: keep-alive, referer: http://RedmineServer001/redmine/admin
5 
[Mon Sep 22 08:49:05.183359 2014] [http:trace4] [pid 2636:tid 1076] http_request.c(303): [client 10.1.59.68:63213]   Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8, referer: http://RedmineServer001/redmine/admin
6 
[Mon Sep 22 08:49:05.183359 2014] [http:trace4] [pid 2636:tid 1076] http_request.c(303): [client 10.1.59.68:63213]   User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/37.0.2062.120 Safari/537.36, referer: http://RedmineServer001/redmine/admin
7 
[Mon Sep 22 08:49:05.183359 2014] [http:trace4] [pid 2636:tid 1076] http_request.c(303): [client 10.1.59.68:63213]   Referer: http://RedmineServer001/redmine/admin, referer: http://RedmineServer001/redmine/admin
8 
[Mon Sep 22 08:49:05.183359 2014] [http:trace4] [pid 2636:tid 1076] http_request.c(303): [client 10.1.59.68:63213]   Accept-Encoding: gzip,deflate,sdch, referer: http://RedmineServer001/redmine/admin
9 
[Mon Sep 22 08:49:05.183359 2014] [http:trace4] [pid 2636:tid 1076] http_request.c(303): [client 10.1.59.68:63213]   Accept-Language: en-US,en;q=0.8, referer: http://RedmineServer001/redmine/admin
10 
[Mon Sep 22 08:49:05.183359 2014] [http:trace4] [pid 2636:tid 1076] http_request.c(303): [client 10.1.59.68:63213]   Cookie: _redmine_session=BAh7B0kiD3Nlc3Npb25faWQGOgZFRkkiJWE5M2I4OGU3NTdiMzdhMTcyZGNmMjAwN2E0ZDgzMTVjBjsAVEkiEF9jc3JmX3Rva2VuBjsARkkiMXViK0orZ21FUVZndXh0N3pEaXlNQ2gwcVZML2RuaE1UTTM1SjZnRG9RVHc9BjsARg%3D%3D--b2f38fd33d164770e05938eadf09b864c07521de, referer: http://RedmineServer001/redmine/admin
11 
[Mon Sep 22 08:49:05.183359 2014] [authz_core:debug] [pid 2636:tid 1076] mod_authz_core.c(799): [client 10.1.59.68:63213] AH01626: authorization result of Require valid-user : denied (no authenticated user yet), referer: http://RedmineServer001/redmine/admin
12 
[Mon Sep 22 08:49:05.183359 2014] [authz_core:debug] [pid 2636:tid 1076] mod_authz_core.c(799): [client 10.1.59.68:63213] AH01626: authorization result of <RequireAny>: denied (no authenticated user yet), referer: http://RedmineServer001/redmine/admin
13 
[Mon Sep 22 08:49:05.183359 2014] [auth_ntlm:debug] [pid 2636:tid 1076] mod_ntlm_authentication.c(476): [client 10.1.59.68:63213] SSPI00001: Entering authenticate_sspi_user(), referer: http://RedmineServer001/redmine/admin
14 
[Mon Sep 22 08:49:05.183359 2014] [auth_ntlm:debug] [pid 2636:tid 1076] mod_ntlm_authentication.c(580): [client 10.1.59.68:63213] SSPI00009: Authenticated user: APPDOMAIN\\j.smith, referer: http://RedmineServer001/redmine/admin
15 
[Mon Sep 22 08:49:05.183359 2014] [authz_core:debug] [pid 2636:tid 1076] mod_authz_core.c(799): [client 10.1.59.68:63213] AH01626: authorization result of Require valid-user : granted, referer: http://RedmineServer001/redmine/admin
16 
[Mon Sep 22 08:49:05.183359 2014] [authz_core:debug] [pid 2636:tid 1076] mod_authz_core.c(799): [client 10.1.59.68:63213] AH01626: authorization result of <RequireAny>: granted, referer: http://RedmineServer001/redmine/admin
17 
[Mon Sep 22 08:49:05.183359 2014] [proxy_balancer:trace1] [pid 2636:tid 1076] mod_proxy_balancer.c(73): [client 10.1.59.68:63213] canonicalising URL //redminecluster/groups, referer: http://RedmineServer001/redmine/admin
18 
[Mon Sep 22 08:49:05.183359 2014] [rewrite:trace3] [pid 2636:tid 1076] mod_rewrite.c(475): [client 10.1.59.68:63213] 10.1.59.68 - APPDOMAIN\\j.smith [RedmineServer001/sid#15ca268][rid#2586128/initial] [perdir /redmine/] add path info postfix: proxy:balancer://redminecluster/groups -> proxy:balancer://redminecluster/groups/groups, referer: http://RedmineServer001/redmine/admin
19 
[Mon Sep 22 08:49:05.183359 2014] [rewrite:trace3] [pid 2636:tid 1076] mod_rewrite.c(475): [client 10.1.59.68:63213] 10.1.59.68 - APPDOMAIN\\j.smith [RedmineServer001/sid#15ca268][rid#2586128/initial] [perdir /redmine/] applying pattern '.' to uri 'proxy:balancer://redminecluster/groups/groups', referer: http://RedmineServer001/redmine/admin
20 
[Mon Sep 22 08:49:05.183359 2014] [rewrite:trace4] [pid 2636:tid 1076] mod_rewrite.c(475): [client 10.1.59.68:63213] 10.1.59.68 - APPDOMAIN\\j.smith [RedmineServer001/sid#15ca268][rid#2586128/initial] [perdir /redmine/] RewriteCond: input='false' pattern='^false$' => matched, referer: http://RedmineServer001/redmine/admin
21 
[Mon Sep 22 08:49:05.183359 2014] [authz_core:debug] [pid 2636:tid 1076] mod_authz_core.c(799): [client 10.1.59.68:63213] AH01626: authorization result of Require valid-user : denied (no authenticated user yet), referer: http://RedmineServer001/redmine/admin
22 
[Mon Sep 22 08:49:05.183359 2014] [authz_core:debug] [pid 2636:tid 1076] mod_authz_core.c(799): [client 10.1.59.68:63213] AH01626: authorization result of <RequireAny>: denied (no authenticated user yet), referer: http://RedmineServer001/redmine/admin
23 
[Mon Sep 22 08:49:05.183359 2014] [auth_ntlm:debug] [pid 2636:tid 1076] mod_ntlm_authentication.c(476): [client 10.1.59.68:63213] SSPI00001: Entering authenticate_sspi_user(), referer: http://RedmineServer001/redmine/admin
24 
[Mon Sep 22 08:49:05.183359 2014] [auth_ntlm:debug] [pid 2636:tid 1076] mod_ntlm_authentication.c(580): [client 10.1.59.68:63213] SSPI00009: Authenticated user: APPDOMAIN\\j.smith, referer: http://RedmineServer001/redmine/admin
25 
[Mon Sep 22 08:49:05.183359 2014] [authz_core:debug] [pid 2636:tid 1076] mod_authz_core.c(799): [client 10.1.59.68:63213] AH01626: authorization result of Require valid-user : granted, referer: http://RedmineServer001/redmine/admin
26 
[Mon Sep 22 08:49:05.183359 2014] [authz_core:debug] [pid 2636:tid 1076] mod_authz_core.c(799): [client 10.1.59.68:63213] AH01626: authorization result of <RequireAny>: granted, referer: http://RedmineServer001/redmine/admin
27 
[Mon Sep 22 08:49:05.183359 2014] [proxy_balancer:trace1] [pid 2636:tid 1076] mod_proxy_balancer.c(73): [client 10.1.59.68:63213] canonicalising URL //redminecluster/proxy:balancer://redminecluster/groups/groups, referer: http://RedmineServer001/redmine/admin
28 
[Mon Sep 22 08:49:05.183359 2014] [rewrite:trace3] [pid 2636:tid 1076] mod_rewrite.c(475): [client 10.1.59.68:63213] 10.1.59.68 - APPDOMAIN\\j.smith [RedmineServer001/sid#15ca268][rid#25c80a8/subreq] [perdir /redmine/] add path info postfix: proxy:balancer://redminecluster/proxy:balancer://redminecluster/groups/groups -> proxy:balancer://redminecluster/proxy:balancer://redminecluster/groups/groups/proxy:balancer://redminecluster/groups/groups, referer: http://RedmineServer001/redmine/admin
29 
[Mon Sep 22 08:49:05.183359 2014] [rewrite:trace3] [pid 2636:tid 1076] mod_rewrite.c(475): [client 10.1.59.68:63213] 10.1.59.68 - APPDOMAIN\\j.smith [RedmineServer001/sid#15ca268][rid#25c80a8/subreq] [perdir /redmine/] applying pattern '.' to uri 'proxy:balancer://redminecluster/proxy:balancer://redminecluster/groups/groups/proxy:balancer://redminecluster/groups/groups', referer: http://RedmineServer001/redmine/admin
30 
[Mon Sep 22 08:49:05.183359 2014] [rewrite:trace4] [pid 2636:tid 1076] mod_rewrite.c(475): [client 10.1.59.68:63213] 10.1.59.68 - APPDOMAIN\\j.smith [RedmineServer001/sid#15ca268][rid#25c80a8/subreq] [perdir /redmine/] RewriteCond: input='true' pattern='^false$' => not-matched, referer: http://RedmineServer001/redmine/admin
31 
[Mon Sep 22 08:49:05.183359 2014] [rewrite:trace1] [pid 2636:tid 1076] mod_rewrite.c(475): [client 10.1.59.68:63213] 10.1.59.68 - APPDOMAIN\\j.smith [RedmineServer001/sid#15ca268][rid#25c80a8/subreq] [perdir /redmine/] pass through proxy:balancer://redminecluster/proxy:balancer://redminecluster/groups/groups, referer: http://RedmineServer001/redmine/admin
32 
[Mon Sep 22 08:49:05.183359 2014] [rewrite:trace5] [pid 2636:tid 1076] mod_rewrite.c(475): [client 10.1.59.68:63213] 10.1.59.68 - APPDOMAIN\\j.smith [RedmineServer001/sid#15ca268][rid#2586128/initial] [perdir /redmine/] lookahead: path=/redmine/proxy:balancer://redminecluster/groups/groups var=REMOTE_USER -> val=APPDOMAIN\\j.smith, referer: http://RedmineServer001/redmine/admin
33 
[Mon Sep 22 08:49:05.183359 2014] [rewrite:trace4] [pid 2636:tid 1076] mod_rewrite.c(475): [client 10.1.59.68:63213] 10.1.59.68 - APPDOMAIN\\j.smith [RedmineServer001/sid#15ca268][rid#2586128/initial] [perdir /redmine/] RewriteCond: input='APPDOMAIN\\j.smith' pattern='(.+)' => matched, referer: http://RedmineServer001/redmine/admin
34 
[Mon Sep 22 08:49:05.183359 2014] [rewrite:trace5] [pid 2636:tid 1076] mod_rewrite.c(475): [client 10.1.59.68:63213] 10.1.59.68 - APPDOMAIN\\j.smith [RedmineServer001/sid#15ca268][rid#2586128/initial] setting env variable 'RU' to 'APPDOMAIN\\j.smith', referer: http://RedmineServer001/redmine/admin
35 
[Mon Sep 22 08:49:05.183359 2014] [rewrite:trace1] [pid 2636:tid 1076] mod_rewrite.c(475): [client 10.1.59.68:63213] 10.1.59.68 - APPDOMAIN\\j.smith [RedmineServer001/sid#15ca268][rid#2586128/initial] [perdir /redmine/] pass through proxy:balancer://redminecluster/groups, referer: http://RedmineServer001/redmine/admin
36 
[Mon Sep 22 08:49:05.183359 2014] [lbmethod_byrequests:debug] [pid 2636:tid 1076] mod_lbmethod_byrequests.c(95): AH01207: proxy: Entering byrequests for BALANCER (balancer://redminecluster)
37 
[Mon Sep 22 08:49:05.183359 2014] [proxy:debug] [pid 2636:tid 1076] proxy_util.c(1884): AH00933: BALANCER: too soon to retry worker for (127.0.0.1)
38 
[Mon Sep 22 08:49:05.183359 2014] [lbmethod_byrequests:debug] [pid 2636:tid 1076] mod_lbmethod_byrequests.c(142): AH01208: proxy: byrequests selected worker "http://127.0.0.1:3001/redmine" : busy 0 : lbstatus 0
39 
[Mon Sep 22 08:49:05.183359 2014] [proxy_balancer:debug] [pid 2636:tid 1076] mod_proxy_balancer.c(614): [client 10.1.59.68:63213] AH01172: balancer://redminecluster: worker (http://127.0.0.1:3001/redmine) rewritten to http://127.0.0.1:3001/redmine/groups, referer: http://RedmineServer001/redmine/admin
40 
[Mon Sep 22 08:49:05.183359 2014] [proxy:debug] [pid 2636:tid 1076] proxy_util.c(1759): AH00924: worker http://127.0.0.1:3001/redmine shared already initialized
41 
[Mon Sep 22 08:49:05.183359 2014] [proxy:debug] [pid 2636:tid 1076] proxy_util.c(1801): AH00926: worker http://127.0.0.1:3001/redmine local already initialized
42 
[Mon Sep 22 08:49:05.183359 2014] [proxy:debug] [pid 2636:tid 1076] mod_proxy.c(1136): [client 10.1.59.68:63213] AH01143: Running scheme balancer handler (attempt 0), referer: http://RedmineServer001/redmine/admin
43 
[Mon Sep 22 08:49:05.183359 2014] [proxy_ajp:debug] [pid 2636:tid 1076] mod_proxy_ajp.c(713): [client 10.1.59.68:63213] AH00894: declining URL http://127.0.0.1:3001/redmine/groups, referer: http://RedmineServer001/redmine/admin
44 
[Mon Sep 22 08:49:05.183359 2014] [proxy_http:trace1] [pid 2636:tid 1076] mod_proxy_http.c(1923): [client 10.1.59.68:63213] HTTP: serving URL http://127.0.0.1:3001/redmine/groups, referer: http://RedmineServer001/redmine/admin
45 
[Mon Sep 22 08:49:05.183359 2014] [proxy:debug] [pid 2636:tid 1076] proxy_util.c(2092): AH00942: HTTP: has acquired connection for (127.0.0.1)
46 
[Mon Sep 22 08:49:05.183359 2014] [proxy:debug] [pid 2636:tid 1076] proxy_util.c(2168): [client 10.1.59.68:63213] AH00944: connecting http://127.0.0.1:3001/redmine/groups to 127.0.0.1:3001, referer: http://RedmineServer001/redmine/admin
47 
[Mon Sep 22 08:49:05.183359 2014] [proxy:debug] [pid 2636:tid 1076] proxy_util.c(2303): [client 10.1.59.68:63213] AH00947: connected /redmine/groups to 127.0.0.1:3001, referer: http://RedmineServer001/redmine/admin
48 
[Mon Sep 22 08:49:05.183359 2014] [proxy:trace2] [pid 2636:tid 1076] proxy_util.c(2637): HTTP: fam 2 socket created to connect to 127.0.0.1
49 
[Mon Sep 22 08:49:05.183359 2014] [proxy:debug] [pid 2636:tid 1076] proxy_util.c(2790): AH00962: HTTP: connection complete to 127.0.0.1:3001 (127.0.0.1)
50 
[Mon Sep 22 08:49:05.183359 2014] [core:trace6] [pid 2636:tid 1076] core_filters.c(525): [remote 127.0.0.1:3001] core_output_filter: flushing because of FLUSH bucket
51 
[Mon Sep 22 08:49:55.105329 2014] [proxy_http:trace3] [pid 2636:tid 1076] mod_proxy_http.c(1419): [client 10.1.59.68:63213] Status from backend: 500, referer: http://RedmineServer001/redmine/admin
52 
[Mon Sep 22 08:49:55.105329 2014] [proxy_http:trace4] [pid 2636:tid 1076] mod_proxy_http.c(1102): [client 10.1.59.68:63213] Headers received from backend:, referer: http://RedmineServer001/redmine/admin
53 
[Mon Sep 22 08:49:55.105329 2014] [proxy_http:trace4] [pid 2636:tid 1076] mod_proxy_http.c(1105): [client 10.1.59.68:63213] Content-Type: text/html; charset=utf-8, referer: http://RedmineServer001/redmine/admin
54 
[Mon Sep 22 08:49:55.105329 2014] [proxy_http:trace4] [pid 2636:tid 1076] mod_proxy_http.c(1105): [client 10.1.59.68:63213] Content-Length: 646, referer: http://RedmineServer001/redmine/admin
55 
[Mon Sep 22 08:49:55.105329 2014] [proxy_http:trace4] [pid 2636:tid 1076] mod_proxy_http.c(1105): [client 10.1.59.68:63213] X-Request-Id: 272bc1b9d296247866f99f717d408d4c, referer: http://RedmineServer001/redmine/admin
56 
[Mon Sep 22 08:49:55.105329 2014] [proxy_http:trace4] [pid 2636:tid 1076] mod_proxy_http.c(1105): [client 10.1.59.68:63213] X-Runtime: 49.906348, referer: http://RedmineServer001/redmine/admin
57 
[Mon Sep 22 08:49:55.105329 2014] [proxy_http:trace4] [pid 2636:tid 1076] mod_proxy_http.c(1105): [client 10.1.59.68:63213] Date: Mon, 22 Sep 2014 12:49:55 GMT, referer: http://RedmineServer001/redmine/admin
58 
[Mon Sep 22 08:49:55.105329 2014] [proxy_http:trace4] [pid 2636:tid 1076] mod_proxy_http.c(1105): [client 10.1.59.68:63213] Cache-Control: private, referer: http://RedmineServer001/redmine/admin
59 
[Mon Sep 22 08:49:55.105329 2014] [proxy_http:trace4] [pid 2636:tid 1076] mod_proxy_http.c(1105): [client 10.1.59.68:63213] X-Rack-Cache: miss, referer: http://RedmineServer001/redmine/admin
60 
[Mon Sep 22 08:49:55.105329 2014] [proxy_http:trace4] [pid 2636:tid 1076] mod_proxy_http.c(1105): [client 10.1.59.68:63213] Connection: keep-alive, referer: http://RedmineServer001/redmine/admin
61 
[Mon Sep 22 08:49:55.105329 2014] [proxy_http:trace4] [pid 2636:tid 1076] mod_proxy_http.c(1105): [client 10.1.59.68:63213] Server: thin 1.3.1 codename Triple Espresso, referer: http://RedmineServer001/redmine/admin
62 
[Mon Sep 22 08:49:55.105329 2014] [proxy_http:trace3] [pid 2636:tid 1076] mod_proxy_http.c(1671): [client 10.1.59.68:63213] start body send, referer: http://RedmineServer001/redmine/admin
63 
[Mon Sep 22 08:49:55.105329 2014] [proxy:debug] [pid 2636:tid 1076] proxy_util.c(2130): AH00943: http: has released connection for (127.0.0.1)
64 
[Mon Sep 22 08:49:55.105329 2014] [headers:debug] [pid 2636:tid 1076] mod_headers.c(844): AH01502: headers: ap_headers_output_filter()
65 
[Mon Sep 22 08:49:55.105329 2014] [http:trace3] [pid 2636:tid 1076] http_filters.c(1005): [client 10.1.59.68:63213] Response sent with status 500, headers:, referer: http://RedmineServer001/redmine/admin
    (1-1/1)