Re: [mod-security-users] Apache reverse proxy timeout value
Brought to you by:
victorhora,
zimmerletw
Menu
▾
▴
Re: [mod-security-users] Apache reverse proxy timeout value
|
From: Christian F. <chr...@ne...> - 2024-01-29 07:44:41
|
Hey Homesh, This is very much an Apache question. Please address it to the Apache user's mailinglist or some other Apache forum. With that being said, it's a very odd behavior, I have never see. Best, Christian On Mon, Jan 29, 2024 at 12:31:13PM +0530, homesh joshi wrote: > Hi All, > > I am not sure if this is a modsec issue as I have tested it by disabling > the modsec still I face this issue. > I have apache setup in reverse proxy configuration with proxy timeout set > as 20 sec. > for one website request for /favicon.ico takes 20 sec. if I reduce the > proxy timeout to 2 sec then request for favicon.ico takes 2 sec. I put the > proxy module log level to trace 8 and apache log level to debug. but still > i am not able to find why apache waits for timeout. Attached are the logs > for your reference. > > Thanks in advance. > Homesh > [Thu Jan 25 15:47:22.967833 2024] [socache_shmcb:debug] [pid 5731:tid 140199434626624] mod_socache_shmcb.c(508): AH00831: socache_shmcb_store (0x61 -> subcache 1) > [Thu Jan 25 15:47:22.967900 2024] [socache_shmcb:debug] [pid 5731:tid 140199434626624] mod_socache_shmcb.c(862): AH00847: insert happened at idx=29, data=(6525:6557) > [Thu Jan 25 15:47:22.967923 2024] [socache_shmcb:debug] [pid 5731:tid 140199434626624] mod_socache_shmcb.c(865): AH00848: finished insert, subcache: idx_pos/idx_used=25/5, > data_pos/data_used=5638/1084 > [Thu Jan 25 15:47:22.967927 2024] [socache_shmcb:debug] [pid 5731:tid 140199434626624] mod_socache_shmcb.c(530): AH00834: leaving socache_shmcb_store successfully > [Thu Jan 25 15:47:22.968048 2024] [socache_shmcb:debug] [pid 5731:tid 140199434626624] mod_socache_shmcb.c(508): AH00831: socache_shmcb_store (0xab -> subcache 11) > [Thu Jan 25 15:47:22.968062 2024] [socache_shmcb:debug] [pid 5731:tid 140199434626624] mod_socache_shmcb.c(862): AH00847: insert happened at idx=26, data=(5857:5889) > [Thu Jan 25 15:47:22.968067 2024] [socache_shmcb:debug] [pid 5731:tid 140199434626624] mod_socache_shmcb.c(865): AH00848: finished insert, subcache: idx_pos/idx_used=22/5, > data_pos/data_used=4954/1099 > [Thu Jan 25 15:47:22.968071 2024] [socache_shmcb:debug] [pid 5731:tid 140199434626624] mod_socache_shmcb.c(530): AH00834: leaving socache_shmcb_store successfully > [Thu Jan 25 15:47:22.969591 2024] [ssl:debug] [pid 5731:tid 140200633919040] ssl_engine_kernel.c(415): [remote 1.2.3.4:58139] AH02034: Subsequent (No.2) HTTPS request > received for child 5394 (server play.lvu:443) > [Thu Jan 25 15:47:22.971124 2024] [proxy:trace2] [pid 5731:tid 140200633919040] mod_proxy.c(881): [remote 1.2.3.4:58139] AH03461: attempting to match URI path '/favic > on.ico' against prefix '/error/' for proxying > [Thu Jan 25 15:47:22.971161 2024] [proxy:trace2] [pid 5731:tid 140200633919040] mod_proxy.c(881): [remote 1.2.3.4:58139] AH03461: attempting to match URI path '/favic > on.ico' against prefix '/' for proxying > [Thu Jan 25 15:47:22.971167 2024] [proxy:trace1] [pid 5731:tid 140200633919040] mod_proxy.c(998): [remote 1.2.3.4:58139] AH03464: URI path '/favicon.ico' matches prox > y handler 'proxy:https://play-lvu-205133111.ap-south-1.elb.amazonaws.com:443/favicon.ico' > [Thu Jan 25 15:47:22.971190 2024] [authz_core:debug] [pid 5731:tid 140200633919040] mod_authz_core.c(843): [remote 1.2.3.4:58139] AH01628: authorization result: grant > ed (no directives) > [Thu Jan 25 15:47:22.975603 2024] [proxy:trace2] [pid 5731:tid 140200633919040] proxy_util.c(2335): [remote 1.2.3.4:58139] https: found worker https://play-lvu-20510 > 2675.ap-south-1.elb.amazonaws.com/ for https://play-lvu-205133111.ap-south-1.elb.amazonaws.com/favicon.ico > [Thu Jan 25 15:47:22.975651 2024] [proxy:debug] [pid 5731:tid 140200633919040] mod_proxy.c(1503): [remote 1.2.3.4:58139] AH01143: Running scheme https handler (attemp > t 0) > [Thu Jan 25 15:47:22.975660 2024] [proxy_fcgi:debug] [pid 5731:tid 140200633919040] mod_proxy_fcgi.c(1054): [remote 1.2.3.4:58139] AH01076: url: https://play-lvu-205 > 102675.ap-south-1.elb.amazonaws.com/favicon.ico proxyname: (null) proxyport: 0 > [Thu Jan 25 15:47:22.975666 2024] [proxy_fcgi:debug] [pid 5731:tid 140200633919040] mod_proxy_fcgi.c(1059): [remote 1.2.3.4:58139] AH01077: declining URL https://play > -lvu-205133111.ap-south-1.elb.amazonaws.com/favicon.ico > [Thu Jan 25 15:47:22.975682 2024] [proxy:debug] [pid 5731:tid 140200633919040] proxy_util.c(2531): AH00942: https: has acquired connection for (play-lvu-205133111.ap-south > -1.elb.amazonaws.com) > [Thu Jan 25 15:47:22.975694 2024] [proxy:debug] [pid 5731:tid 140200633919040] proxy_util.c(2587): [remote 1.2.3.4:58139] AH00944: connecting https://play-lvu-205102 > 675.ap-south-1.elb.amazonaws.com/favicon.ico to play-lvu-205133111.ap-south-1.elb.amazonaws.com:443 > [Thu Jan 25 15:47:23.019184 2024] [proxy:debug] [pid 5731:tid 140200633919040] proxy_util.c(2810): [remote 1.2.3.4:58139] AH00947: connected /favicon.ico to play-lvu > -205133111.ap-south-1.elb.amazonaws.com:443 > [Thu Jan 25 15:47:23.019277 2024] [proxy:trace2] [pid 5731:tid 140200633919040] proxy_util.c(3244): https: fam 2 socket created to connect to play-lvu-205133111.ap-south-1 > .elb.amazonaws.com > [Thu Jan 25 15:47:43.039441 2024] [proxy:debug] [pid 5731:tid 140200633919040] proxy_util.c(3267): (70007)The timeout specified has expired: AH00957: https: attempt to conn > ect to 3.111.227.162:443 (play-lvu-205133111.ap-south-1.elb.amazonaws.com) failed > [Thu Jan 25 15:47:43.039558 2024] [proxy:trace2] [pid 5731:tid 140200633919040] proxy_util.c(3244): https: fam 2 socket created to connect to play-lvu-205133111.ap-south-1 > .elb.amazonaws.com > [Thu Jan 25 15:47:43.057570 2024] [proxy:debug] [pid 5731:tid 140200633919040] proxy_util.c(3276): AH02824: https: connection established with 3.109.6.57:443 (play-lvu-205 > 102675.ap-south-1.elb.amazonaws.com) > [Thu Jan 25 15:47:43.057649 2024] [proxy:trace1] [pid 5731:tid 140200633919040] proxy_util.c(3450): [remote 3.109.6.57:443] https: set SNI to play.lvu for (play-lvu-20510 > 2675.ap-south-1.elb.amazonaws.com) > [Thu Jan 25 15:47:43.057655 2024] [proxy:debug] [pid 5731:tid 140200633919040] proxy_util.c(3462): AH00962: https: connection complete to 3.111.227.162:443 (play-lvu-20510 > 2675.ap-south-1.elb.amazonaws.com) > [Thu Jan 25 15:47:43.057663 2024] [qos:debug] [pid 5731:tid 140200633919040] apache2/mod_qos.c(8587): mod_qos(): skip processing of outgoing connection 3.109.6.57<->165.232 > .187.180 > [Thu Jan 25 15:47:43.057669 2024] [ssl:info] [pid 5731:tid 140200633919040] [remote 3.109.6.57:443] AH01964: Connection to child 0 established (server play.lvu:443) > [Thu Jan 25 15:47:43.078549 2024] [ssl:debug] [pid 5731:tid 140200633919040] ssl_engine_kernel.c(1764): [remote 3.109.6.57:443] AH02275: Certificate Verification, depth 3, > CRL checking mode: none (0) [subject: CN=Starfield Services Root Certificate Authority - G2,O=Starfield Technologies\\, Inc.,L=Scottsdale,ST=Arizona,C=US / issuer: OU=Starf > ield Class 2 Certification Authority,O=Starfield Technologies\\, Inc.,C=US / serial: A70E4A4C3482B77F / notbefore: Sep 2 00:00:00 2009 GMT / notafter: Jun 28 17:39:16 2034 > GMT] > [Thu Jan 25 15:47:43.078695 2024] [ssl:debug] [pid 5731:tid 140200633919040] ssl_engine_kernel.c(1764): [remote 3.109.6.57:443] AH02275: Certificate Verification, depth 2, > CRL checking mode: none (0) [subject: CN=Amazon Root CA 1,O=Amazon,C=US / issuer: CN=Starfield Services Root Certificate Authority - G2,O=Starfield Technologies\\, Inc.,L=S > cottsdale,ST=Arizona,C=US / serial: 067F944A2A27CDF3FAC2AE2B01F908EEB9C4C6 / notbefore: May 25 12:00:00 2015 GMT / notafter: Dec 31 01:00:00 2037 GMT] > [Thu Jan 25 15:47:43.078779 2024] [ssl:debug] [pid 5731:tid 140200633919040] ssl_engine_kernel.c(1764): [remote 3.109.6.57:443] AH02275: Certificate Verification, depth 1, > CRL checking mode: none (0) [subject: CN=Amazon RSA 2048 M01,O=Amazon,C=US / issuer: CN=Amazon Root CA 1,O=Amazon,C=US / serial: 077312380B9D6688A33B1ED9BF9CCDA68E0E0F / no > tbefore: Aug 23 22:21:28 2022 GMT / notafter: Aug 23 22:21:28 2030 GMT] > [Thu Jan 25 15:47:43.078863 2024] [ssl:debug] [pid 5731:tid 140200633919040] ssl_engine_kernel.c(1764): [remote 3.109.6.57:443] AH02275: Certificate Verification, depth 0, > CRL checking mode: none (0) [subject: CN=play.lvu / issuer: CN=Amazon RSA 2048 M01,O=Amazon,C=US / serial: 088DB8B2694138D3A4624BF0EEFF3856 / notbefore: Oct 11 00:00:00 20 > 23 GMT / notafter: Nov 8 23:59:59 2024 GMT] > [Thu Jan 25 15:47:43.079137 2024] [ssl:debug] [pid 5731:tid 140200633919040] ssl_engine_kernel.c(2254): [remote 3.109.6.57:443] AH02041: Protocol: TLSv1.3, Cipher: TLS_AES_ > 128_GCM_SHA256 (128/128 bits) > [Thu Jan 25 15:47:43.079199 2024] [ssl:debug] [pid 5731:tid 140200633919040] ssl_util_ssl.c(451): AH02412: [play.lvu:443] Cert matches for name 'play.lvu' [subject: CN=kl > ay.lvu / issuer: CN=Amazon RSA 2048 M01,O=Amazon,C=US / serial: 088DB8B2694138D3A4624BF0EEFF3856 / notbefore: Oct 11 00:00:00 2023 GMT / notafter: Nov 8 23:59:59 2024 GMT > ] > [Thu Jan 25 15:47:43.100903 2024] [proxy:debug] [pid 5731:tid 140200633919040] proxy_util.c(2546): AH00943: https: has released connection for (play-lvu-205133111.ap-south > -1.elb.amazonaws.com) > [Thu Jan 25 15:47:43.100989 2024] [ssl:debug] [pid 5731:tid 140200633919040] ssl_engine_io.c(1147): [remote 3.109.6.57:443] AH02001: Connection closed to child 0 with stand > ard shutdown (server play.lvu:443) > [Thu Jan 25 15:47:43.101088 2024] [proxy:debug] [pid 5731:tid 140200633919040] proxy_util.c(3386): [remote 3.109.6.57:443] AH02642: proxy: connection shutdown > [Thu Jan 25 15:47:43.863505 2024] [ssl:debug] [pid 5731:tid 140200650737216] ssl_engine_kernel.c(415): [remote 1.2.3.4:58139] AH02034: Subsequent (No.2) HTTPS request > received for child 1808 (server play.lvu:443), referer: https://play.lvu/favicon.ico > [Thu Jan 25 15:47:43.865077 2024] [proxy:trace2] [pid 5731:tid 140200650737216] mod_proxy.c(881): [remote 1.2.3.4:58139] AH03461: attempting to match URI path '/favic > on.ico' against prefix '/error/' for proxying, referer: https://play.lvu/favicon.ico > [Thu Jan 25 15:47:43.865165 2024] [proxy:trace2] [pid 5731:tid 140200650737216] mod_proxy.c(881): [remote 1.2.3.4:58139] AH03461: attempting to match URI path '/favic > on.ico' against prefix '/' for proxying, referer: https://play.lvu/favicon.ico > [Thu Jan 25 15:47:43.865192 2024] [proxy:trace1] [pid 5731:tid 140200650737216] mod_proxy.c(998): [remote 1.2.3.4:58139] AH03464: URI path '/favicon.ico' matches prox > y handler 'proxy:https://play-lvu-205133111.ap-south-1.elb.amazonaws.com:443/favicon.ico', referer: https://play.lvu/favicon.ico > [Thu Jan 25 15:47:43.865231 2024] [authz_core:debug] [pid 5731:tid 140200650737216] mod_authz_core.c(843): [remote 1.2.3.4:58139] AH01628: authorization result: grant > ed (no directives), referer: https://play.lvu/favicon.ico > [Thu Jan 25 15:47:43.868082 2024] [proxy:trace2] [pid 5731:tid 140200650737216] proxy_util.c(2335): [remote 1.2.3.4:58139] https: found worker https://play-lvu-20510 > 2675.ap-south-1.elb.amazonaws.com/ for https://play-lvu-205133111.ap-south-1.elb.amazonaws.com/favicon.ico, referer: https://play.lvu/favicon.ico > [Thu Jan 25 15:47:43.868164 2024] [proxy:debug] [pid 5731:tid 140200650737216] mod_proxy.c(1503): [remote 1.2.3.4:58139] AH01143: Running scheme https handler (attemp > t 0), referer: https://play.lvu/favicon.ico > [Thu Jan 25 15:47:43.868198 2024] [proxy_fcgi:debug] [pid 5731:tid 140200650737216] mod_proxy_fcgi.c(1054): [remote 1.2.3.4:58139] AH01076: url: https://play-lvu-205 > 102675.ap-south-1.elb.amazonaws.com/favicon.ico proxyname: (null) proxyport: 0, referer: https://play.lvu/favicon.ico > [Thu Jan 25 15:47:43.868223 2024] [proxy_fcgi:debug] [pid 5731:tid 140200650737216] mod_proxy_fcgi.c(1059): [remote 1.2.3.4:58139] AH01077: declining URL https://play > -lvu-205133111.ap-south-1.elb.amazonaws.com/favicon.ico, referer: https://play.lvu/favicon.ico > [Thu Jan 25 15:47:43.868248 2024] [proxy:debug] [pid 5731:tid 140200650737216] proxy_util.c(2531): AH00942: https: has acquired connection for (play-lvu-205133111.ap-south > -1.elb.amazonaws.com) > [Thu Jan 25 15:47:43.868273 2024] [proxy:debug] [pid 5731:tid 140200650737216] proxy_util.c(2587): [remote 1.2.3.4:58139] AH00944: connecting https://play-lvu-205102 > 675.ap-south-1.elb.amazonaws.com/favicon.ico to play-lvu-205133111.ap-south-1.elb.amazonaws.com:443, referer: https://play.lvu/favicon.ico > [Thu Jan 25 15:47:43.868630 2024] [proxy:debug] [pid 5731:tid 140200650737216] proxy_util.c(2810): [remote 1.2.3.4:58139] AH00947: connected /favicon.ico to play-lvu > -205133111.ap-south-1.elb.amazonaws.com:443, referer: https://play.lvu/favicon.ico > [Thu Jan 25 15:47:43.868704 2024] [proxy:trace2] [pid 5731:tid 140200650737216] proxy_util.c(3244): https: fam 2 socket created to connect to play-lvu-205133111.ap-south-1 > .elb.amazonaws.com > [Thu Jan 25 15:47:43.894557 2024] [proxy:debug] [pid 5731:tid 140200650737216] proxy_util.c(3276): AH02824: https: connection established with 3.109.172.68:443 (play-lvu-2 > 05102675.ap-south-1.elb.amazonaws.com) > [Thu Jan 25 15:47:43.894681 2024] [proxy:trace1] [pid 5731:tid 140200650737216] proxy_util.c(3450): [remote 3.109.172.68:443] https: set SNI to play.lvu for (play-lvu-205 > 102675.ap-south-1.elb.amazonaws.com) > [Thu Jan 25 15:47:43.894708 2024] [proxy:debug] [pid 5731:tid 140200650737216] proxy_util.c(3462): AH00962: https: connection complete to 3.109.172.68:443 (play-lvu-205102 > 675.ap-south-1.elb.amazonaws.com) > [Thu Jan 25 15:47:43.894748 2024] [qos:debug] [pid 5731:tid 140200650737216] apache2/mod_qos.c(8587): mod_qos(): skip processing of outgoing connection 3.109.172.68<->165.2 > 32.187.180 > [Thu Jan 25 15:47:43.894770 2024] [ssl:info] [pid 5731:tid 140200650737216] [remote 3.109.172.68:443] AH01964: Connection to child 0 established (server play.lvu:443) > [Thu Jan 25 15:47:43.923819 2024] [ssl:debug] [pid 5731:tid 140200650737216] ssl_engine_kernel.c(1764): [remote 3.109.172.68:443] AH02275: Certificate Verification, depth 3 > , CRL checking mode: none (0) [subject: CN=Starfield Services Root Certificate Authority - G2,O=Starfield Technologies\\, Inc.,L=Scottsdale,ST=Arizona,C=US / issuer: OU=Sta > rfield Class 2 Certification Authority,O=Starfield Technologies\\, Inc.,C=US / serial: A70E4A4C3482B77F / notbefore: Sep 2 00:00:00 2009 GMT / notafter: Jun 28 17:39:16 20 > 34 GMT] > [Thu Jan 25 15:47:43.924033 2024] [ssl:debug] [pid 5731:tid 140200650737216] ssl_engine_kernel.c(1764): [remote 3.109.172.68:443] AH02275: Certificate Verification, depth 2 > , CRL checking mode: none (0) [subject: CN=Amazon Root CA 1,O=Amazon,C=US / issuer: CN=Starfield Services Root Certificate Authority - G2,O=Starfield Technologies\\, Inc.,L > =Scottsdale,ST=Arizona,C=US / serial: 067F944A2A27CDF3FAC2AE2B01F908EEB9C4C6 / notbefore: May 25 12:00:00 2015 GMT / notafter: Dec 31 01:00:00 2037 GMT] > [Thu Jan 25 15:47:43.924124 2024] [ssl:debug] [pid 5731:tid 140200650737216] ssl_engine_kernel.c(1764): [remote 3.109.172.68:443] AH02275: Certificate Verification, depth 1 > , CRL checking mode: none (0) [subject: CN=Amazon RSA 2048 M01,O=Amazon,C=US / issuer: CN=Amazon Root CA 1,O=Amazon,C=US / serial: 077312380B9D6688A33B1ED9BF9CCDA68E0E0F / > notbefore: Aug 23 22:21:28 2022 GMT / notafter: Aug 23 22:21:28 2030 GMT] > [Thu Jan 25 15:47:43.924208 2024] [ssl:debug] [pid 5731:tid 140200650737216] ssl_engine_kernel.c(1764): [remote 3.109.172.68:443] AH02275: Certificate Verification, depth 0 > , CRL checking mode: none (0) [subject: CN=play.lvu / issuer: CN=Amazon RSA 2048 M01,O=Amazon,C=US / serial: 088DB8B2694138D3A4624BF0EEFF3856 / notbefore: Oct 11 00:00:00 > 2023 GMT / notafter: Nov 8 23:59:59 2024 GMT] > [Thu Jan 25 15:47:43.924468 2024] [ssl:debug] [pid 5731:tid 140200650737216] ssl_engine_kernel.c(2254): [remote 3.109.172.68:443] AH02041: Protocol: TLSv1.3, Cipher: TLS_AE > S_128_GCM_SHA256 (128/128 bits) > [Thu Jan 25 15:47:43.924535 2024] [ssl:debug] [pid 5731:tid 140200650737216] ssl_util_ssl.c(451): AH02412: [play.lvu:443] Cert matches for name 'play.lvu' [subject: CN=kl > ay.lvu / issuer: CN=Amazon RSA 2048 M01,O=Amazon,C=US / serial: 088DB8B2694138D3A4624BF0EEFF3856 / notbefore: Oct 11 00:00:00 2023 GMT / notafter: Nov 8 23:59:59 2024 GMT > ] > [Thu Jan 25 15:47:43.959108 2024] [proxy:debug] [pid 5731:tid 140200650737216] proxy_util.c(2546): AH00943: https: has released connection for (play-lvu-205133111.ap-south > -1.elb.amazonaws.com) > [Thu Jan 25 15:47:43.959261 2024] [ssl:debug] [pid 5731:tid 140200650737216] ssl_engine_io.c(1147): [remote 3.109.172.68:443] AH02001: Connection closed to child 0 with sta > ndard shutdown (server play.lvu:443) > [Thu Jan 25 15:47:43.959361 2024] [proxy:debug] [pid 5731:tid 140200650737216] proxy_util.c(3386): [remote 3.109.172.68:443] AH02642: proxy: connection shutdown > [Thu Jan 25 15:47:48.965114 2024] [ssl:debug] [pid 5731:tid 140199476590144] ssl_engine_io.c(1147): [client 1.2.3.4:58139] AH02001: Connection closed to child 16 with > standard shutdown (server play.lvu:443) > > > > ▸ > _______________________________________________ > mod-security-users mailing list > mod...@li... > https://lists.sourceforge.net/lists/listinfo/mod-security-users > Commercial ModSecurity Rules and Support from Trustwave's SpiderLabs: > http://www.modsecurity.org/projects/commercial/rules/ > http://www.modsecurity.org/projects/commercial/support/ |
