Non-nominal runtime behavior on MacOS

[monelgordillo]

Describe the bug

I'm running this on my laptop - trying to do a VNC tunnel on a remote Ubuntu device.

./localproxy -r us-east-1 -s 8000 -v 6 -t TOKEN_HERE

I am getting this from localproxy:

Handling tcp socket error for service id: VNC connection id: 1. error message: End of file

And, I'm getting this from aws-iot-device-client logs:

TcpForward::OnConnectionResult error_code=1047

To Reproduce

Steps to reproduce the behavior:

VNC is running on the remote Ubuntu device already.

Creating tunnel first...

aws iotsecuretunneling open-tunnel --cli-input-json file:///X/tunnel.json --region us-east-1

Running local proxy on my laptop...

./localproxy -r us-east-1 -s 8000 -v 6 -t TOKEN_HERE

Expected behavior

A working VNC tunnel.

Actual behavior

No VNC tunnel. :(

Logs

./localproxy -r us-east-1 -s 8000 -v 6 -t TOKEN_HERE
[2023-01-27T09:46:03.623285]{51191}[warning] Found access token supplied via CLI arg. Consider using environment variable AWSIOT_TUNNEL_ACCESS_TOKEN instead
[2023-01-27T09:46:03.623943]{51191}[debug]   v2 local proxy starts with v1 local proxy format
[2023-01-27T09:46:03.624045]{51191}[debug]   /Users/XX/Downloads/aws-iot-device-client/dependencies/aws-iot-securetunneling-localproxy/build/bin/config does not exist!
[2023-01-27T09:46:03.624062]{51191}[info]    Starting proxy in source mode
[2023-01-27T09:46:03.624109]{51191}[trace]   Setting up web socket...
[2023-01-27T09:46:03.654195]{51191}[trace]   Calling control_callback with type: websocket_stream_single_ssl_type
[2023-01-27T09:46:03.654423]{51191}[info]    Attempting to establish web socket connection with endpoint wss://data.tunneling.iot.us-east-1.amazonaws.com:443
[2023-01-27T09:46:03.654433]{51191}[trace]   Resolving proxy server host: data.tunneling.iot.us-east-1.amazonaws.com
[2023-01-27T09:46:04.770449]{51191}[debug]   Resolved proxy server IP: 34.225.0.142
[2023-01-27T09:46:04.770936]{51191}[trace]   Calling lowest_layer with type: websocket_stream_single_ssl_type
[2023-01-27T09:46:04.826284]{51191}[debug]   Connected successfully with proxy server
[2023-01-27T09:46:04.826315]{51191}[trace]   Calling lowest_layer with type: websocket_stream_single_ssl_type
[2023-01-27T09:46:04.826328]{51191}[trace]   Calling lowest_layer with type: websocket_stream_single_ssl_type
[2023-01-27T09:46:04.826337]{51191}[trace]   Performing SSL handshake with proxy server
[2023-01-27T09:46:04.826346]{51191}[trace]   Calling set_verify_mode with type: single_ssl_stream
[2023-01-27T09:46:04.826354]{51191}[trace]   Calling set_verify_callback with type: single_ssl_stream
[2023-01-27T09:46:04.826371]{51191}[trace]   Calling next_layer().async_handshake with type: websocket_stream_single_ssl_type
[2023-01-27T09:46:04.947921]{51191}[debug]   Successfully completed SSL handshake with proxy server
[2023-01-27T09:46:04.948092]{51191}[trace]   Performing websocket handshake with proxy server
[2023-01-27T09:46:04.948145]{51191}[trace]   Calling async_handshake with type: websocket_stream_single_ssl_type
[2023-01-27T09:46:04.950210]{51191}[trace]   Web socket ugprade request(*not entirely final):
GET /tunnel?local-proxy-mode=source HTTP/1.1
Host: data.tunneling.iot.us-east-1.amazonaws.com
Upgrade: websocket
Connection: upgrade
Sec-WebSocket-Key: SVLqp5coGNQRi+ZmPwOfzw==
Sec-WebSocket-Version: 13
Sec-WebSocket-Protocol: aws.iot.securetunneling-3.0
access-token: ***ACCESS_TOKEN_REMOVED***
User-Agent: localproxy Mac OS 64-bit/boost-1.79.0/openssl-3.0.0/protobuf-3.21.12

[2023-01-27T09:46:05.049432]{51191}[trace]   Web socket upgrade response:
HTTP/1.1 101 Switching Protocols
Date: Fri, 27 Jan 2023 15:46:05 GMT
Content-Length: 0
Connection: upgrade
channel-id: 0eb09ffffe7028c1-00000859-00023a24-980ab6cb8f9aaa61-3246b4b7
upgrade: websocket
sec-websocket-accept: SsvcnZBAQzc/Hdwv8FpleBIoATc=
sec-websocket-protocol: aws.iot.securetunneling-3.0

[2023-01-27T09:46:05.049708]{51191}[trace]   Calling binary with type: websocket_stream_single_ssl_type
[2023-01-27T09:46:05.049738]{51191}[trace]   Calling auto_fragment with type: websocket_stream_single_ssl_type
[2023-01-27T09:46:05.049758]{51191}[info]    Web socket session ID: 0eb09ffffe7028c1-00000859-00023a24-980ab6cb8f9aaa61-3246b4b7
[2023-01-27T09:46:05.049782]{51191}[debug]   Web socket subprotocol selected: aws.iot.securetunneling-3.0
[2023-01-27T09:46:05.049804]{51191}[info]    Successfully established websocket connection with proxy server: wss://data.tunneling.iot.us-east-1.amazonaws.com:443
[2023-01-27T09:46:05.049842]{51191}[debug]   Seting up web socket pings for every 20000 milliseconds
[2023-01-27T09:46:05.049863]{51191}[trace]   Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-27T09:46:05.050200]{51191}[trace]   Waiting for service ids...
[2023-01-27T09:46:05.050238]{51191}[trace]   async_web_socket_read_loop_for_service_ids
[2023-01-27T09:46:05.050259]{51191}[debug]   Scheduled next read:
[2023-01-27T09:46:05.050279]{51191}[trace]   Calling async_read_some with type: websocket_stream_single_ssl_type
[2023-01-27T09:46:05.052968]{51191}[trace]   Processing control message
[2023-01-27T09:46:05.053017]{51191}[trace]   Using global control message handler
[2023-01-27T09:46:05.053038]{51191}[debug]   Extracting service Ids from control message 5
[2023-01-27T09:46:05.053062]{51191}[trace]   Service id received: 
[2023-01-27T09:46:05.053080]{51191}[trace]   VNC
[2023-01-27T09:46:05.053099]{51191}[trace]   Validating service ids configuration
[2023-01-27T09:46:05.053126]{51191}[info]    Updated port mapping for v1 format: 
[2023-01-27T09:46:05.053144]{51191}[info]    VNC = 8000
[2023-01-27T09:46:05.053163]{51191}[trace]   Setting up tcp sockets 
[2023-01-27T09:46:05.053181]{51191}[trace]   Clearing all ws data buffers
[2023-01-27T09:46:05.053199]{51191}[trace]   Finished Clearing all ws data buffers
[2023-01-27T09:46:05.053217]{51191}[trace]   Initializing tcp servers ...
[2023-01-27T09:46:05.053234]{51191}[trace]   Setting up source tcp sockets
[2023-01-27T09:46:05.053339]{51191}[info]    calling setup from loop
[2023-01-27T09:46:05.053367]{51191}[trace]   Setting up tcp socket for service id: VNC
[2023-01-27T09:46:05.053410]{51191}[debug]   Resolving bind address host: localhost
[2023-01-27T09:46:05.053449]{51191}[debug]   Port to connect 8000
[2023-01-27T09:46:05.053485]{51191}[trace]   return continue_reading true
[2023-01-27T09:46:05.053508]{51191}[debug]   Starting web socket read loop continue reading...
[2023-01-27T09:46:05.053526]{51191}[trace]   Calling async_read_some with type: websocket_stream_single_ssl_type
[2023-01-27T09:46:05.054645]{51191}[debug]   Resolved bind IP: 127.0.0.1
[2023-01-27T09:46:05.054842]{51191}[info]    Listening for new connection on port 8000
[2023-01-27T09:46:05.103105]{51191}[trace]   Pong reply latency: 54 ms
[2023-01-27T09:46:16.705453]{51191}[debug]   socket port 8000
[2023-01-27T09:46:16.705600]{51191}[debug]   endpoint mapping:
[2023-01-27T09:46:16.705614]{51191}[debug]   VNC = 8000
[2023-01-27T09:46:16.705630]{51191}[info]    creating tcp connection id 1
[2023-01-27T09:46:16.705657]{51191}[info]    Accepted tcp connection on port 8000 from 127.0.0.1:62381
[2023-01-27T09:46:16.705684]{51191}[debug]   Sending stream start, setting new stream ID to: 1, service id: VNC
[2023-01-27T09:46:16.705751]{51191}[trace]   Sending messages over web socket for service id: VNC connection id: 1
[2023-01-27T09:46:16.705763]{51191}[trace]   Current queue size: 0
[2023-01-27T09:46:16.705772]{51191}[trace]   Put data 13 bytes into the web_socket_outgoing_message_queue for service id: VNC connection id: 1
[2023-01-27T09:46:16.705783]{51191}[trace]   Getting tcp connection with id: 1
[2023-01-27T09:46:16.705793]{51191}[trace]   num active connections for service id VNC: 1
[2023-01-27T09:46:16.705823]{51191}[trace]   Calling async_write with type: websocket_stream_single_ssl_type
[2023-01-27T09:46:16.709566]{51191}[trace]   Sent 13 bytes over websocket for service id: VNC connection id: 1
[2023-01-27T09:46:16.709599]{51191}[trace]   capturing after_send_message
[2023-01-27T09:46:16.709610]{51191}[trace]   Setting up bi-directional data transfer for service id: VNC connection id: 1
[2023-01-27T09:46:16.709634]{51191}[trace]   Getting tcp connection with id: 1
[2023-01-27T09:46:16.709643]{51191}[trace]   num active connections for service id VNC: 1
[2023-01-27T09:46:16.709652]{51191}[trace]   Clearing tcp connection buffers
[2023-01-27T09:46:16.709666]{51191}[debug]   Starting web socket read loop while web socket is already reading. Ignoring...
[2023-01-27T09:46:16.709718]{51191}[trace]   Begin tcp socket read loop for service id : VNC connection id : 1
[2023-01-27T09:46:16.709731]{51191}[trace]   Getting tcp connection with id: 1
[2023-01-27T09:46:16.709740]{51191}[trace]   num active connections for service id VNC: 1
[2023-01-27T09:46:16.709749]{51191}[trace]   Initiating tcp socket read
[2023-01-27T09:46:16.709858]{51191}[trace]   web_socket_outgoing_message_queue is empty, no more messages to send.
[2023-01-27T09:46:25.053361]{51191}[trace]   Sent ping data: 1674834385053
[2023-01-27T09:46:25.053499]{51191}[trace]   Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-27T09:46:25.108217]{51191}[trace]   Pong reply latency: 55 ms
[2023-01-27T09:46:45.054964]{51191}[trace]   Sent ping data: 1674834405054
[2023-01-27T09:46:45.055114]{51191}[trace]   Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-27T09:46:45.111432]{51191}[trace]   Pong reply latency: 57 ms
[2023-01-27T09:47:05.056718]{51191}[trace]   Sent ping data: 1674834425056
[2023-01-27T09:47:05.056868]{51191}[trace]   Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-27T09:47:05.115184]{51191}[trace]   Pong reply latency: 59 ms
[2023-01-27T09:47:25.058556]{51191}[trace]   Sent ping data: 1674834445058
[2023-01-27T09:47:25.058758]{51191}[trace]   Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-27T09:47:25.115621]{51191}[trace]   Pong reply latency: 57 ms
[2023-01-27T09:47:45.060577]{51191}[trace]   Sent ping data: 1674834465060
[2023-01-27T09:47:45.060693]{51191}[trace]   Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-27T09:47:45.117544]{51191}[trace]   Pong reply latency: 57 ms
[2023-01-27T09:48:05.062961]{51191}[trace]   Sent ping data: 1674834485062
[2023-01-27T09:48:05.063130]{51191}[trace]   Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-27T09:48:05.117347]{51191}[trace]   Pong reply latency: 55 ms
[2023-01-27T09:48:25.064799]{51191}[trace]   Sent ping data: 1674834505064
[2023-01-27T09:48:25.065126]{51191}[trace]   Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-27T09:48:25.121384]{51191}[trace]   Pong reply latency: 57 ms
[2023-01-27T09:48:45.066164]{51191}[trace]   Sent ping data: 1674834525066
[2023-01-27T09:48:45.066316]{51191}[trace]   Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-27T09:48:45.381085]{51191}[trace]   Pong reply latency: 315 ms
[2023-01-27T09:49:05.066725]{51191}[trace]   Sent ping data: 1674834545066
[2023-01-27T09:49:05.066885]{51191}[trace]   Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-27T09:49:05.131174]{51191}[trace]   Pong reply latency: 65 ms
[2023-01-27T09:49:25.068413]{51191}[trace]   Sent ping data: 1674834565068
[2023-01-27T09:49:25.068568]{51191}[trace]   Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-27T09:49:25.124325]{51191}[trace]   Pong reply latency: 56 ms
[2023-01-27T09:49:45.070074]{51191}[trace]   Sent ping data: 1674834585070
[2023-01-27T09:49:45.070237]{51191}[trace]   Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-27T09:49:45.659112]{51191}[trace]   Pong reply latency: 589 ms
[2023-01-27T09:50:05.073947]{51191}[trace]   Sent ping data: 1674834605073
[2023-01-27T09:50:05.074068]{51191}[trace]   Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-27T09:50:05.127182]{51191}[trace]   Pong reply latency: 54 ms
[2023-01-27T09:50:25.076024]{51191}[trace]   Sent ping data: 1674834625075
[2023-01-27T09:50:25.076186]{51191}[trace]   Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-27T09:50:25.135193]{51191}[trace]   Pong reply latency: 60 ms
[2023-01-27T09:50:45.078008]{51191}[trace]   Sent ping data: 1674834645077
[2023-01-27T09:50:45.078182]{51191}[trace]   Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-27T09:50:45.133711]{51191}[trace]   Pong reply latency: 56 ms
[2023-01-27T09:51:05.079519]{51191}[trace]   Sent ping data: 1674834665079
[2023-01-27T09:51:05.079742]{51191}[trace]   Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-27T09:51:05.135645]{51191}[trace]   Pong reply latency: 56 ms
[2023-01-27T09:51:06.465979]{51191}[trace]   Handling read from tcp socket for service id VNC connection id 1
[2023-01-27T09:51:06.466140]{51191}[trace]   Getting tcp connection with id: 1
[2023-01-27T09:51:06.466343]{51191}[trace]   num active connections for service id VNC: 1
[2023-01-27T09:51:06.466371]{51191}[trace]   received error code: asio.misc:2
[2023-01-27T09:51:06.466975]{51191}[debug]   Handling tcp socket error for service id: VNC connection id: 1. error message: End of file
[2023-01-27T09:51:06.467006]{51191}[trace]   Getting tcp connection with id: 1
[2023-01-27T09:51:06.467027]{51191}[trace]   num active connections for service id VNC: 1
[2023-01-27T09:51:06.467046]{51191}[info]    Disconnected from: 127.0.0.1:62381
[2023-01-27T09:51:06.473420]{51191}[fatal]   shutdown: Socket is not connected [system:57]

Environment (please complete the following information):

• OS: Ubuntu (remote), and source is MacOS laptop
• Version 18 (remote)
• Architecture: x86-64
• Localproxy commit: latest

[RogerZhongAWS]

Hello Monica! Thanks for posting these logs. I suspect that in certain cases, there is an issue with the interoperability between Device Client and the local proxy since these two codebases do not have feature/function parity at the moment. It is very much still a bug, and will keep this issue open as we try to find a short-term fix for it.

If you want to make sure that this is indeed the case, please try running the localproxy on both the source and destination side (without device client) to see if the tunnel works.

[RogerZhongAWS]

As a follow up if you still want to use Device Client on the destination, try using the previous version of the local proxy and repeat the steps you took to open your VNC tunnel. Please let me know if you still run into issues.

v2.3.1 here: https://github.com/aws-samples/aws-iot-securetunneling-localproxy/releases/tag/v2.3.1

[monelgordillo]

I'll try both. With device client, and without. I'll reply shortly with my results.

[monelgordillo]

No luck with using localproxy v2.3.1. I didn't really get an error code or error message. When I try to connect to the port, it just hangs for me.

I'll try local proxy on both source & destination now...

[monelgordillo]

I'm trying local proxy v2.3.1 on destination. Now I'm getting this:

./localproxy -r us-east-1 -d 5901 -v 6 -t <TOKEN_HERE>

2023-02-01T12:31:36.349070]{3846}[error] Proxy server rejected web socket upgrade request: (HTTP/1.1 400 Bad Request) "Invalid access token: The access token was previously used and can not be used again."

I'm getting that even when I regenerated the access tokens. I'm not sure why I'm getting that message, even if I never used the access token before.

I'm going to try an updated version of local proxy on destination next.

[monelgordillo]

I'm getting the same behavior on the destination side with the updated version of local proxy.

On the source side, I get error_code=1047.

[RogerZhongAWS]

Thanks for testing. So just to confirm when you use the latest local proxy version on the destination side, are you getting the same error as in "invalid access token" or another error you mentioned above? Also was curious to see that you get error code 1047 from the source side as well.

Apologies for the inconvenience, we're working on getting a VNC test environment set up on our side so we can better understand where this issue is coming from.

[monelgordillo]

On the destination side with the latest local proxy version, I get the "invalid access token".

`./localproxy -r us-east-1 -d 127.0.0.1:5901 -v 6 -t TOKEN_HERE
[2023-02-01T15:50:39.705006]{28514}[warning] Found access token supplied via CLI arg. Consider using environment variable AWSIOT_TUNNEL_ACCESS_TOKEN instead
[2023-02-01T15:50:39.705118]{28514}[debug] v2 local proxy starts with v1 local proxy format
[2023-02-01T15:50:39.705176]{28514}[debug] /root/aws-iot-securetunneling-localproxy-latest/dependencies/aws-iot-securetunneling-localproxy/build/bin/config does not exist!
[2023-02-01T15:50:39.705249]{28514}[info] Starting proxy in destination mode
[2023-02-01T15:50:39.705275]{28514}[trace] Setting up web socket...
[2023-02-01T15:50:39.707834]{28514}[trace] Calling control_callback with type: websocket_stream_single_ssl_type
[2023-02-01T15:50:39.707907]{28514}[info] Attempting to establish web socket connection with endpoint wss://data.tunneling.iot.us-east-1.amazonaws.com:443
[2023-02-01T15:50:39.707929]{28514}[trace] Resolving proxy server host: data.tunneling.iot.us-east-1.amazonaws.com
[2023-02-01T15:50:40.015348]{28514}[debug] Resolved proxy server IP: 3.208.121.231
[2023-02-01T15:50:40.015423]{28514}[trace] Calling lowest_layer with type: websocket_stream_single_ssl_type
[2023-02-01T15:50:40.057921]{28514}[debug] Connected successfully with proxy server
[2023-02-01T15:50:40.058014]{28514}[trace] Calling lowest_layer with type: websocket_stream_single_ssl_type
[2023-02-01T15:50:40.058046]{28514}[trace] Calling lowest_layer with type: websocket_stream_single_ssl_type
[2023-02-01T15:50:40.058077]{28514}[trace] Performing SSL handshake with proxy server
[2023-02-01T15:50:40.058101]{28514}[trace] Calling set_verify_mode with type: single_ssl_stream
[2023-02-01T15:50:40.058125]{28514}[trace] Calling set_verify_callback with type: single_ssl_stream
[2023-02-01T15:50:40.058156]{28514}[trace] Calling next_layer().async_handshake with type: websocket_stream_single_ssl_type
[2023-02-01T15:50:40.154265]{28514}[debug] Successfully completed SSL handshake with proxy server
[2023-02-01T15:50:40.154336]{28514}[trace] Performing websocket handshake with proxy server
[2023-02-01T15:50:40.154377]{28514}[trace] Calling async_handshake with type: websocket_stream_single_ssl_type
[2023-02-01T15:50:40.154492]{28514}[trace] Web socket ugprade request(*not entirely final):
GET /tunnel?local-proxy-mode=destination HTTP/1.1
Host: data.tunneling.iot.us-east-1.amazonaws.com
Upgrade: websocket
Connection: upgrade
Sec-WebSocket-Key: XGzwEgOFcIeKBsRYhixhhQ==
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.79.0/openssl-1.1.1/protobuf-3.17.3

[2023-02-01T15:50:40.204826]{28514}[trace] Web socket upgrade response:
HTTP/1.1 400 Bad Request
Date: Wed, 01 Feb 2023 20:50:40 GMT
Content-Type: text/plain
Content-Length: 85
Connection: keep-alive
channel-id: 123e51fffe4b1e21-00003302-0006d1e0-7ced66fb9829e1be-11940099
**X-Status-Reason: Invalid access token: The access token was previously used and can not be used again.

Invalid access token: The access token was previously used and can not be used again.
[2023-02-01T15:50:40.204960]{28514}[error] Proxy server rejected web socket upgrade request: (HTTP/1.1 400 Bad Request) "Invalid access token: The access token was previously used and can not be used again."**
[2023-02-01T15:50:40.205015]{28514}[trace] Calling is_open with type: websocket_stream_single_ssl_type
[2023-02-01T15:50:40.205037]{28514}[trace] Calling lowest_layer with type: websocket_stream_single_ssl_type
[2023-02-01T15:50:40.205058]{28514}[trace] Calling lowest_layer with type: websocket_stream_single_ssl_type`

On the source side with the latest proxy version, I get the error_code=1047 with the aws-iot-device-client logs.

`./localproxy -r us-east-1 -s 5555 -v 6 -t TOKEN_HERE
[2023-01-31T13:45:27.675612]{35422}[warning] Found access token supplied via CLI arg. Consider using environment variable AWSIOT_TUNNEL_ACCESS_TOKEN instead
[2023-01-31T13:45:27.675956]{35422}[debug] v2 local proxy starts with v1 local proxy format
[2023-01-31T13:45:27.675997]{35422}[debug] /Users/monicagordillo/Downloads/aws-iot-device-client2/dependencies/aws-iot-securetunneling-localproxy/build/bin/config does not exist!
[2023-01-31T13:45:27.676008]{35422}[info] Starting proxy in source mode
[2023-01-31T13:45:27.676015]{35422}[trace] Setting up web socket...
[2023-01-31T13:45:27.692484]{35422}[trace] Calling control_callback with type: websocket_stream_single_ssl_type
[2023-01-31T13:45:27.692503]{35422}[info] Attempting to establish web socket connection with endpoint wss://data.tunneling.iot.us-east-1.amazonaws.com:443
[2023-01-31T13:45:27.692507]{35422}[trace] Resolving proxy server host: data.tunneling.iot.us-east-1.amazonaws.com
[2023-01-31T13:45:27.727893]{35422}[debug] Resolved proxy server IP: 3.208.121.231
[2023-01-31T13:45:27.727913]{35422}[trace] Calling lowest_layer with type: websocket_stream_single_ssl_type
[2023-01-31T13:45:27.769847]{35422}[debug] Connected successfully with proxy server
[2023-01-31T13:45:27.769857]{35422}[trace] Calling lowest_layer with type: websocket_stream_single_ssl_type
[2023-01-31T13:45:27.769862]{35422}[trace] Calling lowest_layer with type: websocket_stream_single_ssl_type
[2023-01-31T13:45:27.769866]{35422}[trace] Performing SSL handshake with proxy server
[2023-01-31T13:45:27.769870]{35422}[trace] Calling set_verify_mode with type: single_ssl_stream
[2023-01-31T13:45:27.769873]{35422}[trace] Calling set_verify_callback with type: single_ssl_stream
[2023-01-31T13:45:27.769879]{35422}[trace] Calling next_layer().async_handshake with type: websocket_stream_single_ssl_type
[2023-01-31T13:45:28.107915]{35422}[debug] Successfully completed SSL handshake with proxy server
[2023-01-31T13:45:28.108077]{35422}[trace] Performing websocket handshake with proxy server
[2023-01-31T13:45:28.108125]{35422}[trace] Calling async_handshake with type: websocket_stream_single_ssl_type
[2023-01-31T13:45:28.108463]{35422}[trace] Web socket ugprade request(*not entirely final):
GET /tunnel?local-proxy-mode=source HTTP/1.1
Host: data.tunneling.iot.us-east-1.amazonaws.com
Upgrade: websocket
Connection: upgrade
Sec-WebSocket-Key: IP961nRFEu82wIHD4oV3QA==
Sec-WebSocket-Version: 13
Sec-WebSocket-Protocol: aws.iot.securetunneling-2.0
access-token: ACCESS_TOKEN_REMOVED
User-Agent: localproxy Mac OS 64-bit/boost-1.79.0/openssl-3.0.0/protobuf-3.21.12

[2023-01-31T13:45:28.188785]{35422}[trace] Web socket upgrade response:
HTTP/1.1 101 Switching Protocols
Date: Tue, 31 Jan 2023 19:45:28 GMT
Content-Length: 0
Connection: upgrade
channel-id: 12541ffffed8f21d-000024de-0005bfbd-003505e5b235f44b-53aa2d35
upgrade: websocket
sec-websocket-accept: N9ISFCWV7ajwSAw0q1RBHkY/dRc=
sec-websocket-protocol: aws.iot.securetunneling-2.0

[2023-01-31T13:45:28.188942]{35422}[trace] Calling binary with type: websocket_stream_single_ssl_type
[2023-01-31T13:45:28.188955]{35422}[trace] Calling auto_fragment with type: websocket_stream_single_ssl_type
[2023-01-31T13:45:28.188966]{35422}[info] Web socket session ID: 12541ffffed8f21d-000024de-0005bfbd-003505e5b235f44b-53aa2d35
[2023-01-31T13:45:28.188978]{35422}[debug] Web socket subprotocol selected: aws.iot.securetunneling-2.0
[2023-01-31T13:45:28.188987]{35422}[info] Successfully established websocket connection with proxy server: wss://data.tunneling.iot.us-east-1.amazonaws.com:443
[2023-01-31T13:45:28.189008]{35422}[debug] Seting up web socket pings for every 5000 milliseconds
[2023-01-31T13:45:28.189018]{35422}[trace] Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-31T13:45:28.189254]{35422}[trace] Waiting for service ids...
[2023-01-31T13:45:28.189268]{35422}[trace] async_web_socket_read_loop_for_service_ids
[2023-01-31T13:45:28.189277]{35422}[debug] Scheduled next read:
[2023-01-31T13:45:28.189286]{35422}[trace] Calling async_read_some with type: websocket_stream_single_ssl_type
[2023-01-31T13:45:28.189643]{35422}[debug] No serviceId_to_tcp_server mapping for service_id:
[2023-01-31T13:45:28.189670]{35422}[debug] Extracting service Ids from control message 5
[2023-01-31T13:45:28.189819]{35422}[trace] Service id received:
[2023-01-31T13:45:28.189829]{35422}[trace] VNC
[2023-01-31T13:45:28.189838]{35422}[trace] Validating service ids configuration
[2023-01-31T13:45:28.189854]{35422}[info] Updated port mapping for v1 format:
[2023-01-31T13:45:28.189863]{35422}[info] VNC = 5555
[2023-01-31T13:45:28.189873]{35422}[trace] Setting up tcp sockets
[2023-01-31T13:45:28.189883]{35422}[trace] Clearing all ws data buffers
[2023-01-31T13:45:28.189892]{35422}[trace] Finished Clearing all ws data buffers
[2023-01-31T13:45:28.189901]{35422}[trace] Initializing tcp servers ...
[2023-01-31T13:45:28.189931]{35422}[trace] Setting up source tcp sockets
[2023-01-31T13:45:28.189941]{35422}[trace] Setting up tcp socket for service id: VNC
[2023-01-31T13:45:28.189963]{35422}[debug] Resolving bind address host: localhost
[2023-01-31T13:45:28.189987]{35422}[debug] Port to connect 5555
[2023-01-31T13:45:28.190036]{35422}[debug] Starting web socket read loop continue reading...
[2023-01-31T13:45:28.190048]{35422}[trace] Calling async_read_some with type: websocket_stream_single_ssl_type
[2023-01-31T13:45:28.190862]{35422}[debug] Resolved bind IP: ::1
[2023-01-31T13:45:28.191097]{35422}[info] Listening for new connection on port 5555
[2023-01-31T13:45:28.230000]{35422}[trace] Pong reply latency: 41 ms
[2023-01-31T13:45:33.190633]{35422}[trace] Sent ping data: 1675194333190
[2023-01-31T13:45:33.190693]{35422}[trace] Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-31T13:45:33.231959]{35422}[trace] Pong reply latency: 41 ms
[2023-01-31T13:45:38.193616]{35422}[trace] Sent ping data: 1675194338193
[2023-01-31T13:45:38.193737]{35422}[trace] Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-31T13:45:38.234941]{35422}[trace] Pong reply latency: 41 ms
[2023-01-31T13:45:43.194914]{35422}[trace] Sent ping data: 1675194343194
[2023-01-31T13:45:43.195049]{35422}[trace] Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-31T13:45:43.237076]{35422}[trace] Pong reply latency: 43 ms
[2023-01-31T13:45:48.197466]{35422}[trace] Sent ping data: 1675194348197
[2023-01-31T13:45:48.197534]{35422}[trace] Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-31T13:45:48.238160]{35422}[trace] Pong reply latency: 41 ms
[2023-01-31T13:45:53.199605]{35422}[trace] Sent ping data: 1675194353199
[2023-01-31T13:45:53.199651]{35422}[trace] Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-31T13:45:53.239968]{35422}[trace] Pong reply latency: 40 ms
[2023-01-31T13:45:58.203320]{35422}[trace] Sent ping data: 1675194358203
[2023-01-31T13:45:58.203371]{35422}[trace] Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-31T13:45:58.243826]{35422}[trace] Pong reply latency: 40 ms
[2023-01-31T13:46:03.205242]{35422}[trace] Sent ping data: 1675194363205
[2023-01-31T13:46:03.205307]{35422}[trace] Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-31T13:46:03.245827]{35422}[trace] Pong reply latency: 40 ms
[2023-01-31T13:46:08.206871]{35422}[trace] Sent ping data: 1675194368206
[2023-01-31T13:46:08.206986]{35422}[trace] Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-31T13:46:08.248310]{35422}[trace] Pong reply latency: 42 ms
[2023-01-31T13:46:13.209307]{35422}[trace] Sent ping data: 1675194373209
[2023-01-31T13:46:13.209572]{35422}[trace] Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-31T13:46:13.250059]{35422}[trace] Pong reply latency: 41 ms
[2023-01-31T13:46:18.210994]{35422}[trace] Sent ping data: 1675194378210
[2023-01-31T13:46:18.211119]{35422}[trace] Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-31T13:46:18.251864]{35422}[trace] Pong reply latency: 41 ms
[2023-01-31T13:46:23.214700]{35422}[trace] Sent ping data: 1675194383214
[2023-01-31T13:46:23.214767]{35422}[trace] Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-31T13:46:23.255373]{35422}[trace] Pong reply latency: 41 ms
[2023-01-31T13:46:23.279344]{35422}[debug] socket port 5555
[2023-01-31T13:46:23.279418]{35422}[debug] endpoint mapping:
[2023-01-31T13:46:23.279440]{35422}[debug] VNC = 5555
[2023-01-31T13:46:23.279460]{35422}[info] Accepted tcp connection on port 5555 from [::1]:62311
[2023-01-31T13:46:23.279496]{35422}[debug] Setting new stream ID to: 1, service id: VNC
[2023-01-31T13:46:23.279572]{35422}[trace] Sending messages over web socket for service id: VNC
[2023-01-31T13:46:23.279593]{35422}[trace] Current queue size: 0
[2023-01-31T13:46:23.279631]{35422}[trace] Put data 11 bytes into the web_socket_outgoing_message_queue for service id: VNC
[2023-01-31T13:46:23.279712]{35422}[trace] Calling async_write with type: websocket_stream_single_ssl_type
[2023-01-31T13:46:23.281656]{35422}[trace] Sent 11 bytes over websocket for service id: VNC
[2023-01-31T13:46:23.281715]{35422}[trace] Setting up bi-directional data transfer for service id: VNC
[2023-01-31T13:46:23.281736]{35422}[trace] Clearing tcp connection buffers
[2023-01-31T13:46:23.281755]{35422}[debug] Starting web socket read loop while web socket is already reading. Ignoring...
[2023-01-31T13:46:23.282234]{35422}[trace] Begin tcp socket read loop for service id : VNC
[2023-01-31T13:46:23.282495]{35422}[trace] web_socket_outgoing_message_queue is empty, no more messages to send.
[2023-01-31T13:46:28.216290]{35422}[trace] Sent ping data: 1675194388216
[2023-01-31T13:46:28.216381]{35422}[trace] Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-31T13:46:28.257443]{35422}[trace] Pong reply latency: 41 ms
[2023-01-31T13:46:33.218898]{35422}[trace] Sent ping data: 1675194393218
[2023-01-31T13:46:33.218952]{35422}[trace] Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-31T13:46:33.259695]{35422}[trace] Pong reply latency: 41 ms
[2023-01-31T13:46:38.220276]{35422}[trace] Sent ping data: 1675194398220
[2023-01-31T13:46:38.220377]{35422}[trace] Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-31T13:46:38.260808]{35422}[trace] Pong reply latency: 40 ms
[2023-01-31T13:46:43.221948]{35422}[trace] Sent ping data: 1675194403221
[2023-01-31T13:46:43.222075]{35422}[trace] Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-31T13:46:43.263628]{35422}[trace] Pong reply latency: 42 ms
[2023-01-31T13:46:48.224364]{35422}[trace] Sent ping data: 1675194408224
[2023-01-31T13:46:48.224414]{35422}[trace] Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-31T13:46:48.453345]{35422}[trace] Pong reply latency: 229 ms
[2023-01-31T13:46:53.225399]{35422}[trace] Sent ping data: 1675194413225
[2023-01-31T13:46:53.225534]{35422}[trace] Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-31T13:46:53.267083]{35422}[trace] Pong reply latency: 42 ms
[2023-01-31T13:46:58.227248]{35422}[trace] Sent ping data: 1675194418227
[2023-01-31T13:46:58.227372]{35422}[trace] Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-31T13:46:58.269482]{35422}[trace] Pong reply latency: 42 ms
[2023-01-31T13:47:03.229366]{35422}[trace] Sent ping data: 1675194423229
[2023-01-31T13:47:03.229444]{35422}[trace] Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-31T13:47:03.270360]{35422}[trace] Pong reply latency: 41 ms
[2023-01-31T13:47:08.230974]{35422}[trace] Sent ping data: 1675194428230
[2023-01-31T13:47:08.231022]{35422}[trace] Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-31T13:47:08.273585]{35422}[trace] Pong reply latency: 43 ms
[2023-01-31T13:47:13.232728]{35422}[trace] Sent ping data: 1675194433232
[2023-01-31T13:47:13.232777]{35422}[trace] Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-31T13:47:13.273199]{35422}[trace] Pong reply latency: 41 ms
[2023-01-31T13:47:17.802404]{35422}[trace] Reading from tcp socket for service id VNC
[2023-01-31T13:47:17.802498]{35422}[debug] Handling tcp socket error for service id: VNC . error message:End of file
[2023-01-31T13:47:17.802510]{35422}[info] Disconnected from: [::1]:62311
[2023-01-31T13:47:17.802559]{35422}[trace] Web socket write buffer drain for service id: VNC
[2023-01-31T13:47:17.802574]{35422}[trace] Reset stream for service id: VNC
[2023-01-31T13:47:17.802595]{35422}[trace] Sending messages over web socket for service id: VNC
[2023-01-31T13:47:17.802604]{35422}[trace] Current queue size: 0
[2023-01-31T13:47:17.802613]{35422}[trace] Put data 11 bytes into the web_socket_outgoing_message_queue for service id: VNC
[2023-01-31T13:47:17.802626]{35422}[trace] Calling async_write with type: websocket_stream_single_ssl_type
[2023-01-31T13:47:17.803202]{35422}[trace] Sent 11 bytes over websocket for service id: VNC
[2023-01-31T13:47:17.803222]{35422}[trace] Setting up tcp socket for service id: VNC
[2023-01-31T13:47:17.803253]{35422}[debug] Resolving bind address host: localhost
[2023-01-31T13:47:17.803272]{35422}[debug] Port to connect 5555
[2023-01-31T13:47:17.803336]{35422}[trace] web_socket_outgoing_message_queue is empty, no more messages to send.
[2023-01-31T13:47:17.803938]{35422}[debug] Resolved bind IP: ::1
[2023-01-31T13:47:17.804034]{35422}[info] Listening for new connection on port 5555
[2023-01-31T13:47:18.234181]{35422}[trace] Sent ping data: 1675194438234
[2023-01-31T13:47:18.234299]{35422}[trace] Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-31T13:47:18.275586]{35422}[trace] Pong reply latency: 41 ms
[2023-01-31T13:47:23.235781]{35422}[trace] Sent ping data: 1675194443235
[2023-01-31T13:47:23.235913]{35422}[trace] Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-31T13:47:23.277194]{35422}[trace] Pong reply latency: 42 ms
[2023-01-31T13:47:28.237770]{35422}[trace] Sent ping data: 1675194448237
[2023-01-31T13:47:28.237835]{35422}[trace] Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-31T13:47:28.278279]{35422}[trace] Pong reply latency: 41 ms
[2023-01-31T13:47:33.239013]{35422}[trace] Sent ping data: 1675194453238
[2023-01-31T13:47:33.239147]{35422}[trace] Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-31T13:47:33.280226]{35422}[trace] Pong reply latency: 42 ms
[2023-01-31T13:47:34.146073]{35422}[debug] socket port 5555
[2023-01-31T13:47:34.146152]{35422}[debug] endpoint mapping:
[2023-01-31T13:47:34.146175]{35422}[debug] VNC = 5555
[2023-01-31T13:47:34.146195]{35422}[info] Accepted tcp connection on port 5555 from [::1]:62327
[2023-01-31T13:47:34.146231]{35422}[debug] Setting new stream ID to: 2, service id: VNC
[2023-01-31T13:47:34.146262]{35422}[trace] Sending messages over web socket for service id: VNC
[2023-01-31T13:47:34.146282]{35422}[trace] Current queue size: 0
[2023-01-31T13:47:34.146300]{35422}[trace] Put data 11 bytes into the web_socket_outgoing_message_queue for service id: VNC
[2023-01-31T13:47:34.146324]{35422}[trace] Calling async_write with type: websocket_stream_single_ssl_type
[2023-01-31T13:47:34.146758]{35422}[trace] Sent 11 bytes over websocket for service id: VNC
[2023-01-31T13:47:34.146788]{35422}[trace] Setting up bi-directional data transfer for service id: VNC
[2023-01-31T13:47:34.146939]{35422}[trace] Clearing tcp connection buffers
[2023-01-31T13:47:34.146957]{35422}[debug] Starting web socket read loop while web socket is already reading. Ignoring...
[2023-01-31T13:47:34.146971]{35422}[trace] Begin tcp socket read loop for service id : VNC
[2023-01-31T13:47:34.146995]{35422}[trace] web_socket_outgoing_message_queue is empty, no more messages to send.
[2023-01-31T13:47:38.240399]{35422}[trace] Sent ping data: 1675194458240
[2023-01-31T13:47:38.240442]{35422}[trace] Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-31T13:47:38.280633]{35422}[trace] Pong reply latency: 40 ms
[2023-01-31T13:47:43.241842]{35422}[trace] Sent ping data: 1675194463241
[2023-01-31T13:47:43.241959]{35422}[trace] Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-31T13:47:43.283359]{35422}[trace] Pong reply latency: 42 ms
[2023-01-31T13:47:48.243923]{35422}[trace] Sent ping data: 1675194468243
[2023-01-31T13:47:48.244066]{35422}[trace] Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-31T13:47:48.285982]{35422}[trace] Pong reply latency: 42 ms
[2023-01-31T13:47:51.854450]{35422}[trace] Reading from tcp socket for service id VNC
[2023-01-31T13:47:51.854514]{35422}[debug] Handling tcp socket error for service id: VNC . error message:End of file
[2023-01-31T13:47:51.854554]{35422}[info] Disconnected from: [::1]:62327
[2023-01-31T13:47:51.854596]{35422}[trace] Web socket write buffer drain for service id: VNC
[2023-01-31T13:47:51.854610]{35422}[trace] Reset stream for service id: VNC
[2023-01-31T13:47:51.854628]{35422}[trace] Sending messages over web socket for service id: VNC
[2023-01-31T13:47:51.854637]{35422}[trace] Current queue size: 0
[2023-01-31T13:47:51.854645]{35422}[trace] Put data 11 bytes into the web_socket_outgoing_message_queue for service id: VNC
[2023-01-31T13:47:51.854657]{35422}[trace] Calling async_write with type: websocket_stream_single_ssl_type
[2023-01-31T13:47:51.855023]{35422}[trace] Sent 11 bytes over websocket for service id: VNC
[2023-01-31T13:47:51.855039]{35422}[trace] Setting up tcp socket for service id: VNC
[2023-01-31T13:47:51.855065]{35422}[debug] Resolving bind address host: localhost
[2023-01-31T13:47:51.855112]{35422}[debug] Port to connect 5555
[2023-01-31T13:47:51.855138]{35422}[trace] web_socket_outgoing_message_queue is empty, no more messages to send.
[2023-01-31T13:47:51.855548]{35422}[debug] Resolved bind IP: ::1
[2023-01-31T13:47:51.855631]{35422}[info] Listening for new connection on port 5555
[2023-01-31T13:47:53.246309]{35422}[trace] Sent ping data: 1675194473246
[2023-01-31T13:47:53.246444]{35422}[trace] Calling async_ping with type: websocket_stream_single_ssl_type
[2023-01-31T13:47:53.287442]{35422}[trace] Pong reply latency: 41 ms
^C
`

[RogerZhongAWS]

I will say though, that this stale access token behavior is a little strange and this is the first time I've heard of such a thing happening. If you want to set the environment variable instead, you can cat from a file like this.

export AWSIOT_TUNNEL_ACCESS_TOKEN=$(cat destinationAccessToken.txt)
export AWSIOT_TUNNEL_CLIENT_TOKEN=$(cat clientAccessToken.txt)
./localproxy -d 5901 -b 127.0.0.1 -v 6 -r us-east-1

The clientAccessToken is optional and should be locally generated once-per-tunnel using uuidgen, but it does allow you to close and restart the local proxy without having to generate new access tokens every single time... otherwise you would have to generate a new token every time you CTRL+C the application.

If it is indeed an issue with the service-side validation, I will have to consult with their team.

[monelgordillo]

hmmm....now I'm getting this:

X-Status-Reason: client-token must match ^[a-zA-Z0-9-]{32,128}$

client-token must match ^[a-zA-Z0-9-]{32,128}$
[2023-02-02T10:50:51.613008]{56023}[error] Proxy server rejected web socket upgrade request: (HTTP/1.1 400 Bad Request) "client-token must match ^[a-zA-Z0-9-]{32,128}$"
[2023-02-02T10:50:51.613055]{56023}[trace] Calling is_open with type: websocket_stream_single_ssl_type

[RogerZhongAWS]

Looks like the token failed the regex check, make sure there are no special characters, spaces, and remove any newlines at the end of the file. Example of a generated unique id: 994c3f1e-0de0-4699-8132-bb8f0edacae1

[shangabl]

You can generate a valid uuid with the linux command uuidgen

[monelgordillo]

I added up installing the local proxy (source) on Ubuntu, instead of Mac. I was able to setup the ssh & vnc connection to the remote/destination device (Ubuntu too).

Seems like local proxy does not work very well with Mac as the source.

[RogerZhongAWS]

Thank you for the insights, renaming this issue to more closely reflect the nature of the problem...