Bug Report: Raspberry Pi armv8 /aarch64 Secure Tunnelling Component crashes out on tunnel creation

bml1g12 commented 1 year ago

When a tunnel is opened, the Secure Tunnelling Component throws many error logs, but I am unclear what the issue is. Much appreciated if you are able to provide any support on this, as it seems like a bug.

This seems to be the same as this unresolved issue.

I am using the following setup:

Using 1.0.9 Secure Tunnelling component

2.7.0 Nucleus component

uname -a
Linux ${HOSTNAME} 5.15.74-v8+ #1595 SMP PREEMPT Wed Oct 26 11:07:24 BST 2022 aarch64 GNU/Linux

This is a standard build of raspbian 64 bit OS

How I installed the Secure Tunneling Greengrass Component:

When deploying the component, setting the OS_DIST_INFO as raspberry this issue, resulted in an error Cannot find file: aws.greengrass.SecureTunneling/linux/aarch64/raspberrypi/aws-iot-device so I used

{
  "reset": [],
  "merge": {
    "OS_DIST_INFO": "ubuntu"
  }
}

Instead (which actually I think is also what OS_DIST_INFO="auto" obtains in this particular OS).

Details of the Issue:

This results in a component that is RUNNING state, but when we open a tunnel (aws iotsecuretunneling open-tunnel --region ap-northeast-1 --destination-config thingName=${THING_NAME},services=SSH) I get the following in /greengrass/v2/logs/aws.greengrass.SecureTunneling.log

2022-11-08T16:27:58.691Z [INFO] (pool-2-thread-218) aws.greengrass.SecureTunneling: shell-runner-start. {scriptName=services.aws.greengrass.SecureTunneling.lifecycle.run.script, serviceName=aws.greengrass.SecureTunneling, currentState=STARTING, command=["java -jar /greengrass/v2/packages/artifacts/aws.greengrass.SecureTunneling/1.0..."]}
2022-11-08T16:28:06.474Z [INFO] (Copier) aws.greengrass.SecureTunneling: stdout. [INFO ] 2022-11-09 01:28:06.435 [main] SecureTunneling - Starting secure tunneling component!. {scriptName=services.aws.greengrass.SecureTunneling.lifecycle.run.script, serviceName=aws.greengrass.SecureTunneling, currentState=RUNNING}
2022-11-08T16:28:08.502Z [WARN] (Copier) aws.greengrass.SecureTunneling: stderr. Nov 09, 2022 1:28:08 AM software.amazon.awssdk.eventstreamrpc.EventStreamRPCConnection$1 onConnectionSetup. {scriptName=services.aws.greengrass.SecureTunneling.lifecycle.run.script, serviceName=aws.greengrass.SecureTunneling, currentState=RUNNING}
2022-11-08T16:28:08.503Z [WARN] (Copier) aws.greengrass.SecureTunneling: stderr. INFO: Socket connection /greengrass/v2/ipc.socket:8033 to server result [AWS_ERROR_SUCCESS]. {scriptName=services.aws.greengrass.SecureTunneling.lifecycle.run.script, serviceName=aws.greengrass.SecureTunneling, currentState=RUNNING}
2022-11-08T16:28:09.262Z [WARN] (Copier) aws.greengrass.SecureTunneling: stderr. Nov 09, 2022 1:28:09 AM software.amazon.awssdk.eventstreamrpc.EventStreamRPCConnection$1 onProtocolMessage. {scriptName=services.aws.greengrass.SecureTunneling.lifecycle.run.script, serviceName=aws.greengrass.SecureTunneling, currentState=RUNNING}
2022-11-08T16:28:09.263Z [WARN] (Copier) aws.greengrass.SecureTunneling: stderr. INFO: Connection established with event stream RPC server. {scriptName=services.aws.greengrass.SecureTunneling.lifecycle.run.script, serviceName=aws.greengrass.SecureTunneling, currentState=RUNNING}
2022-11-08T16:28:09.345Z [INFO] (Copier) aws.greengrass.SecureTunneling: stdout. [INFO ] 2022-11-09 01:28:09.336 [main] SecureTunnelingExecutor - Starting secure tunneling.. {scriptName=services.aws.greengrass.SecureTunneling.lifecycle.run.script, serviceName=aws.greengrass.SecureTunneling, currentState=RUNNING}
2022-11-08T16:28:09.897Z [INFO] (Copier) aws.greengrass.SecureTunneling: stdout. [INFO ] 2022-11-09 01:28:09.893 [Thread-1] SecureTunnelingTask - Successfully subscribed to topic: $aws/things/mcs-respeaker-4-ca69de/tunnels/notify. {scriptName=services.aws.greengrass.SecureTunneling.lifecycle.run.script, serviceName=aws.greengrass.SecureTunneling, currentState=RUNNING}
2022-11-08T16:28:45.306Z [INFO] (Copier) aws.greengrass.SecureTunneling: stdout. [INFO ] 2022-11-09 01:28:45.305 [Thread-1] SubscribeResponseHandler - Received new tunnel notification message.. {scriptName=services.aws.greengrass.SecureTunneling.lifecycle.run.script, serviceName=aws.greengrass.SecureTunneling, currentState=RUNNING}
2022-11-08T16:28:45.489Z [INFO] (Copier) aws.greengrass.SecureTunneling: stdout. [ERROR] 2022-11-09 01:28:45.487 [pool-3-thread-1] SubscribeResponseHandler - Secure Tunneling Process: 2022-11-08T16:28:45.332Z [WARN]  {FileUtils.cpp}: Permissions to given file/dir path '/tmp/' is not set to recommended value... {Permissions: {desired: 745, actual: 777}}. {scriptName=services.aws.greengrass.SecureTunneling.lifecycle.run.script, serviceName=aws.greengrass.SecureTunneling, currentState=RUNNING}
2022-11-08T16:28:45.491Z [INFO] (Copier) aws.greengrass.SecureTunneling: stdout. [ERROR] 2022-11-09 01:28:45.489 [pool-3-thread-1] SubscribeResponseHandler - Secure Tunneling Process: 2022-11-08T16:28:45.332Z [WARN]  {Config.cpp}: Path replace_with_root_ca_file_location to RootCA is invalid. Ignoring... Will attempt to use default trust store.. {scriptName=services.aws.greengrass.SecureTunneling.lifecycle.run.script, serviceName=aws.greengrass.SecureTunneling, currentState=RUNNING}
2022-11-08T16:28:45.492Z [INFO] (Copier) aws.greengrass.SecureTunneling: stdout. [ERROR] 2022-11-09 01:28:45.491 [pool-3-thread-1] SubscribeResponseHandler - Secure Tunneling Process: 2022-11-08T16:28:45.332Z [INFO]  {Config.cpp}: Successfully fetched JSON config file: {. {scriptName=services.aws.greengrass.SecureTunneling.lifecycle.run.script, serviceName=aws.greengrass.SecureTunneling, currentState=RUNNING}
2022-11-08T16:28:45.495Z [INFO] (Copier) aws.greengrass.SecureTunneling: stdout. [ERROR] 2022-11-09 01:28:45.494 [pool-3-thread-1] SubscribeResponseHandler - Secure Tunneling Process:   "endpoint": "replace_with_endpoint_value",. {scriptName=services.aws.greengrass.SecureTunneling.lifecycle.run.script, serviceName=aws.greengrass.SecureTunneling, currentState=RUNNING}
2022-11-08T16:28:45.497Z [INFO] (Copier) aws.greengrass.SecureTunneling: stdout. [ERROR] 2022-11-09 01:28:45.495 [pool-3-thread-1] SubscribeResponseHandler - Secure Tunneling Process:   "cert": "replace_with_certificate_file_location",. {scriptName=services.aws.greengrass.SecureTunneling.lifecycle.run.script, serviceName=aws.greengrass.SecureTunneling, currentState=RUNNING}
2022-11-08T16:28:45.499Z [INFO] (Copier) aws.greengrass.SecureTunneling: stdout. [ERROR] 2022-11-09 01:28:45.497 [pool-3-thread-1] SubscribeResponseHandler - Secure Tunneling Process:   "key": "replace_with_private_key_file_location",. {scriptName=services.aws.greengrass.SecureTunneling.lifecycle.run.script, serviceName=aws.greengrass.SecureTunneling, currentState=RUNNING}
2022-11-08T16:28:45.501Z [INFO] (Copier) aws.greengrass.SecureTunneling: stdout. [ERROR] 2022-11-09 01:28:45.498 [pool-3-thread-1] SubscribeResponseHandler - Secure Tunneling Process:   "root-ca": "replace_with_root_ca_file_location",. {scriptName=services.aws.greengrass.SecureTunneling.lifecycle.run.script, serviceName=aws.greengrass.SecureTunneling, currentState=RUNNING}
2022-11-08T16:28:45.503Z [INFO] (Copier) aws.greengrass.SecureTunneling: stdout. [ERROR] 2022-11-09 01:28:45.500 [pool-3-thread-1] SubscribeResponseHandler - Secure Tunneling Process:   "thing-name": "replace_with_thing_name",. {scriptName=services.aws.greengrass.SecureTunneling.lifecycle.run.script, serviceName=aws.greengrass.SecureTunneling, currentState=RUNNING}
2022-11-08T16:28:45.518Z [INFO] (Copier) aws.greengrass.SecureTunneling: stdout. [ERROR] 2022-11-09 01:28:45.501 [pool-3-thread-1] SubscribeResponseHandler - Secure Tunneling Process:   "logging": {. {scriptName=services.aws.greengrass.SecureTunneling.lifecycle.run.script, serviceName=aws.greengrass.SecureTunneling, currentState=RUNNING}
2022-11-08T16:28:45.520Z [INFO] (Copier) aws.greengrass.SecureTunneling: stdout. [ERROR] 2022-11-09 01:28:45.518 [pool-3-thread-1] SubscribeResponseHandler - Secure Tunneling Process:     "level": "ERROR",. {scriptName=services.aws.greengrass.SecureTunneling.lifecycle.run.script, serviceName=aws.greengrass.SecureTunneling, currentState=RUNNING}
2022-11-08T16:28:45.523Z [INFO] (Copier) aws.greengrass.SecureTunneling: stdout. [ERROR] 2022-11-09 01:28:45.519 [pool-3-thread-1] SubscribeResponseHandler - Secure Tunneling Process:     "type": "STDOUT",. {scriptName=services.aws.greengrass.SecureTunneling.lifecycle.run.script, serviceName=aws.greengrass.SecureTunneling, currentState=RUNNING}
2022-11-08T16:28:45.525Z [INFO] (Copier) aws.greengrass.SecureTunneling: stdout. [ERROR] 2022-11-09 01:28:45.520 [pool-3-thread-1] SubscribeResponseHandler - Secure Tunneling Process:     "file": "/var/log/aws-iot-device-client/aws-iot-device-client.log". {scriptName=services.aws.greengrass.SecureTunneling.lifecycle.run.script, serviceName=aws.greengrass.SecureTunneling, currentState=RUNNING}
2022-11-08T16:28:45.527Z [INFO] (Copier) aws.greengrass.SecureTunneling: stdout. [ERROR] 2022-11-09 01:28:45.521 [pool-3-thread-1] SubscribeResponseHandler - Secure Tunneling Process:   },. {scriptName=services.aws.greengrass.SecureTunneling.lifecycle.run.script, serviceName=aws.greengrass.SecureTunneling, currentState=RUNNING}
2022-11-08T16:28:45.530Z [INFO] (Copier) aws.greengrass.SecureTunneling: stdout. [ERROR] 2022-11-09 01:28:45.522 [pool-3-thread-1] SubscribeResponseHandler - Secure Tunneling Process:   "jobs": {. {scriptName=services.aws.greengrass.SecureTunneling.lifecycle.run.script, serviceName=aws.greengrass.SecureTunneling, currentState=RUNNING}
2022-11-08T16:28:45.535Z [INFO] (Copier) aws.greengrass.SecureTunneling: stdout. [ERROR] 2022-11-09 01:28:45.534 [pool-3-thread-1] SubscribeResponseHandler - Secure Tunneling Process:     "enabled": false,. {scriptName=services.aws.greengrass.SecureTunneling.lifecycle.run.script, serviceName=aws.greengrass.SecureTunneling, currentState=RUNNING}
2022-11-08T16:28:45.537Z [INFO] (Copier) aws.greengrass.SecureTunneling: stdout. [ERROR] 2022-11-09 01:28:45.535 [pool-3-thread-1] SubscribeResponseHandler - Secure Tunneling Process:     "handler-directory": "replace_with_path_to_handler_dir". {scriptName=services.aws.greengrass.SecureTunneling.lifecycle.run.script, serviceName=aws.greengrass.SecureTunneling, currentState=RUNNING}
2022-11-08T16:28:45.540Z [INFO] (Copier) aws.greengrass.SecureTunneling: stdout. [ERROR] 2022-11-09 01:28:45.536 [pool-3-thread-1] SubscribeResponseHandler - Secure Tunneling Process:   },. {scriptName=services.aws.greengrass.SecureTunneling.lifecycle.run.script, serviceName=aws.greengrass.SecureTunneling, currentState=RUNNING}
2022-11-08T16:28:45.545Z [INFO] (Copier) aws.greengrass.SecureTunneling: stdout. [ERROR] 2022-11-09 01:28:45.537 [pool-3-thread-1] SubscribeResponseHandler - Secure Tunneling Process:   "tunneling": {. {scriptName=services.aws.greengrass.SecureTunneling.lifecycle.run.script, serviceName=aws.greengrass.SecureTunneling, currentState=RUNNING}
2022-11-08T16:28:45.547Z [INFO] (Copier) aws.greengrass.SecureTunneling: stdout. [ERROR] 2022-11-09 01:28:45.538 [pool-3-thread-1] SubscribeResponseHandler - Secure Tunneling Process:     "enabled": true. {scriptName=services.aws.greengrass.SecureTunneling.lifecycle.run.script, serviceName=aws.greengrass.SecureTunneling, currentState=RUNNING}
2022-11-08T16:28:45.551Z [INFO] (Copier) aws.greengrass.SecureTunneling: stdout. [ERROR] 2022-11-09 01:28:45.539 [pool-3-thread-1] SubscribeResponseHandler - Secure Tunneling Process:   },. {scriptName=services.aws.greengrass.SecureTunneling.lifecycle.run.script, serviceName=aws.greengrass.SecureTunneling, currentState=RUNNING}
2022-11-08T16:28:45.552Z [INFO] (Copier) aws.greengrass.SecureTunneling: stdout. [ERROR] 2022-11-09 01:28:45.540 [pool-3-thread-1] SubscribeResponseHandler - Secure Tunneling Process:   "device-defender":    {. {scriptName=services.aws.greengrass.SecureTunneling.lifecycle.run.script, serviceName=aws.greengrass.SecureTunneling, currentState=RUNNING}
2022-11-08T16:28:45.554Z [INFO] (Copier) aws.greengrass.SecureTunneling: stdout. [ERROR] 2022-11-09 01:28:45.541 [pool-3-thread-1] SubscribeResponseHandler - Secure Tunneling Process:     "enabled":  false,. {scriptName=services.aws.greengrass.SecureTunneling.lifecycle.run.script, serviceName=aws.greengrass.SecureTunneling, currentState=RUNNING}
2022-11-08T16:28:45.556Z [INFO] (Copier) aws.greengrass.SecureTunneling: stdout. [ERROR] 2022-11-09 01:28:45.542 [pool-3-thread-1] SubscribeResponseHandler - Secure Tunneling Process:     "interval": 300. {scriptName=services.aws.greengrass.SecureTunneling.lifecycle.run.script, serviceName=aws.greengrass.SecureTunneling, currentState=RUNNING}
2022-11-08T16:28:45.558Z [INFO] (Copier) aws.greengrass.SecureTunneling: stdout. [ERROR] 2022-11-09 01:28:45.544 [pool-3-thread-1] SubscribeResponseHandler - Secure Tunneling Process:   },. {scriptName=services.aws.greengrass.SecureTunneling.lifecycle.run.script, serviceName=aws.greengrass.SecureTunneling, currentState=RUNNING}
2022-11-08T16:28:45.563Z [INFO] (Copier) aws.greengrass.SecureTunneling: stdout. [ERROR] 2022-11-09 01:28:45.545 [pool-3-thread-1] SubscribeResponseHandler - Secure Tunneling Process:   "fleet-provisioning": {. {scriptName=services.aws.greengrass.SecureTunneling.lifecycle.run.script, serviceName=aws.greengrass.SecureTunneling, currentState=RUNNING}
2022-11-08T16:28:45.577Z [INFO] (Copier) aws.greengrass.SecureTunneling: stdout. [ERROR] 2022-11-09 01:28:45.546 [pool-3-thread-1] SubscribeResponseHandler - Secure Tunneling Process:     "enabled": false,. {scriptName=services.aws.greengrass.SecureTunneling.lifecycle.run.script, serviceName=aws.greengrass.SecureTunneling, currentState=RUNNING}
2022-11-08T16:28:45.578Z [INFO] (Copier) aws.greengrass.SecureTunneling: stdout. [ERROR] 2022-11-09 01:28:45.547 [pool-3-thread-1] SubscribeResponseHandler - Secure Tunneling Process:     "template-name": "replace_with_template_name",. {scriptName=services.aws.greengrass.SecureTunneling.lifecycle.run.script, serviceName=aws.greengrass.SecureTunneling, currentState=RUNNING}
2022-11-08T16:28:45.580Z [INFO] (Copier) aws.greengrass.SecureTunneling: stdout. [ERROR] 2022-11-09 01:28:45.548 [pool-3-thread-1] SubscribeResponseHandler - Secure Tunneling Process:     "csr-file": "replace_with_csr-file-path". {scriptName=services.aws.greengrass.SecureTunneling.lifecycle.run.script, serviceName=aws.greengrass.SecureTunneling, currentState=RUNNING}
2022-11-08T16:28:45.582Z [INFO] (Copier) aws.greengrass.SecureTunneling: stdout. [ERROR] 2022-11-09 01:28:45.549 [pool-3-thread-1] SubscribeResponseHandler - Secure Tunneling Process:   }. {scriptName=services.aws.greengrass.SecureTunneling.lifecycle.run.script, serviceName=aws.greengrass.SecureTunneling, currentState=RUNNING}
2022-11-08T16:28:45.583Z [INFO] (Copier) aws.greengrass.SecureTunneling: stdout. [ERROR] 2022-11-09 01:28:45.550 [pool-3-thread-1] SubscribeResponseHandler - Secure Tunneling Process: }. {scriptName=services.aws.greengrass.SecureTunneling.lifecycle.run.script, serviceName=aws.greengrass.SecureTunneling, currentState=RUNNING}
2022-11-08T16:28:45.585Z [INFO] (Copier) aws.greengrass.SecureTunneling: stdout. [ERROR] 2022-11-09 01:28:45.551 [pool-3-thread-1] SubscribeResponseHandler - Secure Tunneling Process: 2022-11-08T16:28:45.333Z [DEBUG] {Config.cpp}: Did not find a runtime configuration file, assuming Fleet Provisioning has not run for this device. {scriptName=services.aws.greengrass.SecureTunneling.lifecycle.run.script, serviceName=aws.greengrass.SecureTunneling, currentState=RUNNING}

And in the IoT Client I get the following:

bash-4.2# ./localproxy -s 7777  -b 0.0.0.0 -v 5 -r ap-northeast-1 -t ${TOKEN}
[2022-11-08T16:26:30.262011]{11}[warning] Found access token supplied via CLI arg. Consider using environment variable AWSIOT_TUNNEL_ACCESS_TOKEN instead
[2022-11-08T16:26:30.262063]{11}[debug]   v2 local proxy starts with v1 local proxy format
[2022-11-08T16:26:30.262078]{11}[debug]   /home/aws-iot-securetunneling-localproxy/config does not exist!
[2022-11-08T16:26:30.262102]{11}[info]    Starting proxy in source mode
[2022-11-08T16:26:30.267169]{11}[info]    Attempting to establish web socket connection with endpoint wss://data.tunneling.iot.ap-northeast-1.amazonaws.com:443
[2022-11-08T16:26:30.414326]{11}[debug]   Resolved proxy server IP: 18.179.243.10
[2022-11-08T16:26:30.821672]{11}[debug]   Connected successfully with proxy server
[2022-11-08T16:26:31.639321]{11}[debug]   Successfully completed SSL handshake with proxy server
[2022-11-08T16:26:32.049196]{11}[error]   Proxy server rejected web socket upgrade request: (HTTP/1.1 400 Bad Request) "The client access token and local-proxy-mode are mismatched"

Some questions that come to mind:

: Permissions to given file/dir path '/tmp/' is not set to recommended value... {Permissions: {desired: 745, actual: 777}}

Does Greengrass require 747 permissions on /tmp? I couldn't find this documented anywhere.

: Path replace_with_root_ca_file_location to RootCA is invalid. Ignoring... Will attempt to use default trust store. "endpoint": "replace_with_endpoint_value", "key": "replace_with_private_key_file_location"

It looks to me like it is crashing because it is defaulting to some template config file, and failing to insert dynamically the correct values - but I do not know why.

What I've tried

I've tried restarting the device
I've tried OS_DIST_INFO "ubuntu" and OS_DIST_INFO "raspberrypi"

Kriechi commented 1 year ago

@bml1g12 technically this repository is for a different component than the one you seem to be having a problem with. You seem to be using the official SecureTunneling component in version 1.0.9.

This repository describes an alternative approach using the aws-iot-device-client and a Python application packaged into a container image. Using a container image allows you to customize and tailor the device client independent from the host operating system and therefore avoid issues with incompatibilities between Linux distributions or library dependencies.

/cc @HarshGandhi-AWS for visibility on the re:port thread.

shangabl commented 1 year ago

Hi @bml1g12,

I think this might actually be an issue with the log output. Those error logs don't appear to be error logs... The logs have both [INFO] and [ERROR] and it may be that the GreenGrass SecureTunneling Component is outputting the logs incorrectly here... I will take a look into that.

But I think that it may actually be working here. If you check the status of the tunnel either with the describe-tunnel API or through the console, is the destination CONNECTED?

I do not believe the file permissions on /tmp/ is fatal.

The component is looking for the path to the RootCA in that dummy config file that is passed to it... and then defaulting to the default trust store. That shouldn't be a problem either.

"It looks to me like it is crashing because it is defaulting to some template config file"

Is it actually crashing? If not I think it might actually be working and this is a logging issue.

[2022-11-08T16:26:32.049196]{11}[error] Proxy server rejected web socket upgrade request: (HTTP/1.1 400 Bad Request) "The client access token and local-proxy-mode are mismatched"

I think you may be attempting to use the destination access token instead of the source access token.

bml1g12 commented 1 year ago

Thank you for your swift responses!

@bml1g12 technically this repository is for a different component than the one you seem to be having a problem with. You seem to be using the official SecureTunneling component in version 1.0.9.

Sorry about that - unfortunately the component has no repo associated so this is the closest match I think.

I think you may be attempting to use the destination access token instead of the source access token.

Oh dear me, thank you so much - I'm embarrassed to say this was a human error on my part, and using the correct token it resolves the issue.

As you say, however, it does seem to indicate some logging bugs:

ERROR level logs for info logs
The contents of the "key": "replace_with_private_key_file_location" these look odd even for an info log
The fact that it warns about /tmp permissions, when /tmp is configured with a fairly standard permission set on my machine 777

Given those are not related to my issue, I'll close this ticket. Thank you very much for your support.

awslabs / aws-greengrass-labs-containerized-secure-tunneling

Bug Report: Raspberry Pi armv8 /aarch64 Secure Tunnelling Component crashes out on tunnel creation #2