Issues with Running proxy-mitm on EC2 Instance and proxy-client in Raspberry Pi 4 (using 64bit OS): device Stuck in Online (Heartbeat Only) Status

destradar93 commented 9 months ago

I'm experiencing a problem with my Raspberry Pi 4 device, set up as part of a new Balena fleet, which fails to fully come online after configuring redsocks to work with mitmproxy hosted on an EC2 instance. The device is stuck in an "Online (Heartbeat Only)" status, and I'm unable to see its traffic in the Mitmweb UI.

Setup and Steps Taken:

Cloned the repository to an EC2 instance.
Ran the project using docker-compose, specifying amd64 as %%BALENA_MACHINE_NAME%%.
Opened all traffic for my IP in the EC2 security group.
Verified the proxy's operation at http://<ec2-instance-public-ip>:8081/, where the Mitmweb UI was accessible.
Successfully executed nslookup www.balena.io <ec2-instance-public-ip>, confirming DNS resolution.
Created a new fleet in Balena, adding a Raspberry Pi 4 device (using a 64-bit OS).
Opened all traffic for the balena device IP in the EC2 security group.
Modified /mnt/boot/config.json on the device to include "dnsServers": "" and "balenaRootCA": "LS0t...0=".

Configured /mnt/boot/system-proxy/redsocks.conf with the following settings:


base {
log_debug = on;
log_info = on;
log = stderr;
daemon = off;
redirector = iptables;
}

redsocks { type = http-connect; ip = ; port = 8080; local_ip = 127.0.0.1; local_port = 12345; }


10. Rebooted the Raspberry Pi 4 device.

**Expected Behavior:**
The device should reconnect to the Balena Cloud, redirect its traffic through the configured mitmproxy, and show traffic in the Mitmweb UI.

**Actual Behavior:**
After rebooting with the new redsocks configuration, the device switched to "Online (Heartbeat Only)" status and did not appear in the Mitmweb UI.

kb2ma commented 9 months ago

Hi, the status indicates the device can connect to balenaAPI; however, it cannot connect to Cloudlink. Do you have local ssh access to the RPi4 device? If so, please post the logs for the openvpn component for some period of time, via journalctl -a -u openvpn -S "2023-11-xx hh:mm" -U "2023-11-xx hh:mm" --no-pager

destradar93 commented 9 months ago

Hey @kb2ma, thanks for the response! Here are the OpenVPN, supervisor and redsocks logs:

OpenVPN:
Nov 16 19:58:05 219d1f5 openvpn[1869]: 2023-11-16 19:58:05 TCP/UDP: Preserving recently used remote address: [AF_INET]52.21.201.98:443
Nov 16 19:58:05 219d1f5 openvpn[1869]: 2023-11-16 19:58:05 Socket Buffers: R=[131072->131072] S=[16384->16384]
Nov 16 19:58:05 219d1f5 openvpn[1869]: 2023-11-16 19:58:05 Attempting to establish TCP connection with [AF_INET]52.21.201.98:443 [nonblock]
Nov 16 19:58:05 219d1f5 openvpn[1869]: 2023-11-16 19:58:05 TCP connection established with [AF_INET]52.21.201.98:443
Nov 16 19:58:05 219d1f5 openvpn[1869]: 2023-11-16 19:58:05 TCP_CLIENT link local: (not bound)
Nov 16 19:58:05 219d1f5 openvpn[1869]: 2023-11-16 19:58:05 TCP_CLIENT link remote: [AF_INET]52.21.201.98:443
Nov 16 19:59:05 219d1f5 openvpn[1869]: 2023-11-16 19:59:05 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Nov 16 19:59:05 219d1f5 openvpn[1869]: 2023-11-16 19:59:05 TLS Error: TLS handshake failed
Nov 16 19:59:05 219d1f5 openvpn[1869]: 2023-11-16 19:59:05 Fatal TLS error (check_tls_errors_co), restarting
Nov 16 19:59:05 219d1f5 openvpn[1869]: 2023-11-16 19:59:05 SIGUSR1[soft,tls-error] received, process restarting
Nov 16 19:59:05 219d1f5 openvpn[1869]: 2023-11-16 19:59:05 Restart pause, 5 second(s)
Nov 16 19:59:10 219d1f5 openvpn[1869]: 2023-11-16 19:59:10 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Nov 16 19:59:10 219d1f5 openvpn[1869]: 2023-11-16 19:59:10 TCP/UDP: Preserving recently used remote address: [AF_INET]44.219.65.162:443
Nov 16 19:59:10 219d1f5 openvpn[1869]: 2023-11-16 19:59:10 Socket Buffers: R=[131072->131072] S=[16384->16384]
Nov 16 19:59:10 219d1f5 openvpn[1869]: 2023-11-16 19:59:10 Attempting to establish TCP connection with [AF_INET]44.219.65.162:443 [nonblock]
Nov 16 19:59:10 219d1f5 openvpn[1869]: 2023-11-16 19:59:10 TCP connection established with [AF_INET]44.219.65.162:443
Nov 16 19:59:10 219d1f5 openvpn[1869]: 2023-11-16 19:59:10 TCP_CLIENT link local: (not bound)
Nov 16 19:59:10 219d1f5 openvpn[1869]: 2023-11-16 19:59:10 TCP_CLIENT link remote: [AF_INET]44.219.65.162:443
Nov 16 20:00:10 219d1f5 openvpn[1869]: 2023-11-16 20:00:10 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Nov 16 20:00:10 219d1f5 openvpn[1869]: 2023-11-16 20:00:10 TLS Error: TLS handshake failed
Nov 16 20:00:10 219d1f5 openvpn[1869]: 2023-11-16 20:00:10 Fatal TLS error (check_tls_errors_co), restarting
Nov 16 20:00:10 219d1f5 openvpn[1869]: 2023-11-16 20:00:10 SIGUSR1[soft,tls-error] received, process restarting
Nov 16 20:00:10 219d1f5 openvpn[1869]: 2023-11-16 20:00:10 Restart pause, 5 second(s)
Nov 16 20:00:15 219d1f5 openvpn[1869]: 2023-11-16 20:00:15 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Nov 16 20:00:15 219d1f5 openvpn[1869]: 2023-11-16 20:00:15 TCP/UDP: Preserving recently used remote address: [AF_INET6]2600:1f18:6600:7f01:4bf8:9300:e137:a0f5:443
Nov 16 20:00:15 219d1f5 openvpn[1869]: 2023-11-16 20:00:15 Socket Buffers: R=[131072->131072] S=[16384->16384]
Nov 16 20:00:15 219d1f5 openvpn[1869]: 2023-11-16 20:00:15 Attempting to establish TCP connection with [AF_INET6]2600:1f18:6600:7f01:4bf8:9300:e137:a0f5:443 [nonblock]
Nov 16 20:00:15 219d1f5 openvpn[1869]: 2023-11-16 20:00:15 TCP: connect to [AF_INET6]2600:1f18:6600:7f01:4bf8:9300:e137:a0f5:443 failed: Network is unreachable
Nov 16 20:00:15 219d1f5 openvpn[1869]: 2023-11-16 20:00:15 SIGUSR1[connection failed(soft),init_instance] received, process restarting
Nov 16 20:00:15 219d1f5 openvpn[1869]: 2023-11-16 20:00:15 Restart pause, 5 second(s)
Nov 16 20:00:20 219d1f5 openvpn[1869]: 2023-11-16 20:00:20 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Nov 16 20:00:20 219d1f5 openvpn[1869]: 2023-11-16 20:00:20 TCP/UDP: Preserving recently used remote address: [AF_INET6]2600:1f18:6600:7f00:174b:18f5:aacf:6b8e:443
Nov 16 20:00:20 219d1f5 openvpn[1869]: 2023-11-16 20:00:20 Socket Buffers: R=[131072->131072] S=[16384->16384]
Nov 16 20:00:20 219d1f5 openvpn[1869]: 2023-11-16 20:00:20 Attempting to establish TCP connection with [AF_INET6]2600:1f18:6600:7f00:174b:18f5:aacf:6b8e:443 [nonblock]
Nov 16 20:00:20 219d1f5 openvpn[1869]: 2023-11-16 20:00:20 TCP: connect to [AF_INET6]2600:1f18:6600:7f00:174b:18f5:aacf:6b8e:443 failed: Network is unreachable
Nov 16 20:00:20 219d1f5 openvpn[1869]: 2023-11-16 20:00:20 SIGUSR1[connection failed(soft),init_instance] received, process restarting
Nov 16 20:00:20 219d1f5 openvpn[1869]: 2023-11-16 20:00:20 Restart pause, 5 second(s)
Nov 16 20:00:25 219d1f5 openvpn[1869]: 2023-11-16 20:00:25 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Nov 16 20:00:25 219d1f5 openvpn[1869]: 2023-11-16 20:00:25 TCP/UDP: Preserving recently used remote address: [AF_INET]44.219.65.162:443
Nov 16 20:00:25 219d1f5 openvpn[1869]: 2023-11-16 20:00:25 Socket Buffers: R=[131072->131072] S=[16384->16384]
Nov 16 20:00:25 219d1f5 openvpn[1869]: 2023-11-16 20:00:25 Attempting to establish TCP connection with [AF_INET]44.219.65.162:443 [nonblock]
Nov 16 20:00:25 219d1f5 openvpn[1869]: 2023-11-16 20:00:25 TCP connection established with [AF_INET]44.219.65.162:443
Nov 16 20:00:25 219d1f5 openvpn[1869]: 2023-11-16 20:00:25 TCP_CLIENT link local: (not bound)
Nov 16 20:00:25 219d1f5 openvpn[1869]: 2023-11-16 20:00:25 TCP_CLIENT link remote: [AF_INET]44.219.65.162:443
Nov 16 20:01:26 219d1f5 openvpn[1869]: 2023-11-16 20:01:26 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Nov 16 20:01:26 219d1f5 openvpn[1869]: 2023-11-16 20:01:26 TLS Error: TLS handshake failed
Nov 16 20:01:26 219d1f5 openvpn[1869]: 2023-11-16 20:01:26 Fatal TLS error (check_tls_errors_co), restarting
Nov 16 20:01:26 219d1f5 openvpn[1869]: 2023-11-16 20:01:26 SIGUSR1[soft,tls-error] received, process restarting
Nov 16 20:01:26 219d1f5 openvpn[1869]: 2023-11-16 20:01:26 Restart pause, 10 second(s)

Supervisor:
INFO: Found device /dev/mmcblk0p1 on current boot device mmcblk0, using as mount for '(resin|balena)-boot'.
INFO: Found device /dev/mmcblk0p5 on current boot device mmcblk0, using as mount for '(resin|balena)-state'.
INFO: Found device /dev/mmcblk0p6 on current boot device mmcblk0, using as mount for '(resin|balena)-data'.
find: /mnt/root/tmp/balena-supervisor/services: No such file or directory
[info]  Supervisor v14.13.13 starting up...
[info]  Setting host to discoverable
[debug]  Starting systemd unit: avahi-daemon.service
[debug]  Starting systemd unit: avahi-daemon.socket
[debug]  Starting logging infrastructure
[info]  Starting firewall
[warn]  Invalid firewall mode: . Reverting to state: off
[info]  Applying firewall mode: off
[success] Firewall mode applied
[debug]  Starting api binder
[debug]  Performing database cleanup for container log timestamps
[info]  Previous engine snapshot was not stored. Skipping cleanup.
[debug]  Handling of local mode switch is completed
(node:1) [DEP0005] DeprecationWarning: Buffer() is deprecated due to security and usability issues. Please use the Buffer.alloc(), Buffer.allocUnsafe(), or Buffer.from() methods instead.
(Use `node --trace-deprecation ...` to show where the warning was created)
[info]  API Binder bound to: https://api.balena-cloud.com/v6/
[event]  Event: Supervisor start {}
[info]  Starting API server
[info]  Supervisor API successfully started on port 48484
[debug]  Ensuring device is provisioned
[debug]  Connectivity check enabled: true
[debug]  Starting periodic check for IP addresses
[info]  Reporting initial state, supervisor version and API info
[info]  Waiting for connectivity...
[info]  VPN connection is not active.
[debug]  Skipping preloading
[info]  Applying target state
[debug]  Starting current state report
[debug]  Starting target state poll
[debug]  Spawning journalctl -a --follow -o json _SYSTEMD_UNIT=balena.service
[debug]  Finished applying target state
[success] Device state apply success
[event]  Event: Device state report failure {"error":"ESOCKETTIMEDOUT"}
[info]  Retrying current state report in 15 seconds
[event]  Event: Device state report failure {"error":"ESOCKETTIMEDOUT"}
[info]  Retrying current state report in 30 seconds
[api]   GET /v1/healthy 200 - 15.759 ms

Redsocks:
Nov 16 19:58:01 219d1f5 redsocks[1922]: 1700164681.356365 debug redsocks.c:793 redsocks_shutdown(...) [172.20.5.220:57834->104.18.12.102:443]: shutdown: bufferevent_disable(client, EV_READ)
Nov 16 19:58:05 219d1f5 redsocks[1922]: 1700164685.240630 info redsocks.c:1254 redsocks_accept_client(...) [172.20.5.220:58016->52.21.201.98:443]: accepted
Nov 16 19:58:10 219d1f5 redsocks[1922]: 1700164690.344118 debug redsocks.c:793 redsocks_shutdown(...) [172.20.5.220:62152->104.18.12.102:443]: shutdown: bufferevent_disable(client, EV_READ)
Nov 16 19:58:19 219d1f5 redsocks[1922]: 1700164699.573034 debug redsocks.c:793 redsocks_shutdown(...) [172.20.5.220:64854->104.18.13.102:443]: shutdown: bufferevent_disable(client, EV_READ)
Nov 16 19:58:21 219d1f5 redsocks[1922]: 1700164701.577944 info redsocks.c:1254 redsocks_accept_client(...) [172.20.5.220:57982->104.18.13.102:443]: accepted
Nov 16 19:58:25 219d1f5 redsocks[1922]: 1700164705.553979 info redsocks.c:1254 redsocks_accept_client(...) [172.20.5.220:56824->104.18.12.102:443]: accepted
Nov 16 19:58:51 219d1f5 redsocks[1922]: 1700164731.573810 debug redsocks.c:793 redsocks_shutdown(...) [172.20.5.220:57982->104.18.13.102:443]: shutdown: bufferevent_disable(client, EV_READ)
Nov 16 19:58:53 219d1f5 redsocks[1922]: 1700164733.577781 info redsocks.c:1254 redsocks_accept_client(...) [172.20.5.220:58956->104.18.13.102:443]: accepted
Nov 16 19:59:05 219d1f5 redsocks[1922]: 1700164745.403611 info redsocks.c:1254 redsocks_accept_client(...) [172.20.5.220:53836->104.18.12.102:443]: accepted
Nov 16 19:59:05 219d1f5 redsocks[1922]: 1700164745.834726 debug redsocks.c:793 redsocks_shutdown(...) [172.20.5.220:58016->52.21.201.98:443]: shutdown: bufferevent_disable(client, EV_READ)
Nov 16 19:59:10 219d1f5 redsocks[1922]: 1700164750.400758 debug redsocks.c:793 redsocks_shutdown(...) [172.20.5.220:53836->104.18.12.102:443]: shutdown: bufferevent_disable(client, EV_READ)
Nov 16 19:59:10 219d1f5 redsocks[1922]: 1700164750.836949 info redsocks.c:1254 redsocks_accept_client(...) [172.20.5.220:52468->44.219.65.162:443]: accepted
Nov 16 19:59:23 219d1f5 redsocks[1922]: 1700164763.574746 debug redsocks.c:793 redsocks_shutdown(...) [172.20.5.220:58956->104.18.13.102:443]: shutdown: bufferevent_disable(client, EV_READ)
Nov 16 19:59:25 219d1f5 redsocks[1922]: 1700164765.578523 info redsocks.c:1254 redsocks_accept_client(...) [172.20.5.220:58566->104.18.13.102:443]: accepted
Nov 16 19:59:55 219d1f5 redsocks[1922]: 1700164795.575468 debug redsocks.c:793 redsocks_shutdown(...) [172.20.5.220:58566->104.18.13.102:443]: shutdown: bufferevent_disable(client, EV_READ)
Nov 16 19:59:57 219d1f5 redsocks[1922]: 1700164797.578868 info redsocks.c:1254 redsocks_accept_client(...) [172.20.5.220:53522->104.18.12.102:443]: accepted
Nov 16 20:00:10 219d1f5 redsocks[1922]: 1700164810.615426 debug redsocks.c:793 redsocks_shutdown(...) [172.20.5.220:52468->44.219.65.162:443]: shutdown: bufferevent_disable(client, EV_READ)
Nov 16 20:00:14 219d1f5 redsocks[1922]: 1700164814.455252 info redsocks.c:1254 redsocks_accept_client(...) [172.20.5.220:56664->104.18.12.102:443]: accepted
Nov 16 20:00:19 219d1f5 redsocks[1922]: 1700164819.443751 debug redsocks.c:793 redsocks_shutdown(...) [172.20.5.220:56664->104.18.12.102:443]: shutdown: bufferevent_disable(client, EV_READ)
Nov 16 20:00:23 219d1f5 redsocks[1922]: 1700164823.560261 debug redsocks.c:793 redsocks_shutdown(...) [172.20.5.220:56824->104.18.12.102:443]: shutdown: bufferevent_disable(client, EV_READ)
Nov 16 20:00:25 219d1f5 redsocks[1922]: 1700164825.647738 info redsocks.c:1254 redsocks_accept_client(...) [172.20.5.220:60982->44.219.65.162:443]: accepted
Nov 16 20:00:27 219d1f5 redsocks[1922]: 1700164827.576306 debug redsocks.c:793 redsocks_shutdown(...) [172.20.5.220:53522->104.18.12.102:443]: shutdown: bufferevent_disable(client, EV_READ)
Nov 16 20:00:29 219d1f5 redsocks[1922]: 1700164829.580079 info redsocks.c:1254 redsocks_accept_client(...) [172.20.5.220:58528->104.18.13.102:443]: accepted
Nov 16 20:00:53 219d1f5 redsocks[1922]: 1700164853.727548 info redsocks.c:1254 redsocks_accept_client(...) [172.20.5.220:49516->104.18.12.102:443]: accepted
Nov 16 20:00:59 219d1f5 redsocks[1922]: 1700164859.576982 debug redsocks.c:793 redsocks_shutdown(...) [172.20.5.220:58528->104.18.13.102:443]: shutdown: bufferevent_disable(client, EV_READ)
Nov 16 20:01:01 219d1f5 redsocks[1922]: 1700164861.582019 info redsocks.c:1254 redsocks_accept_client(...) [172.20.5.220:50344->104.18.13.102:443]: accepted
Nov 16 20:01:23 219d1f5 redsocks[1922]: 1700164883.490948 info redsocks.c:1254 redsocks_accept_client(...) [172.20.5.220:63058->104.18.12.102:443]: accepted
Nov 16 20:01:26 219d1f5 redsocks[1922]: 1700164886.108341 debug redsocks.c:793 redsocks_shutdown(...) [172.20.5.220:60982->44.219.65.162:443]: shutdown: bufferevent_disable(client, EV_READ)
Nov 16 20:01:28 219d1f5 redsocks[1922]: 1700164888.489304 debug redsocks.c:793 redsocks_shutdown(...) [172.20.5.220:63058->104.18.12.102:443]: shutdown: bufferevent_disable(client, EV_READ)
Nov 16 20:01:31 219d1f5 redsocks[1922]: 1700164891.577773 debug redsocks.c:793 redsocks_shutdown(...) [172.20.5.220:50344->104.18.13.102:443]: shutdown: bufferevent_disable(client, EV_READ)
Nov 16 20:01:33 219d1f5 redsocks[1922]: 1700164893.580956 info redsocks.c:1254 redsocks_accept_client(...) [172.20.5.220:63638->104.18.13.102:443]: accepted
Nov 16 20:01:36 219d1f5 redsocks[1922]: 1700164896.110927 info redsocks.c:1254 redsocks_accept_client(...) [172.20.5.220:62246->52.21.201.98:443]: accepted

kb2ma commented 9 months ago

Apologies for the delayed response. It sounds like the device has some connectivity since it is in Heartbeat Only mode. It's odd to see the socket timeouts in the Supervisor log though. The problem with openVPN connection is the line below.

TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)

My theory would be some intermediary or firewalling on the AWS side. To test this idea, have you tried setting up the mitmproxy on a computer on the same subnet as the balena device? That should confirm the proxy setup is OK, and indicate the problem is specific to the AWS setup.

balena-io-experimental / proxy-mitm

Issues with Running proxy-mitm on EC2 Instance and proxy-client in Raspberry Pi 4 (using 64bit OS): device Stuck in Online (Heartbeat Only) Status #1