search

aws-samples / aws-iot-securetunneling-localproxy

AWS Iot Secure Tunneling local proxy reference C++ implementation
https://docs.aws.amazon.com/iot/latest/developerguide/what-is-secure-tunneling.html
Apache License 2.0
74 stars 71 forks source link

localproxytest fails intermittently? #24

Closed jamesrusso closed 4 years ago

jamesrusso commented 4 years ago 

After building the binaries using the supplied Dockerfile, the localproxytest will fail occasionally when running it inside the docker image. 

root@f61b375b563c:/home/dependencies/aws-iot-securetunneling-localproxy/build/bin# ./localproxytest 
Test server is listening on address: 127.0.0.1 and port: 35659
[2020-04-27 20:46:38.044775] [0x00007f9e047c1700] [info]    Starting proxy in source mode
[2020-04-27 20:46:38.046043] [0x00007f9e047c1700] [trace]   Setting up web socket...
[2020-04-27 20:46:38.046089] [0x00007f9e047c1700] [info]    Attempting to establish web socket connection with endpoint wss://127.0.0.1:35659
[2020-04-27 20:46:38.046095] [0x00007f9e047c1700] [trace]   Resolving proxy host: 127.0.0.1
[2020-04-27 20:46:38.046169] [0x00007f9e047c1700] [debug]   Resolved proxy server IP: 127.0.0.1
[2020-04-27 20:46:38.046227] [0x00007f9e047c1700] [debug]   Connected successfully with proxy server
[2020-04-27 20:46:38.046242] [0x00007f9e047c1700] [trace]   Performing websocket handshake with proxy server
[2020-04-27 20:46:38.046506] [0x00007f9e047c1700] [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: ZoAiNxFLaMZAH0ZklOlZdw==
Sec-WebSocket-Version: 13
Sec-WebSocket-Protocol: aws.iot.securetunneling-1.0
access-token: ***ACCESS_TOKEN_REMOVED***
User-Agent: localproxy linux 64-bit/boost-1.69.0/openssl-1.1.1/protobuf-3.6.1

[2020-04-27 20:46:38.046683] [0x00007f9e047c1700] [trace]   Web socket upgrade response:
HTTP/1.1 101 Switching Protocols
Upgrade: websocket
Connection: upgrade
Sec-WebSocket-Accept: akkjzLum/ZhhTRXbKvhKQ04WDFw=
channel-id: 00000000-0000-0000-0000-000000000000
Sec-WebSocket-Protocol: aws.iot.securetunneling-1.0
Server: Boost.Beast/189

[2020-04-27 20:46:38.046699] [0x00007f9e047c1700] [info]    Web socket session ID: 00000000-0000-0000-0000-000000000000
[2020-04-27 20:46:38.046705] [0x00007f9e047c1700] [debug]   Web socket subprotocol selected: aws.iot.securetunneling-1.0
[2020-04-27 20:46:38.046709] [0x00007f9e047c1700] [info]    Successfully established websocket connection with proxy server: wss://127.0.0.1:35659
[2020-04-27 20:46:38.046721] [0x00007f9e047c1700] [debug]   Seting up web socket pings for every 5000 milliseconds
[2020-04-27 20:46:38.046756] [0x00007f9e047c1700] [trace]   Setting up tcp socket...
[2020-04-27 20:46:38.046773] [0x00007f9e047c1700] [debug]   Resolving bind address host: 127.0.0.1
[2020-04-27 20:46:38.046829] [0x00007f9e047c1700] [debug]   Resolved bind IP: 127.0.0.1
[2020-04-27 20:46:38.046850] [0x00007f9e047c1700] [info]    Listening for new connection on port 47597
[2020-04-27 20:46:38.095290] [0x00007f9e047c1700] [info]    Accepted tcp connection on port 47597 from 127.0.0.1:38246
[2020-04-27 20:46:38.095326] [0x00007f9e047c1700] [debug]   Setting new stream ID to: 1
[2020-04-27 20:46:38.095404] [0x00007f9e047c1700] [trace]   Sent 6 bytes over websocket
[2020-04-27 20:46:38.095418] [0x00007f9e047c1700] [trace]   Setting up bi-directional data transfer with stream_id: 1
[2020-04-27 20:46:38.095426] [0x00007f9e047c1700] [trace]   Clearing all data buffers
[2020-04-27 20:46:38.095504] [0x00007f9e047c1700] [trace]   Pong reply latency: 49 ms
[2020-04-27 20:46:38.095549] [0x00007f9e047c1700] [trace]   Sent 23 bytes over websocket
[2020-04-27 20:46:38.095664] [0x00007f9e047c1700] [trace]   Wrote 15 bytes to tcp socket
[2020-04-27 20:46:38.095795] [0x00007f9e047c1700] [trace]   Sent 23 bytes over websocket
[2020-04-27 20:46:38.095949] [0x00007f9e047c1700] [trace]   Wrote 15 bytes to tcp socket
[2020-04-27 20:46:38.096209] [0x00007f9e047c1700] [trace]   Sent 23 bytes over websocket
[2020-04-27 20:46:38.096365] [0x00007f9e047c1700] [trace]   Wrote 15 bytes to tcp socket
[2020-04-27 20:46:38.096545] [0x00007f9e047c1700] [trace]   Sent 23 bytes over websocket
[2020-04-27 20:46:38.096700] [0x00007f9e047c1700] [trace]   Wrote 15 bytes to tcp socket
[2020-04-27 20:46:38.096870] [0x00007f9e047c1700] [trace]   Sent 23 bytes over websocket
[2020-04-27 20:46:38.096953] [0x00007f9e047c1700] [trace]   Wrote 15 bytes to tcp socket
[2020-04-27 20:46:38.097165] [0x00007f9e047c1700] [debug]   Handling tcp socket error: End of file
[2020-04-27 20:46:38.097187] [0x00007f9e047c1700] [info]    Disconnected from: 127.0.0.1:38246
[2020-04-27 20:46:38.097284] [0x00007f9e047c1700] [trace]   Sent 6 bytes over websocket
[2020-04-27 20:46:38.097295] [0x00007f9e047c1700] [trace]   Setting up tcp socket...
[2020-04-27 20:46:38.097373] [0x00007f9e047c1700] [debug]   Resolving bind address host: 127.0.0.1
[2020-04-27 20:46:38.097457] [0x00007f9e047c1700] [debug]   Resolved bind IP: 127.0.0.1
[2020-04-27 20:46:38.097582] [0x00007f9e047c1700] [info]    Listening for new connection on port 42565
[2020-04-27 20:46:38.147328] [0x00007f9e047c1700] [info]    Accepted tcp connection on port 42565 from 127.0.0.1:46048
[2020-04-27 20:46:38.147858] [0x00007f9e047c1700] [debug]   Setting new stream ID to: 2
[2020-04-27 20:46:38.148233] [0x00007f9e047c1700] [trace]   Sent 6 bytes over websocket
[2020-04-27 20:46:38.148624] [0x00007f9e047c1700] [trace]   Setting up bi-directional data transfer with stream_id: 2
[2020-04-27 20:46:38.149180] [0x00007f9e047c1700] [trace]   Clearing all data buffers
[2020-04-27 20:46:38.150022] [0x00007f9e047c1700] [trace]   Sent 23 bytes over websocket
[2020-04-27 20:46:38.152240] [0x00007f9e047c1700] [trace]   Wrote 15 bytes to tcp socket
[2020-04-27 20:46:38.152364] [0x00007f9e047c1700] [trace]   Sent 23 bytes over websocket
[2020-04-27 20:46:38.152507] [0x00007f9e047c1700] [trace]   Wrote 15 bytes to tcp socket
[2020-04-27 20:46:38.152539] [0x00007f9e047c1700] [trace]   Sent 23 bytes over websocket
[2020-04-27 20:46:38.152624] [0x00007f9e047c1700] [trace]   Wrote 15 bytes to tcp socket
[2020-04-27 20:46:38.152661] [0x00007f9e047c1700] [trace]   Sent 23 bytes over websocket
[2020-04-27 20:46:38.152742] [0x00007f9e047c1700] [trace]   Wrote 15 bytes to tcp socket
[2020-04-27 20:46:38.152788] [0x00007f9e047c1700] [trace]   Sent 23 bytes over websocket
[2020-04-27 20:46:38.152867] [0x00007f9e047c1700] [trace]   Wrote 15 bytes to tcp socket
[2020-04-27 20:46:38.152892] [0x00007f9e047c1700] [info]    Web socket close recieved. Code: 1011; Reason: test_closure
[2020-04-27 20:46:38.152898] [0x00007f9e047c1700] [debug]   Handling explicit reset by closing TCP
[2020-04-27 20:46:38.152904] [0x00007f9e047c1700] [trace]   Post-reset web socket drain complete
[2020-04-27 20:46:38.152907] [0x00007f9e047c1700] [trace]   Post-reset TCP drain complete. Closing TCP socket
[2020-04-27 20:46:38.152916] [0x00007f9e047c1700] [info]    Disconnected from: 127.0.0.1:46048
[2020-04-27 20:46:38.152938] [0x00007f9e047c1700] [trace]   Both socket drains complete. Setting up TCP socket again
Destination app listening on address: 127.0.0.1:38303
Test server listening on address: 127.0.0.1 and port: 34291
[2020-04-27 20:46:38.204152] [0x00007f9e03fc0700] [info]    Starting proxy in destination mode
[2020-04-27 20:46:38.204315] [0x00007f9e03fc0700] [trace]   Setting up web socket...
[2020-04-27 20:46:38.204341] [0x00007f9e03fc0700] [info]    Attempting to establish web socket connection with endpoint wss://127.0.0.1:34291
[2020-04-27 20:46:38.204353] [0x00007f9e03fc0700] [trace]   Resolving proxy host: 127.0.0.1
[2020-04-27 20:46:38.204484] [0x00007f9e03fc0700] [debug]   Resolved proxy server IP: 127.0.0.1
[2020-04-27 20:46:38.204596] [0x00007f9e03fc0700] [debug]   Connected successfully with proxy server
[2020-04-27 20:46:38.204614] [0x00007f9e03fc0700] [trace]   Performing websocket handshake with proxy server
[2020-04-27 20:46:38.204646] [0x00007f9e03fc0700] [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: ZOxs7iGHKGj4UAggr4iAyw==
Sec-WebSocket-Version: 13
Sec-WebSocket-Protocol: aws.iot.securetunneling-1.0
access-token: ***ACCESS_TOKEN_REMOVED***
User-Agent: localproxy linux 64-bit/boost-1.69.0/openssl-1.1.1/protobuf-3.6.1

[2020-04-27 20:46:38.205058] [0x00007f9e03fc0700] [trace]   Web socket upgrade response:
HTTP/1.1 101 Switching Protocols
Upgrade: websocket
Connection: upgrade
Sec-WebSocket-Accept: Y8YSWGod5EY00O7llGGeG/PWys4=
channel-id: 00000000-0000-0000-0000-000000000000
Sec-WebSocket-Protocol: aws.iot.securetunneling-1.0
Server: Boost.Beast/189

[2020-04-27 20:46:38.205117] [0x00007f9e03fc0700] [info]    Web socket session ID: 00000000-0000-0000-0000-000000000000
[2020-04-27 20:46:38.205128] [0x00007f9e03fc0700] [debug]   Web socket subprotocol selected: aws.iot.securetunneling-1.0
[2020-04-27 20:46:38.205137] [0x00007f9e03fc0700] [info]    Successfully established websocket connection with proxy server: wss://127.0.0.1:34291
[2020-04-27 20:46:38.205148] [0x00007f9e03fc0700] [debug]   Seting up web socket pings for every 5000 milliseconds
[2020-04-27 20:46:38.205185] [0x00007f9e03fc0700] [trace]   Setting up tcp socket...
[2020-04-27 20:46:38.205192] [0x00007f9e03fc0700] [trace]   Waiting for stream start...
[2020-04-27 20:46:38.205241] [0x00007f9e03fc0700] [trace]   Pong reply latency: 0 ms
[2020-04-27 20:46:38.255521] [0x00007f9e03fc0700] [info]    Attempting to establish tcp socket connection to: 127.0.0.1:38303
[2020-04-27 20:46:38.255562] [0x00007f9e03fc0700] [debug]   Resolving local address host: 127.0.0.1
[2020-04-27 20:46:38.255579] [0x00007f9e03fc0700] [debug]   Web socket read loop stopped
[2020-04-27 20:46:38.255610] [0x00007f9e03fc0700] [debug]   Resolved bind IP: 127.0.0.1
[2020-04-27 20:46:38.255648] [0x00007f9e03fc0700] [trace]   Resolving destination host: 127.0.0.1
[2020-04-27 20:46:38.255678] [0x00007f9e03fc0700] [debug]   Resolved destination host to IP: 127.0.0.1
[2020-04-27 20:46:38.255691] [0x00007f9e03fc0700] [trace]   Connecting to 127.0.0.1
[2020-04-27 20:46:38.255830] [0x00007f9e03fc0700] [info]    Connected to 127.0.0.1:38303
[2020-04-27 20:46:38.255845] [0x00007f9e03fc0700] [trace]   Setting up bi-directional data transfer with stream_id: 1
[2020-04-27 20:46:38.255850] [0x00007f9e03fc0700] [trace]   Clearing all data buffers
[2020-04-27 20:46:38.305893] [0x00007f9e03fc0700] [trace]   Sent 23 bytes over websocket
[2020-04-27 20:46:38.306204] [0x00007f9e03fc0700] [trace]   Wrote 15 bytes to tcp socket
[2020-04-27 20:46:38.306299] [0x00007f9e03fc0700] [trace]   Sent 23 bytes over websocket
[2020-04-27 20:46:38.306555] [0x00007f9e03fc0700] [trace]   Wrote 15 bytes to tcp socket
[2020-04-27 20:46:38.306613] [0x00007f9e03fc0700] [trace]   Sent 23 bytes over websocket
[2020-04-27 20:46:38.306697] [0x00007f9e03fc0700] [trace]   Wrote 15 bytes to tcp socket
[2020-04-27 20:46:38.306814] [0x00007f9e03fc0700] [trace]   Sent 23 bytes over websocket
[2020-04-27 20:46:38.307131] [0x00007f9e03fc0700] [trace]   Wrote 15 bytes to tcp socket
[2020-04-27 20:46:38.307187] [0x00007f9e03fc0700] [trace]   Sent 23 bytes over websocket
[2020-04-27 20:46:38.307259] [0x00007f9e03fc0700] [trace]   Wrote 15 bytes to tcp socket
[2020-04-27 20:46:38.307517] [0x00007f9e03fc0700] [debug]   Handling tcp socket error: End of file
[2020-04-27 20:46:38.307536] [0x00007f9e03fc0700] [info]    Disconnected from: 127.0.0.1:38303
localproxytest: /usr/local/include/boost/beast/websocket/detail/stream_base.hpp:105: bool boost::beast::websocket::detail::soft_mutex::try_lock(const T*) [with T = boost::beast::websocket::stream<boost::asio::basic_stream_socket<boost::asio::ip::tcp> >::write_some_op<boost::asio::const_buffer, std::_Bind<void (aws::iot::securedtunneling::test::TestWebsocketServer::*(aws::iot::securedtunneling::test::TestWebsocketServer*, std::reference_wrapper<boost::beast::websocket::stream<boost::asio::basic_stream_socket<boost::asio::ip::tcp> > >, std::_Placeholder<1>, std::_Placeholder<2>))(boost::beast::websocket::stream<boost::asio::basic_stream_socket<boost::asio::ip::tcp> >&, const boost::system::error_code&, long unsigned int)> >]: Assertion `id_ != T::id' failed.
[2020-04-27 20:46:38.307592] [0x00007f9e03fc0700] [trace]   Sent 6 bytes over websocket
[2020-04-27 20:46:38.307597] [0x00007f9e03fc0700] [trace]   Setting up tcp socket...

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

-------------------------------------------------------------------------------
Test destination mode
[2020-04-27 20:46:38.307602] [0x00007f9e03fc0700] [trace]   Waiting for stream start...
-------------------------------------------------------------------------------
/home/dependencies/aws-iot-securetunneling-localproxy/test/AdapterTests.cpp:131
...............................................................................

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

===============================================================================
test cases:  2 |  1 passed | 1 failed
assertions: 26 | 25 passed | 1 failed

Aborted (core dumped)

Seems like some type of race condition? Bumping up the IO_PAUSE_MS in the AdapterTests.cpp seemed to fix the issue for me.

HarshGandhi-AWS commented 4 years ago

Hello @jamesrusso ,

Thank you for your feedback. This issue was present for very few platforms which were taking more than expected time to get the proxy server running. Can you tell me more about the platform your docker was running on and the updated value for IO_PAUSE_MS which fixed your problem?

Thank you, Harsh Gandhi

jamesrusso commented 4 years ago

Sorry for the delay. This was on a raspberry Pi Zero, so not strong CPU. I don't recall the IO_PAUSE_MS, since I moved on to just an OpenVPN solution due to the costs of the proxy from AWS.

Minipada commented 4 years ago

@jamesrusso thanks for pointing this out. The costs are insane.

jamesrusso commented 4 years ago

@Minipada They are. I didn't realize the costs were $5/tunnel and I spent about $1k just testing and trying to get it to work and tested.