Can't start localproxy in Docker

Lard4 commented 3 years ago

Describe the bug

After creating the docker image and running it, localproxy does not "perform the SSL handshake with the proxy server, and the script fails.

To Reproduce

I'm facing the same issue on an Intel Mac running Big Sur (run in docker). I downloaded this repo (fresh, maybe 30 minutes before this comment), made the docker image, then ./docker-run.sh -p 5555 then export my source token, then ./localproxy -r us-west-2 -s 5555 -c ./certs -v 6 and get:

Steps to reproduce the behavior:

download this repository on an Intel Mac running Big Sur (11.1)
make the docker image
run ./docker-run.sh -p 5555
export the source token
run ./localproxy -r us-west-2 -s 5555 -c ./certs -v 6
wait the SSL handshake fail.

Expected behavior

The script continues and opens the tunnel.

Actual behavior

root@8915eb202273:/home/aws-iot-securetunneling-localproxy# ./localproxy -r us-west-2 -s 5555 -c /home/aws-iot-securetunneling-localproxy/certs -v 6
[2021-05-26T01:20:14.773713]{12}[debug]   v2 local proxy starts with v1 local proxy format
[2021-05-26T01:20:14.773874]{12}[debug]   /home/aws-iot-securetunneling-localproxy/config does not exist!
[2021-05-26T01:20:14.773935]{12}[info]    Starting proxy in source mode
[2021-05-26T01:20:14.776374]{12}[trace]   Setting up web socket...
[2021-05-26T01:20:14.776663]{12}[info]    Attempting to establish web socket connection with endpoint wss://data.tunneling.iot.us-west-2.amazonaws.com:443
[2021-05-26T01:20:14.776730]{12}[trace]   Resolving proxy host: data.tunneling.iot.us-west-2.amazonaws.com
[2021-05-26T01:20:14.843111]{12}[debug]   Resolved proxy server IP: <redacted>
[2021-05-26T01:20:14.843502]{12}[debug]   Connected successfully with proxy server
[2021-05-26T01:20:14.843557]{12}[trace]   Performing SSL handshake with proxy server
[2021-05-26T01:20:14.844489]{12}[error]   Could not perform SSL handshake with proxy server: stream truncated

Logs

see above.

Environment (please complete the following information):

OS: MacOS
Version: Big Sur 11.1
Architecture: x86_64
Localproxy commit: bc2f28ee69cd694ba09db72b0b7f6a5309bd337d

Additional context

None

YSUN-coder commented 3 years ago

Facing the same issue when using the command ./localproxy -s 5555 -b 0.0.0.0 -r ca-central-1 -c ./certs -v 6 -t <source_access_token>. If I just run ./localproxy -s 5555 -b 0.0.0.0 -r ca-central-1 -t <source_access_token>, the log will be as below:

[info]    Starting proxy in source mode
[info]    Attempting to establish web socket connection with endpoint wss://data.tunneling.iot.ca-central-1.amazonaws.com:443
[error]   Could not perform SSL handshake with proxy server: stream truncated
[info]    Attempting to establish web socket connection with endpoint wss://data.tunneling.iot.ca-central-1.amazonaws.com:443
[error]   Could not perform SSL handshake with proxy server: stream truncated

OS: MacOS
Version: 10.15.7
Docker Desktop version：3.3.0
Docker Engine version: 20.10.5
Architecture: x86_64
Localproxy commit: commit bc2f28ee69cd694ba09db72b0b7f6a5309bd337d (HEAD -> master, origin/master, origin/HEAD) Merge: c46dc0e c4d25d9

kareali commented 3 years ago

I can't reproduce this on my macOS Big Sur 11.3 with x86_64 processor.

➜  tst git clone https://github.com/aws-samples/aws-iot-securetunneling-localproxy
Cloning into 'aws-iot-securetunneling-localproxy'...
remote: Enumerating objects: 176, done.
remote: Counting objects: 100% (81/81), done.
remote: Compressing objects: 100% (55/55), done.
remote: Total 176 (delta 24), reused 52 (delta 14), pack-reused 95
Receiving objects: 100% (176/176), 146.05 KiB | 1.22 MiB/s, done.
Resolving deltas: 100% (67/67), done.
➜  tst cd aws-iot-securetunneling-localproxy 
➜  aws-iot-securetunneling-localproxy git:(master) ./docker-build.sh 
Architecture: x86_64
OpenSSL configurations: linux-generic64
[+] Building 2315.5s (22/22) FINISHED                                                                                                                                                                                                                 
 => [internal] load build definition from Dockerfile                                                                                                                                                                                             0.0s
 => => transferring dockerfile: 3.23kB                                                                                                                                                                                                           0.0s
 => [internal] load .dockerignore                                                                                                                                                                                                                0.0s
 => => transferring context: 2B                                                                                                                                                                                                                  0.0s
 => [internal] load metadata for docker.io/library/ubuntu:18.04                                                                                                                                                                                  2.5s
 => [auth] library/ubuntu:pull token for registry-1.docker.io                                                                                                                                                                                    0.0s
 => [builder  1/13] FROM docker.io/library/ubuntu:18.04@sha256:04919776d30640ce4ed24442d5f7c1a8e4bd0e4793ed9469843cedaecb0d72fb                                                                                                                  7.9s
 => => resolve docker.io/library/ubuntu:18.04@sha256:04919776d30640ce4ed24442d5f7c1a8e4bd0e4793ed9469843cedaecb0d72fb                                                                                                                            0.0s
 => => sha256:04919776d30640ce4ed24442d5f7c1a8e4bd0e4793ed9469843cedaecb0d72fb 1.41kB / 1.41kB                                                                                                                                                   0.0s
 => => sha256:ceed028aae0eac7db9dd33bd89c14d5a9991d73443b0de24ba0db250f47491d2 943B / 943B                                                                                                                                                       0.0s
 => => sha256:81bcf752ac3dc8a12d54908ecdfe98a857c84285e5d50bed1d10f9812377abd6 3.32kB / 3.32kB                                                                                                                                                   0.0s
 => => sha256:4bbfd2c87b7524455f144a03bf387c88b6d4200e5e0df9139a9d5e79110f89ca 26.70MB / 26.70MB                                                                                                                                                 5.4s
 => => sha256:d2e110be24e168b42c1a2ddbc4a476a217b73cccdba69cdcb212b812a88f5726 857B / 857B                                                                                                                                                       0.3s
 => => sha256:889a7173dcfeb409f9d88054a97ab2445f5a799a823f719a5573365ee3662b6f 189B / 189B                                                                                                                                                       0.4s
 => => extracting sha256:4bbfd2c87b7524455f144a03bf387c88b6d4200e5e0df9139a9d5e79110f89ca                                                                                                                                                        1.4s
 => => extracting sha256:d2e110be24e168b42c1a2ddbc4a476a217b73cccdba69cdcb212b812a88f5726                                                                                                                                                        0.0s
 => => extracting sha256:889a7173dcfeb409f9d88054a97ab2445f5a799a823f719a5573365ee3662b6f                                                                                                                                                        0.0s
 => [builder  2/13] RUN apt update && apt upgrade -y &&  apt install -y git libboost-all-dev autoconf automake  wget libtool curl make g++ unzip cmake libssl-dev                                                                              102.5s
 => [stage-1 2/5] RUN apt update && apt upgrade -y &&     apt install -y openssl wget &&     rm -rf /var/lib/apt/lists/* &&     apt-get clean                                                                                                   19.5s
 => [stage-1 3/5] RUN mkdir -p /home/aws-iot-securetunneling-localproxy/certs &&     cd /home/aws-iot-securetunneling-localproxy/certs &&     wget https://www.amazontrust.com/repository/AmazonRootCA1.pem &&  openssl rehash ./                1.1s
 => [builder  3/13] RUN mkdir /home/dependencies                                                                                                                                                                                                 0.3s 
 => [builder  4/13] WORKDIR /home/dependencies                                                                                                                                                                                                   0.0s 
 => [builder  5/13] RUN wget https://www.zlib.net/zlib-1.2.11.tar.gz -O /tmp/zlib-1.2.11.tar.gz &&  tar xzvf /tmp/zlib-1.2.11.tar.gz &&  cd zlib-1.2.11 &&  ./configure &&  make &&  make install &&  cd /home/dependencies                      6.8s 
 => [builder  6/13] RUN wget https://boostorg.jfrog.io/artifactory/main/release/1.69.0/source/boost_1_69_0.tar.gz -O /tmp/boost.tar.gz &&  tar xzvf /tmp/boost.tar.gz &&  cd boost_1_69_0 &&  ./bootstrap.sh &&  ./b2 install &&  cd /home/d  1123.8s 
 => [builder  7/13] RUN wget https://github.com/protocolbuffers/protobuf/releases/download/v3.6.1/protobuf-all-3.6.1.tar.gz -O /tmp/protobuf-all-3.6.1.tar.gz &&  tar xzvf /tmp/protobuf-all-3.6.1.tar.gz &&  cd protobuf-3.6.1 &&  mkdir bui  584.5s 
 => [builder  8/13] RUN git clone https://github.com/openssl/openssl.git &&  cd openssl &&  git checkout OpenSSL_1_1_1-stable &&  ./Configure linux-generic64 &&  make depend &&  make all &&  cd /home/dependencies                           196.8s 
 => [builder  9/13] RUN git clone --branch v2.13.2 https://github.com/catchorg/Catch2.git &&  cd Catch2 &&  mkdir build &&  cd build &&  cmake ../ &&  make &&  make install &&  cd /home/dependencies                                         107.6s 
 => [builder 10/13] RUN git clone https://github.com/aws-samples/aws-iot-securetunneling-localproxy &&  cd aws-iot-securetunneling-localproxy &&  mkdir build &&  cd build &&  cmake ../ &&  make                                              174.8s 
 => [builder 11/13] RUN mkdir -p /home/aws-iot-securetunneling-localproxy &&  cd /home/aws-iot-securetunneling-localproxy &&  cp /home/dependencies/aws-iot-securetunneling-localproxy/build/bin/* /home/aws-iot-securetunneling-localproxy/     0.4s 
 => [builder 12/13] RUN rm -rf /home/dependencies                                                                                                                                                                                                6.9s 
 => [builder 13/13] WORKDIR /home/aws-iot-securetunneling-localproxy/                                                                                                                                                                            0.0s 
 => [stage-1 4/5] COPY --from=builder /home/aws-iot-securetunneling-localproxy /home/aws-iot-securetunneling-localproxy                                                                                                                          0.1s 
 => [stage-1 5/5] WORKDIR /home/aws-iot-securetunneling-localproxy                                                                                                                                                                               0.0s 
 => exporting to image                                                                                                                                                                                                                           0.5s 
 => => exporting layers                                                                                                                                                                                                                          0.5s
 => => writing image sha256:0f4189b65b8c0c79ef4c11c736113b42e5de58e492813e8f0051e7fab2c714d6                                                                                                                                                     0.0s
 => => naming to docker.io/library/aws-iot-securetunneling-localproxy:latest                                                                                                                                                                     0.0s

Use 'docker scan' to run Snyk tests against images to find vulnerabilities and learn how to fix them
➜  aws-iot-securetunneling-localproxy git:(master) ./docker-run.sh -p 5555
Running the container with exposed port: 5555
root@0f2b03aed659:/home/aws-iot-securetunneling-localproxy# export AWSIOT_TUNNEL_ACCESS_TOKEN=<TOKEN>
root@0f2b03aed659:/home/aws-iot-securetunneling-localproxy# ./localproxy -r us-west-2 -s 5555 -c ./certs -v 6
[2021-05-26T16:24:17.227355]{11}[debug]   v2 local proxy starts with v1 local proxy format
[2021-05-26T16:24:17.228063]{11}[debug]   /home/aws-iot-securetunneling-localproxy/config does not exist!
[2021-05-26T16:24:17.228487]{11}[info]    Starting proxy in source mode
[2021-05-26T16:24:17.238282]{11}[trace]   Setting up web socket...
[2021-05-26T16:24:17.241627]{11}[info]    Attempting to establish web socket connection with endpoint wss://data.tunneling.iot.us-west-2.amazonaws.com:443
[2021-05-26T16:24:17.241689]{11}[trace]   Resolving proxy host: data.tunneling.iot.us-west-2.amazonaws.com
[2021-05-26T16:24:17.353746]{11}[debug]   Resolved proxy server IP: 52.26.8.178
[2021-05-26T16:24:17.415099]{11}[debug]   Connected successfully with proxy server
[2021-05-26T16:24:17.415190]{11}[trace]   Performing SSL handshake with proxy server
[2021-05-26T16:24:17.541906]{11}[debug]   Successfully completed SSL handshake with proxy server
[2021-05-26T16:24:17.542014]{11}[trace]   Performing websocket handshake with proxy server
[2021-05-26T16:24:17.542711]{11}[trace]   Web socket ugprade request(*not entirely final):
GET /tunnel?local-proxy-mode=source HTTP/1.1
Host: data.tunneling.iot.us-west-2.amazonaws.com
Upgrade: websocket
Connection: upgrade
Sec-WebSocket-Key: yWMMgwjpIj85vk6rEzAIZQ==
Sec-WebSocket-Version: 13
Sec-WebSocket-Protocol: aws.iot.securetunneling-2.0
access-token: ***ACCESS_TOKEN_REMOVED***
User-Agent: localproxy linux 64-bit/boost-1.69.0/openssl-1.1.1/protobuf-3.6.1

[2021-05-26T16:24:17.640298]{11}[trace]   Web socket upgrade response:
HTTP/1.1 101 Switching Protocols
Date: Wed, 26 May 2021 16:24:17 GMT
Content-Length: 0
Connection: upgrade
channel-id: 0ab8d1fffe9ed215-000013c9-00005b05-8c22ca0843efb242-eaf5ad49
upgrade: websocket
sec-websocket-accept: 0Dp9Prd0lOcSsfTN0oCKYWqubPk=
sec-websocket-protocol: aws.iot.securetunneling-2.0

[2021-05-26T16:24:17.640399]{11}[info]    Web socket session ID: 0ab8d1fffe9ed215-000013c9-00005b05-8c22ca0843efb242-eaf5ad49
[2021-05-26T16:24:17.640417]{11}[debug]   Web socket subprotocol selected: aws.iot.securetunneling-2.0
[2021-05-26T16:24:17.640435]{11}[info]    Successfully established websocket connection with proxy server: wss://data.tunneling.iot.us-west-2.amazonaws.com:443
[2021-05-26T16:24:17.641517]{11}[debug]   Seting up web socket pings for every 5000 milliseconds
[2021-05-26T16:24:17.642217]{11}[trace]   Waiting for service ids...
[2021-05-26T16:24:17.642273]{11}[trace]   async_web_socket_read_loop_for_service_ids
[2021-05-26T16:24:17.642308]{11}[debug]   Scheduled next read:
[2021-05-26T16:24:17.642573]{11}[debug]   No serviceId_to_tcp_server mapping for service_id: 
[2021-05-26T16:24:17.642614]{11}[debug]   Extracting service Ids from control message 5
[2021-05-26T16:24:17.642630]{11}[trace]   Service id received: 
[2021-05-26T16:24:17.642643]{11}[trace]   Validating service ids configuration
[2021-05-26T16:24:17.643174]{11}[trace]   Setting up tcp sockets 
[2021-05-26T16:24:17.643207]{11}[trace]   Clearing all ws data buffers
[2021-05-26T16:24:17.643226]{11}[trace]   Finished Clearing all ws data buffers
[2021-05-26T16:24:17.643294]{11}[trace]   Initializing tcp servers ...
[2021-05-26T16:24:17.643329]{11}[trace]   Setting up source tcp sockets
[2021-05-26T16:24:17.643377]{11}[trace]   Setting up tcp socket for service id: 
[2021-05-26T16:24:17.643432]{11}[debug]   Resolving bind address host: localhost
[2021-05-26T16:24:17.643473]{11}[debug]   Port to connect 5555
[2021-05-26T16:24:17.643512]{11}[debug]   Starting web socket read loop continue reading...
[2021-05-26T16:24:17.644346]{11}[debug]   Resolved bind IP: 127.0.0.1
[2021-05-26T16:24:17.644426]{11}[info]    Listening for new connection on port 5555
[2021-05-26T16:24:22.644719]{11}[trace]   Sent ping data: 1622046262644

Lard4 commented 3 years ago

confirmed it is working on my raspberry pi. so, it must be something with the way my mac is configured with docker. is there a chance it could be something with how docker is configured or openssl?

YSUN-coder commented 3 years ago

confirmed it is working on my raspberry pi. so, it must be something with the way my mac is configured with docker. is there a chance it could be something with how docker is configured or openssl?

It seems possible. Are you also using Docker Desktop? I saw a reply here.

Lard4 commented 3 years ago

I am actually using Docker Desktop.... let me see if that's it

kareali commented 3 years ago

I'm using Docker desktop as well, installed it a couple of weeks ago by following these instructions, I didn't change any settings. Can you share the stdout for running the docker-build.sh script?

Lard4 commented 3 years ago

it looks identical to yours except for the times. i reran it this morning and my laptop died after completing (and subsequently not working properly again), and i lost the output. it takes a painfully long time to build, so i'm not sure what the benefit of running it again for 30 some odd minutes would have.

MiaoZhangAWS commented 3 years ago

@YSUN-coder, can you open a separate Github issue by following the issue template? Your issue may not have the same root cause with the current one and merging them together for debugging can add more confusions.

MiaoZhangAWS commented 3 years ago

@Lard4

Is this the first time you use this setup and found this issue? Or this same setup has been working in the past but stop working recently?
Can you run localproxytest in the container and see if it's passing? If the test does not pass, can you share the error logs? If you need to run localproxy only in source mode in the container, you can run:
```
./localproxytest [source]
```
If you need to run localproxy in both source and destination mode, you can simply run:
```
./localproxytest
```
When this issue happens, what's the state of the destination device that you are trying to connect to? Have you started running localproxy or other client on destination device ?

Lard4 commented 3 years ago

This is my first time doing this, so i've never had it working on my mac.

the localproxytest has errrors:


./docker-run.sh -p 5555
Running the container with exposed port: 5555
root@af885fd7cda4:/home/aws-iot-securetunneling-localproxy# ./localproxytest 
[2021-05-30 00:35:37.198381] [0x00007f703b8250c0] [debug]   a does not exist!
[2021-05-30 00:35:37.198727] [0x00007f703b8250c0] [debug]   testDir empty dir! Please add configuration files.
[2021-05-30 00:35:37.199053] [0x00007f703b8250c0] [debug]   configFile is not a directory!
[2021-05-30 00:35:37.199572] [0x00007f703b8250c0] [info]    Detect configuration files: 
[2021-05-30 00:35:37.200115] [0x00007f703b8250c0] [info]    Detect configuration files: 
[2021-05-30 00:35:37.200168] [0x00007f703b8250c0] [info]    /home/aws-iot-securetunneling-localproxy/certs/AmazonRootCA1.pem
[2021-05-30 00:35:37.200182] [0x00007f703b8250c0] [info]    Detect configuration files: 
[2021-05-30 00:35:37.200225] [0x00007f703b8250c0] [info]    /home/aws-iot-securetunneling-localproxy/certs/ce5e74ef.0
[2021-05-30 00:35:37.200279] [0x00007f703b8250c0] [info]    Detect configuration files: 
[2021-05-30 00:35:37.200330] [0x00007f703b8250c0] [info]    Detect configuration files: 
[2021-05-30 00:35:37.200346] [0x00007f703b8250c0] [info]    /home/aws-iot-securetunneling-localproxy/configFile
[2021-05-30 00:35:37.200359] [0x00007f703b8250c0] [info]    Detect configuration files: 
[2021-05-30 00:35:37.200375] [0x00007f703b8250c0] [info]    /home/aws-iot-securetunneling-localproxy/localproxytest
[2021-05-30 00:35:37.200452] [0x00007f703b8250c0] [info]    Detect configuration files: 
[2021-05-30 00:35:37.200473] [0x00007f703b8250c0] [info]    /home/aws-iot-securetunneling-localproxy/localproxy
Test server is listening on address: 127.0.0.1 and port: 42931
[2021-05-30 00:35:37.202876] [0x00007f7039556700] [info]    Starting proxy in source mode
[2021-05-30 00:35:37.212684] [0x00007f7039556700] [trace]   Setting up web socket...
[2021-05-30 00:35:37.212866] [0x00007f7039556700] [info]    Attempting to establish web socket connection with endpoint wss://127.0.0.1:42931
[2021-05-30 00:35:37.212912] [0x00007f7039556700] [trace]   Resolving proxy host: 127.0.0.1
[2021-05-30 00:35:37.213254] [0x00007f7039556700] [debug]   Resolved proxy server IP: 127.0.0.1
[2021-05-30 00:35:37.213755] [0x00007f7039556700] [debug]   Connected successfully with proxy server
[2021-05-30 00:35:37.213823] [0x00007f7039556700] [trace]   Performing websocket handshake with proxy server
[2021-05-30 00:35:37.214121] [0x00007f7039556700] [trace]   Web socket ugprade request(*not entirely final):
GET /tunnel?local-proxy-mode=source HTTP/1.1
Host: 127.0.0.1
Upgrade: websocket
Connection: upgrade
Sec-WebSocket-Key: Yyxkd9F09/NVRMli95XRUQ==
Sec-WebSocket-Version: 13
Sec-WebSocket-Protocol: aws.iot.securetunneling-2.0
access-token: ***ACCESS_TOKEN_REMOVED***
User-Agent: localproxy linux 64-bit/boost-1.69.0/openssl-1.1.1/protobuf-3.6.1

[2021-05-30 00:35:37.214475] [0x00007f7039556700] [trace] Web socket upgrade response: HTTP/1.1 101 Switching Protocols Upgrade: websocket Connection: upgrade Sec-WebSocket-Accept: iK0GR+8alUvL7qmiUiesnK+vNb0= channel-id: 00000000-0000-0000-0000-000000000000 Sec-WebSocket-Protocol: aws.iot.securetunneling-2.0 Server: Boost.Beast/189

[2021-05-30 00:35:37.214590] [0x00007f7039556700] [info] Web socket session ID: 00000000-0000-0000-0000-000000000000 [2021-05-30 00:35:37.214637] [0x00007f7039556700] [debug] Web socket subprotocol selected: aws.iot.securetunneling-2.0 [2021-05-30 00:35:37.214653] [0x00007f7039556700] [info] Successfully established websocket connection with proxy server: wss://127.0.0.1:42931 [2021-05-30 00:35:37.214673] [0x00007f7039556700] [debug] Seting up web socket pings for every 5000 milliseconds [2021-05-30 00:35:37.215032] [0x00007f7039556700] [trace] Waiting for service ids... [2021-05-30 00:35:37.215144] [0x00007f7039556700] [trace] async_web_socket_read_loop_for_service_ids [2021-05-30 00:35:37.215164] [0x00007f7039556700] [debug] Scheduled next read: [2021-05-30 00:35:37.215232] [0x00007f7039556700] [trace] Pong reply latency: 1 ms [2021-05-30 00:35:37.254363] [0x00007f7039556700] [debug] No serviceId_to_tcp_server mapping for service_id: [2021-05-30 00:35:37.254563] [0x00007f7039556700] [debug] Extracting service Ids from control message 5 [2021-05-30 00:35:37.254632] [0x00007f7039556700] [trace] Service id received: [2021-05-30 00:35:37.254641] [0x00007f7039556700] [trace] ssh1 [2021-05-30 00:35:37.254648] [0x00007f7039556700] [trace] Validating service ids configuration [2021-05-30 00:35:37.254660] [0x00007f7039556700] [trace] Setting up tcp sockets [2021-05-30 00:35:37.254668] [0x00007f7039556700] [trace] Clearing all ws data buffers [2021-05-30 00:35:37.254678] [0x00007f7039556700] [trace] Finished Clearing all ws data buffers [2021-05-30 00:35:37.254685] [0x00007f7039556700] [trace] Initializing tcp servers ... [2021-05-30 00:35:37.254700] [0x00007f7039556700] [trace] Setting up source tcp sockets [2021-05-30 00:35:37.254709] [0x00007f7039556700] [trace] Setting up tcp socket for service id: ssh1 [2021-05-30 00:35:37.254740] [0x00007f7039556700] [debug] Resolving bind address host: 127.0.0.1 [2021-05-30 00:35:37.254755] [0x00007f7039556700] [debug] Port to connect 37205 [2021-05-30 00:35:37.254800] [0x00007f7039556700] [debug] Starting web socket read loop continue reading... [2021-05-30 00:35:37.255255] [0x00007f7039556700] [debug] Resolved bind IP: 127.0.0.1 [2021-05-30 00:35:37.255301] [0x00007f7039556700] [info] Listening for new connection on port 37205 [2021-05-30 00:35:37.310778] [0x00007f7039556700] [debug] socket port 37205 [2021-05-30 00:35:37.310897] [0x00007f7039556700] [debug] endpoint mapping: [2021-05-30 00:35:37.310906] [0x00007f7039556700] [debug] ssh1 = 37205 [2021-05-30 00:35:37.310951] [0x00007f7039556700] [info] Accepted tcp connection on port 37205 from 127.0.0.1:34384 [2021-05-30 00:35:37.310962] [0x00007f7039556700] [debug] Setting new stream ID to: 1, service id: ssh1 [2021-05-30 00:35:37.311071] [0x00007f7039556700] [trace] Sending messages over web socket for service id: ssh1 [2021-05-30 00:35:37.311164] [0x00007f7039556700] [trace] Current queue size: 0 [2021-05-30 00:35:37.311184] [0x00007f7039556700] [trace] Put data 12 bytes into the web_socket_outgoing_message_queue for service id: ssh1 [2021-05-30 00:35:37.311541] [0x00007f7039556700] [trace] Sent 12 bytes over websocket for service id: ssh1 [2021-05-30 00:35:37.311563] [0x00007f7039556700] [trace] Setting up bi-directional data transfer for service id: ssh1 [2021-05-30 00:35:37.311578] [0x00007f7039556700] [trace] Clearing tcp connection buffers [2021-05-30 00:35:37.311590] [0x00007f7039556700] [debug] Starting web socket read loop while web socket is already reading. Ignoring... [2021-05-30 00:35:37.311602] [0x00007f7039556700] [trace] Begin tcp socket read loop for service id : ssh1 [2021-05-30 00:35:37.311927] [0x00007f7039556700] [trace] web_socket_outgoing_message_queue is empty, no more messages to send. [2021-05-30 00:35:37.312012] [0x00007f7039556700] [trace] Reading from tcp socket for service id ssh1 [2021-05-30 00:35:37.312027] [0x00007f7039556700] [trace] TCP socket read 15 bytes [2021-05-30 00:35:37.312136] [0x00007f7039556700] [trace] Begin tcp socket read loop for service id : ssh1 [2021-05-30 00:35:37.312155] [0x00007f7039556700] [trace] Web socket write buffer drain for service id: ssh1 [2021-05-30 00:35:37.312176] [0x00007f7039556700] [debug] Prepare to send data message: service id: ssh1 stream id: 1 [2021-05-30 00:35:37.312252] [0x00007f7039556700] [trace] Sending messages over web socket for service id: ssh1 [2021-05-30 00:35:37.312566] [0x00007f7039556700] [trace] Current queue size: 0 [2021-05-30 00:35:37.312609] [0x00007f7039556700] [trace] Put data 29 bytes into the web_socket_outgoing_message_queue for service id: ssh1 [2021-05-30 00:35:37.312710] [0x00007f7039556700] [debug] Write buffer has enough space, continue tcp read loop for ssh1 [2021-05-30 00:35:37.312736] [0x00007f7039556700] [trace] Begin tcp socket read loop for service id : ssh1 [2021-05-30 00:35:37.312755] [0x00007f7039556700] [trace] Sent 29 bytes over websocket for service id: ssh1 [2021-05-30 00:35:37.312774] [0x00007f7039556700] [trace] Web socket write buffer drain for service id: ssh1 [2021-05-30 00:35:37.312814] [0x00007f7039556700] [trace] web_socket_outgoing_message_queue is empty, no more messages to send. [2021-05-30 00:35:37.313066] [0x00007f7039556700] [debug] Starting web socket read loop continue reading... [2021-05-30 00:35:37.313204] [0x00007f7039556700] [trace] write done service id ssh1 [2021-05-30 00:35:37.313575] [0x00007f7039556700] [trace] Wrote 15 bytes to tcp socket [2021-05-30 00:35:37.313602] [0x00007f7039556700] [trace] TCP write buffer drain complete [2021-05-30 00:35:37.313619] [0x00007f7039556700] [trace] Done writing for: ssh1 [2021-05-30 00:35:37.313640] [0x00007f7039556700] [trace] Reading from tcp socket for service id ssh1 [2021-05-30 00:35:37.313696] [0x00007f7039556700] [trace] TCP socket read 15 bytes [2021-05-30 00:35:37.314004] [0x00007f7039556700] [trace] Begin tcp socket read loop for service id : ssh1 [2021-05-30 00:35:37.314065] [0x00007f7039556700] [trace] Web socket write buffer drain for service id: ssh1 [2021-05-30 00:35:37.314082] [0x00007f7039556700] [debug] Prepare to send data message: service id: ssh1 stream id: 1 [2021-05-30 00:35:37.314113] [0x00007f7039556700] [trace] Sending messages over web socket for service id: ssh1 [2021-05-30 00:35:37.314130] [0x00007f7039556700] [trace] Current queue size: 0 [2021-05-30 00:35:37.314139] [0x00007f7039556700] [trace] Put data 29 bytes into the web_socket_outgoing_message_queue for service id: ssh1 [2021-05-30 00:35:37.314179] [0x00007f7039556700] [debug] Write buffer has enough space, continue tcp read loop for ssh1 [2021-05-30 00:35:37.314197] [0x00007f7039556700] [trace] Begin tcp socket read loop for service id : ssh1 [2021-05-30 00:35:37.314212] [0x00007f7039556700] [trace] Sent 29 bytes over websocket for service id: ssh1 [2021-05-30 00:35:37.314220] [0x00007f7039556700] [trace] Web socket write buffer drain for service id: ssh1 [2021-05-30 00:35:37.314300] [0x00007f7039556700] [trace] web_socket_outgoing_message_queue is empty, no more messages to send. [2021-05-30 00:35:37.314905] [0x00007f7039556700] [debug] Starting web socket read loop continue reading... [2021-05-30 00:35:37.314971] [0x00007f7039556700] [trace] write done service id ssh1 [2021-05-30 00:35:37.314989] [0x00007f7039556700] [trace] Wrote 15 bytes to tcp socket [2021-05-30 00:35:37.315005] [0x00007f7039556700] [trace] TCP write buffer drain complete [2021-05-30 00:35:37.315027] [0x00007f7039556700] [trace] Done writing for: ssh1 [2021-05-30 00:35:37.315284] [0x00007f7039556700] [trace] Reading from tcp socket for service id ssh1 [2021-05-30 00:35:37.315299] [0x00007f7039556700] [trace] TCP socket read 15 bytes [2021-05-30 00:35:37.315306] [0x00007f7039556700] [trace] Begin tcp socket read loop for service id : ssh1 [2021-05-30 00:35:37.315317] [0x00007f7039556700] [trace] Web socket write buffer drain for service id: ssh1 [2021-05-30 00:35:37.315326] [0x00007f7039556700] [debug] Prepare to send data message: service id: ssh1 stream id: 1 [2021-05-30 00:35:37.315753] [0x00007f7039556700] [trace] Sending messages over web socket for service id: ssh1 [2021-05-30 00:35:37.315773] [0x00007f7039556700] [trace] Current queue size: 0 [2021-05-30 00:35:37.315788] [0x00007f7039556700] [trace] Put data 29 bytes into the web_socket_outgoing_message_queue for service id: ssh1 [2021-05-30 00:35:37.316330] [0x00007f7039556700] [debug] Write buffer has enough space, continue tcp read loop for ssh1 [2021-05-30 00:35:37.316378] [0x00007f7039556700] [trace] Begin tcp socket read loop for service id : ssh1 [2021-05-30 00:35:37.316396] [0x00007f7039556700] [trace] Sent 29 bytes over websocket for service id: ssh1 [2021-05-30 00:35:37.316406] [0x00007f7039556700] [trace] Web socket write buffer drain for service id: ssh1 [2021-05-30 00:35:37.316414] [0x00007f7039556700] [trace] web_socket_outgoing_message_queue is empty, no more messages to send. [2021-05-30 00:35:37.316861] [0x00007f7039556700] [debug] Starting web socket read loop continue reading... [2021-05-30 00:35:37.316887] [0x00007f7039556700] [trace] write done service id ssh1 [2021-05-30 00:35:37.316899] [0x00007f7039556700] [trace] Wrote 15 bytes to tcp socket [2021-05-30 00:35:37.316917] [0x00007f7039556700] [trace] TCP write buffer drain complete [2021-05-30 00:35:37.316999] [0x00007f7039556700] [trace] Done writing for: ssh1 [2021-05-30 00:35:37.317024] [0x00007f7039556700] [trace] Reading from tcp socket for service id ssh1 [2021-05-30 00:35:37.317039] [0x00007f7039556700] [trace] TCP socket read 15 bytes [2021-05-30 00:35:37.317223] [0x00007f7039556700] [trace] Begin tcp socket read loop for service id : ssh1 [2021-05-30 00:35:37.317258] [0x00007f7039556700] [trace] Web socket write buffer drain for service id: ssh1 [2021-05-30 00:35:37.317268] [0x00007f7039556700] [debug] Prepare to send data message: service id: ssh1 stream id: 1 [2021-05-30 00:35:37.317302] [0x00007f7039556700] [trace] Sending messages over web socket for service id: ssh1 [2021-05-30 00:35:37.317332] [0x00007f7039556700] [trace] Current queue size: 0 [2021-05-30 00:35:37.317519] [0x00007f7039556700] [trace] Put data 29 bytes into the web_socket_outgoing_message_queue for service id: ssh1 [2021-05-30 00:35:37.317629] [0x00007f7039556700] [debug] Write buffer has enough space, continue tcp read loop for ssh1 [2021-05-30 00:35:37.318021] [0x00007f7039556700] [trace] Begin tcp socket read loop for service id : ssh1 [2021-05-30 00:35:37.318043] [0x00007f7039556700] [trace] Sent 29 bytes over websocket for service id: ssh1 [2021-05-30 00:35:37.318056] [0x00007f7039556700] [trace] Web socket write buffer drain for service id: ssh1 [2021-05-30 00:35:37.318067] [0x00007f7039556700] [trace] web_socket_outgoing_message_queue is empty, no more messages to send. [2021-05-30 00:35:37.318410] [0x00007f7039556700] [debug] Starting web socket read loop continue reading... [2021-05-30 00:35:37.318532] [0x00007f7039556700] [trace] write done service id ssh1 [2021-05-30 00:35:37.318827] [0x00007f7039556700] [trace] Wrote 15 bytes to tcp socket [2021-05-30 00:35:37.318863] [0x00007f7039556700] [trace] TCP write buffer drain complete [2021-05-30 00:35:37.318884] [0x00007f7039556700] [trace] Done writing for: ssh1 [2021-05-30 00:35:37.318897] [0x00007f7039556700] [trace] Reading from tcp socket for service id ssh1 [2021-05-30 00:35:37.318911] [0x00007f7039556700] [trace] TCP socket read 15 bytes [2021-05-30 00:35:37.318919] [0x00007f7039556700] [trace] Begin tcp socket read loop for service id : ssh1 [2021-05-30 00:35:37.318929] [0x00007f7039556700] [trace] Web socket write buffer drain for service id: ssh1 [2021-05-30 00:35:37.319024] [0x00007f7039556700] [debug] Prepare to send data message: service id: ssh1 stream id: 1 [2021-05-30 00:35:37.319188] [0x00007f7039556700] [trace] Sending messages over web socket for service id: ssh1 [2021-05-30 00:35:37.319213] [0x00007f7039556700] [trace] Current queue size: 0 [2021-05-30 00:35:37.319222] [0x00007f7039556700] [trace] Put data 29 bytes into the web_socket_outgoing_message_queue for service id: ssh1 [2021-05-30 00:35:37.319268] [0x00007f7039556700] [debug] Write buffer has enough space, continue tcp read loop for ssh1 [2021-05-30 00:35:37.319942] [0x00007f7039556700] [trace] Begin tcp socket read loop for service id : ssh1 [2021-05-30 00:35:37.320023] [0x00007f7039556700] [trace] Sent 29 bytes over websocket for service id: ssh1 [2021-05-30 00:35:37.320050] [0x00007f7039556700] [trace] Web socket write buffer drain for service id: ssh1 [2021-05-30 00:35:37.320071] [0x00007f7039556700] [trace] web_socket_outgoing_message_queue is empty, no more messages to send. [2021-05-30 00:35:37.320694] [0x00007f7039556700] [debug] Starting web socket read loop continue reading... [2021-05-30 00:35:37.320790] [0x00007f7039556700] [trace] write done service id ssh1 [2021-05-30 00:35:37.320800] [0x00007f7039556700] [trace] Wrote 15 bytes to tcp socket [2021-05-30 00:35:37.320814] [0x00007f7039556700] [trace] TCP write buffer drain complete [2021-05-30 00:35:37.320825] [0x00007f7039556700] [trace] Done writing for: ssh1 [2021-05-30 00:35:37.320849] [0x00007f7039556700] [trace] Reading from tcp socket for service id ssh1 [2021-05-30 00:35:37.320865] [0x00007f7039556700] [debug] Handling tcp socket error for service id: ssh1 . error message:End of file [2021-05-30 00:35:37.320985] [0x00007f7039556700] [info] Disconnected from: 127.0.0.1:34384 [2021-05-30 00:35:37.321356] [0x00007f7039556700] [trace] Web socket write buffer drain for service id: ssh1 [2021-05-30 00:35:37.321478] [0x00007f7039556700] [trace] Reset stream for service id: ssh1 [2021-05-30 00:35:37.321585] [0x00007f7039556700] [trace] Sending messages over web socket for service id: ssh1 [2021-05-30 00:35:37.321603] [0x00007f7039556700] [trace] Current queue size: 0 [2021-05-30 00:35:37.321648] [0x00007f7039556700] [trace] Put data 12 bytes into the web_socket_outgoing_message_queue for service id: ssh1 [2021-05-30 00:35:37.321813] [0x00007f7039556700] [trace] Sent 12 bytes over websocket for service id: ssh1 [2021-05-30 00:35:37.321929] [0x00007f7039556700] [trace] Setting up tcp socket for service id: ssh1 [2021-05-30 00:35:37.322611] [0x00007f7039556700] [debug] Resolving bind address host: 127.0.0.1 [2021-05-30 00:35:37.322678] [0x00007f7039556700] [debug] Port to connect 37205 [2021-05-30 00:35:37.322876] [0x00007f7039556700] [trace] web_socket_outgoing_message_queue is empty, no more messages to send. [2021-05-30 00:35:37.322937] [0x00007f7039556700] [debug] Resolved bind IP: 127.0.0.1 [2021-05-30 00:35:37.322975] [0x00007f7039556700] [info] Listening for new connection on port 37205 [2021-05-30 00:35:37.377685] [0x00007f7039556700] [debug] socket port 37205 [2021-05-30 00:35:37.377768] [0x00007f7039556700] [debug] endpoint mapping: [2021-05-30 00:35:37.377787] [0x00007f7039556700] [debug] ssh1 = 37205 [2021-05-30 00:35:37.377808] [0x00007f7039556700] [info] Accepted tcp connection on port 37205 from 127.0.0.1:34386 [2021-05-30 00:35:37.377828] [0x00007f7039556700] [debug] Setting new stream ID to: 2, service id: ssh1 [2021-05-30 00:35:37.377858] [0x00007f7039556700] [trace] Sending messages over web socket for service id: ssh1 [2021-05-30 00:35:37.377869] [0x00007f7039556700] [trace] Current queue size: 0 [2021-05-30 00:35:37.377879] [0x00007f7039556700] [trace] Put data 12 bytes into the web_socket_outgoing_message_queue for service id: ssh1 [2021-05-30 00:35:37.378098] [0x00007f7039556700] [trace] Sent 12 bytes over websocket for service id: ssh1 [2021-05-30 00:35:37.378729] [0x00007f7039556700] [trace] Setting up bi-directional data transfer for service id: ssh1 [2021-05-30 00:35:37.378751] [0x00007f7039556700] [trace] Clearing tcp connection buffers [2021-05-30 00:35:37.378769] [0x00007f7039556700] [debug] Starting web socket read loop while web socket is already reading. Ignoring... [2021-05-30 00:35:37.378788] [0x00007f7039556700] [trace] Begin tcp socket read loop for service id : ssh1 [2021-05-30 00:35:37.378814] [0x00007f7039556700] [trace] web_socket_outgoing_message_queue is empty, no more messages to send. [2021-05-30 00:35:37.379033] [0x00007f7039556700] [trace] Reading from tcp socket for service id ssh1 [2021-05-30 00:35:37.379057] [0x00007f7039556700] [trace] TCP socket read 15 bytes [2021-05-30 00:35:37.379396] [0x00007f7039556700] [trace] Begin tcp socket read loop for service id : ssh1 [2021-05-30 00:35:37.379450] [0x00007f7039556700] [trace] Web socket write buffer drain for service id: ssh1 [2021-05-30 00:35:37.379473] [0x00007f7039556700] [debug] Prepare to send data message: service id: ssh1 stream id: 2 [2021-05-30 00:35:37.379832] [0x00007f7039556700] [trace] Sending messages over web socket for service id: ssh1 [2021-05-30 00:35:37.379850] [0x00007f7039556700] [trace] Current queue size: 0 [2021-05-30 00:35:37.379859] [0x00007f7039556700] [trace] Put data 29 bytes into the web_socket_outgoing_message_queue for service id: ssh1 [2021-05-30 00:35:37.379910] [0x00007f7039556700] [debug] Write buffer has enough space, continue tcp read loop for ssh1 [2021-05-30 00:35:37.379935] [0x00007f7039556700] [trace] Begin tcp socket read loop for service id : ssh1 [2021-05-30 00:35:37.379956] [0x00007f7039556700] [trace] Sent 29 bytes over websocket for service id: ssh1 [2021-05-30 00:35:37.380128] [0x00007f7039556700] [trace] Web socket write buffer drain for service id: ssh1 [2021-05-30 00:35:37.380160] [0x00007f7039556700] [trace] web_socket_outgoing_message_queue is empty, no more messages to send. [2021-05-30 00:35:37.380591] [0x00007f7039556700] [debug] Starting web socket read loop continue reading... [2021-05-30 00:35:37.381013] [0x00007f7039556700] [trace] write done service id ssh1 [2021-05-30 00:35:37.381043] [0x00007f7039556700] [trace] Wrote 15 bytes to tcp socket [2021-05-30 00:35:37.381070] [0x00007f7039556700] [trace] TCP write buffer drain complete [2021-05-30 00:35:37.381089] [0x00007f7039556700] [trace] Done writing for: ssh1 [2021-05-30 00:35:37.381112] [0x00007f7039556700] [trace] Reading from tcp socket for service id ssh1 [2021-05-30 00:35:37.381497] [0x00007f7039556700] [trace] TCP socket read 15 bytes [2021-05-30 00:35:37.381512] [0x00007f7039556700] [trace] Begin tcp socket read loop for service id : ssh1 [2021-05-30 00:35:37.381528] [0x00007f7039556700] [trace] Web socket write buffer drain for service id: ssh1 [2021-05-30 00:35:37.381544] [0x00007f7039556700] [debug] Prepare to send data message: service id: ssh1 stream id: 2 [2021-05-30 00:35:37.381569] [0x00007f7039556700] [trace] Sending messages over web socket for service id: ssh1 [2021-05-30 00:35:37.381581] [0x00007f7039556700] [trace] Current queue size: 0 [2021-05-30 00:35:37.381589] [0x00007f7039556700] [trace] Put data 29 bytes into the web_socket_outgoing_message_queue for service id: ssh1 [2021-05-30 00:35:37.381967] [0x00007f7039556700] [debug] Write buffer has enough space, continue tcp read loop for ssh1 [2021-05-30 00:35:37.382004] [0x00007f7039556700] [trace] Begin tcp socket read loop for service id : ssh1 [2021-05-30 00:35:37.382042] [0x00007f7039556700] [trace] Sent 29 bytes over websocket for service id: ssh1 [2021-05-30 00:35:37.382132] [0x00007f7039556700] [trace] Web socket write buffer drain for service id: ssh1 [2021-05-30 00:35:37.382144] [0x00007f7039556700] [trace] web_socket_outgoing_message_queue is empty, no more messages to send. [2021-05-30 00:35:37.382363] [0x00007f7039556700] [debug] Starting web socket read loop continue reading... [2021-05-30 00:35:37.382453] [0x00007f7039556700] [trace] write done service id ssh1 [2021-05-30 00:35:37.382476] [0x00007f7039556700] [trace] Wrote 15 bytes to tcp socket [2021-05-30 00:35:37.382506] [0x00007f7039556700] [trace] TCP write buffer drain complete [2021-05-30 00:35:37.382524] [0x00007f7039556700] [trace] Done writing for: ssh1 [2021-05-30 00:35:37.382539] [0x00007f7039556700] [trace] Reading from tcp socket for service id ssh1 [2021-05-30 00:35:37.382549] [0x00007f7039556700] [trace] TCP socket read 15 bytes [2021-05-30 00:35:37.382558] [0x00007f7039556700] [trace] Begin tcp socket read loop for service id : ssh1 [2021-05-30 00:35:37.382567] [0x00007f7039556700] [trace] Web socket write buffer drain for service id: ssh1 [2021-05-30 00:35:37.382577] [0x00007f7039556700] [debug] Prepare to send data message: service id: ssh1 stream id: 2 [2021-05-30 00:35:37.382656] [0x00007f7039556700] [trace] Sending messages over web socket for service id: ssh1 [2021-05-30 00:35:37.382670] [0x00007f7039556700] [trace] Current queue size: 0 [2021-05-30 00:35:37.382679] [0x00007f7039556700] [trace] Put data 29 bytes into the web_socket_outgoing_message_queue for service id: ssh1 [2021-05-30 00:35:37.383176] [0x00007f7039556700] [debug] Write buffer has enough space, continue tcp read loop for ssh1 [2021-05-30 00:35:37.383228] [0x00007f7039556700] [trace] Begin tcp socket read loop for service id : ssh1 [2021-05-30 00:35:37.383246] [0x00007f7039556700] [trace] Sent 29 bytes over websocket for service id: ssh1 [2021-05-30 00:35:37.383256] [0x00007f7039556700] [trace] Web socket write buffer drain for service id: ssh1 [2021-05-30 00:35:37.383265] [0x00007f7039556700] [trace] web_socket_outgoing_message_queue is empty, no more messages to send. [2021-05-30 00:35:37.383461] [0x00007f7039556700] [debug] Starting web socket read loop continue reading... [2021-05-30 00:35:37.383517] [0x00007f7039556700] [trace] write done service id ssh1 [2021-05-30 00:35:37.383912] [0x00007f7039556700] [trace] Wrote 15 bytes to tcp socket [2021-05-30 00:35:37.383940] [0x00007f7039556700] [trace] TCP write buffer drain complete [2021-05-30 00:35:37.383958] [0x00007f7039556700] [trace] Done writing for: ssh1 [2021-05-30 00:35:37.383982] [0x00007f7039556700] [trace] Reading from tcp socket for service id ssh1 [2021-05-30 00:35:37.383997] [0x00007f7039556700] [trace] TCP socket read 15 bytes [2021-05-30 00:35:37.384012] [0x00007f7039556700] [trace] Begin tcp socket read loop for service id : ssh1 [2021-05-30 00:35:37.384103] [0x00007f7039556700] [trace] Web socket write buffer drain for service id: ssh1 [2021-05-30 00:35:37.384340] [0x00007f7039556700] [debug] Prepare to send data message: service id: ssh1 stream id: 2 [2021-05-30 00:35:37.384365] [0x00007f7039556700] [trace] Sending messages over web socket for service id: ssh1 [2021-05-30 00:35:37.384375] [0x00007f7039556700] [trace] Current queue size: 0 [2021-05-30 00:35:37.384383] [0x00007f7039556700] [trace] Put data 29 bytes into the web_socket_outgoing_message_queue for service id: ssh1 [2021-05-30 00:35:37.384635] [0x00007f7039556700] [debug] Write buffer has enough space, continue tcp read loop for ssh1 [2021-05-30 00:35:37.384688] [0x00007f7039556700] [trace] Begin tcp socket read loop for service id : ssh1 [2021-05-30 00:35:37.384711] [0x00007f7039556700] [trace] Sent 29 bytes over websocket for service id: ssh1 [2021-05-30 00:35:37.384727] [0x00007f7039556700] [trace] Web socket write buffer drain for service id: ssh1 [2021-05-30 00:35:37.384741] [0x00007f7039556700] [trace] web_socket_outgoing_message_queue is empty, no more messages to send. [2021-05-30 00:35:37.385001] [0x00007f7039556700] [debug] Starting web socket read loop continue reading... [2021-05-30 00:35:37.385021] [0x00007f7039556700] [trace] write done service id ssh1 [2021-05-30 00:35:37.385031] [0x00007f7039556700] [trace] Wrote 15 bytes to tcp socket [2021-05-30 00:35:37.385042] [0x00007f7039556700] [trace] TCP write buffer drain complete [2021-05-30 00:35:37.385050] [0x00007f7039556700] [trace] Done writing for: ssh1 [2021-05-30 00:35:37.385061] [0x00007f7039556700] [trace] Reading from tcp socket for service id ssh1 [2021-05-30 00:35:37.385073] [0x00007f7039556700] [trace] TCP socket read 15 bytes [2021-05-30 00:35:37.385317] [0x00007f7039556700] [trace] Begin tcp socket read loop for service id : ssh1 [2021-05-30 00:35:37.385334] [0x00007f7039556700] [trace] Web socket write buffer drain for service id: ssh1 [2021-05-30 00:35:37.385344] [0x00007f7039556700] [debug] Prepare to send data message: service id: ssh1 stream id: 2 [2021-05-30 00:35:37.385369] [0x00007f7039556700] [trace] Sending messages over web socket for service id: ssh1 [2021-05-30 00:35:37.385381] [0x00007f7039556700] [trace] Current queue size: 0 [2021-05-30 00:35:37.385395] [0x00007f7039556700] [trace] Put data 29 bytes into the web_socket_outgoing_message_queue for service id: ssh1 [2021-05-30 00:35:37.385458] [0x00007f7039556700] [debug] Write buffer has enough space, continue tcp read loop for ssh1 [2021-05-30 00:35:37.385660] [0x00007f7039556700] [trace] Begin tcp socket read loop for service id : ssh1 [2021-05-30 00:35:37.385682] [0x00007f7039556700] [trace] Sent 29 bytes over websocket for service id: ssh1 [2021-05-30 00:35:37.385699] [0x00007f7039556700] [trace] Web socket write buffer drain for service id: ssh1 [2021-05-30 00:35:37.385712] [0x00007f7039556700] [trace] web_socket_outgoing_message_queue is empty, no more messages to send. [2021-05-30 00:35:37.385779] [0x00007f7039556700] [debug] Starting web socket read loop continue reading... [2021-05-30 00:35:37.385995] [0x00007f7039556700] [trace] write done service id ssh1 [2021-05-30 00:35:37.386008] [0x00007f7039556700] [trace] Wrote 15 bytes to tcp socket [2021-05-30 00:35:37.386021] [0x00007f7039556700] [trace] TCP write buffer drain complete [2021-05-30 00:35:37.386029] [0x00007f7039556700] [trace] Done writing for: ssh1 [2021-05-30 00:35:37.428012] [0x00007f7039556700] [info] Web socket close received. Code: 1011; Reason: test_closure [2021-05-30 00:35:37.428090] [0x00007f7039556700] [debug] Handling explicit reset by closing TCP for service id: ssh1 [2021-05-30 00:35:37.428106] [0x00007f7039556700] [trace] Web socket write buffer drain for service id: ssh1 [2021-05-30 00:35:37.428117] [0x00007f7039556700] [trace] Post-reset web socket drain complete [2021-05-30 00:35:37.428128] [0x00007f7039556700] [trace] Post-reset TCP drain complete. Closing TCP socket for service id ssh1 [2021-05-30 00:35:37.428148] [0x00007f7039556700] [info] Disconnected from: 127.0.0.1:34386 [2021-05-30 00:35:37.428273] [0x00007f7039556700] [trace] Both socket drains complete. Setting up TCP socket again Destination app listening on address: 127.0.0.1:45989 Test server listening on address: 127.0.0.1 and port: 45209 [2021-05-30 00:35:37.487824] [0x00007f7039d57700] [info] Starting proxy in destination mode [2021-05-30 00:35:37.487966] [0x00007f7039d57700] [trace] Setting up web socket... [2021-05-30 00:35:37.488035] [0x00007f7039d57700] [info] Attempting to establish web socket connection with endpoint wss://127.0.0.1:45209 [2021-05-30 00:35:37.488071] [0x00007f7039d57700] [trace] Resolving proxy host: 127.0.0.1 [2021-05-30 00:35:37.488345] [0x00007f7039d57700] [debug] Resolved proxy server IP: 127.0.0.1 [2021-05-30 00:35:37.488586] [0x00007f7039d57700] [debug] Connected successfully with proxy server [2021-05-30 00:35:37.488640] [0x00007f7039d57700] [trace] Performing websocket handshake with proxy server [2021-05-30 00:35:37.488676] [0x00007f7039d57700] [trace] Web socket ugprade request(*not entirely final): GET /tunnel?local-proxy-mode=destination HTTP/1.1 Host: 127.0.0.1 Upgrade: websocket Connection: upgrade Sec-WebSocket-Key: 5goXCjldaRnT+i3PN/hGXw== Sec-WebSocket-Version: 13 Sec-WebSocket-Protocol: aws.iot.securetunneling-2.0 access-token: ACCESS_TOKEN_REMOVED User-Agent: localproxy linux 64-bit/boost-1.69.0/openssl-1.1.1/protobuf-3.6.1

[2021-05-30 00:35:37.489173] [0x00007f7039d57700] [trace] Web socket upgrade response: HTTP/1.1 101 Switching Protocols Upgrade: websocket Connection: upgrade Sec-WebSocket-Accept: lE9/4oVVVUlZp/Rncjyn63ySflI= channel-id: 00000000-0000-0000-0000-000000000000 Sec-WebSocket-Protocol: aws.iot.securetunneling-2.0 Server: Boost.Beast/189

[2021-05-30 00:35:37.489259] [0x00007f7039d57700] [info] Web socket session ID: 00000000-0000-0000-0000-000000000000 [2021-05-30 00:35:37.489299] [0x00007f7039d57700] [debug] Web socket subprotocol selected: aws.iot.securetunneling-2.0 [2021-05-30 00:35:37.489353] [0x00007f7039d57700] [info] Successfully established websocket connection with proxy server: wss://127.0.0.1:45209 [2021-05-30 00:35:37.489366] [0x00007f7039d57700] [debug] Seting up web socket pings for every 5000 milliseconds [2021-05-30 00:35:37.489398] [0x00007f7039d57700] [trace] Waiting for service ids... [2021-05-30 00:35:37.489413] [0x00007f7039d57700] [trace] async_web_socket_read_loop_for_service_ids [2021-05-30 00:35:37.489517] [0x00007f7039d57700] [debug] Scheduled next read: [2021-05-30 00:35:37.489538] [0x00007f7039d57700] [trace] Pong reply latency: 0 ms [2021-05-30 00:35:37.539495] [0x00007f7039d57700] [debug] No serviceId_to_tcp_client mapping for service_id: [2021-05-30 00:35:37.539567] [0x00007f7039d57700] [debug] Extracting service Ids from control message 5 [2021-05-30 00:35:37.539577] [0x00007f7039d57700] [trace] Service id received: [2021-05-30 00:35:37.539581] [0x00007f7039d57700] [trace] ssh1 [2021-05-30 00:35:37.539586] [0x00007f7039d57700] [trace] Validating service ids configuration [2021-05-30 00:35:37.539592] [0x00007f7039d57700] [trace] Setting up tcp sockets [2021-05-30 00:35:37.539596] [0x00007f7039d57700] [trace] Clearing all ws data buffers [2021-05-30 00:35:37.539600] [0x00007f7039d57700] [trace] Finished Clearing all ws data buffers [2021-05-30 00:35:37.539604] [0x00007f7039d57700] [trace] Initializing tcp clients ... [2021-05-30 00:35:37.539622] [0x00007f7039d57700] [trace] Setting up tcp socket for service id: ssh1 [2021-05-30 00:35:37.539628] [0x00007f7039d57700] [trace] Waiting for stream start... [2021-05-30 00:35:37.539636] [0x00007f7039d57700] [debug] Starting web socket read loop continue reading... [2021-05-30 00:35:37.539648] [0x00007f7039d57700] [debug] Starting web socket read loop while web socket is already reading. Ignoring... [2021-05-30 00:35:37.591621] [0x00007f7039d57700] [trace] Wait for control message stream start, receive message type:2 [2021-05-30 00:35:37.591748] [0x00007f7039d57700] [debug] Received service id :ssh1 ,stream id: 1 [2021-05-30 00:35:37.591768] [0x00007f7039d57700] [trace] Setup destination tcp socket for service idssh1 [2021-05-30 00:35:37.591800] [0x00007f7039d57700] [info] Attempting to establish tcp socket connection to: 127.0.0.1:45989 [2021-05-30 00:35:37.591809] [0x00007f7039d57700] [debug] Resolving local address host: 127.0.0.1 [2021-05-30 00:35:37.591894] [0x00007f7039d57700] [debug] Web socket read loop stopped [2021-05-30 00:35:37.592284] [0x00007f7039d57700] [debug] Resolved bind IP: 127.0.0.1 [2021-05-30 00:35:37.592922] [0x00007f7039d57700] [trace] Resolve destination to connect for service id: ssh1 [2021-05-30 00:35:37.593068] [0x00007f7039d57700] [debug] Resolved destination host to IP: 127.0.0.1 , connecting ... [2021-05-30 00:35:37.593667] [0x00007f7039d57700] [info] Connected to 127.0.0.1, port: 45989 [2021-05-30 00:35:37.593797] [0x00007f7039d57700] [trace] Setting up bi-directional data transfer for service id: ssh1 [2021-05-30 00:35:37.593926] [0x00007f7039d57700] [trace] Clearing tcp connection buffers [2021-05-30 00:35:37.594074] [0x00007f7039d57700] [debug] Starting web socket read loop continue reading... [2021-05-30 00:35:37.594206] [0x00007f7039d57700] [trace] Begin tcp socket read loop for service id : ssh1 [2021-05-30 00:35:37.645557] [0x00007f7039d57700] [trace] Reading from tcp socket for service id ssh1 [2021-05-30 00:35:37.645670] [0x00007f7039d57700] [trace] TCP socket read 15 bytes [2021-05-30 00:35:37.645688] [0x00007f7039d57700] [trace] Begin tcp socket read loop for service id : ssh1 [2021-05-30 00:35:37.645705] [0x00007f7039d57700] [trace] Web socket write buffer drain for service id: ssh1 [2021-05-30 00:35:37.645717] [0x00007f7039d57700] [debug] Prepare to send data message: service id: ssh1 stream id: 1 [2021-05-30 00:35:37.645765] [0x00007f7039d57700] [trace] Sending messages over web socket for service id: ssh1 [2021-05-30 00:35:37.645774] [0x00007f7039d57700] [trace] Current queue size: 0 [2021-05-30 00:35:37.645784] [0x00007f7039d57700] [trace] Put data 29 bytes into the web_socket_outgoing_message_queue for service id: ssh1 [2021-05-30 00:35:37.645930] [0x00007f7039d57700] [debug] Write buffer has enough space, continue tcp read loop for ssh1 [2021-05-30 00:35:37.646016] [0x00007f7039d57700] [trace] Begin tcp socket read loop for service id : ssh1 [2021-05-30 00:35:37.646044] [0x00007f7039d57700] [trace] Sent 29 bytes over websocket for service id: ssh1 [2021-05-30 00:35:37.646055] [0x00007f7039d57700] [trace] Web socket write buffer drain for service id: ssh1 [2021-05-30 00:35:37.646065] [0x00007f7039d57700] [trace] web_socket_outgoing_message_queue is empty, no more messages to send. [2021-05-30 00:35:37.646631] [0x00007f7039d57700] [debug] Starting web socket read loop continue reading... [2021-05-30 00:35:37.646757] [0x00007f7039d57700] [trace] write done service id ssh1 [2021-05-30 00:35:37.646769] [0x00007f7039d57700] [trace] Wrote 15 bytes to tcp socket [2021-05-30 00:35:37.646784] [0x00007f7039d57700] [trace] TCP write buffer drain complete [2021-05-30 00:35:37.646790] [0x00007f7039d57700] [trace] Done writing for: ssh1 [2021-05-30 00:35:37.646805] [0x00007f7039d57700] [trace] Reading from tcp socket for service id ssh1 [2021-05-30 00:35:37.646812] [0x00007f7039d57700] [trace] TCP socket read 15 bytes [2021-05-30 00:35:37.646819] [0x00007f7039d57700] [trace] Begin tcp socket read loop for service id : ssh1 [2021-05-30 00:35:37.646827] [0x00007f7039d57700] [trace] Web socket write buffer drain for service id: ssh1 [2021-05-30 00:35:37.646835] [0x00007f7039d57700] [debug] Prepare to send data message: service id: ssh1 stream id: 1 [2021-05-30 00:35:37.646899] [0x00007f7039d57700] [trace] Sending messages over web socket for service id: ssh1 [2021-05-30 00:35:37.646914] [0x00007f7039d57700] [trace] Current queue size: 0 [2021-05-30 00:35:37.646981] [0x00007f7039d57700] [trace] Put data 29 bytes into the web_socket_outgoing_message_queue for service id: ssh1 [2021-05-30 00:35:37.647129] [0x00007f7039d57700] [debug] Write buffer has enough space, continue tcp read loop for ssh1 [2021-05-30 00:35:37.647219] [0x00007f7039d57700] [trace] Begin tcp socket read loop for service id : ssh1 [2021-05-30 00:35:37.647248] [0x00007f7039d57700] [trace] Sent 29 bytes over websocket for service id: ssh1 [2021-05-30 00:35:37.647257] [0x00007f7039d57700] [trace] Web socket write buffer drain for service id: ssh1 [2021-05-30 00:35:37.647265] [0x00007f7039d57700] [trace] web_socket_outgoing_message_queue is empty, no more messages to send. [2021-05-30 00:35:37.647779] [0x00007f7039d57700] [debug] Starting web socket read loop continue reading... [2021-05-30 00:35:37.647818] [0x00007f7039d57700] [trace] write done service id ssh1 [2021-05-30 00:35:37.647837] [0x00007f7039d57700] [trace] Wrote 15 bytes to tcp socket [2021-05-30 00:35:37.647856] [0x00007f7039d57700] [trace] TCP write buffer drain complete [2021-05-30 00:35:37.647864] [0x00007f7039d57700] [trace] Done writing for: ssh1 [2021-05-30 00:35:37.648072] [0x00007f7039d57700] [trace] Reading from tcp socket for service id ssh1 [2021-05-30 00:35:37.648145] [0x00007f7039d57700] [trace] TCP socket read 15 bytes [2021-05-30 00:35:37.648161] [0x00007f7039d57700] [trace] Begin tcp socket read loop for service id : ssh1 [2021-05-30 00:35:37.648175] [0x00007f7039d57700] [trace] Web socket write buffer drain for service id: ssh1 [2021-05-30 00:35:37.648184] [0x00007f7039d57700] [debug] Prepare to send data message: service id: ssh1 stream id: 1 [2021-05-30 00:35:37.648222] [0x00007f7039d57700] [trace] Sending messages over web socket for service id: ssh1 [2021-05-30 00:35:37.648231] [0x00007f7039d57700] [trace] Current queue size: 0 [2021-05-30 00:35:37.648236] [0x00007f7039d57700] [trace] Put data 29 bytes into the web_socket_outgoing_message_queue for service id: ssh1 [2021-05-30 00:35:37.648371] [0x00007f7039d57700] [debug] Write buffer has enough space, continue tcp read loop for ssh1 [2021-05-30 00:35:37.648442] [0x00007f7039d57700] [trace] Begin tcp socket read loop for service id : ssh1 [2021-05-30 00:35:37.648583] [0x00007f7039d57700] [trace] Sent 29 bytes over websocket for service id: ssh1 [2021-05-30 00:35:37.648600] [0x00007f7039d57700] [trace] Web socket write buffer drain for service id: ssh1 [2021-05-30 00:35:37.648607] [0x00007f7039d57700] [trace] web_socket_outgoing_message_queue is empty, no more messages to send. [2021-05-30 00:35:37.649172] [0x00007f7039d57700] [debug] Starting web socket read loop continue reading... [2021-05-30 00:35:37.649241] [0x00007f7039d57700] [trace] write done service id ssh1 [2021-05-30 00:35:37.649351] [0x00007f7039d57700] [trace] Wrote 15 bytes to tcp socket [2021-05-30 00:35:37.649383] [0x00007f7039d57700] [trace] TCP write buffer drain complete [2021-05-30 00:35:37.650211] [0x00007f7039d57700] [trace] Done writing for: ssh1 [2021-05-30 00:35:37.650428] [0x00007f7039d57700] [trace] Reading from tcp socket for service id ssh1 [2021-05-30 00:35:37.650670] [0x00007f7039d57700] [trace] TCP socket read 15 bytes [2021-05-30 00:35:37.650767] [0x00007f7039d57700] [trace] Begin tcp socket read loop for service id : ssh1 [2021-05-30 00:35:37.650811] [0x00007f7039d57700] [trace] Web socket write buffer drain for service id: ssh1 [2021-05-30 00:35:37.650840] [0x00007f7039d57700] [debug] Prepare to send data message: service id: ssh1 stream id: 1 [2021-05-30 00:35:37.650934] [0x00007f7039d57700] [trace] Sending messages over web socket for service id: ssh1 [2021-05-30 00:35:37.651000] [0x00007f7039d57700] [trace] Current queue size: 0 [2021-05-30 00:35:37.651016] [0x00007f7039d57700] [trace] Put data 29 bytes into the web_socket_outgoing_message_queue for service id: ssh1 [2021-05-30 00:35:37.651250] [0x00007f7039d57700] [debug] Write buffer has enough space, continue tcp read loop for ssh1 [2021-05-30 00:35:37.651313] [0x00007f7039d57700] [trace] Begin tcp socket read loop for service id : ssh1 [2021-05-30 00:35:37.651333] [0x00007f7039d57700] [trace] Sent 29 bytes over websocket for service id: ssh1 [2021-05-30 00:35:37.651340] [0x00007f7039d57700] [trace] Web socket write buffer drain for service id: ssh1 [2021-05-30 00:35:37.651345] [0x00007f7039d57700] [trace] web_socket_outgoing_message_queue is empty, no more messages to send. [2021-05-30 00:35:37.651731] [0x00007f7039d57700] [debug] Starting web socket read loop continue reading... [2021-05-30 00:35:37.651814] [0x00007f7039d57700] [trace] write done service id ssh1 [2021-05-30 00:35:37.651823] [0x00007f7039d57700] [trace] Wrote 15 bytes to tcp socket [2021-05-30 00:35:37.651834] [0x00007f7039d57700] [trace] TCP write buffer drain complete [2021-05-30 00:35:37.651884] [0x00007f7039d57700] [trace] Done writing for: ssh1 [2021-05-30 00:35:37.651906] [0x00007f7039d57700] [trace] Reading from tcp socket for service id ssh1 [2021-05-30 00:35:37.651913] [0x00007f7039d57700] [trace] TCP socket read 15 bytes [2021-05-30 00:35:37.651982] [0x00007f7039d57700] [trace] Begin tcp socket read loop for service id : ssh1 [2021-05-30 00:35:37.652033] [0x00007f7039d57700] [trace] Web socket write buffer drain for service id: ssh1 [2021-05-30 00:35:37.652045] [0x00007f7039d57700] [debug] Prepare to send data message: service id: ssh1 stream id: 1 [2021-05-30 00:35:37.652152] [0x00007f7039d57700] [trace] Sending messages over web socket for service id: ssh1 [2021-05-30 00:35:37.652167] [0x00007f7039d57700] [trace] Current queue size: 0 [2021-05-30 00:35:37.652175] [0x00007f7039d57700] [trace] Put data 29 bytes into the web_socket_outgoing_message_queue for service id: ssh1 [2021-05-30 00:35:37.652214] [0x00007f7039d57700] [debug] Write buffer has enough space, continue tcp read loop for ssh1 [2021-05-30 00:35:37.652226] [0x00007f7039d57700] [trace] Begin tcp socket read loop for service id : ssh1 [2021-05-30 00:35:37.652237] [0x00007f7039d57700] [trace] Sent 29 bytes over websocket for service id: ssh1 [2021-05-30 00:35:37.652290] [0x00007f7039d57700] [trace] Web socket write buffer drain for service id: ssh1 [2021-05-30 00:35:37.652302] [0x00007f7039d57700] [trace] web_socket_outgoing_message_queue is empty, no more messages to send. [2021-05-30 00:35:37.652904] [0x00007f7039d57700] [debug] Starting web socket read loop continue reading... [2021-05-30 00:35:37.652967] [0x00007f7039d57700] [trace] write done service id ssh1 [2021-05-30 00:35:37.652980] [0x00007f7039d57700] [trace] Wrote 15 bytes to tcp socket [2021-05-30 00:35:37.652993] [0x00007f7039d57700] [trace] TCP write buffer drain complete [2021-05-30 00:35:37.653000] [0x00007f7039d57700] [trace] Done writing for: ssh1 [2021-05-30 00:35:37.653013] [0x00007f7039d57700] [trace] Handling control message... [2021-05-30 00:35:37.653033] [0x00007f7039d57700] [debug] Starting web socket read loop continue reading... [2021-05-30 00:35:37.653053] [0x00007f7039d57700] [trace] Reading from tcp socket for service id ssh1 [2021-05-30 00:35:37.653092] [0x00007f7039d57700] [debug] Handling tcp socket error for service id: ssh1 . error message:End of file [2021-05-30 00:35:37.653112] [0x00007f7039d57700] [info] Disconnected from: 127.0.0.1:45989 [2021-05-30 00:35:37.653283] [0x00007f7039d57700] [trace] Web socket write buffer drain for service id: ssh1 [2021-05-30 00:35:37.653363] [0x00007f7039d57700] [trace] Reset stream for service id: ssh1 [2021-05-30 00:35:37.653424] [0x00007f7039d57700] [trace] Sending messages over web socket for service id: ssh1 [2021-05-30 00:35:37.653510] [0x00007f7039d57700] [trace] Current queue size: 0 [2021-05-30 00:35:37.653521] [0x00007f7039d57700] [trace] Put data 12 bytes into the web_socket_outgoing_message_queue for service id: ssh1 [2021-05-30 00:35:37.653590] [0x00007f7039d57700] [trace] Sent 12 bytes over websocket for service id: ssh1 [2021-05-30 00:35:37.653607] [0x00007f7039d57700] [trace] Setting up tcp socket for service id: ssh1 [2021-05-30 00:35:37.653620] [0x00007f7039d57700] [trace] Waiting for stream start... [2021-05-30 00:35:37.653629] [0x00007f7039d57700] [debug] Starting web socket read loop while web socket is already reading. Ignoring... [2021-05-30 00:35:37.653634] [0x00007f7039d57700] [trace] web_socket_outgoing_message_queue is empty, no more messages to send.


localproxytest is a Catch v2.13.2 host application.
Run with -? for options

-------------------------------------------------------------------------------
Test destination mode
-------------------------------------------------------------------------------
/home/dependencies/aws-iot-securetunneling-localproxy/test/AdapterTests.cpp:284
...............................................................................

/home/dependencies/aws-iot-securetunneling-localproxy/test/AdapterTests.cpp:386: FAILED:
  REQUIRE( accepted )
with expansion:
  false

terminate called without an active exception
/home/dependencies/aws-iot-securetunneling-localproxy/test/AdapterTests.cpp:386: FAILED:
  {Unknown expression after the reported line}
due to a fatal error condition:
  SIGABRT - Abort (abnormal termination) signal

===============================================================================
test cases:  3 |  2 passed | 1 failed
assertions: 65 | 63 passed | 2 failed

Aborted
```
3.the destination device is connected fine. it is a raspberry pi on greengrass using the secure tunnel component. i can connect to it just fine over a secure tunnel built on a different pi.

MiaoZhangAWS commented 3 years ago

@Lard4 Thanks for providing more information. If localproxytest has failed test case, it means you will see problem when running localproxy. This should be a client side issue within localproxy, and NOT the cloud side(ex, cloud side have problem to handle the request from localproxy).

Since this is your first time to set it up, it could also be a configuration issue with the docker on your mac. I am trying to reproduce this issue. If both @kareali and me can not reproduce, it's most likely related to your setup. Will keep you posted regarding the result.

MiaoZhangAWS commented 3 years ago

@Lard4 , I tried it on my Mac and cannot reproduce this issue.

Some information for my Mac:

OS: MacOS Mojave
Version: 10.14.6 
Docker Desktop version：3.3.3
Docker Engine version: 20.10.6
Architecture: x86_64

Commit: latest commit from this repo Observation 1: localproxytest behavior I observed localproxytest has intermittent failed test case when running in destination mode (when running command ./localproxytest [destination]). It failed at the same step as you experienced. This could be docker container as problem receiving TCP connections on certain ports. localproxytest constantly succeed when running in source mode (when running command ./localproxytest [source]). In the issue you reported, you are running localproxy in source mode, so the failed test cases in destination mode should be unrelated. You can double check if running /localproxytest [source] has any failures for you.

Observation 2: localproxy behavior No issue is observed when running localproxy in source mode.

Logs:

root@9327b88a1253:/home/aws-iot-securetunneling-localproxy# export AWSIOT_TUNNEL_ACCESS_TOKEN=<TOKEN>
root@9327b88a1253:/home/aws-iot-securetunneling-localproxy# ./localproxy -r  us-west-2 -s 5555 -c ./certs  -v 6
[2021-06-03T19:05:19.300103]{233}[debug]   v2 local proxy starts with v1 local proxy format
[2021-06-03T19:05:19.300211]{233}[debug]   /home/aws-iot-securetunneling-localproxy/config does not exist!
[2021-06-03T19:05:19.300309]{233}[info]    Starting proxy in source mode
[2021-06-03T19:05:19.302728]{233}[trace]   Setting up web socket...
[2021-06-03T19:05:19.303074]{233}[info]    Attempting to establish web socket connection with endpoint wss://data.tunneling.iot.us-west-2.amazonaws.com:443
[2021-06-03T19:05:19.303137]{233}[trace]   Resolving proxy host: data.tunneling.iot.us-west-2.amazonaws.com
[2021-06-03T19:05:19.382661]{233}[debug]   Resolved proxy server IP: 35.164.173.102
[2021-06-03T19:05:19.410407]{233}[debug]   Connected successfully with proxy server
[2021-06-03T19:05:19.410597]{233}[trace]   Performing SSL handshake with proxy server
[2021-06-03T19:05:19.463853]{233}[debug]   Successfully completed SSL handshake with proxy server
[2021-06-03T19:05:19.463966]{233}[trace]   Performing websocket handshake with proxy server
[2021-06-03T19:05:19.464207]{233}[trace]   Web socket ugprade request(*not entirely final):
GET /tunnel?local-proxy-mode=source HTTP/1.1
Host: data.tunneling.iot.us-west-2.amazonaws.com
Upgrade: websocket
Connection: upgrade
Sec-WebSocket-Key: NoqXg7iUTaZ/N0CWaBabpg==
Sec-WebSocket-Version: 13
Sec-WebSocket-Protocol: aws.iot.securetunneling-2.0
access-token: ***ACCESS_TOKEN_REMOVED***
User-Agent: localproxy linux 64-bit/boost-1.69.0/openssl-1.1.1/protobuf-3.6.1

[2021-06-03T19:05:19.534229]{233}[trace]   Web socket upgrade response:
HTTP/1.1 101 Switching Protocols
Date: Thu, 03 Jun 2021 19:05:19 GMT
Content-Length: 0
Connection: upgrade
channel-id: 02d096fffe0ed543-0000135e-0003780f-0e5628e4fca0bf66-9f769229
upgrade: websocket
sec-websocket-accept: pLfxO+FYAYlfS+Yiq1RpSh6Xc68=
sec-websocket-protocol: aws.iot.securetunneling-2.0

[2021-06-03T19:05:19.534359]{233}[info]    Web socket session ID: 02d096fffe0ed543-0000135e-0003780f-0e5628e4fca0bf66-9f769229
[2021-06-03T19:05:19.534383]{233}[debug]   Web socket subprotocol selected: aws.iot.securetunneling-2.0
[2021-06-03T19:05:19.534397]{233}[info]    Successfully established websocket connection with proxy server: wss://data.tunneling.iot.us-west-2.amazonaws.com:443
[2021-06-03T19:05:19.534424]{233}[debug]   Seting up web socket pings for every 5000 milliseconds
[2021-06-03T19:05:19.534593]{233}[trace]   Waiting for service ids...
[2021-06-03T19:05:19.534780]{233}[trace]   async_web_socket_read_loop_for_service_ids
[2021-06-03T19:05:19.534813]{233}[debug]   Scheduled next read:
[2021-06-03T19:05:19.535060]{233}[debug]   No serviceId_to_tcp_server mapping for service_id:
[2021-06-03T19:05:19.535265]{233}[debug]   Extracting service Ids from control message 5
[2021-06-03T19:05:19.535302]{233}[trace]   Service id received:
[2021-06-03T19:05:19.535391]{233}[trace]   Validating service ids configuration
[2021-06-03T19:05:19.535424]{233}[trace]   Setting up tcp sockets
[2021-06-03T19:05:19.535491]{233}[trace]   Clearing all ws data buffers
[2021-06-03T19:05:19.535514]{233}[trace]   Finished Clearing all ws data buffers
[2021-06-03T19:05:19.535574]{233}[trace]   Initializing tcp servers ...
[2021-06-03T19:05:19.535608]{233}[trace]   Setting up source tcp sockets
[2021-06-03T19:05:19.535669]{233}[trace]   Setting up tcp socket for service id:
[2021-06-03T19:05:19.535806]{233}[debug]   Resolving bind address host: localhost
[2021-06-03T19:05:19.535891]{233}[debug]   Port to connect 5555
[2021-06-03T19:05:19.535984]{233}[debug]   Starting web socket read loop continue reading...
[2021-06-03T19:05:19.536743]{233}[debug]   Resolved bind IP: 127.0.0.1
[2021-06-03T19:05:19.536900]{233}[info]    Listening for new connection on port 5555
[2021-06-03T19:05:24.519944]{233}[trace]   Sent ping data: 1622747124519

Suggestion to your issue: Since both kareali @ and me can not reproduce this issue, it's most likely related to your setup. Something you can check on your setup:

Check if you see any test case failures when running /localproxytest [source].
Check the port you are using is available. Try to change to other ports and see if it will make a difference.
Check in ./certs directory if there is a valid cert present.

kareali commented 3 years ago

Closed due to inability to reproduce the issue

mladen-simplifa commented 3 years ago

Anyone still facing this issue, I could solve it by JUST updating docker Desktop version to 3.4.0.

OS: MacOS Version: Big Sur 11.1 Architecture: x86_64 Docker engine: 20.10.7

zhex900 commented 6 months ago

Anyone got it working? I have the same problem

[2024-04-04 13:06:02.699964] (0x0000ffff8c840fc0) [info] Attempting to establish web socket connection with endpoint wss://data.tunneling.iot.us-east-1.amazonaws.com:443
[2024-04-04 13:06:02.699983] (0x0000ffff8c840fc0) [trace] Resolving proxy server host: data.tunneling.iot.us-east-1.amazonaws.com
[2024-04-04 13:06:02.713055] (0x0000ffff8c840fc0) [debug] Resolved proxy server IP: 34.205.235.63
[2024-04-04 13:06:02.713137] (0x0000ffff8c840fc0) [trace] Calling lowest_layer with type: websocket_stream_single_ssl_type
[2024-04-04 13:06:02.741645] (0x0000ffff8c840fc0) [debug] Connected successfully with proxy server
[2024-04-04 13:06:02.741725] (0x0000ffff8c840fc0) [trace] Calling lowest_layer with type: websocket_stream_single_ssl_type
[2024-04-04 13:06:02.741737] (0x0000ffff8c840fc0) [trace] Calling lowest_layer with type: websocket_stream_single_ssl_type
[2024-04-04 13:06:02.741745] (0x0000ffff8c840fc0) [trace] Performing SSL handshake with proxy server
[2024-04-04 13:06:02.741752] (0x0000ffff8c840fc0) [trace] Calling set_verify_mode with type: single_ssl_stream
[2024-04-04 13:06:02.741759] (0x0000ffff8c840fc0) [trace] Calling set_verify_callback with type: single_ssl_stream
[2024-04-04 13:06:02.741775] (0x0000ffff8c840fc0) [trace] Calling next_layer().async_handshake with type: websocket_stream_single_ssl_type
[2024-04-04 13:06:02.741797] (0x0000ffff8c840fc0) [trace] SSL next_layer() SNI is set : data.tunneling.iot.us-east-1.amazonaws.com
[2024-04-04 13:06:03.220246] (0x0000ffff8c840fc0) [error] Could not perform SSL handshake with proxy server: unregistered scheme (STORE routines)
[2024-04-04 13:06:05.722934] (0x0000ffff8c840fc0) [trace] Calling is_open with type: websocket_stream_single_ssl_type
[2024-04-04 13:06:05.723034] (0x0000ffff8c840fc0) [trace] Calling lowest_layer with type: websocket_stream_single_ssl_type
[2024-04-04 13:06:05.723042] (0x0000ffff8c840fc0) [trace] Calling lowest_layer with type: websocket_stream_single_ssl_type
[2024-04-04 13:06:05.723827] (0x0000ffff8c840fc0) [trace] Calling control_callback with type: websocket_stream_single_ssl_type

njZhuMin commented 6 months ago

@zhex900 Same issue here with arm64 pre-built docker image. Downgrading image to older version which was published 1 year ago solves this problem temporarily. Ref: https://gallery.ecr.aws/aws-iot-securetunneling-localproxy/ubuntu-bin

RogerZhongAWS commented 4 months ago

@njZhuMin https://github.com/aws-samples/aws-iot-securetunneling-localproxy/issues/151 contains a similar issue, please check it out.

aws-samples / aws-iot-securetunneling-localproxy

Can't start localproxy in Docker #48