issues Node.js hello world running core 1.9.2

0

I have an issue where the Node HelloWorld example behaves differently than the python version. I have tested this with core 1.9.2 on two different hardware platforms (both armv7l - one is raspi). The issue are:

  1. MQTT messages from cloud to core are received three times by the HW lambda( only sent once)
  2. Lambda receives SIGTERM after even+ timeout

lambda is configured with heaps of RAM (100MB), longlived, timeout 30 seconds

  1. could be explained by QoS, but I'm not sure how to configure this - wasn't an issue with python
  2. this related to timeout, but python HelloW did't have this issue.

Only one mqtt message was sent by test interface, but lambda received it three times.

[2019-09-12T14:46:47.791+01:00][INFO]-Posting work for function [arn:aws:lambda:::function:GGRouter] to /2016-11-01/functions/arn:aws:lambda:::function:GGRouter
[2019-09-12T14:46:47.797+01:00][INFO]-Work posted with invocation ID [8d5d5ef1-4464-4468-5c34-b367a29cd6e9]
[2019-09-12T14:46:47.798+01:00][INFO]-null
[2019-09-12T14:46:47.799+01:00][INFO]-8d5d5ef1-4464-4468-5c34-b367a29cd6e9
[2019-09-12T14:46:49.972+01:00][INFO]-Got work item with invocation id [52b9df8c-d6d1-4f8e-5624-a8d29108db4e]
[2019-09-12T14:46:49.981+01:00][INFO]-START RequestId: 52b9df8c-d6d1-4f8e-5624-a8d29108db4e

[2019-09-12T14:46:49.984+01:00][INFO]-EVENT: {
[2019-09-12T14:46:49.984+01:00][INFO]- "message": "msg1"
[2019-09-12T14:46:49.984+01:00][INFO]-}

[2019-09-12T14:46:49.984+01:00][INFO]-End RequestId: 52b9df8c-d6d1-4f8e-5624-a8d29108db4e
[2019-09-12T14:46:57.801+01:00][INFO]-Publishing message on topic "hello/world" with Payload "
{ "message": "Hello world!!! Sent from Greengrass Core running on platform: linux-4.14.79-v7+ using NodeJS" }
"
[2019-09-12T14:46:57.801+01:00][INFO]-Posting work for function [arn:aws:lambda:::function:GGRouter] to /2016-11-01/functions/arn:aws:lambda:::function:GGRouter
[2019-09-12T14:46:57.807+01:00][INFO]-Work posted with invocation ID [3f5ccd05-1c1e-42d1-563c-562cb3e57ecc]
[2019-09-12T14:46:57.807+01:00][INFO]-null
[2019-09-12T14:46:57.808+01:00][INFO]-3f5ccd05-1c1e-42d1-563c-562cb3e57ecc
[2019-09-12T14:47:07.814+01:00][INFO]-Publishing message on topic "hello/world" with Payload "
{ "message": "Hello world!!! Sent from Greengrass Core running on platform: linux-4.14.79-v7+ using NodeJS" }
"
[2019-09-12T14:47:07.814+01:00][INFO]-Posting work for function [arn:aws:lambda:::function:GGRouter] to /2016-11-01/functions/arn:aws:lambda:::function:GGRouter
[2019-09-12T14:47:07.82+01:00][INFO]-Work posted with invocation ID [91c9c396-b3e7-40c4-5567-7db36a5ccfd7]
[2019-09-12T14:47:07.822+01:00][INFO]-null
[2019-09-12T14:47:07.822+01:00][INFO]-91c9c396-b3e7-40c4-5567-7db36a5ccfd7
[2019-09-12T14:47:17.826+01:00][INFO]-Publishing message on topic "hello/world" with Payload "
{ "message": "Hello world!!! Sent from Greengrass Core running on platform: linux-4.14.79-v7+ using NodeJS" }
"
[2019-09-12T14:47:17.827+01:00][INFO]-Posting work for function [arn:aws:lambda:::function:GGRouter] to /2016-11-01/functions/arn:aws:lambda:::function:GGRouter
[2019-09-12T14:47:17.833+01:00][INFO]-Work posted with invocation ID [3132ce31-3509-4ea4-50f4-237606a8c74f]
[2019-09-12T14:47:17.834+01:00][INFO]-null
[2019-09-12T14:47:17.835+01:00][INFO]-3132ce31-3509-4ea4-50f4-237606a8c74f
[2019-09-12T14:47:19.972+01:00][INFO]-Caught SIGTERM. Stopping runtime.
[2019-09-12T14:47:20.745+01:00][INFO]-Running [arn:aws:lambda:us-east-1:886556155174:function:NodeHelloW:9]
[2019-09-12T14:47:20.797+01:00][INFO]-Getting work for function [arn:aws:lambda:us-east-1:886556155174:function:NodeHelloW:9] from /2016-11-01/functions/arn:aws:lambda:us-east-1:886556155174:function:NodeHelloW:9/work
[2019-09-12T14:47:20.837+01:00][INFO]-Got work item with invocation id [52b9df8c-d6d1-4f8e-5624-a8d29108db4e]
[2019-09-12T14:47:20.845+01:00][INFO]-START RequestId: 52b9df8c-d6d1-4f8e-5624-a8d29108db4e

[2019-09-12T14:47:20.848+01:00][INFO]-EVENT: {
[2019-09-12T14:47:20.849+01:00][INFO]- "message": "msg1"
[2019-09-12T14:47:20.849+01:00][INFO]-}

[2019-09-12T14:47:20.849+01:00][INFO]-End RequestId: 52b9df8c-d6d1-4f8e-5624-a8d29108db4e
[2019-09-12T14:47:30.768+01:00][INFO]-Publishing message on topic "hello/world" with Payload "
{ "message": "Hello world!!! Sent from Greengrass Core running on platform: linux-4.14.79-v7+ using NodeJS" }
"
[2019-09-12T14:47:30.774+01:00][INFO]-Posting work for function [arn:aws:lambda:::function:GGRouter] to /2016-11-01/functions/arn:aws:lambda:::function:GGRouter
[2019-09-12T14:47:30.789+01:00][INFO]-Work posted with invocation ID [7b398182-e1b9-43bd-4bba-e89caa272d76]
[2019-09-12T14:47:30.793+01:00][INFO]-null
[2019-09-12T14:47:30.794+01:00][INFO]-7b398182-e1b9-43bd-4bba-e89caa272d76
[2019-09-12T14:47:40.791+01:00][INFO]-Publishing message on topic "hello/world" with Payload "
{ "message": "Hello world!!! Sent from Greengrass Core running on platform: linux-4.14.79-v7+ using NodeJS" }
"
[2019-09-12T14:47:40.791+01:00][INFO]-Posting work for function [arn:aws:lambda:::function:GGRouter] to /2016-11-01/functions/arn:aws:lambda:::function:GGRouter
[2019-09-12T14:47:40.799+01:00][INFO]-Work posted with invocation ID [0dcd71b8-38fa-426e-483a-30ff1d1433d2]
[2019-09-12T14:47:40.8+01:00][INFO]-null
[2019-09-12T14:47:40.801+01:00][INFO]-0dcd71b8-38fa-426e-483a-30ff1d1433d2
[2019-09-12T14:47:50.796+01:00][INFO]-Publishing message on topic "hello/world" with Payload "
{ "message": "Hello world!!! Sent from Greengrass Core running on platform: linux-4.14.79-v7+ using NodeJS" }
"
[2019-09-12T14:47:50.796+01:00][INFO]-Posting work for function [arn:aws:lambda:::function:GGRouter] to /2016-11-01/functions/arn:aws:lambda:::function:GGRouter
[2019-09-12T14:47:50.802+01:00][INFO]-Work posted with invocation ID [17b39082-17fc-49da-42a1-807569f76dc4]
[2019-09-12T14:47:50.803+01:00][INFO]-null
[2019-09-12T14:47:50.804+01:00][INFO]-17b39082-17fc-49da-42a1-807569f76dc4
[2019-09-12T14:47:50.831+01:00][INFO]-Caught SIGTERM. Stopping runtime.
[2019-09-12T14:47:51.766+01:00][INFO]-Running [arn:aws:lambda:us-east-1:886556155174:function:NodeHelloW:9]
[2019-09-12T14:47:51.817+01:00][INFO]-Getting work for function [arn:aws:lambda:us-east-1:886556155174:function:NodeHelloW:9] from /2016-11-01/functions/arn:aws:lambda:us-east-1:886556155174:function:NodeHelloW:9/work
[2019-09-12T14:47:51.856+01:00][INFO]-Got work item with invocation id [52b9df8c-d6d1-4f8e-5624-a8d29108db4e]
[2019-09-12T14:47:51.865+01:00][INFO]-START RequestId: 52b9df8c-d6d1-4f8e-5624-a8d29108db4e

[2019-09-12T14:47:51.868+01:00][INFO]-EVENT: {
[2019-09-12T14:47:51.868+01:00][INFO]- "message": "msg1"
[2019-09-12T14:47:51.868+01:00][INFO]-}

[2019-09-12T14:47:51.868+01:00][INFO]-End RequestId: 52b9df8c-d6d1-4f8e-5624-a8d29108db4e
[2019-09-12T14:48:01.789+01:00][INFO]-Publishing message on topic "hello/world" with Payload "
{ "message": "Hello world!!! Sent from Greengrass Core running on platform: linux-4.14.79-v7+ using NodeJS" }
"
[2019-09-12T14:48:01.795+01:00][INFO]-Posting work for function [arn:aws:lambda:::function:GGRouter] to /2016-11-01/functions/arn:aws:lambda:::function:GGRouter
[2019-09-12T14:48:01.811+01:00][INFO]-Work posted with invocation ID [f3aa5543-8ca8-427a-58a8-d782b893f65d]
[2019-09-12T14:48:01.814+01:00][INFO]-null
[2019-09-12T14:48:01.815+01:00][INFO]-f3aa5543-8ca8-427a-58a8-d782b893f65d
[2019-09-12T14:48:11.812+01:00][INFO]-Publishing message on topic "hello/world" with Payload "
{ "message": "Hello world!!! Sent from Greengrass Core running on platform: linux-4.14.79-v7+ using NodeJS" }
"
[2019-09-12T14:48:11.813+01:00][INFO]-Posting work for function [arn:aws:lambda:::function:GGRouter] to /2016-11-01/functions/arn:aws:lambda:::function:GGRouter
[2019-09-12T14:48:11.819+01:00][INFO]-Work posted with invocation ID [c484d3e1-4042-49dc-7adc-8bd44fe0164f]
[2019-09-12T14:48:11.821+01:00][INFO]-null
[2019-09-12T14:48:11.821+01:00][INFO]-c484d3e1-4042-49dc-7adc-8bd44fe0164f
[2019-09-12T14:48:21.825+01:00][INFO]-Publishing message on topic "hello/world" with Payload "
{ "message": "Hello world!!! Sent from Greengrass Core running on platform: linux-4.14.79-v7+ using NodeJS" }
"
[2019-09-12T14:48:21.826+01:00][INFO]-Posting work for function [arn:aws:lambda:::function:GGRouter] to /2016-11-01/functions/arn:aws:lambda:::function:GGRouter
[2019-09-12T14:48:21.832+01:00][INFO]-Work posted with invocation ID [4f9493c4-94f5-424e-447e-9a302f7d436c]
[2019-09-12T14:48:21.833+01:00][INFO]-null
[2019-09-12T14:48:21.834+01:00][INFO]-4f9493c4-94f5-424e-447e-9a302f7d436c
[2019-09-12T14:48:21.851+01:00][INFO]-Caught SIGTERM. Stopping runtime.

Edited by: KidIT on Sep 12, 2019 7:34 AM

Edited by: KidIT on Sep 12, 2019 7:36 AM

KidIT
asked 5 years ago277 views
4 Answers
0

Hi KidIT,

What does it say in your Lambda logs? You may need to enable lambda logging and redeploy.
https://docs.aws.amazon.com/greengrass/latest/developerguide/gg-troubleshooting.html#troubleshooting-logs

To your first question, that's expected. The lambda will be triggered up to three times attempting to get a successful execution. If the lambda crashes it will try again.

You're having this issue on a Raspberry Pi, correct? What's the output of the following?

cat /etc/os-release
uname -a

Is this the hello world example at https://github.com/aws/aws-greengrass-core-sdk-js/blob/master/greengrassExamples/HelloWorld/index.js
Or have you made changes?

Thanks,
KR-AWS

AWS
KR-AWS
answered 5 years ago
0

Hey,

I tried this again with different settings:

  • previously, I had a symlink from nodejs.8.10 to node ( AWS SDK github pages says not to do this)
  • I was using master branch of aws-greengrass-node-sdk moved to tag 1.4

I thought I had posted my lambda logs. I had enabled cloudwatch logs to capture "user lambda" logs.
What are the other lambda logs ?

So the lambda is crashing? I though the sigterm was triggered by the timeout since it's always roughly what I have the timeout set for.

PRETTY_NAME="Raspbian GNU/Linux 9 (stretch)"
NAME="Raspbian GNU/Linux"
VERSION_ID="9"
VERSION="9 (stretch)"
ID=raspbian
ID_LIKE=debian
HOME_URL="http://www.raspbian.org/"
SUPPORT_URL="http://www.raspbian.org/RaspbianForums"
BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs"

Linux raspberrypi 4.14.79-v7+ #1159 SMP Sun Nov 4 17:50:20 GMT 2018 armv7l GNU/Linux

Edited by: KidIT on Sep 26, 2019 12:49 PM

KidIT
answered 5 years ago
0

Hello again,

Here are logs from a different platform. The lambda is the Hello World example from the SDK with two changes.

  1. the HW message interval was changed from 5 to 15 seconds. The HW message was shortened

  2. The event object is serialized before it is console.log'd.

The settings are for long lived. the timeout is 30 seconds. In the log, you can see that the sigterm comes roughly after the duration of the timeout after a message is received.
I am sending the "message": "test1" only once. - it's received three times.

This was with tag 1.4 of the AWS greengrass js SDK.

2019-09-27T11:06:44.637Z -Running arn:aws:lambda:us-east-1:886556155174:function:nodeHello:2
2019-09-27T11:06:44.893Z -Getting work for function arn:aws:lambda:us-east-1:886556155174:function:nodeHello:2 from /2016-11-01/functions/arn:aws:lambda:us-east-1:886556155174:function:nodeHello:2/work
2019-09-27T11:06:59.797Z -Publishing message on topic "hello/world" with Payload "
{
"message": "Hello! Greengrass Core running on platform: linux-4.19.19 using NodeJS"
}
"
2019-09-27T11:06:59.897Z -Posting work for function arn:aws:lambda:::function:GGRouter to /2016-11-01/functions/arn:aws:lambda:::function:GGRouter
2019-09-27T11:07:00.321Z -Work posted with invocation ID a77bb319-f84a-4cbb-71d0-3a3c09c30852
2019-09-27T11:07:00.464Z -null
2019-09-27T11:07:00.526Z -a77bb319-f84a-4cbb-71d0-3a3c09c30852
2019-09-27T11:07:14.995Z -Publishing message on topic "hello/world" with Payload "
{
"message": "Hello! Greengrass Core running on platform: linux-4.19.19 using NodeJS"
}
"
2019-09-27T11:07:14.999Z -Posting work for function arn:aws:lambda:::function:GGRouter to /2016-11-01/functions/arn:aws:lambda:::function:GGRouter
2019-09-27T11:07:15.041Z -Work posted with invocation ID 94e9e190-cf16-43eb-7a98-a72b112ea464
2019-09-27T11:07:15.048Z -null
2019-09-27T11:07:15.052Z -94e9e190-cf16-43eb-7a98-a72b112ea464
2019-09-27T11:07:17.396Z -Got work item with invocation id a3346363-f423-4404-790a-7785c45b5f7c
2019-09-27T11:07:17.429Z -START RequestId: a3346363-f423-4404-790a-7785c45b5f7c
2019-09-27T11:07:17.438Z -EVENT:
2019-09-27T11:07:17.438Z -{
2019-09-27T11:07:17.438Z - "message": "test1"
2019-09-27T11:07:17.438Z -}
2019-09-27T11:07:17.438Z -End RequestId: a3346363-f423-4404-790a-7785c45b5f7c
2019-09-27T11:07:30.008Z -Publishing message on topic "hello/world" with Payload "
{
"message": "Hello! Greengrass Core running on platform: linux-4.19.19 using NodeJS"
}
"
2019-09-27T11:07:30.017Z -Posting work for function arn:aws:lambda:::function:GGRouter to /2016-11-01/functions/arn:aws:lambda:::function:GGRouter
2019-09-27T11:07:30.039Z -Work posted with invocation ID 4e659245-d554-47d2-75d7-43fd6cac6bf7
2019-09-27T11:07:30.043Z -null
2019-09-27T11:07:30.046Z -4e659245-d554-47d2-75d7-43fd6cac6bf7
2019-09-27T11:07:45.029Z -Publishing message on topic "hello/world" with Payload "
{
"message": "Hello! Greengrass Core running on platform: linux-4.19.19 using NodeJS"
}
"
2019-09-27T11:07:45.03Z -Posting work for function arn:aws:lambda:::function:GGRouter to /2016-11-01/functions/arn:aws:lambda:::function:GGRouter
2019-09-27T11:07:45.058Z -Work posted with invocation ID 8d204065-101d-460f-42f4-a3d7a1204c68
2019-09-27T11:07:45.061Z -null
2019-09-27T11:07:45.063Z -8d204065-101d-460f-42f4-a3d7a1204c68
2019-09-27T11:07:47.393Z -Caught SIGTERM. Stopping runtime.
2019-09-27T11:07:58.057Z -Running arn:aws:lambda:us-east-1:886556155174:function:nodeHello:2
2019-09-27T11:07:58.206Z -Getting work for function arn:aws:lambda:us-east-1:886556155174:function:nodeHello:2 from /2016-11-01/functions/arn:aws:lambda:us-east-1:886556155174:function:nodeHello:2/work
2019-09-27T11:07:58.499Z -Got work item with invocation id a3346363-f423-4404-790a-7785c45b5f7c
2019-09-27T11:07:58.561Z -START RequestId: a3346363-f423-4404-790a-7785c45b5f7c
2019-09-27T11:07:58.597Z -EVENT:
2019-09-27T11:07:58.597Z -{
2019-09-27T11:07:58.597Z - "message": "test1"
2019-09-27T11:07:58.597Z -}
2019-09-27T11:07:58.597Z -End RequestId: a3346363-f423-4404-790a-7785c45b5f7c
2019-09-27T11:08:13.135Z -Publishing message on topic "hello/world" with Payload "
{
"message": "Hello! Greengrass Core running on platform: linux-4.19.19 using NodeJS"
}
"
2019-09-27T11:08:13.153Z -Posting work for function arn:aws:lambda:::function:GGRouter to /2016-11-01/functions/arn:aws:lambda:::function:GGRouter
2019-09-27T11:08:13.21Z -Work posted with invocation ID b77f1c98-1328-4332-6dab-ac4428ed144c
2019-09-27T11:08:13.221Z -null
2019-09-27T11:08:13.225Z -b77f1c98-1328-4332-6dab-ac4428ed144c
2019-09-27T11:08:28.19Z -Publishing message on topic "hello/world" with Payload "
{
"message": "Hello! Greengrass Core running on platform: linux-4.19.19 using NodeJS"
}
"
2019-09-27T11:08:28.194Z -Posting work for function arn:aws:lambda:::function:GGRouter to /2016-11-01/functions/arn:aws:lambda:::function:GGRouter
2019-09-27T11:08:28.225Z -Work posted with invocation ID 3be706ff-00fc-4478-516c-3d3b1c59046e
2019-09-27T11:08:28.229Z -null
2019-09-27T11:08:28.232Z -3be706ff-00fc-4478-516c-3d3b1c59046e
2019-09-27T11:08:28.43Z -Caught SIGTERM. Stopping runtime.
2019-09-27T11:08:39.297Z -Running arn:aws:lambda:us-east-1:886556155174:function:nodeHello:2
2019-09-27T11:08:39.443Z -Getting work for function arn:aws:lambda:us-east-1:886556155174:function:nodeHello:2 from /2016-11-01/functions/arn:aws:lambda:us-east-1:886556155174:function:nodeHello:2/work
2019-09-27T11:08:39.701Z -Got work item with invocation id a3346363-f423-4404-790a-7785c45b5f7c
2019-09-27T11:08:39.763Z -START RequestId: a3346363-f423-4404-790a-7785c45b5f7c
2019-09-27T11:08:39.785Z -EVENT:
2019-09-27T11:08:39.785Z -{
2019-09-27T11:08:39.785Z - "message": "test1"
2019-09-27T11:08:39.785Z -}
2019-09-27T11:08:39.785Z -End RequestId: a3346363-f423-4404-790a-7785c45b5f7c
2019-09-27T11:08:54.375Z -Publishing message on topic "hello/world" with Payload "
{
"message": "Hello! Greengrass Core running on platform: linux-4.19.19 using NodeJS"
}
"
2019-09-27T11:08:54.394Z -Posting work for function arn:aws:lambda:::function:GGRouter to /2016-11-01/functions/arn:aws:lambda:::function:GGRouter
2019-09-27T11:08:54.451Z -Work posted with invocation ID 52583486-308f-442f-5856-516c7a6dbf32
2019-09-27T11:08:54.462Z -null
2019-09-27T11:08:54.466Z -52583486-308f-442f-5856-516c7a6dbf32
2019-09-27T11:09:09.432Z -Publishing message on topic "hello/world" with Payload "
{
"message": "Hello! Greengrass Core running on platform: linux-4.19.19 using NodeJS"
}
"
2019-09-27T11:09:09.436Z -Posting work for function arn:aws:lambda:::function:GGRouter to /2016-11-01/functions/arn:aws:lambda:::function:GGRouter
2019-09-27T11:09:09.468Z -Work posted with invocation ID 1124077e-9c57-40f3-64f9-e89b6733327e
2019-09-27T11:09:09.472Z -null
2019-09-27T11:09:09.475Z -1124077e-9c57-40f3-64f9-e89b6733327e
2019-09-27T11:09:09.657Z -Caught SIGTERM. Stopping runtime.
2019-09-27T11:09:20.597Z -Running arn:aws:lambda:us-east-1:886556155174:function:nodeHello:2
2019-09-27T11:09:20.715Z -Getting work for function arn:aws:lambda:us-east-1:886556155174:function:nodeHello:2 from /2016-11-01/functions/arn:aws:lambda:us-east-1:886556155174:function:nodeHello:2/work
2019-09-27T11:09:21.011Z -Got work item with invocation id 368f4813-b6e7-442d-4381-87e3fc39d87e
2019-09-27T11:09:21.072Z -START RequestId: 368f4813-b6e7-442d-4381-87e3fc39d87e
2019-09-27T11:09:21.094Z -EVENT:
2019-09-27T11:09:21.094Z -{
2019-09-27T11:09:21.094Z - "message": "test2"
2019-09-27T11:09:21.094Z -}
2019-09-27T11:09:21.094Z -End RequestId: 368f4813-b6e7-442d-4381-87e3fc39d87e
2019-09-27T11:09:35.667Z -Publishing message on topic "hello/world" with Payload "
{
"message": "Hello! Greengrass Core running on platform: linux-4.19.19 using NodeJS"
}
"
2019-09-27T11:09:35.685Z -Posting work for function arn:aws:lambda:::function:GGRouter to /2016-11-01/functions/arn:aws:lambda:::function:GGRouter
2019-09-27T11:09:35.748Z -Work posted with invocation ID c740ebb7-fe38-4269-6904-0aa2dbab880f
2019-09-27T11:09:35.759Z -null

KidIT
answered 5 years ago
0

I found the solution. The handler in the example wasn't calling the the callback function.
See thread 3073088
https://forums.aws.amazon.com/thread.jspa?threadID=307308&tstart=25

KidIT
answered 4 years ago

You are not logged in. Log in to post an answer.

A good answer clearly answers the question and provides constructive feedback and encourages professional growth in the question asker.

Guidelines for Answering Questions