search

adobe / frl-online-proxy

A simple solution for managing feature-restricted Adobe licenses in an isolated network.
https://opensource.adobe.com/frl-online-proxy/
MIT License
5 stars 8 forks source link

FRL docker failed every night at 3.40 #44

Open maartenpols-united opened 2 years ago

maartenpols-united commented 2 years ago

Description I created a FRL docker, our test server is working fine (doesn't get requests) however the production one is crashing every night at 3.40, at that time its also consuming a lot more memory. is there scheduled some thing in the service? a cleanup? i cant find anything in the logs: [2022-06-14][03:38:01][frl_proxy::proxy][INFO] Received GET request for /status [2022-06-14][03:38:01][frl_proxy::proxy][DEBUG] Received request headers: {"host": "localhost:8443", "user-agent": "Wget/1.21.2", "accept": "/", "accept-encoding": "identity", "connection": "Keep-Alive"} [2022-06-14][03:38:01][frl_proxy::proxy][INFO] Returning status: proxyVersion: 1.2.0, message: Proxy is running [2022-06-14][03:38:01][mio::poll][TRACE] deregistering event source from poller [2022-06-14][03:38:31][mio::poll][TRACE] registering event source with poller: token=Token(184549378), interests=READABLE | WRITABLE [2022-06-14][03:38:31][frl_proxy::proxy][INFO] Received GET request for /status [2022-06-14][03:38:31][frl_proxy::proxy][DEBUG] Received request headers: {"host": "localhost:8443", "user-agent": "Wget/1.21.2", "accept": "/", "accept-encoding": "identity", "connection": "Keep-Alive"} [2022-06-14][03:38:31][frl_proxy::proxy][INFO] Returning status: proxyVersion: 1.2.0, message: Proxy is running [2022-06-14][03:38:31][mio::poll][TRACE] deregistering event source from poller [2022-06-14][03:39:01][mio::poll][TRACE] registering event source with poller: token=Token(201326594), interests=READABLE | WRITABLE [2022-06-14][03:39:01][frl_proxy::proxy][INFO] Received GET request for /status [2022-06-14][03:39:01][frl_proxy::proxy][DEBUG] Received request headers: {"host": "localhost:8443", "user-agent": "Wget/1.21.2", "accept": "/", "accept-encoding": "identity", "connection": "Keep-Alive"} [2022-06-14][03:39:01][frl_proxy::proxy][INFO] Returning status: proxyVersion: 1.2.0, message: Proxy is running [2022-06-14][03:39:01][mio::poll][TRACE] deregistering event source from poller [2022-06-14][03:39:31][mio::poll][TRACE] registering event source with poller: token=Token(218103810), interests=READABLE | WRITABLE [2022-06-14][03:39:31][frl_proxy::proxy][INFO] Received GET request for /status [2022-06-14][03:39:31][frl_proxy::proxy][DEBUG] Received request headers: {"host": "localhost:8443", "user-agent": "Wget/1.21.2", "accept": "/", "accept-encoding": "identity", "connection": "Keep-Alive"} [2022-06-14][03:39:31][frl_proxy::proxy][INFO] Returning status: proxyVersion: 1.2.0, message: Proxy is running [2022-06-14][03:39:31][mio::poll][TRACE] deregistering event source from poller [2022-06-14][03:40:01][mio::poll][TRACE] registering event source with poller: token=Token(234881026), interests=READABLE | WRITABLE [2022-06-14][03:40:01][frl_proxy::proxy][INFO] Received GET request for /status [2022-06-14][03:40:01][frl_proxy::proxy][DEBUG] Received request headers: {"host": "localhost:8443", "user-agent": "Wget/1.21.2", "accept": "/", "accept-encoding": "identity", "connection": "Keep-Alive"} [2022-06-14][03:40:01][frl_proxy::proxy][INFO] Returning status: proxyVersion: 1.2.0, message: Proxy is running [2022-06-14][03:40:01][mio::poll][TRACE] deregistering event source from poller [2022-06-14][03:40:32][mio::poll][TRACE] registering event source with poller: token=Token(251658242), interests=READABLE | WRITABLE [2022-06-14][03:40:32][frl_proxy::proxy][INFO] Received GET request for /status [2022-06-14][03:40:32][frl_proxy::proxy][DEBUG] Received request headers: {"host": "localhost:8443", "user-agent": "Wget/1.21.2", "accept": "/", "accept-encoding": "identity", "connection": "Keep-Alive"} [2022-06-14][03:40:32][frl_proxy::proxy][INFO] Returning status: proxyVersion: 1.2.0, message: Proxy is running [2022-06-14][03:40:32][mio::poll][TRACE] deregistering event source from poller [2022-06-14][03:40:52][mio::poll][TRACE] registering event source with poller: token=Token(268435458), interests=READABLE | WRITABLE [2022-06-14][03:40:52][frl_proxy::proxy][INFO] Received GET request for /status [2022-06-14][03:40:52][frl_proxy::proxy][DEBUG] Received request headers: {"host": "adobe-licensing.nl.emglive.com:8443", "connection": "Keep-Alive, TE", "te": "trailers, deflate, gzip, compress", "user-agent": "RPT-HTTPClient/0.3-3E", "pragma": "no-cache", "accept-language": "en-us,en;q=0.5", "accept-encoding": "gzip, deflate, x-gzip, compress, x-compress"} [2022-06-14][03:40:52][frl_proxy::proxy][INFO] Returning status: proxyVersion: 1.2.0, message: Proxy is running [2022-06-14][03:41:02][mio::poll][TRACE] registering event source with poller: token=Token(1795162115), interests=READABLE | WRITABLE [2022-06-14][03:41:02][frl_proxy::proxy][INFO] Received GET request for /status [2022-06-14][03:41:02][frl_proxy::proxy][DEBUG] Received request headers: {"host": "localhost:8443", "user-agent": "Wget/1.21.2", "accept": "/", "accept-encoding": "identity", "connection": "Keep-Alive"} [2022-06-14][03:41:02][frl_proxy::proxy][INFO] Returning status: proxyVersion: 1.2.0, message: Proxy is running [2022-06-14][03:41:02][mio::poll][TRACE] deregistering event source from poller [2022-06-14][03:41:18][mio::poll][TRACE] registering event source with poller: token=Token(1811939331), interests=READABLE | WRITABLE [2022-06-14][03:41:52][mio::poll][TRACE] deregistering event source from poller [2022-06-14][08:04:28][frl_proxy][DEBUG] conf: Settings { proxy: Proxy { mode: Passthrough, host: "0.0.0.0", port: "8080", ssl_port: "8443", remote_host: "https://lcs-cops.adobe.io", ssl: true }, ssl: Ssl { cert_path: "/etc/frl-proxy/nl.emglive_com.pfx", password: "[OBSCURED]" }, logging: Logging { level: Trace, destination: File, file_path: "/etc/frl-proxy/frl-proxy-log.log" }, cache: Cache { db_path: "proxy-cache.sqlite" }, network: Network { use_proxy: false, proxy_host: "127.0.0.1", proxy_port: "8888", use_proxy: false, proxy_username: "", proxy_password: "[OBSCURED]" } } [2022-06-14][08:12:21][frl_proxy::proxy][INFO] Starting graceful shutdown [2022-06-14][08:12:21][mio::poll][TRACE] deregistering event source from poller [2022-06-14][08:12:21][mio::poll][TRACE] deregistering event source from poller

Steps to reproduce My docker file: FROM alpine:latest

UPDATE IMAGE

RUN apk update RUN apk upgrade

Install wget

RUN apk add wget RUN apk add curl

Download latest FRL version and move to correct location

RUN echo "$(curl -s https://api.github.com/repos/adobe/frl-online-proxy/tags | sed -n 's/."name": "(.)",.*/\1/p' | head -n 1)" > ./URL

RUN URL=$(curl -s https://api.github.com/repos/adobe/frl-online-proxy/tags | sed -n 's/."name": "(.)",.*/\1/p' | head -n 1)

RUN echo "$(curl -s https://api.github.com/repos/adobe/frl-online-proxy/tags | sed -n 's/."name": "(.)",.*/\1/p' | head -n 1 | cut -c 2-)" > ./VERSION

RUN VERSION=$(curl -s https://api.github.com/repos/adobe/frl-online-proxy/tags | sed -n 's/."name": "(.)",.*/\1/p' | head -n 1 | cut -c 2-)

RUN wget https://github.com/adobe/frl-online-proxy/releases/download/$(cat ./URL)/frl-proxy-linux-$(cat ./VERSION).tar.gz RUN tar xf frl-proxy-linux-$(cat ./VERSION).tar.gz

Remove old content

RUN rm frl-proxy-linux-$(cat ./VERSION).tar.gz RUN rm URL

Set container timezone to Europe/Amsterdam

RUN apk add tzdata && cp /usr/share/zoneinfo/Europe/Amsterdam /etc/localtime && echo "Europe/Amsterdam" > /etc/timezone

HEALTHCHECK CMD wget https://localhost:8443/status --no-check-certificate -q -O - > /dev/null 2>&1

CMD ./frl-proxy/frl-proxy -c /etc/frl-proxy/proxy-conf.toml start

Expected behavior A clear and concise description of what you expected to happen.

Screenshots image image

Environment

[ssl] cert_path = "/etc/frl-proxy/nl.emglive_com.pfx" cert_password = "XXXXX"

[logging] level = "trace" destination = "file" file_path = "/etc/frl-proxy/frl-proxy-log.log"

adorton-adobe commented 2 years ago

I don't think we've ever tested the Linux binary on Alpine. You may want to test is using a different base image (e.g. Ubuntu or Debian) and see if that makes a difference. You can also try building the proxy in the Dockerfile instead of downloading the Linux binary. The official rust image provides Alpine variants that will get you the Rust toolchain.

To build and install to $PATH, you just need to run cargo install.

WORKDIR /usr/src/frl-online-proxy
COPY . .
RUN cargo install --path .

Give either of those options a try and let me know if they make a difference. If not I'll see if there's anything else we can try.

maartenpols-united commented 2 years ago

I will try to move the image to another OS, however can you think of anything thats starting twice a day and is consuming (or leaking) memory?

maartenpols-united commented 2 years ago

I moved the container image from Alpine to Ubuntu, however still the same problem, at exact the same time, I installed an autoheal image, so downtime is max 30 seconds now, but prefers to fix the problem: 21-06-2022 03:49:26 Container /adobe-frl found to be unhealthy - Restarting container now with 10s timeout 21-06-2022 13:40:35 Container /adobe-frl found to be unhealthy - Restarting container now with 10s timeout 22-06-2022 03:50:12 Container /adobe-frl found to be unhealthy - Restarting container now with 10s timeout

clickonetwo commented 2 years ago

Hi @maartenpols-united, I am actually seeing one anomaly in your log snippet: [2022-06-14][03:40:52][frl_proxy::proxy][DEBUG] Received request headers: {"host": "adobe-licensing.nl.emglive.com:8443", "connection": "Keep-Alive, TE", "te": "trailers, deflate, gzip, compress", "user-agent": "RPT-HTTPClient/0.3-3E", "pragma": "no-cache", "accept-language": "en-us,en;q=0.5", "accept-encoding": "gzip, deflate, x-gzip, compress, x-compress"} This is a different client than your local wget status checker, and it's calling in at a different time. What's fishy here is that the user agent is a very old Java client that has been used by malicious spiders in the past. Do you know what the source of this call is?

maartenpols-united commented 2 years ago

Hi Daniel, This client is out monitoring system, and its checking if the URL is up, every minute, the wget is the internal docker healthcheck, this are the logs from last night: [2022-06-23][03:45:02][mio::poll][TRACE] registering event source with poller: token=Token(117440515), interests=READABLE | WRITABLE [2022-06-23][03:45:02][frl_proxy::proxy][INFO] Received GET request for /status [2022-06-23][03:45:02][frl_proxy::proxy][DEBUG] Received request headers: {"host": "localhost:8443", "user-agent": "Wget/1.21.2", "accept": "/", "accept-encoding": "identity", "connection": "Keep-Alive"} [2022-06-23][03:45:02][frl_proxy::proxy][INFO] Returning status: proxyVersion: 1.2.0, message: Proxy is running [2022-06-23][03:45:02][mio::poll][TRACE] deregistering event source from poller [2022-06-23][03:45:32][mio::poll][TRACE] registering event source with poller: token=Token(134217731), interests=READABLE | WRITABLE [2022-06-23][03:45:32][frl_proxy::proxy][INFO] Received GET request for /status [2022-06-23][03:45:32][frl_proxy::proxy][DEBUG] Received request headers: {"host": "localhost:8443", "user-agent": "Wget/1.21.2", "accept": "/", "accept-encoding": "identity", "connection": "Keep-Alive"} [2022-06-23][03:45:32][frl_proxy::proxy][INFO] Returning status: proxyVersion: 1.2.0, message: Proxy is running [2022-06-23][03:45:32][mio::poll][TRACE] deregistering event source from poller [2022-06-23][03:45:51][mio::poll][TRACE] deregistering event source from poller [2022-06-23][03:45:52][mio::poll][TRACE] registering event source with poller: token=Token(822083586), interests=READABLE | WRITABLE [2022-06-23][03:45:52][frl_proxy::proxy][INFO] Received GET request for /status [2022-06-23][03:45:52][frl_proxy::proxy][DEBUG] Received request headers: {"host": "adobe-licensing.nl.emglive.com:8443", "connection": "Keep-Alive, TE", "te": "trailers, deflate, gzip, compress", "user-agent": "RPT-HTTPClient/0.3-3E", "pragma": "no-cache", "accept-language": "en-us,en;q=0.5", "accept-encoding": "gzip, deflate, x-gzip, compress, x-compress"} [2022-06-23][03:45:52][frl_proxy::proxy][INFO] Returning status: proxyVersion: 1.2.0, message: Proxy is running [2022-06-23][03:46:02][mio::poll][TRACE] registering event source with poller: token=Token(150994947), interests=READABLE | WRITABLE [2022-06-23][03:46:02][frl_proxy::proxy][INFO] Received GET request for /status [2022-06-23][03:46:02][frl_proxy::proxy][DEBUG] Received request headers: {"host": "localhost:8443", "user-agent": "Wget/1.21.2", "accept": "/", "accept-encoding": "identity", "connection": "Keep-Alive"} [2022-06-23][03:46:02][frl_proxy::proxy][INFO] Returning status: proxyVersion: 1.2.0, message: Proxy is running [2022-06-23][03:46:02][mio::poll][TRACE] deregistering event source from poller [2022-06-23][03:46:32][mio::poll][TRACE] registering event source with poller: token=Token(167772163), interests=READABLE | WRITABLE [2022-06-23][03:46:32][frl_proxy::proxy][INFO] Received GET request for /status [2022-06-23][03:46:32][frl_proxy::proxy][DEBUG] Received request headers: {"host": "localhost:8443", "user-agent": "Wget/1.21.2", "accept": "/", "accept-encoding": "identity", "connection": "Keep-Alive"} [2022-06-23][03:46:32][frl_proxy::proxy][INFO] Returning status: proxyVersion: 1.2.0, message: Proxy is running [2022-06-23][03:46:32][mio::poll][TRACE] deregistering event source from poller [2022-06-23][03:46:52][mio::poll][TRACE] deregistering event source from poller [2022-06-23][03:46:52][mio::poll][TRACE] registering event source with poller: token=Token(838860802), interests=READABLE | WRITABLE [2022-06-23][03:46:52][frl_proxy::proxy][INFO] Received GET request for /status [2022-06-23][03:46:52][frl_proxy::proxy][DEBUG] Received request headers: {"host": "adobe-licensing.nl.emglive.com:8443", "connection": "Keep-Alive, TE", "te": "trailers, deflate, gzip, compress", "user-agent": "RPT-HTTPClient/0.3-3E", "pragma": "no-cache", "accept-language": "en-us,en;q=0.5", "accept-encoding": "gzip, deflate, x-gzip, compress, x-compress"} [2022-06-23][03:46:52][frl_proxy::proxy][INFO] Returning status: proxyVersion: 1.2.0, message: Proxy is running [2022-06-23][03:47:02][mio::poll][TRACE] registering event source with poller: token=Token(184549379), interests=READABLE | WRITABLE [2022-06-23][03:47:02][frl_proxy::proxy][INFO] Received GET request for /status [2022-06-23][03:47:02][frl_proxy::proxy][DEBUG] Received request headers: {"host": "localhost:8443", "user-agent": "Wget/1.21.2", "accept": "/", "accept-encoding": "identity", "connection": "Keep-Alive"} [2022-06-23][03:47:02][frl_proxy::proxy][INFO] Returning status: proxyVersion: 1.2.0, message: Proxy is running [2022-06-23][03:47:02][mio::poll][TRACE] deregistering event source from poller [2022-06-23][03:47:32][mio::poll][TRACE] registering event source with poller: token=Token(201326595), interests=READABLE | WRITABLE [2022-06-23][03:47:32][frl_proxy::proxy][INFO] Received GET request for /status [2022-06-23][03:47:32][frl_proxy::proxy][DEBUG] Received request headers: {"host": "localhost:8443", "user-agent": "Wget/1.21.2", "accept": "/", "accept-encoding": "identity", "connection": "Keep-Alive"} [2022-06-23][03:47:32][frl_proxy::proxy][INFO] Returning status: proxyVersion: 1.2.0, message: Proxy is running [2022-06-23][03:47:32][mio::poll][TRACE] deregistering event source from poller [2022-06-23][03:47:52][mio::poll][TRACE] deregistering event source from poller [2022-06-23][03:47:52][mio::poll][TRACE] registering event source with poller: token=Token(855638018), interests=READABLE | WRITABLE [2022-06-23][03:47:52][frl_proxy::proxy][INFO] Received GET request for /status [2022-06-23][03:47:52][frl_proxy::proxy][DEBUG] Received request headers: {"host": "adobe-licensing.nl.emglive.com:8443", "connection": "Keep-Alive, TE", "te": "trailers, deflate, gzip, compress", "user-agent": "RPT-HTTPClient/0.3-3E", "pragma": "no-cache", "accept-language": "en-us,en;q=0.5", "accept-encoding": "gzip, deflate, x-gzip, compress, x-compress"} [2022-06-23][03:47:52][frl_proxy::proxy][INFO] Returning status: proxyVersion: 1.2.0, message: Proxy is running [2022-06-23][03:48:03][mio::poll][TRACE] registering event source with poller: token=Token(218103811), interests=READABLE | WRITABLE [2022-06-23][03:48:03][frl_proxy::proxy][INFO] Received GET request for /status [2022-06-23][03:48:03][frl_proxy::proxy][DEBUG] Received request headers: {"host": "localhost:8443", "user-agent": "Wget/1.21.2", "accept": "/", "accept-encoding": "identity", "connection": "Keep-Alive"} [2022-06-23][03:48:03][frl_proxy::proxy][INFO] Returning status: proxyVersion: 1.2.0, message: Proxy is running [2022-06-23][03:48:03][mio::poll][TRACE] deregistering event source from poller [2022-06-23][03:48:13][mio::poll][TRACE] registering event source with poller: token=Token(234881027), interests=READABLE | WRITABLE [2022-06-23][03:48:52][mio::poll][TRACE] deregistering event source from poller [2022-06-23][03:51:19][frl_proxy][DEBUG] conf: Settings { proxy: Proxy { mode: Passthrough, host: "0.0.0.0", port: "8080", ssl_port: "8443", remote_host: "https://lcs-cops.adobe.io", ssl: true }, ssl: Ssl { cert_path: "/etc/frl-proxy/nl.emglive_com.pfx", password: "[OBSCURED]" }, logging: Logging { level: Trace, destination: File, file_path: "/etc/frl-proxy/frl-proxy-log.log" }, cache: Cache { db_path: "proxy-cache.sqlite" }, network: Network { use_proxy: false, proxy_host: "127.0.0.1", proxy_port: "8888", use_proxy: false, proxy_username: "", proxy_password: "[OBSCURED]" } } [2022-06-23][03:51:19][mio::poll][TRACE] registering event source with poller: token=Token(1), interests=READABLE | WRITABLE [2022-06-23][03:51:19][frl_proxy::proxy::secure][INFO] Starting to serve on https://0.0.0.0:8443 [2022-06-23][03:51:44][mio::poll][TRACE] registering event source with poller: token=Token(2), interests=READABLE | WRITABLE [2022-06-23][03:51:44][frl_proxy::proxy][INFO] Received GET request for /status [2022-06-23][03:51:44][frl_proxy::proxy][DEBUG] Received request headers: {"host": "localhost:8443", "user-agent": "Wget/1.21.2", "accept": "/", "accept-encoding": "identity", "connection": "Keep-Alive"} [2022-06-23][03:51:44][frl_proxy::proxy][INFO] Returning status: proxyVersion: 1.2.0, message: Proxy is running [2022-06-23][03:51:44][mio::poll][TRACE] deregistering event source from poller [2022-06-23][03:51:52][mio::poll][TRACE] registering event source with poller: token=Token(16777218), interests=READABLE | WRITABLE [2022-06-23][03:51:52][frl_proxy::proxy][INFO] Received GET request for /status [2022-06-23][03:51:52][frl_proxy::proxy][DEBUG] Received request headers: {"host": "adobe-licensing.nl.emglive.com:8443", "connection": "Keep-Alive, TE", "te": "trailers, deflate, gzip, compress", "user-agent": "RPT-HTTPClient/0.3-3E", "pragma": "no-cache", "accept-language": "en-us,en;q=0.5", "accept-encoding": "gzip, deflate, x-gzip, compress, x-compress"} [2022-06-23][03:51:52][frl_proxy::proxy][INFO] Returning status: proxyVersion: 1.2.0, message: Proxy is running [2022-06-23][03:52:14][mio::poll][TRACE] registering event source with poller: token=Token(3), interests=READABLE | WRITABLE [2022-06-23][03:52:14][frl_proxy::proxy][INFO] Received GET request for /status

23-06-2022 03:51:04 Container /adobe-frl found to be unhealthy - Restarting container now with 10s timeout

clickonetwo commented 2 years ago

Hi @maartenpols-united, thanks for the background. I would like to run your exact ubuntu container in my environment in order to figure out whether what's happening is specific to your environment. Can you post that container publicly (e.g., on Docker) so I can download it? If not, can you post the Dockerfile here that you use to build the container?

maartenpols-united commented 2 years ago

@adorton-adobe @clickonetwo We found the reason for crashing, this are vulnerability scans, the question is why is the application crashing on this scans? a view examples about the execution (i dont have the execution codes): Apache.Log4j.Error.Log.Remote.Code.Execution (http://www.fortinet.com/ids/VID51006) Cisco.Smart.Install.Feature.Enable.Scanner (http://www.fortinet.com/ids/VID45938) DDWRT.HTTP.Daemon.Arbitrary.Command.Execution (http://www.fortinet.com/ids/VID17600) ZGrab.Scanner (http://www.fortinet.com/ids/VID48805)

we see this traffic in the firewall, but nothing in the logs of frl

clickonetwo commented 2 years ago

Hi @maartenpols-united, which kind of vulnerability scanning are we talking about: (1) local vulnerability scans run by a scanner in the container, or (2) remote vulnerability scans where a network agent contacts the endpoint with intentionally bad data hoping to find a vulnerability?

If it's (2), then there's likely a bug associated with not limiting the size of incoming messages to the endpoints: that would explain why memory bloats and then the app crashes. This would be hard to fix in the current implementation, because it's a completely homegrown web service. But I am planning in the near future to move the proxy onto the (excellent) warp crate which should make it a lot more resilient. In addition, I'm planning to move logging from fern to log4rs which will allow us to do automatic log rotation directly in the app.

maartenpols-united commented 2 years ago

Hi @clickonetwo its an remote vulnerability scan, thats why its crashing every night at the same time :(

This traffic is blocked by our firewall, however the session is made before the block, so it looks like an idle session, and because this traffic is blocked we dont see any debug data in the event log.

If you need someone to test this new environment, you can contact me.

clickonetwo commented 2 years ago

Ok thanks @maartenpols-united for the additional info. It sounds like we are not timing out the connection once it's made; I will take a look to see if that's a guard we can easily put in. If so, I'll try to get you a build you can try.

clickonetwo commented 1 year ago

Hi @maartenpols-united, I have completely overhauled this server and released it (still open-source) as the adlu-proxy (part of the adobe-desktop-licensing-utilities). If you are still having an issue with the frl-online-proxy, can you see if this separate release solves the problem?

Also, have you tried using nginx in your container to do the SSL termination, rather than having the proxy do it directly? I have found that nginx has a lot of built-in defenses for these kinds of abandoned connections, so just putting it in front of the proxy may solve your problem without a server change.