Join Log in
Score:0
Tore Ericsson avatar Ubuntu

Ubuntu server running a proxied Node/JS web app with Apache2 gets weird connection failure

in flag
Tore Ericsson

Like this, I am running an Express JS app trough Apache (note retry=0 is important):

...
   ProxyRequests Off
   ProxyPreserveHost On
   ProxyVia Full
   <Proxy *>
       Require all granted
   </Proxy>
   ProxyPass / http://127.0.0.1:3000/ retry=0
   ProxyPassReverse / http://127.0.0.1:3000/
...

After upgrade of some software (e.g. to Ubuntu 20.04 server) and of the internet gateway (Sagecom 5370e) I am stuck with the apache2 server not connecting to localhost:3000 with the following fine grained logout, which I cannot interpret. Can somebody please provide a hint how to proceed to understand the reason?

Apache2 detailed log

The emphasized gray part starts with seemingly successful access/permission negotiations but ends after ...HTTP: fam 2 socket created to connect to 127.0.0.1 with ...AH00957: HTTP: attempt to connect to 127.0.0.1:3000 (127.0.0.1) failed and browser 503 error. (why fam 2 socket?)

Or find that in the same plain text (at another point in time):

[Tue Aug 10 20:08:28.154152 2021] [http:trace4] [pid 2513680] http_request.c(439): [client 88.83.62.147:50644]   Sec-Fetch-Mode: navigate
[Tue Aug 10 20:08:28.154155 2021] [http:trace4] [pid 2513680] http_request.c(439): [client 88.83.62.147:50644]   Sec-Fetch-Site: none
[Tue Aug 10 20:08:28.154158 2021] [http:trace4] [pid 2513680] http_request.c(439): [client 88.83.62.147:50644]   Sec-Fetch-User: ?1
[Tue Aug 10 20:08:28.154164 2021] [http:trace4] [pid 2513680] http_request.c(439): [client 88.83.62.147:50644]   DNT: 1
[Tue Aug 10 20:08:28.154167 2021] [http:trace4] [pid 2513680] http_request.c(439): [client 88.83.62.147:50644]   Sec-GPC: 1
[Tue Aug 10 20:08:28.154170 2021] [http:trace4] [pid 2513680] http_request.c(439): [client 88.83.62.147:50644]   Cache-Control: max-age=0
[Tue Aug 10 20:08:28.154187 2021] [rewrite:trace2] [pid 2513680] mod_rewrite.c(483): [client 88.83.62.147:50644] 88.83.62.147 - - [mish.hopto.org/sid#7fca5ec89460][rid#7fca612f90a0/initial] init rewrite engine with requested uri /
[Tue Aug 10 20:08:28.154192 2021] [rewrite:trace1] [pid 2513680] mod_rewrite.c(483): [client 88.83.62.147:50644] 88.83.62.147 - - [mish.hopto.org/sid#7fca5ec89460][rid#7fca612f90a0/initial] pass through /
[Tue Aug 10 20:08:28.154196 2021] [proxy:trace2] [pid 2513680] mod_proxy.c(686): [client 88.83.62.147:50644] AH03461: attempting to match URI path '/' against prefix '/' for proxying
[Tue Aug 10 20:08:28.154206 2021] [proxy:trace1] [pid 2513680] mod_proxy.c(772): [client 88.83.62.147:50644] AH03464: URI path '/' matches proxy handler 'proxy:http://127.0.0.1:3000/'
[Tue Aug 10 20:08:28.154224 2021] [authz_core:debug] [pid 2513680] mod_authz_core.c(817): [client 88.83.62.147:50644] AH01626: authorization result of Require all granted: granted
[Tue Aug 10 20:08:28.154228 2021] [authz_core:debug] [pid 2513680] mod_authz_core.c(817): [client 88.83.62.147:50644] AH01626: authorization result of <RequireAny>: granted
[Tue Aug 10 20:08:28.154232 2021] [core:trace3] [pid 2513680] request.c(310): [client 88.83.62.147:50644] request authorized without authentication by access_checker_ex hook: /
[Tue Aug 10 20:08:28.154247 2021] [proxy_http:trace1] [pid 2513680] mod_proxy_http.c(62): [client 88.83.62.147:50644] HTTP: canonicalising URL //127.0.0.1:3000/
[Tue Aug 10 20:08:28.154276 2021] [proxy:trace2] [pid 2513680] proxy_util.c(2131): [client 88.83.62.147:50644] http: found worker http://127.0.0.1:3000/ for http://127.0.0.1:3000/
[Tue Aug 10 20:08:28.154281 2021] [proxy:debug] [pid 2513680] mod_proxy.c(1253): [client 88.83.62.147:50644] AH01143: Running scheme http handler (attempt 0)
[Tue Aug 10 20:08:28.154285 2021] [proxy_http:trace1] [pid 2513680] mod_proxy_http.c(1985): [client 88.83.62.147:50644] HTTP: serving URL http://127.0.0.1:3000/
[Tue Aug 10 20:08:28.154288 2021] [proxy:debug] [pid 2513680] proxy_util.c(2325): AH00942: HTTP: has acquired connection for (127.0.0.1)
[Tue Aug 10 20:08:28.154296 2021] [proxy:debug] [pid 2513680] proxy_util.c(2379): [client 88.83.62.147:50644] AH00944: connecting http://127.0.0.1:3000/ to 127.0.0.1:3000
[Tue Aug 10 20:08:28.154358 2021] [proxy:debug] [pid 2513680] proxy_util.c(2588): [client 88.83.62.147:50644] AH00947: connected / to 127.0.0.1:3000
[Tue Aug 10 20:08:28.154393 2021] [proxy:trace2] [pid 2513680] proxy_util.c(3022): HTTP: fam 2 socket created to connect to 127.0.0.1
[Tue Aug 10 20:08:28.154440 2021] [proxy:error] [pid 2513680] (111)Connection refused: AH00957: HTTP: attempt to connect to 127.0.0.1:3000 (127.0.0.1) failed
[Tue Aug 10 20:08:28.154459 2021] [proxy_http:error] [pid 2513680] [client 88.83.62.147:50644] AH01114: HTTP: failed to make connection to backend: 127.0.0.1
[Tue Aug 10 20:08:28.154463 2021] [proxy:debug] [pid 2513680] proxy_util.c(2340): AH00943: HTTP: has released connection for (127.0.0.1)
[Tue Aug 10 20:08:28.154495 2021] [http:trace3] [pid 2513680] http_filters.c(1125): [client 88.83.62.147:50644] Response sent with status 503, headers:
[Tue Aug 10 20:08:28.154499 2021] [http:trace5] [pid 2513680] http_filters.c(1134): [client 88.83.62.147:50644]   Date: Tue, 10 Aug 2021 18:08:28 GMT
[Tue Aug 10 20:08:28.154503 2021] [http:trace5] [pid 2513680] http_filters.c(1137): [client 88.83.62.147:50644]   Server: Apache/2.4.41 (Ubuntu)
[Tue Aug 10 20:08:28.154506 2021] [http:trace4] [pid 2513680] http_filters.c(955): [client 88.83.62.147:50644]   Content-Length: 380
[Tue Aug 10 20:08:28.154514 2021] [http:trace4] [pid 2513680] http_filters.c(955): [client 88.83.62.147:50644]   Connection: close
[Tue Aug 10 20:08:28.154517 2021] [http:trace4] [pid 2513680] http_filters.c(955): [client 88.83.62.147:50644]   Content-Type: text/html; charset=iso-8859-1
[Tue Aug 10 20:08:28.154522 2021] [ssl:trace4] [pid 2513680] ssl_engine_io.c(1657): [client 88.83.62.147:50644] coalesce: have 0 bytes, adding 190 more
[Tue Aug 10 20:08:28.154526 2021] [ssl:trace4] [pid 2513680] ssl_engine_io.c(1657): [client 88.83.62.147:50644] coalesce: have 190 bytes, adding 380 more
[Tue Aug 10 20:08:28.154529 2021] [ssl:trace4] [pid 2513680] ssl_engine_io.c(1718): [client 88.83.62.147:50644] coalesce: passing on 570 bytes
[Tue Aug 10 20:08:28.154540 2021] [core:trace8] [pid 2513680] core_filters.c(575): [client 88.83.62.147:50644] brigade contains: bytes: 592, non-file bytes: 592, eor buckets: 0, morphing buckets: 0
[Tue Aug 10 20:08:28.154545 2021] [ssl:trace4] [pid 2513680] ssl_engine_io.c(2207): [client 88.83.62.147:50644] OpenSSL: write 592/592 bytes to BIO#55edbb4540b0 [mem: 55edbb4f45f3] (BIO dump follows)
[Tue Aug 10 20:08:28.154548 2021] [ssl:trace7] [pid 2513680] ssl_engine_io.c(2134): [client 88.83.62.147:50644] +---------------------------------------------+
[Tue Aug 10 20:08:28.154554 2021] [ssl:trace7] [pid 2513680] ssl_engine_io.c(2173): [client 88.83.62.147:50644] | 0000: 17 03 03 02 4b 00 8c af-a7 6c 28 46 85 23 66 8f  ....K....l(F.#f. |
[Tue Aug 10 20:08:28.154559 2021] [ssl:trace7] [pid 2513680] ssl_engine_io.c(2173): [client 88.83.62.147:50644] | 0010: bd aa 6b 06 77 a6 17 df-a7 f3 5d 33 e5 a9 94 b7  ..k.w.....]3.... |
[Tue Aug 10 20:08:28.154563 2021] [ssl:trace7] [pid 2513680] ssl_engine_io.c(2173): [client 88.83.62.147:50644] | 0020: a4 b2 be b7 e1 5a 64 20-38 50 d4 96 53 0c cf 19  .....Zd 8P..S... |
[Tue Aug 10 20:08:28.154568 2021] [ssl:trace7] [pid 2513680] ssl_engine_io.c(2173): [client 88.83.62.147:50644] | 0030: ef 10 dc 8d ba bc 1e f1-79 b7 54 2a 93 af 8a c9  ........y.T*.... |
[Tue Aug 10 20:08:28.154573 2021] [ssl:trace7] [pid 2513680] ssl_engine_io.c(2173): [client 88.83.62.147:50644] | 0040: a1 a4 8c 9d a8 2f 3c 1d-3d 48 91 27 c1 bd 44 42  ...../<.=H.'..DB |
[Tue Aug 10 20:08:28.154577 2021] [ssl:trace7] [pid 2513680] ssl_engine_io.c(2173): [client 88.83.62.147:50644] | 0050: 75 8a 5a 4c ff eb 9b ec-cc e4 23 ce 69 cf 13 4d  u.ZL......#.i..M |

My internet connection's port-forwarding and firewall settings were successful ten days ago (with Sagecom 5370e), but the device is not under my control and may be remotely updated by the provider. It happens to even seem possible to promote communication between the server (LAN IP, apache2) and its localhost (127.0.0.1) through gateway GUI admission settings, but no luck. -- How do I proceed in order to at least understand what happens?

ADDED: Cannot find information in ANY other log than Apache's. Any hint as regards some other way to retreive info? Some network tool?

ADDED: May some extra difficulties come up when localhost goes online, in this case via the pm2 service?

ADDED: @bodo thank you (see comment). The log of course tells in this laconic way that nobody is listening to localhost:3000, which is like 'prepared and unlocked' by the authentication procedure. I regret not being enough alert checking that thoroughly ... will mark resolved when online, hopefully soon!

FINALLY: Much ado about nothing! Just missed that little check: is there anyone listening? (Ok, my apologize: It's always like that, further: I did underestimate the complexity of the js-npm-nvm-node dependency web). Good to get an eyeopener ... thanks!

106
1 + 3
Bodo avatar
pt flag
Bodo
Please [edit] your question and copy&paste the (relevant part of the) logfile as text and format it as a code block instead of showing a screenshot. Is there a process listening on `localhost` (`127.0.0.1`) port `3000`? Please answer by adding details to your question. (`fam 2` might be the numeric value of `AF_INET`.)
0
Reply
Tore Ericsson avatar
in flag
Tore Ericsson
@Bodo A text file added. I cannot find (with `lsof`) any other listening to port 3000.
0
Reply
Bodo avatar
pt flag
Bodo
If I understand correct, this config tells Apache to act as a proxy and to forward all requests to `http://127.0.0.1:3000/`, so there should be a HTTP server listening on port 3000. The error message may mean that nothing is listening on this port or that it doesn't accept HTTP requests. (I don't know which.) What did you configure to listen on port 3000? Maybe there is something in Apache's configuration that you did not show in the question. As you wrote "I cannot find ... *any other* listening to port 3000": Did you find anything? Apache itself? **Please [edit] your question to answer.**
0
Reply
Score:0
Tore Ericsson avatar Ubuntu
in flag
Tore Ericsson

JUST REPEATING: @bodo thank you (see comment). The log of course tells in this laconic way that nobody is listening to localhost:3000, which is like 'prepared and unlocked' by the authentication procedure. I regret not being enough alert checking that thoroughly ... will mark resolved when online, hopefully soon!

FINALLY: Much ado about nothing! Just missed that little check: is there anyone listening? (Ok, my apologize: It's always like that, further: I did underestimate the complexity of the js-npm-nvm-node dependency web). Good to get an eyeopener ... thanks!

0 + 0
ธงชาติไทย
Elon Musk
I sit in a Tesla and translated this thread with Ai:

mangohost

Post an answer

Most people don’t grasp that asking a lot of questions unlocks learning and improves interpersonal bonding. In Alison’s studies, for example, though people could accurately recall how many questions had been asked in their conversations, they didn’t intuit the link between questions and liking. Across four studies, in which participants were engaged in conversations themselves or read transcripts of others’ conversations, people tended not to realize that question asking would influence—or had influenced—the level of amity between the conversationalists.