Bug 63277 - All workers are in error state for route ...
Summary: All workers are in error state for route ...
Status: NEW
Alias: None
Product: Apache httpd-2
Classification: Unclassified
Component: mod_proxy_balancer (show other bugs)
Version: 2.4.41
Hardware: PC Linux
: P2 normal (vote)
Target Milestone: ---
Assignee: Apache HTTPD Bugs Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2019-03-21 14:08 UTC by Antony
Modified: 2019-08-22 13:11 UTC (History)
1 user (show)



Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Antony 2019-03-21 14:08:02 UTC
Hello to everyone,

I am receiving the below errors in apache log for 3 (!!!) apache load balancers, although the workers apache servers are working correctly !!!!

[Thu Mar 21 10:17:24.335819 2019] [proxy_balancer:error] [pid 3803:tid 140235396585216] [client ############:50494] AH01167: balancer://###############: All workers are in error state for route (2), referer: https://#####.#####.######/
[Thu Mar 21 10:17:24.354218 2019] [proxy_balancer:error] [pid 16483:tid 140235337836288] [client ############:55946] AH01167: balancer://###############: All workers are in error state for route (2), referer: https://#####.#####.######/
[Thu Mar 21 10:17:24.377296 2019] [proxy_balancer:error] [pid 3803:tid 140235379799808] [client ############:50495] AH01167: balancer://###############: All workers are in error state for route (2), referer: https://#####.#####.######/
[Thu Mar 21 10:17:24.413650 2019] [proxy_balancer:error] [pid 31177:tid 140235446941440] [client ############:50496] AH01167: balancer://###############: All workers are in error state for route (2), referer: https://#####.#####.######/
[Thu Mar 21 10:17:24.418306 2019] [proxy_balancer:error] [pid 31377:tid 140235559737088] [client ############:55947] AH01167: balancer://###############: All workers are in error state for route (2), referer: https://#####.#####.######/
[Thu Mar 21 10:17:24.421468 2019] [proxy_balancer:error] [pid 27890:tid 140235354621696] [client ############:55948] AH01167: balancer://###############: All workers are in error state for route (2), referer: https://#####.#####.######/
[Thu Mar 21 10:17:24.448442 2019] [proxy_balancer:error] [pid 3003:tid 140235388192512] [client ############:50497] AH01167: balancer://###############: All workers are in error state for route (2), referer: https://#####.#####.######/
[Thu Mar 21 12:39:40.205880 2019] [proxy_balancer:error] [pid 31377:tid 140235534558976] [client ############:59457] AH01167: balancer://###############: All workers are in error state for route (1), referer: https://#####.#####.######/
[Thu Mar 21 12:39:40.242508 2019] [proxy_balancer:error] [pid 1200:tid 140235542951680] [client ############:59456] AH01167: balancer://###############: All workers are in error state for route (1), referer: https://#####.#####.######/
[Thu Mar 21 12:39:40.318190 2019] [proxy_balancer:error] [pid 31377:tid 140235404977920] [client ############:59458] AH01167: balancer://###############: All workers are in error state for route (1), referer: https://#####.#####.######/
[Thu Mar 21 12:39:40.328191 2019] [proxy_balancer:error] [pid 31377:tid 140235396585216] [client ############:59459] AH01167: balancer://###############: All workers are in error state for route (1), referer: https://#####.#####.######/
[Thu Mar 21 12:39:40.484980 2019] [proxy_balancer:error] [pid 31177:tid 140235526166272] [client ############:59460] AH01167: balancer://###############: All workers are in error state for route (1), referer: https://#####.#####.######/
[Thu Mar 21 12:39:40.500728 2019] [proxy_balancer:error] [pid 1200:tid 140235413370624] [client ############:59461] AH01167: balancer://###############: All workers are in error state for route (1), referer: https://#####.#####.######/
[Thu Mar 21 12:39:40.586331 2019] [proxy_balancer:error] [pid 30003:tid 140235337836288] [client ############:59462] AH01167: balancer://###############: All workers are in error state for route (1), referer: https://#####.#####.######/
[Thu Mar 21 12:39:40.588165 2019] [proxy_balancer:error] [pid 30003:tid 140235421763328] [client ############:59463] AH01167: balancer://###############: All workers are in error state for route (1), referer: https://#####.#####.######/
[Thu Mar 21 12:39:40.728050 2019] [proxy_balancer:error] [pid 3803:tid 140235312658176] [client ############:59464] AH01167: balancer://###############: All workers are in error state for route (1), referer: https://#####.#####.######/
[Thu Mar 21 12:39:40.754865 2019] [proxy_balancer:error] [pid 3803:tid 140235526166272] [client ############:59465] AH01167: balancer://###############: All workers are in error state for route (1), referer: https://#####.#####.######/
[Thu Mar 21 12:39:40.795053 2019] [proxy_balancer:error] [pid 31377:tid 140235526166272] [client ############:59455] AH01167: balancer://###############: All workers are in error state for route (1), referer: https://#####.#####.######/
[Thu Mar 21 12:39:40.805764 2019] [proxy_balancer:error] [pid 16483:tid 140235551344384] [client ############:59466] AH01167: balancer://###############: All workers are in error state for route (1), referer: https://#####.#####.######/

Do you have any idea why this happens and what can I do to avoid it ?
Is there any other log(s) that I can look for any additional info ?

This error appears for a little while and then it's gone and then (after hours) appears again and then again it's gone !!!! 
It does not appear at the same time period for all the clients.

I don't know what to do with it.

Regards
Comment 1 Eric Covener 2019-03-21 14:41:44 UTC
Can you try to capture debug/trace of when they go into error state?
Comment 2 Antony 2019-03-21 17:16:46 UTC
That's my issue. The apache workers do not ever go into error state and other clients can work without problems when these messages are displayed into the load balancers logs !!!
Comment 3 Antony 2019-03-25 07:56:25 UTC
Goodmorning to all,'

After a little search, I have found that (sometimes but not always) there are many "304" http codes in the apache workers logs during the appearance of the message "All workers are in error state" in the apache load balancers logs.

Can this be the cause of the problem that I have ?

Do you have any idea ?

Regards
Comment 4 Antony 2019-05-01 18:34:39 UTC
Goodmorning to all,

After a more precise search, I have found that there are ALWAYS many (from 10 to 100) "304" http codes in the apache workers logs during the appearance of the message "All workers are in error state" in the apache load balancers logs.

And I think that this is the issue for this problem.

Can anyone help me on this ?

Regards
Comment 5 evgeniusx@ukr.net 2019-08-20 09:18:47 UTC
Hello! I have similar issue on apache 2.4.41. On my backends i use basic auth and when connect through Proxy balancer:// got 401 code. also with Proxy configered healthcheck and when i disable the healthcheck proxy member work fine. On apache 2.4.39 also work fine with original config PROXY. Sory for my bad english.


configs:

PROXY:

<VirtualHost *:91>
LogLevel debug
LogLevel proxy_hcheck:trace2
LogLevel proxy:trace2
LogLevel watchdog:trace2
ErrorLog /var/log/httpd/catalog-error_log
CustomLog "/var/log/catalog-access_log" combined
    ProxyRequests off
    <Proxy balancer://catalog>
        BalancerMember http://1.1.1.1:91 hcmethod=GET  hcuri=/getStatus.php hcinterval=5 timeout=3 retry=5 connectiontimeout=500ms
        BalancerMember http://1.1.1.2:91 hcmethod=GET  hcuri=/getStatus.php hcinterval=5 timeout=3 retry=5 connectiontimeout=500ms
        Require all granted
        ProxySet lbmethod=byrequests
    </Proxy>
    ProxyPass / balancer://catalog/
</VirtualHost>



MEMBER1:
<VirtualHost _default_ *:91>
    ServerName catalog1.example.com
    ServerAlias 1.1.1.1
    DocumentRoot "/var/www/html/service/public"
    ErrorLog /var/log/httpd/catalog1.example.com-error_log
    LogFormat "%h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\"" combined
    CustomLog "logs/catalog1.example.com-access_log" combined
    LogLevel debug
    <Location />
        AuthType Basic
        AuthName "Please enter your username and password"
        AuthUserFile /etc/httpd/conf/htpasswd
        <RequireAny>
            Require ip 127.0.0.1
            Require valid-user
        </RequireAny>
    </Location>

    <Directory "/var/www/html/service/public">
        Options FollowSymLinks
        AllowOverride None
        Require valid-user
    </Directory>

    ProxyPassMatch ^/(.*\.php(/.*)?)$ unix:///var/run/php-fpm.sock|fcgi://127.0.0.1:9000/var/www/html/service/public/$1
    ProxyTimeout 18000
    DirectoryIndex /index.php index.php
</VirtualHost>

MEMBER2:

<VirtualHost _default_ *:91>
    ServerName catalog2.example.com
    ServerAlias 1.1.1.2
    DocumentRoot "/var/www/html/service/public"
    ErrorLog /var/log/httpd/catalog2.example.com-error_log
    LogFormat "%h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\"" combined
    CustomLog "logs/catalog1.example.com-access_log" combined
    LogLevel debug
    <Location />
        AuthType Basic
        AuthName "Please enter your username and password"
        AuthUserFile /etc/httpd/conf/htpasswd
        <RequireAny>
            Require ip 127.0.0.1
            Require valid-user
        </RequireAny>
    </Location>

    <Directory "/var/www/html/service/public">
        Options FollowSymLinks
        AllowOverride None
        Require valid-user
    </Directory>

    ProxyPassMatch ^/(.*\.php(/.*)?)$ unix:///var/run/php-fpm.sock|fcgi://127.0.0.1:9000/var/www/html/service/public/$1
    ProxyTimeout 18000
    DirectoryIndex /index.php index.php
</VirtualHost>

LOG_FROM_PROXY:

[Tue Aug 20 04:33:43.247155 2019] [proxy_balancer:debug] [pid 1:tid 140415046375616] mod_proxy_balancer.c(919): AH01178: Doing balancers create: 544, 1 (6)
[Tue Aug 20 04:33:43.247354 2019] [proxy_balancer:debug] [pid 1:tid 140415046375616] mod_proxy_balancer.c(989): AH01184: Doing workers create: balancer://catalog (p678f5e47_catalog), 1064, 2 [0]
[Tue Aug 20 04:33:43.249728 2019] [proxy_hcheck:debug] [pid 1:tid 140415046375616] mod_proxy_hcheck.c(1053): AH03265: watchdog callback registered (_proxy_hcheck_ for 172.18.0.4)
[Tue Aug 20 04:33:43.253551 2019] [proxy_hcheck:debug] [pid 13:tid 140413710239488] mod_proxy_hcheck.c(899): AH03258: _proxy_hcheck_ watchdog started.
[Tue Aug 20 04:33:43.254200 2019] [proxy_hcheck:debug] [pid 13:tid 140413710239488] mod_proxy_hcheck.c(913): AH03313: apr_thread_pool_create() with 16 threads succeeded
[Tue Aug 20 04:33:43.254294 2019] [proxy_balancer:debug] [pid 13:tid 140415046375616] mod_proxy_balancer.c(134): AH01158: Looking at balancer://catalog -> http://1.1.1.1:91 initialized?
[Tue Aug 20 04:33:43.254316 2019] [proxy:debug] [pid 13:tid 140415046375616] proxy_util.c(1935): AH00925: initializing worker http://1.1.1.1:91 shared
[Tue Aug 20 04:33:43.254339 2019] [proxy:debug] [pid 13:tid 140415046375616] proxy_util.c(1992): AH00927: initializing worker http://1.1.1.1:91 local
[Tue Aug 20 04:33:43.254378 2019] [proxy:debug] [pid 13:tid 140415046375616] proxy_util.c(2027): AH00930: initialized pool in child 13 for (1.1.1.1) min=0 max=74 smax=74
[Tue Aug 20 04:33:43.254388 2019] [proxy_balancer:debug] [pid 13:tid 140415046375616] mod_proxy_balancer.c(134): AH01158: Looking at balancer://catalog -> http://1.1.1.2:91 initialized?
[Tue Aug 20 04:33:43.254392 2019] [proxy:debug] [pid 13:tid 140415046375616] proxy_util.c(1935): AH00925: initializing worker http://1.1.1.2:91 shared
[Tue Aug 20 04:33:43.254397 2019] [proxy:debug] [pid 13:tid 140415046375616] proxy_util.c(1992): AH00927: initializing worker http://1.1.1.2:91 local
[Tue Aug 20 04:33:43.254415 2019] [proxy:debug] [pid 13:tid 140415046375616] proxy_util.c(2027): AH00930: initialized pool in child 13 for (1.1.1.2) min=0 max=74 smax=74
[Tue Aug 20 04:33:43.256466 2019] [proxy_balancer:debug] [pid 14:tid 140415046375616] mod_proxy_balancer.c(134): AH01158: Looking at balancer://catalog -> http://1.1.1.1:91 initialized?
[Tue Aug 20 04:33:43.256501 2019] [proxy_balancer:debug] [pid 14:tid 140415046375616] mod_proxy_balancer.c(134): AH01158: Looking at balancer://catalog -> http://1.1.1.2:91 initialized?
[Tue Aug 20 04:33:48.316338 2019] [proxy_hcheck:debug] [pid 13:tid 140413710239488] mod_proxy_hcheck.c(478): AH03248: Creating hc worker 560d70465d78 for http://1.1.1.1:91
[Tue Aug 20 04:33:48.316669 2019] [proxy:debug] [pid 13:tid 140413710239488] proxy_util.c(1935): AH00925: initializing worker 560d70465d78 shared
[Tue Aug 20 04:33:48.316685 2019] [proxy:debug] [pid 13:tid 140413710239488] proxy_util.c(1992): AH00927: initializing worker 560d70465d78 local
[Tue Aug 20 04:33:48.316708 2019] [proxy:debug] [pid 13:tid 140413710239488] proxy_util.c(2027): AH00930: initialized pool in child 13 for (1.1.1.1) min=0 max=74 smax=74
[Tue Aug 20 04:33:48.316731 2019] [proxy_hcheck:debug] [pid 13:tid 140413710239488] mod_proxy_hcheck.c(837): AH03256: Health checking http://1.1.1.1:91
[Tue Aug 20 04:33:48.316918 2019] [proxy:debug] [pid 13:tid 140413710239488] proxy_util.c(2327): AH00942: HCOH: has acquired connection for (1.1.1.1)
[Tue Aug 20 04:33:48.317026 2019] [proxy:trace2] [pid 13:tid 140413710239488] proxy_util.c(3024): HCOH: fam 2 socket created to connect to 1.1.1.1
[Tue Aug 20 04:33:48.319649 2019] [proxy:debug] [pid 13:tid 140413710239488] proxy_util.c(3058): AH02824: HCOH: connection established with 1.1.1.1:91 (1.1.1.1)
[Tue Aug 20 04:33:48.320042 2019] [proxy:debug] [pid 13:tid 140413710239488] proxy_util.c(3242): AH00962: HCOH: connection complete to 1.1.1.1:91 (1.1.1.1)
[Tue Aug 20 04:33:48.322659 2019] [proxy_hcheck:debug] [pid 13:tid 140413710239488] mod_proxy_hcheck.c(653): AH03254: HTTP/1.1 401 Unauthorized
[Tue Aug 20 04:33:48.322739 2019] [proxy_hcheck:trace2] [pid 13:tid 140413710239488] mod_proxy_hcheck.c(820): Response status 401 for 560d70465d78 (http://1.1.1.1:91): failed
[Tue Aug 20 04:33:48.322748 2019] [proxy:debug] [pid 13:tid 140413710239488] proxy_util.c(2342): AH00943: HCOH: has released connection for (1.1.1.1)
[Tue Aug 20 04:33:48.322804 2019] [proxy_hcheck:debug] [pid 13:tid 140413710239488] mod_proxy_hcheck.c(585): AH03251: Health check GET Status (1) for 560d70465d78.
[Tue Aug 20 04:33:48.322813 2019] [proxy_hcheck:info] [pid 13:tid 140413710239488] AH03303: Health check DISABLING http://1.1.1.1:91
[Tue Aug 20 04:33:48.322819 2019] [proxy_hcheck:debug] [pid 13:tid 140413710239488] mod_proxy_hcheck.c(478): AH03248: Creating hc worker 560d70466590 for http://1.1.1.2:91
[Tue Aug 20 04:33:48.322838 2019] [proxy:debug] [pid 13:tid 140413710239488] proxy_util.c(1935): AH00925: initializing worker 560d70466590 shared
[Tue Aug 20 04:33:48.322845 2019] [proxy:debug] [pid 13:tid 140413710239488] proxy_util.c(1992): AH00927: initializing worker 560d70466590 local
[Tue Aug 20 04:33:48.322854 2019] [proxy:debug] [pid 13:tid 140413710239488] proxy_util.c(2027): AH00930: initialized pool in child 13 for (1.1.1.2) min=0 max=74 smax=74
[Tue Aug 20 04:33:48.322862 2019] [proxy_hcheck:debug] [pid 13:tid 140413710239488] mod_proxy_hcheck.c(837): AH03256: Health checking http://1.1.1.2:91
[Tue Aug 20 04:33:48.322867 2019] [proxy:debug] [pid 13:tid 140413710239488] proxy_util.c(2327): AH00942: HCOH: has acquired connection for (1.1.1.2)
[Tue Aug 20 04:33:48.322913 2019] [proxy:trace2] [pid 13:tid 140413710239488] proxy_util.c(3024): HCOH: fam 2 socket created to connect to 1.1.1.2
[Tue Aug 20 04:33:48.323492 2019] [proxy:debug] [pid 13:tid 140413710239488] proxy_util.c(3058): AH02824: HCOH: connection established with 1.1.1.2:91 (1.1.1.2)
[Tue Aug 20 04:33:48.323512 2019] [proxy:debug] [pid 13:tid 140413710239488] proxy_util.c(3242): AH00962: HCOH: connection complete to 1.1.1.2:91 (1.1.1.2)
[Tue Aug 20 04:33:48.324510 2019] [proxy_hcheck:debug] [pid 13:tid 140413710239488] mod_proxy_hcheck.c(653): AH03254: HTTP/1.1 401 Unauthorized
[Tue Aug 20 04:33:48.324551 2019] [proxy_hcheck:trace2] [pid 13:tid 140413710239488] mod_proxy_hcheck.c(820): Response status 401 for 560d70466590 (http://1.1.1.2:91): failed
[Tue Aug 20 04:33:48.324558 2019] [proxy:debug] [pid 13:tid 140413710239488] proxy_util.c(2342): AH00943: HCOH: has released connection for (1.1.1.2)
[Tue Aug 20 04:33:48.324653 2019] [proxy_hcheck:debug] [pid 13:tid 140413710239488] mod_proxy_hcheck.c(585): AH03251: Health check GET Status (1) for 560d70466590.
[Tue Aug 20 04:33:48.324667 2019] [proxy_hcheck:info] [pid 13:tid 140413710239488] AH03303: Health check DISABLING http://1.1.1.2:91
[Tue Aug 20 04:33:53.333480 2019] [proxy_hcheck:debug] [pid 13:tid 140413710239488] mod_proxy_hcheck.c(837): AH03256: Health checking http://1.1.1.1:91
[Tue Aug 20 04:33:53.333533 2019] [proxy:debug] [pid 13:tid 140413710239488] proxy_util.c(2327): AH00942: HCOH: has acquired connection for (1.1.1.1)
[Tue Aug 20 04:33:53.333643 2019] [proxy:trace2] [pid 13:tid 140413710239488] proxy_util.c(3024): HCOH: fam 2 socket created to connect to 1.1.1.1
[Tue Aug 20 04:33:53.336145 2019] [proxy:debug] [pid 13:tid 140413710239488] proxy_util.c(3058): AH02824: HCOH: connection established with 1.1.1.1:91 (1.1.1.1)
[Tue Aug 20 04:33:53.336186 2019] [proxy:debug] [pid 13:tid 140413710239488] proxy_util.c(3242): AH00962: HCOH: connection complete to 1.1.1.1:91 (1.1.1.1)
[Tue Aug 20 04:33:53.342052 2019] [proxy_hcheck:debug] [pid 13:tid 140413710239488] mod_proxy_hcheck.c(653): AH03254: HTTP/1.1 401 Unauthorized
[Tue Aug 20 04:33:53.342139 2019] [proxy_hcheck:trace2] [pid 13:tid 140413710239488] mod_proxy_hcheck.c(820): Response status 401 for 560d70465d78 (http://1.1.1.1:91): failed
[Tue Aug 20 04:33:53.342188 2019] [proxy:debug] [pid 13:tid 140413710239488] proxy_util.c(2342): AH00943: HCOH: has released connection for (1.1.1.1)
[Tue Aug 20 04:33:53.342273 2019] [proxy_hcheck:debug] [pid 13:tid 140413710239488] mod_proxy_hcheck.c(585): AH03251: Health check GET Status (1) for 560d70465d78.
[Tue Aug 20 04:33:53.342286 2019] [proxy_hcheck:debug] [pid 13:tid 140413710239488] mod_proxy_hcheck.c(837): AH03256: Health checking http://1.1.1.2:91
[Tue Aug 20 04:33:53.342292 2019] [proxy:debug] [pid 13:tid 140413710239488] proxy_util.c(2327): AH00942: HCOH: has acquired connection for (1.1.1.2)
[Tue Aug 20 04:33:53.342368 2019] [proxy:trace2] [pid 13:tid 140413710239488] proxy_util.c(3024): HCOH: fam 2 socket created to connect to 1.1.1.2
[Tue Aug 20 04:33:53.342879 2019] [proxy:debug] [pid 13:tid 140413710239488] proxy_util.c(3058): AH02824: HCOH: connection established with 1.1.1.2:91 (1.1.1.2)
[Tue Aug 20 04:33:53.342908 2019] [proxy:debug] [pid 13:tid 140413710239488] proxy_util.c(3242): AH00962: HCOH: connection complete to 1.1.1.2:91 (1.1.1.2)
[Tue Aug 20 04:33:53.344025 2019] [proxy_hcheck:debug] [pid 13:tid 140413710239488] mod_proxy_hcheck.c(653): AH03254: HTTP/1.1 401 Unauthorized
[Tue Aug 20 04:33:53.344079 2019] [proxy_hcheck:trace2] [pid 13:tid 140413710239488] mod_proxy_hcheck.c(820): Response status 401 for 560d70466590 (http://1.1.1.2:91): failed
[Tue Aug 20 04:33:53.344086 2019] [proxy:debug] [pid 13:tid 140413710239488] proxy_util.c(2342): AH00943: HCOH: has released connection for (1.1.1.2)
[Tue Aug 20 04:33:53.344140 2019] [proxy_hcheck:debug] [pid 13:tid 140413710239488] mod_proxy_hcheck.c(585): AH03251: Health check GET Status (1) for 560d70466590.
[Tue Aug 20 04:33:58.361381 2019] [proxy_hcheck:debug] [pid 13:tid 140413710239488] mod_proxy_hcheck.c(837): AH03256: Health checking http://1.1.1.1:91
[Tue Aug 20 04:33:58.361437 2019] [proxy:debug] [pid 13:tid 140413710239488] proxy_util.c(2327): AH00942: HCOH: has acquired connection for (1.1.1.1)
[Tue Aug 20 04:33:58.361544 2019] [proxy:trace2] [pid 13:tid 140413710239488] proxy_util.c(3024): HCOH: fam 2 socket created to connect to 1.1.1.1
[Tue Aug 20 04:33:58.364033 2019] [proxy:debug] [pid 13:tid 140413710239488] proxy_util.c(3058): AH02824: HCOH: connection established with 1.1.1.1:91 (1.1.1.1)
[Tue Aug 20 04:33:58.364077 2019] [proxy:debug] [pid 13:tid 140413710239488] proxy_util.c(3242): AH00962: HCOH: connection complete to 1.1.1.1:91 (1.1.1.1)
[Tue Aug 20 04:33:58.366786 2019] [proxy_hcheck:debug] [pid 13:tid 140413710239488] mod_proxy_hcheck.c(653): AH03254: HTTP/1.1 401 Unauthorized
[Tue Aug 20 04:33:58.366833 2019] [proxy_hcheck:trace2] [pid 13:tid 140413710239488] mod_proxy_hcheck.c(820): Response status 401 for 560d70465d78 (http://1.1.1.1:91): failed
[Tue Aug 20 04:33:58.366846 2019] [proxy:debug] [pid 13:tid 140413710239488] proxy_util.c(2342): AH00943: HCOH: has released connection for (1.1.1.1)
[Tue Aug 20 04:33:58.366922 2019] [proxy_hcheck:debug] [pid 13:tid 140413710239488] mod_proxy_hcheck.c(585): AH03251: Health check GET Status (1) for 560d70465d78.
[Tue Aug 20 04:33:58.366941 2019] [proxy_hcheck:debug] [pid 13:tid 140413710239488] mod_proxy_hcheck.c(837): AH03256: Health checking http://1.1.1.2:91
[Tue Aug 20 04:33:58.366951 2019] [proxy:debug] [pid 13:tid 140413710239488] proxy_util.c(2327): AH00942: HCOH: has acquired connection for (1.1.1.2)
[Tue Aug 20 04:33:58.367036 2019] [proxy:trace2] [pid 13:tid 140413710239488] proxy_util.c(3024): HCOH: fam 2 socket created to connect to 1.1.1.2
[Tue Aug 20 04:33:58.367718 2019] [proxy:debug] [pid 13:tid 140413710239488] proxy_util.c(3058): AH02824: HCOH: connection established with 1.1.1.2:91 (1.1.1.2)
[Tue Aug 20 04:33:58.367753 2019] [proxy:debug] [pid 13:tid 140413710239488] proxy_util.c(3242): AH00962: HCOH: connection complete to 1.1.1.2:91 (1.1.1.2)
[Tue Aug 20 04:33:58.368749 2019] [proxy_hcheck:debug] [pid 13:tid 140413710239488] mod_proxy_hcheck.c(653): AH03254: HTTP/1.1 401 Unauthorized
Comment 6 Antony 2019-08-20 20:05:26 UTC
(In reply to evgeniusx@ukr.net from comment #5)
> Hello! I have similar issue on apache 2.4.41. On my backends i use basic
> auth and when connect through Proxy balancer:// got 401 code. also with
> Proxy configered healthcheck and when i disable the healthcheck proxy member
> work fine. On apache 2.4.39 also work fine with original config PROXY. Sory
> for my bad english.
> 
> 
> configs:
> 
> PROXY:
> 
> <VirtualHost *:91>
> LogLevel debug
> LogLevel proxy_hcheck:trace2
> LogLevel proxy:trace2
> LogLevel watchdog:trace2
> ErrorLog /var/log/httpd/catalog-error_log
> CustomLog "/var/log/catalog-access_log" combined
>     ProxyRequests off
>     <Proxy balancer://catalog>
>         BalancerMember http://1.1.1.1:91 hcmethod=GET  hcuri=/getStatus.php
> hcinterval=5 timeout=3 retry=5 connectiontimeout=500ms
>         BalancerMember http://1.1.1.2:91 hcmethod=GET  hcuri=/getStatus.php
> hcinterval=5 timeout=3 retry=5 connectiontimeout=500ms
>         Require all granted
>         ProxySet lbmethod=byrequests
>     </Proxy>
>     ProxyPass / balancer://catalog/
> </VirtualHost>
> 
> 
> 
> MEMBER1:
> <VirtualHost _default_ *:91>
>     ServerName catalog1.example.com
>     ServerAlias 1.1.1.1
>     DocumentRoot "/var/www/html/service/public"
>     ErrorLog /var/log/httpd/catalog1.example.com-error_log
>     LogFormat "%h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\""
> combined
>     CustomLog "logs/catalog1.example.com-access_log" combined
>     LogLevel debug
>     <Location />
>         AuthType Basic
>         AuthName "Please enter your username and password"
>         AuthUserFile /etc/httpd/conf/htpasswd
>         <RequireAny>
>             Require ip 127.0.0.1
>             Require valid-user
>         </RequireAny>
>     </Location>
> 
>     <Directory "/var/www/html/service/public">
>         Options FollowSymLinks
>         AllowOverride None
>         Require valid-user
>     </Directory>
> 
>     ProxyPassMatch ^/(.*\.php(/.*)?)$
> unix:///var/run/php-fpm.sock|fcgi://127.0.0.1:9000/var/www/html/service/
> public/$1
>     ProxyTimeout 18000
>     DirectoryIndex /index.php index.php
> </VirtualHost>
> 
> MEMBER2:
> 
> <VirtualHost _default_ *:91>
>     ServerName catalog2.example.com
>     ServerAlias 1.1.1.2
>     DocumentRoot "/var/www/html/service/public"
>     ErrorLog /var/log/httpd/catalog2.example.com-error_log
>     LogFormat "%h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\""
> combined
>     CustomLog "logs/catalog1.example.com-access_log" combined
>     LogLevel debug
>     <Location />
>         AuthType Basic
>         AuthName "Please enter your username and password"
>         AuthUserFile /etc/httpd/conf/htpasswd
>         <RequireAny>
>             Require ip 127.0.0.1
>             Require valid-user
>         </RequireAny>
>     </Location>
> 
>     <Directory "/var/www/html/service/public">
>         Options FollowSymLinks
>         AllowOverride None
>         Require valid-user
>     </Directory>
> 
>     ProxyPassMatch ^/(.*\.php(/.*)?)$
> unix:///var/run/php-fpm.sock|fcgi://127.0.0.1:9000/var/www/html/service/
> public/$1
>     ProxyTimeout 18000
>     DirectoryIndex /index.php index.php
> </VirtualHost>
> 
> LOG_FROM_PROXY:
> 
> [Tue Aug 20 04:33:43.247155 2019] [proxy_balancer:debug] [pid 1:tid
> 140415046375616] mod_proxy_balancer.c(919): AH01178: Doing balancers create:
> 544, 1 (6)
> [Tue Aug 20 04:33:43.247354 2019] [proxy_balancer:debug] [pid 1:tid
> 140415046375616] mod_proxy_balancer.c(989): AH01184: Doing workers create:
> balancer://catalog (p678f5e47_catalog), 1064, 2 [0]
> [Tue Aug 20 04:33:43.249728 2019] [proxy_hcheck:debug] [pid 1:tid
> 140415046375616] mod_proxy_hcheck.c(1053): AH03265: watchdog callback
> registered (_proxy_hcheck_ for 172.18.0.4)
> [Tue Aug 20 04:33:43.253551 2019] [proxy_hcheck:debug] [pid 13:tid
> 140413710239488] mod_proxy_hcheck.c(899): AH03258: _proxy_hcheck_ watchdog
> started.
> [Tue Aug 20 04:33:43.254200 2019] [proxy_hcheck:debug] [pid 13:tid
> 140413710239488] mod_proxy_hcheck.c(913): AH03313: apr_thread_pool_create()
> with 16 threads succeeded
> [Tue Aug 20 04:33:43.254294 2019] [proxy_balancer:debug] [pid 13:tid
> 140415046375616] mod_proxy_balancer.c(134): AH01158: Looking at
> balancer://catalog -> http://1.1.1.1:91 initialized?
> [Tue Aug 20 04:33:43.254316 2019] [proxy:debug] [pid 13:tid 140415046375616]
> proxy_util.c(1935): AH00925: initializing worker http://1.1.1.1:91 shared
> [Tue Aug 20 04:33:43.254339 2019] [proxy:debug] [pid 13:tid 140415046375616]
> proxy_util.c(1992): AH00927: initializing worker http://1.1.1.1:91 local
> [Tue Aug 20 04:33:43.254378 2019] [proxy:debug] [pid 13:tid 140415046375616]
> proxy_util.c(2027): AH00930: initialized pool in child 13 for (1.1.1.1)
> min=0 max=74 smax=74
> [Tue Aug 20 04:33:43.254388 2019] [proxy_balancer:debug] [pid 13:tid
> 140415046375616] mod_proxy_balancer.c(134): AH01158: Looking at
> balancer://catalog -> http://1.1.1.2:91 initialized?
> [Tue Aug 20 04:33:43.254392 2019] [proxy:debug] [pid 13:tid 140415046375616]
> proxy_util.c(1935): AH00925: initializing worker http://1.1.1.2:91 shared
> [Tue Aug 20 04:33:43.254397 2019] [proxy:debug] [pid 13:tid 140415046375616]
> proxy_util.c(1992): AH00927: initializing worker http://1.1.1.2:91 local
> [Tue Aug 20 04:33:43.254415 2019] [proxy:debug] [pid 13:tid 140415046375616]
> proxy_util.c(2027): AH00930: initialized pool in child 13 for (1.1.1.2)
> min=0 max=74 smax=74
> [Tue Aug 20 04:33:43.256466 2019] [proxy_balancer:debug] [pid 14:tid
> 140415046375616] mod_proxy_balancer.c(134): AH01158: Looking at
> balancer://catalog -> http://1.1.1.1:91 initialized?
> [Tue Aug 20 04:33:43.256501 2019] [proxy_balancer:debug] [pid 14:tid
> 140415046375616] mod_proxy_balancer.c(134): AH01158: Looking at
> balancer://catalog -> http://1.1.1.2:91 initialized?
> [Tue Aug 20 04:33:48.316338 2019] [proxy_hcheck:debug] [pid 13:tid
> 140413710239488] mod_proxy_hcheck.c(478): AH03248: Creating hc worker
> 560d70465d78 for http://1.1.1.1:91
> [Tue Aug 20 04:33:48.316669 2019] [proxy:debug] [pid 13:tid 140413710239488]
> proxy_util.c(1935): AH00925: initializing worker 560d70465d78 shared
> [Tue Aug 20 04:33:48.316685 2019] [proxy:debug] [pid 13:tid 140413710239488]
> proxy_util.c(1992): AH00927: initializing worker 560d70465d78 local
> [Tue Aug 20 04:33:48.316708 2019] [proxy:debug] [pid 13:tid 140413710239488]
> proxy_util.c(2027): AH00930: initialized pool in child 13 for (1.1.1.1)
> min=0 max=74 smax=74
> [Tue Aug 20 04:33:48.316731 2019] [proxy_hcheck:debug] [pid 13:tid
> 140413710239488] mod_proxy_hcheck.c(837): AH03256: Health checking
> http://1.1.1.1:91
> [Tue Aug 20 04:33:48.316918 2019] [proxy:debug] [pid 13:tid 140413710239488]
> proxy_util.c(2327): AH00942: HCOH: has acquired connection for (1.1.1.1)
> [Tue Aug 20 04:33:48.317026 2019] [proxy:trace2] [pid 13:tid
> 140413710239488] proxy_util.c(3024): HCOH: fam 2 socket created to connect
> to 1.1.1.1
> [Tue Aug 20 04:33:48.319649 2019] [proxy:debug] [pid 13:tid 140413710239488]
> proxy_util.c(3058): AH02824: HCOH: connection established with 1.1.1.1:91
> (1.1.1.1)
> [Tue Aug 20 04:33:48.320042 2019] [proxy:debug] [pid 13:tid 140413710239488]
> proxy_util.c(3242): AH00962: HCOH: connection complete to 1.1.1.1:91
> (1.1.1.1)
> [Tue Aug 20 04:33:48.322659 2019] [proxy_hcheck:debug] [pid 13:tid
> 140413710239488] mod_proxy_hcheck.c(653): AH03254: HTTP/1.1 401 Unauthorized
> [Tue Aug 20 04:33:48.322739 2019] [proxy_hcheck:trace2] [pid 13:tid
> 140413710239488] mod_proxy_hcheck.c(820): Response status 401 for
> 560d70465d78 (http://1.1.1.1:91): failed
> [Tue Aug 20 04:33:48.322748 2019] [proxy:debug] [pid 13:tid 140413710239488]
> proxy_util.c(2342): AH00943: HCOH: has released connection for (1.1.1.1)
> [Tue Aug 20 04:33:48.322804 2019] [proxy_hcheck:debug] [pid 13:tid
> 140413710239488] mod_proxy_hcheck.c(585): AH03251: Health check GET Status
> (1) for 560d70465d78.
> [Tue Aug 20 04:33:48.322813 2019] [proxy_hcheck:info] [pid 13:tid
> 140413710239488] AH03303: Health check DISABLING http://1.1.1.1:91
> [Tue Aug 20 04:33:48.322819 2019] [proxy_hcheck:debug] [pid 13:tid
> 140413710239488] mod_proxy_hcheck.c(478): AH03248: Creating hc worker
> 560d70466590 for http://1.1.1.2:91
> [Tue Aug 20 04:33:48.322838 2019] [proxy:debug] [pid 13:tid 140413710239488]
> proxy_util.c(1935): AH00925: initializing worker 560d70466590 shared
> [Tue Aug 20 04:33:48.322845 2019] [proxy:debug] [pid 13:tid 140413710239488]
> proxy_util.c(1992): AH00927: initializing worker 560d70466590 local
> [Tue Aug 20 04:33:48.322854 2019] [proxy:debug] [pid 13:tid 140413710239488]
> proxy_util.c(2027): AH00930: initialized pool in child 13 for (1.1.1.2)
> min=0 max=74 smax=74
> [Tue Aug 20 04:33:48.322862 2019] [proxy_hcheck:debug] [pid 13:tid
> 140413710239488] mod_proxy_hcheck.c(837): AH03256: Health checking
> http://1.1.1.2:91
> [Tue Aug 20 04:33:48.322867 2019] [proxy:debug] [pid 13:tid 140413710239488]
> proxy_util.c(2327): AH00942: HCOH: has acquired connection for (1.1.1.2)
> [Tue Aug 20 04:33:48.322913 2019] [proxy:trace2] [pid 13:tid
> 140413710239488] proxy_util.c(3024): HCOH: fam 2 socket created to connect
> to 1.1.1.2
> [Tue Aug 20 04:33:48.323492 2019] [proxy:debug] [pid 13:tid 140413710239488]
> proxy_util.c(3058): AH02824: HCOH: connection established with 1.1.1.2:91
> (1.1.1.2)
> [Tue Aug 20 04:33:48.323512 2019] [proxy:debug] [pid 13:tid 140413710239488]
> proxy_util.c(3242): AH00962: HCOH: connection complete to 1.1.1.2:91
> (1.1.1.2)
> [Tue Aug 20 04:33:48.324510 2019] [proxy_hcheck:debug] [pid 13:tid
> 140413710239488] mod_proxy_hcheck.c(653): AH03254: HTTP/1.1 401 Unauthorized
> [Tue Aug 20 04:33:48.324551 2019] [proxy_hcheck:trace2] [pid 13:tid
> 140413710239488] mod_proxy_hcheck.c(820): Response status 401 for
> 560d70466590 (http://1.1.1.2:91): failed
> [Tue Aug 20 04:33:48.324558 2019] [proxy:debug] [pid 13:tid 140413710239488]
> proxy_util.c(2342): AH00943: HCOH: has released connection for (1.1.1.2)
> [Tue Aug 20 04:33:48.324653 2019] [proxy_hcheck:debug] [pid 13:tid
> 140413710239488] mod_proxy_hcheck.c(585): AH03251: Health check GET Status
> (1) for 560d70466590.
> [Tue Aug 20 04:33:48.324667 2019] [proxy_hcheck:info] [pid 13:tid
> 140413710239488] AH03303: Health check DISABLING http://1.1.1.2:91
> [Tue Aug 20 04:33:53.333480 2019] [proxy_hcheck:debug] [pid 13:tid
> 140413710239488] mod_proxy_hcheck.c(837): AH03256: Health checking
> http://1.1.1.1:91
> [Tue Aug 20 04:33:53.333533 2019] [proxy:debug] [pid 13:tid 140413710239488]
> proxy_util.c(2327): AH00942: HCOH: has acquired connection for (1.1.1.1)
> [Tue Aug 20 04:33:53.333643 2019] [proxy:trace2] [pid 13:tid
> 140413710239488] proxy_util.c(3024): HCOH: fam 2 socket created to connect
> to 1.1.1.1
> [Tue Aug 20 04:33:53.336145 2019] [proxy:debug] [pid 13:tid 140413710239488]
> proxy_util.c(3058): AH02824: HCOH: connection established with 1.1.1.1:91
> (1.1.1.1)
> [Tue Aug 20 04:33:53.336186 2019] [proxy:debug] [pid 13:tid 140413710239488]
> proxy_util.c(3242): AH00962: HCOH: connection complete to 1.1.1.1:91
> (1.1.1.1)
> [Tue Aug 20 04:33:53.342052 2019] [proxy_hcheck:debug] [pid 13:tid
> 140413710239488] mod_proxy_hcheck.c(653): AH03254: HTTP/1.1 401 Unauthorized
> [Tue Aug 20 04:33:53.342139 2019] [proxy_hcheck:trace2] [pid 13:tid
> 140413710239488] mod_proxy_hcheck.c(820): Response status 401 for
> 560d70465d78 (http://1.1.1.1:91): failed
> [Tue Aug 20 04:33:53.342188 2019] [proxy:debug] [pid 13:tid 140413710239488]
> proxy_util.c(2342): AH00943: HCOH: has released connection for (1.1.1.1)
> [Tue Aug 20 04:33:53.342273 2019] [proxy_hcheck:debug] [pid 13:tid
> 140413710239488] mod_proxy_hcheck.c(585): AH03251: Health check GET Status
> (1) for 560d70465d78.
> [Tue Aug 20 04:33:53.342286 2019] [proxy_hcheck:debug] [pid 13:tid
> 140413710239488] mod_proxy_hcheck.c(837): AH03256: Health checking
> http://1.1.1.2:91
> [Tue Aug 20 04:33:53.342292 2019] [proxy:debug] [pid 13:tid 140413710239488]
> proxy_util.c(2327): AH00942: HCOH: has acquired connection for (1.1.1.2)
> [Tue Aug 20 04:33:53.342368 2019] [proxy:trace2] [pid 13:tid
> 140413710239488] proxy_util.c(3024): HCOH: fam 2 socket created to connect
> to 1.1.1.2
> [Tue Aug 20 04:33:53.342879 2019] [proxy:debug] [pid 13:tid 140413710239488]
> proxy_util.c(3058): AH02824: HCOH: connection established with 1.1.1.2:91
> (1.1.1.2)
> [Tue Aug 20 04:33:53.342908 2019] [proxy:debug] [pid 13:tid 140413710239488]
> proxy_util.c(3242): AH00962: HCOH: connection complete to 1.1.1.2:91
> (1.1.1.2)
> [Tue Aug 20 04:33:53.344025 2019] [proxy_hcheck:debug] [pid 13:tid
> 140413710239488] mod_proxy_hcheck.c(653): AH03254: HTTP/1.1 401 Unauthorized
> [Tue Aug 20 04:33:53.344079 2019] [proxy_hcheck:trace2] [pid 13:tid
> 140413710239488] mod_proxy_hcheck.c(820): Response status 401 for
> 560d70466590 (http://1.1.1.2:91): failed
> [Tue Aug 20 04:33:53.344086 2019] [proxy:debug] [pid 13:tid 140413710239488]
> proxy_util.c(2342): AH00943: HCOH: has released connection for (1.1.1.2)
> [Tue Aug 20 04:33:53.344140 2019] [proxy_hcheck:debug] [pid 13:tid
> 140413710239488] mod_proxy_hcheck.c(585): AH03251: Health check GET Status
> (1) for 560d70466590.
> [Tue Aug 20 04:33:58.361381 2019] [proxy_hcheck:debug] [pid 13:tid
> 140413710239488] mod_proxy_hcheck.c(837): AH03256: Health checking
> http://1.1.1.1:91
> [Tue Aug 20 04:33:58.361437 2019] [proxy:debug] [pid 13:tid 140413710239488]
> proxy_util.c(2327): AH00942: HCOH: has acquired connection for (1.1.1.1)
> [Tue Aug 20 04:33:58.361544 2019] [proxy:trace2] [pid 13:tid
> 140413710239488] proxy_util.c(3024): HCOH: fam 2 socket created to connect
> to 1.1.1.1
> [Tue Aug 20 04:33:58.364033 2019] [proxy:debug] [pid 13:tid 140413710239488]
> proxy_util.c(3058): AH02824: HCOH: connection established with 1.1.1.1:91
> (1.1.1.1)
> [Tue Aug 20 04:33:58.364077 2019] [proxy:debug] [pid 13:tid 140413710239488]
> proxy_util.c(3242): AH00962: HCOH: connection complete to 1.1.1.1:91
> (1.1.1.1)
> [Tue Aug 20 04:33:58.366786 2019] [proxy_hcheck:debug] [pid 13:tid
> 140413710239488] mod_proxy_hcheck.c(653): AH03254: HTTP/1.1 401 Unauthorized
> [Tue Aug 20 04:33:58.366833 2019] [proxy_hcheck:trace2] [pid 13:tid
> 140413710239488] mod_proxy_hcheck.c(820): Response status 401 for
> 560d70465d78 (http://1.1.1.1:91): failed
> [Tue Aug 20 04:33:58.366846 2019] [proxy:debug] [pid 13:tid 140413710239488]
> proxy_util.c(2342): AH00943: HCOH: has released connection for (1.1.1.1)
> [Tue Aug 20 04:33:58.366922 2019] [proxy_hcheck:debug] [pid 13:tid
> 140413710239488] mod_proxy_hcheck.c(585): AH03251: Health check GET Status
> (1) for 560d70465d78.
> [Tue Aug 20 04:33:58.366941 2019] [proxy_hcheck:debug] [pid 13:tid
> 140413710239488] mod_proxy_hcheck.c(837): AH03256: Health checking
> http://1.1.1.2:91
> [Tue Aug 20 04:33:58.366951 2019] [proxy:debug] [pid 13:tid 140413710239488]
> proxy_util.c(2327): AH00942: HCOH: has acquired connection for (1.1.1.2)
> [Tue Aug 20 04:33:58.367036 2019] [proxy:trace2] [pid 13:tid
> 140413710239488] proxy_util.c(3024): HCOH: fam 2 socket created to connect
> to 1.1.1.2
> [Tue Aug 20 04:33:58.367718 2019] [proxy:debug] [pid 13:tid 140413710239488]
> proxy_util.c(3058): AH02824: HCOH: connection established with 1.1.1.2:91
> (1.1.1.2)
> [Tue Aug 20 04:33:58.367753 2019] [proxy:debug] [pid 13:tid 140413710239488]
> proxy_util.c(3242): AH00962: HCOH: connection complete to 1.1.1.2:91
> (1.1.1.2)
> [Tue Aug 20 04:33:58.368749 2019] [proxy_hcheck:debug] [pid 13:tid
> 140413710239488] mod_proxy_hcheck.c(653): AH03254: HTTP/1.1 401 Unauthorized

Hello Evgeni (I suppose),

Thanks for your notes but I am not using HealthChecks at all.

My mainly issue is that I am receiving these messages (All workers are in error state for route) while in the workers servers, in the apache log, I don't have ANY ERRORS !!!!!!!!!
Comment 7 evgeniusx@ukr.net 2019-08-22 12:37:06 UTC
what version of apache you use?
Comment 8 Antony 2019-08-22 13:11:51 UTC
(In reply to evgeniusx@ukr.net from comment #7)
> what version of apache you use?

The problem exists with all the 2.4 versions.

The previous version was the 2.4.39.

And now the running version is the 2.4.41.

I have 3 pairs of Balancers (IntNLB1 & 2, ExtNLB1 & 2, WWWNLB1 & 2).

For each pair, I have 2 workers servers.

All the pairs of Balancers have the same issue.

I have try to switch the NLB's (IntNLB1 as Master, IntNLB2 as Backup and vice versa) but nothing changes.

Sometimes the workers servers shows in their logs (during the NLB issue) some 304 messages or 404 messages (about some missing images mainly) but there are times that all the messages in the workers servers (during the NLB issue) are all 200 (ALL OK).

And I don't know what else I can do and how I can trace better this issue.

Any idea is welcome.