localproxy indefinitely stuck in destination mode when unable to connect to destination

[supergillis]

Describe the bug

localproxy gets indefinitely stuck when it cannot connect to the destination, even after closing the AWS secure tunnel. For example, I set up localproxy as destination to port 22. localproxy correctly logs [error] Could not connect to destination 127.0.0.1:22 -- Success when nothing is running on port 22. However, when I close the tunnel on AWS, localproxy does not exit but keeps running forever.

To Reproduce

1. Create an AWS secure tunnel.
2. Start localproxy in destination mode and point it to a port that does not have a service running.
3. Start another localproxy in source mode.
4. Try to connect to the source localproxy. In my case I used an SSH client.
5. Close the AWS secure tunnel.
6. The destination localproxy keeps running indefinitely.

Expected behavior

The destination localproxy should exit when the AWS secure tunnel is closed.

Actual behavior

The destination localproxy keeps running forever when the AWS secure tunnel is closed.

Logs

$ localproxy --destination-app 22 --region eu-west-1 --no-ssl-host-verify -v 6
[2023-04-19 10:37:35.959779] (0x00007fd47f503840) [debug] v2 local proxy starts with v1 local proxy format
[2023-04-19 10:37:35.959800] (0x00007fd47f503840) [debug] /data/restore.energy/projects/iot-optimisation/infra/devices/provisioning-client/config does not exist!
[2023-04-19 10:37:35.959814] (0x00007fd47f503840) [info] Starting proxy in destination mode
[2023-04-19 10:37:35.959819] (0x00007fd47f503840) [trace] Setting up web socket...
[2023-04-19 10:37:35.961330] (0x00007fd47f503840) [trace] Calling control_callback with type: websocket_stream_single_ssl_type
[2023-04-19 10:37:35.961363] (0x00007fd47f503840) [info] Attempting to establish web socket connection with endpoint wss://data.tunneling.iot.eu-west-1.amazonaws.com:443
[2023-04-19 10:37:35.961367] (0x00007fd47f503840) [trace] Resolving proxy server host: data.tunneling.iot.eu-west-1.amazonaws.com
[2023-04-19 10:37:36.017810] (0x00007fd47f503840) [debug] Resolved proxy server IP: 54.217.105.220
[2023-04-19 10:37:36.017848] (0x00007fd47f503840) [trace] Calling lowest_layer with type: websocket_stream_single_ssl_type
[2023-04-19 10:37:36.041882] (0x00007fd47f503840) [debug] Connected successfully with proxy server
[2023-04-19 10:37:36.041940] (0x00007fd47f503840) [trace] Calling lowest_layer with type: websocket_stream_single_ssl_type
[2023-04-19 10:37:36.041950] (0x00007fd47f503840) [trace] Calling lowest_layer with type: websocket_stream_single_ssl_type
[2023-04-19 10:37:36.041955] (0x00007fd47f503840) [trace] Performing SSL handshake with proxy server
[2023-04-19 10:37:36.041960] (0x00007fd47f503840) [debug] SSL host verification is off
[2023-04-19 10:37:36.041965] (0x00007fd47f503840) [trace] Calling next_layer().async_handshake with type: websocket_stream_single_ssl_type
[2023-04-19 10:37:36.101384] (0x00007fd47f503840) [debug] Successfully completed SSL handshake with proxy server
[2023-04-19 10:37:36.101424] (0x00007fd47f503840) [trace] Performing websocket handshake with proxy server
[2023-04-19 10:37:36.101438] (0x00007fd47f503840) [trace] Calling async_handshake with type: websocket_stream_single_ssl_type
[2023-04-19 10:37:36.101494] (0x00007fd47f503840) [trace] Web socket ugprade request(*not entirely final):
GET /tunnel?local-proxy-mode=destination HTTP/1.1
Host: data.tunneling.iot.eu-west-1.amazonaws.com
Upgrade: websocket
Connection: upgrade
Sec-WebSocket-Key: 61LVQOr8oyLKCUzfuTp//g==
Sec-WebSocket-Version: 13
Sec-WebSocket-Protocol: aws.iot.securetunneling-3.0
access-token: ***ACCESS_TOKEN_REMOVED***
User-Agent: localproxy linux 64-bit/boost-1.81.0/openssl-3.0.0/protobuf-3.17.3

[2023-04-19 10:37:36.160881] (0x00007fd47f503840) [trace] Web socket upgrade response:
HTTP/1.1 101 Switching Protocols
Date: Wed, 19 Apr 2023 08:37:36 GMT
Content-Length: 0
Connection: upgrade
channel-id: 02073dfffed7dee7-00001416-00095aa6-6588da590b8858f3-3adb00e4
upgrade: websocket
sec-websocket-accept: DeHi1SQmfgTInyF3cxMhuT+WNV4=
sec-websocket-protocol: aws.iot.securetunneling-3.0

[2023-04-19 10:37:36.160953] (0x00007fd47f503840) [trace] Calling binary with type: websocket_stream_single_ssl_type
[2023-04-19 10:37:36.160965] (0x00007fd47f503840) [trace] Calling auto_fragment with type: websocket_stream_single_ssl_type
[2023-04-19 10:37:36.160972] (0x00007fd47f503840) [info] Web socket session ID: 02073dfffed7dee7-00001416-00095aa6-6588da590b8858f3-3adb00e4
[2023-04-19 10:37:36.160982] (0x00007fd47f503840) [debug] Web socket subprotocol selected: aws.iot.securetunneling-3.0
[2023-04-19 10:37:36.160989] (0x00007fd47f503840) [info] Successfully established websocket connection with proxy server: wss://data.tunneling.iot.eu-west-1.amazonaws.com:443
[2023-04-19 10:37:36.161011] (0x00007fd47f503840) [debug] Seting up web socket pings for every 20000 milliseconds
[2023-04-19 10:37:36.161018] (0x00007fd47f503840) [trace] Calling async_ping with type: websocket_stream_single_ssl_type
[2023-04-19 10:37:36.161067] (0x00007fd47f503840) [trace] Waiting for service ids...
[2023-04-19 10:37:36.161075] (0x00007fd47f503840) [trace] async_web_socket_read_loop_for_service_ids
[2023-04-19 10:37:36.161081] (0x00007fd47f503840) [debug] Scheduled next read:
[2023-04-19 10:37:36.161087] (0x00007fd47f503840) [trace] Calling async_read_some with type: websocket_stream_single_ssl_type
[2023-04-19 10:37:36.161147] (0x00007fd47f503840) [trace] Processing control message
[2023-04-19 10:37:36.161158] (0x00007fd47f503840) [trace] Using global control message handler
[2023-04-19 10:37:36.161167] (0x00007fd47f503840) [debug] Extracting service Ids from control message 5
[2023-04-19 10:37:36.161176] (0x00007fd47f503840) [trace] Service id received: 
[2023-04-19 10:37:36.161182] (0x00007fd47f503840) [trace] SSH
[2023-04-19 10:37:36.161188] (0x00007fd47f503840) [trace] Validating service ids configuration
[2023-04-19 10:37:36.161197] (0x00007fd47f503840) [info] Updated port mapping for v1 format: 
[2023-04-19 10:37:36.161203] (0x00007fd47f503840) [info] SSH = 22
[2023-04-19 10:37:36.161210] (0x00007fd47f503840) [trace] Setting up tcp sockets 
[2023-04-19 10:37:36.161216] (0x00007fd47f503840) [trace] Clearing all ws data buffers
[2023-04-19 10:37:36.161222] (0x00007fd47f503840) [trace] Finished Clearing all ws data buffers
[2023-04-19 10:37:36.161230] (0x00007fd47f503840) [trace] Initializing tcp clients ...
[2023-04-19 10:37:36.161241] (0x00007fd47f503840) [trace] Setting up tcp socket for service id: SSH
[2023-04-19 10:37:36.161249] (0x00007fd47f503840) [trace] Waiting for stream start...
[2023-04-19 10:37:36.161256] (0x00007fd47f503840) [debug] Starting web socket read loop continue reading...
[2023-04-19 10:37:36.161263] (0x00007fd47f503840) [trace] Calling async_read_some with type: websocket_stream_single_ssl_type
[2023-04-19 10:37:36.161277] (0x00007fd47f503840) [trace] return continue_reading true
[2023-04-19 10:37:36.161285] (0x00007fd47f503840) [debug] Starting web socket read loop while web socket is already reading. Ignoring...
# localproxy source connects
[2023-04-19 10:37:56.161205] (0x00007fd47f503840) [trace] Sent ping data: 1681893476161
[2023-04-19 10:37:56.161252] (0x00007fd47f503840) [trace] Calling async_ping with type: websocket_stream_single_ssl_type
[2023-04-19 10:38:16.161542] (0x00007fd47f503840) [trace] Sent ping data: 1681893496161
[2023-04-19 10:38:16.161641] (0x00007fd47f503840) [trace] Calling async_ping with type: websocket_stream_single_ssl_type
[2023-04-19 10:38:16.604484] (0x00007fd47f503840) [trace] Pong reply latency: 40443 ms
[2023-04-19 10:38:16.604512] (0x00007fd47f503840) [trace] Pong reply latency: 20443 ms
[2023-04-19 10:38:16.604516] (0x00007fd47f503840) [trace] Pong reply latency: 443 ms
# SSH client connects to source
[2023-04-19 10:39:02.030520] (0x00007fd47f503840) [trace] Using service-specific control message handler for service id: SSH
[2023-04-19 10:39:02.030528] (0x00007fd47f503840) [trace] Wait for control message stream start, receive message type:2
[2023-04-19 10:39:02.030536] (0x00007fd47f503840) [debug] Received service id : SSH, stream id: 1
[2023-04-19 10:39:02.030543] (0x00007fd47f503840) [trace] Setup destination tcp socket for service idSSH
[2023-04-19 10:39:02.030553] (0x00007fd47f503840) [info] Attempting to establish tcp socket connection to: 22
[2023-04-19 10:39:02.030558] (0x00007fd47f503840) [info] Setting up dest socket with tcp connection id 1
[2023-04-19 10:39:02.030574] (0x00007fd47f503840) [trace] Resolving destination host: 127.0.0.1 port: 22
[2023-04-19 10:39:02.030585] (0x00007fd47f503840) [trace] Resolve destination to connect for service id: SSH connection id: 1
[2023-04-19 10:39:02.030593] (0x00007fd47f503840) [debug] Resolved destination host to IP: 127.0.0.1, connecting ...
[2023-04-19 10:39:02.030678] (0x00007fd47f503840) [error] Could not connect to destination 127.0.0.1:22 -- Success
[2023-04-19 10:39:02.030703] (0x00007fd47f503840) [trace] return continue_reading false
[2023-04-19 10:39:02.030712] (0x00007fd47f503840) [debug] Web socket read loop stopped
[2023-04-19 10:39:04.530775] (0x00007fd47f503840) [info] Attempting to establish tcp socket connection to: 22
[2023-04-19 10:39:04.530882] (0x00007fd47f503840) [info] Setting up dest socket with tcp connection id 1
[2023-04-19 10:39:04.530919] (0x00007fd47f503840) [trace] Resolving destination host: 127.0.0.1 port: 22
[2023-04-19 10:39:04.530946] (0x00007fd47f503840) [trace] Resolve destination to connect for service id: SSH connection id: 1
[2023-04-19 10:39:04.530971] (0x00007fd47f503840) [debug] Resolved destination host to IP: 127.0.0.1, connecting ...
[2023-04-19 10:39:04.531117] (0x00007fd47f503840) [error] Could not connect to destination 127.0.0.1:22 -- Success
[2023-04-19 10:39:07.031233] (0x00007fd47f503840) [info] Attempting to establish tcp socket connection to: 22
[2023-04-19 10:39:07.031327] (0x00007fd47f503840) [info] Setting up dest socket with tcp connection id 1
[2023-04-19 10:39:07.031356] (0x00007fd47f503840) [trace] Resolving destination host: 127.0.0.1 port: 22
[2023-04-19 10:39:07.031379] (0x00007fd47f503840) [trace] Resolve destination to connect for service id: SSH connection id: 1
[2023-04-19 10:39:07.031395] (0x00007fd47f503840) [debug] Resolved destination host to IP: 127.0.0.1, connecting ...
[2023-04-19 10:39:07.031518] (0x00007fd47f503840) [error] Could not connect to destination 127.0.0.1:22 -- Success
[2023-04-19 10:39:09.531577] (0x00007fd47f503840) [info] Attempting to establish tcp socket connection to: 22
[2023-04-19 10:39:09.531603] (0x00007fd47f503840) [info] Setting up dest socket with tcp connection id 1
[2023-04-19 10:39:09.531612] (0x00007fd47f503840) [trace] Resolving destination host: 127.0.0.1 port: 22
[2023-04-19 10:39:09.531623] (0x00007fd47f503840) [trace] Resolve destination to connect for service id: SSH connection id: 1
[2023-04-19 10:39:09.531628] (0x00007fd47f503840) [debug] Resolved destination host to IP: 127.0.0.1, connecting ...
[2023-04-19 10:39:09.531673] (0x00007fd47f503840) [error] Could not connect to destination 127.0.0.1:22 -- Success
[2023-04-19 10:39:12.031757] (0x00007fd47f503840) [info] Attempting to establish tcp socket connection to: 22
[2023-04-19 10:39:12.031831] (0x00007fd47f503840) [info] Setting up dest socket with tcp connection id 1
[2023-04-19 10:39:12.031856] (0x00007fd47f503840) [trace] Resolving destination host: 127.0.0.1 port: 22
[2023-04-19 10:39:12.031877] (0x00007fd47f503840) [trace] Resolve destination to connect for service id: SSH connection id: 1
[2023-04-19 10:39:12.031899] (0x00007fd47f503840) [debug] Resolved destination host to IP: 127.0.0.1, connecting ...
[2023-04-19 10:39:12.032031] (0x00007fd47f503840) [error] Could not connect to destination 127.0.0.1:22 -- Success
[2023-04-19 10:39:14.532219] (0x00007fd47f503840) [info] Attempting to establish tcp socket connection to: 22
[2023-04-19 10:39:14.532249] (0x00007fd47f503840) [info] Setting up dest socket with tcp connection id 1
[2023-04-19 10:39:14.532257] (0x00007fd47f503840) [trace] Resolving destination host: 127.0.0.1 port: 22
[2023-04-19 10:39:14.532263] (0x00007fd47f503840) [trace] Resolve destination to connect for service id: SSH connection id: 1
[2023-04-19 10:39:14.532268] (0x00007fd47f503840) [debug] Resolved destination host to IP: 127.0.0.1, connecting ...
[2023-04-19 10:39:14.532320] (0x00007fd47f503840) [error] Could not connect to destination 127.0.0.1:22 -- Success
[2023-04-19 10:39:16.162681] (0x00007fd47f503840) [trace] Sent ping data: 1681893556162
[2023-04-19 10:39:16.162713] (0x00007fd47f503840) [trace] Calling async_ping with type: websocket_stream_single_ssl_type
[2023-04-19 10:39:17.032708] (0x00007fd47f503840) [info] Attempting to establish tcp socket connection to: 22
[2023-04-19 10:39:17.032842] (0x00007fd47f503840) [info] Setting up dest socket with tcp connection id 1
[2023-04-19 10:39:17.032891] (0x00007fd47f503840) [trace] Resolving destination host: 127.0.0.1 port: 22
[2023-04-19 10:39:17.032928] (0x00007fd47f503840) [trace] Resolve destination to connect for service id: SSH connection id: 1
[2023-04-19 10:39:17.032956] (0x00007fd47f503840) [debug] Resolved destination host to IP: 127.0.0.1, connecting ...
[2023-04-19 10:39:17.033150] (0x00007fd47f503840) [error] Could not connect to destination 127.0.0.1:22 -- Success
[2023-04-19 10:39:19.533252] (0x00007fd47f503840) [info] Attempting to establish tcp socket connection to: 22
[2023-04-19 10:39:19.533289] (0x00007fd47f503840) [info] Setting up dest socket with tcp connection id 1
[2023-04-19 10:39:19.533301] (0x00007fd47f503840) [trace] Resolving destination host: 127.0.0.1 port: 22
[2023-04-19 10:39:19.533323] (0x00007fd47f503840) [trace] Resolve destination to connect for service id: SSH connection id: 1
[2023-04-19 10:39:19.533331] (0x00007fd47f503840) [debug] Resolved destination host to IP: 127.0.0.1, connecting ...
[2023-04-19 10:39:19.533418] (0x00007fd47f503840) [error] Could not connect to destination 127.0.0.1:22 -- Success
[2023-04-19 10:39:22.033610] (0x00007fd47f503840) [info] Attempting to establish tcp socket connection to: 22
[2023-04-19 10:39:22.033714] (0x00007fd47f503840) [info] Setting up dest socket with tcp connection id 1
[2023-04-19 10:39:22.033748] (0x00007fd47f503840) [trace] Resolving destination host: 127.0.0.1 port: 22
[2023-04-19 10:39:22.033771] (0x00007fd47f503840) [trace] Resolve destination to connect for service id: SSH connection id: 1
[2023-04-19 10:39:22.033792] (0x00007fd47f503840) [debug] Resolved destination host to IP: 127.0.0.1, connecting ...
[2023-04-19 10:39:22.033966] (0x00007fd47f503840) [error] Could not connect to destination 127.0.0.1:22 -- Success
[2023-04-19 10:39:24.534165] (0x00007fd47f503840) [info] Attempting to establish tcp socket connection to: 22
[2023-04-19 10:39:24.534245] (0x00007fd47f503840) [info] Setting up dest socket with tcp connection id 1
[2023-04-19 10:39:24.534274] (0x00007fd47f503840) [trace] Resolving destination host: 127.0.0.1 port: 22
[2023-04-19 10:39:24.534295] (0x00007fd47f503840) [trace] Resolve destination to connect for service id: SSH connection id: 1
[2023-04-19 10:39:24.534311] (0x00007fd47f503840) [debug] Resolved destination host to IP: 127.0.0.1, connecting ...
[2023-04-19 10:39:24.534424] (0x00007fd47f503840) [error] Could not connect to destination 127.0.0.1:22 -- Success
[2023-04-19 10:39:27.034655] (0x00007fd47f503840) [info] Attempting to establish tcp socket connection to: 22
[2023-04-19 10:39:27.034717] (0x00007fd47f503840) [info] Setting up dest socket with tcp connection id 1
[2023-04-19 10:39:27.034738] (0x00007fd47f503840) [trace] Resolving destination host: 127.0.0.1 port: 22
[2023-04-19 10:39:27.034753] (0x00007fd47f503840) [trace] Resolve destination to connect for service id: SSH connection id: 1
[2023-04-19 10:39:27.034764] (0x00007fd47f503840) [debug] Resolved destination host to IP: 127.0.0.1, connecting ...
[2023-04-19 10:39:27.034864] (0x00007fd47f503840) [error] Could not connect to destination 127.0.0.1:22 -- Success
[2023-04-19 10:39:29.535086] (0x00007fd47f503840) [info] Attempting to establish tcp socket connection to: 22
[2023-04-19 10:39:29.535204] (0x00007fd47f503840) [info] Setting up dest socket with tcp connection id 1
[2023-04-19 10:39:29.535240] (0x00007fd47f503840) [trace] Resolving destination host: 127.0.0.1 port: 22
[2023-04-19 10:39:29.535268] (0x00007fd47f503840) [trace] Resolve destination to connect for service id: SSH connection id: 1
[2023-04-19 10:39:29.535290] (0x00007fd47f503840) [debug] Resolved destination host to IP: 127.0.0.1, connecting ...
[2023-04-19 10:39:29.535458] (0x00007fd47f503840) [error] Could not connect to destination 127.0.0.1:22 -- Success
[2023-04-19 10:39:32.035726] (0x00007fd47f503840) [info] Attempting to establish tcp socket connection to: 22
[2023-04-19 10:39:32.035827] (0x00007fd47f503840) [info] Setting up dest socket with tcp connection id 1
[2023-04-19 10:39:32.035860] (0x00007fd47f503840) [trace] Resolving destination host: 127.0.0.1 port: 22
[2023-04-19 10:39:32.035883] (0x00007fd47f503840) [trace] Resolve destination to connect for service id: SSH connection id: 1
[2023-04-19 10:39:32.035903] (0x00007fd47f503840) [debug] Resolved destination host to IP: 127.0.0.1, connecting ...
[2023-04-19 10:39:32.036069] (0x00007fd47f503840) [error] Could not connect to destination 127.0.0.1:22 -- Success
[2023-04-19 10:39:34.536196] (0x00007fd47f503840) [info] Attempting to establish tcp socket connection to: 22
[2023-04-19 10:39:34.536286] (0x00007fd47f503840) [info] Setting up dest socket with tcp connection id 1
[2023-04-19 10:39:34.536322] (0x00007fd47f503840) [trace] Resolving destination host: 127.0.0.1 port: 22
[2023-04-19 10:39:34.536350] (0x00007fd47f503840) [trace] Resolve destination to connect for service id: SSH connection id: 1
[2023-04-19 10:39:34.536371] (0x00007fd47f503840) [debug] Resolved destination host to IP: 127.0.0.1, connecting ...
[2023-04-19 10:39:34.536543] (0x00007fd47f503840) [error] Could not connect to destination 127.0.0.1:22 -- Success
# Close tunnel
[2023-04-19 10:39:36.162967] (0x00007fd47f503840) [trace] Sent ping data: 1681893576162
[2023-04-19 10:39:36.163051] (0x00007fd47f503840) [trace] Calling async_ping with type: websocket_stream_single_ssl_type
[2023-04-19 10:39:37.036742] (0x00007fd47f503840) [info] Attempting to establish tcp socket connection to: 22
[2023-04-19 10:39:37.036803] (0x00007fd47f503840) [info] Setting up dest socket with tcp connection id 1
[2023-04-19 10:39:37.036834] (0x00007fd47f503840) [trace] Resolving destination host: 127.0.0.1 port: 22
[2023-04-19 10:39:37.036856] (0x00007fd47f503840) [trace] Resolve destination to connect for service id: SSH connection id: 1
[2023-04-19 10:39:37.036876] (0x00007fd47f503840) [debug] Resolved destination host to IP: 127.0.0.1, connecting ...
[2023-04-19 10:39:37.037008] (0x00007fd47f503840) [error] Could not connect to destination 127.0.0.1:22 -- Success
[2023-04-19 10:39:39.537094] (0x00007fd47f503840) [info] Attempting to establish tcp socket connection to: 22
[2023-04-19 10:39:39.537162] (0x00007fd47f503840) [info] Setting up dest socket with tcp connection id 1
[2023-04-19 10:39:39.537187] (0x00007fd47f503840) [trace] Resolving destination host: 127.0.0.1 port: 22
[2023-04-19 10:39:39.537209] (0x00007fd47f503840) [trace] Resolve destination to connect for service id: SSH connection id: 1
[2023-04-19 10:39:39.537226] (0x00007fd47f503840) [debug] Resolved destination host to IP: 127.0.0.1, connecting ...
[2023-04-19 10:39:39.537337] (0x00007fd47f503840) [error] Could not connect to destination 127.0.0.1:22 -- Success
# Keeps logging "[error] Could not connect to destination 127.0.0.1:22 -- Success" indefinitely

Environment (please complete the following information):

• OS: Arch Linux
• Version: v3.1.0
• Architecture: x86-64
• Localproxy commit: unknown, however I'm using the binary from public.ecr.aws/aws-iot-securetunneling-localproxy/ubuntu-bin:amd64-latest with image ID 21b774378a53

[HarshGandhi-AWS]

Hello @supergillis , looks like this is a bug on our side. Local Proxy should read the tunnel close notification sent from the cloud and stop retrying to connect to tunnel on destination device. Please be patient with us until we reproduce and resolve this bug. I will try to reproduce the issue first to confirm this bug and then will try to fix it.

For now, as a work around, you can set the number of times your destination device retries to connect to the tunnel after failure. You can set tunneling.proxy.tcp.connection_retry_count parameter for that as mentioned over here.

-Harsh Gandhi

[alexbigkid]

HI there, I am getting that error: [2023-05-15 22:52:09.956080] (0x0000007fb7f00010) [error] Could not connect to destination 127.0.0.1:22 -- Success
after opening tunnel, connecting both source and destination. but when I try to ssh into destination the destination side continuously spits out the error on the destination side. The source side seems to work fine though