[auto/nodejs] - Reimplement JSON event parsing with Readline

[komalali]

Description

A few users have reported a failure when running Stack.preview() due to JSON failing to parse. Unfortunately, the error message wasn't really telling us what the actual issue was, but we were able to get some more details by adding debugging logging and getting some help from users.

I traced this issue back to the split2 library, where incomplete lines might be dropped. This could happen if the logfile is polled when a message is being written, resulting in a half-formed JSON line. I've replaced it using Readline. I've also added additional error logging in case we see these errors again.

Fixes: #6768

Checklist

• I have added tests that prove my fix is effective or that my feature works

• I have updated the CHANGELOG-PENDING file with my change

This error is difficult to test as it is intermittent, but the existing tests for parsing events continue to succeed. We'll keep an eye on this to see if we see any more reports.

[lukehoban]

Fixes #6768

Don't we still want to fix the issue that is causing malformed event payloads to be received from the CLI? Is that perhaps an issue with needing to flush some buffer before the CLI exits?

[alex-berger]

I monkey patched my system with this PR and now I see the following log messages, which reveal that the event's JSON payload is invalid. It looks like there are some bytes missing at the beginning of the JSON payload.

failed to parse engine event
event: arent":"urn:pulumi:dev.cd-lab-nexiot.eu-central-1::eks-cluster-nxc-v1::nx:aws:eks:ControlPlane::EKSClusterV1","inputs":{"apiVersion":"v1","kind":"Namespace","metadata":{"annotations":{"config.linkerd.io/admission-webhooks":"disabled"},"labels":{"app.kubernetes.io/managed-by":"pulumi"},"name":"linkerd"}},"outputs":{"__initialApiVersion":"v1","__inputs":{"apiVersion":"v1","kind":"Namespace","metadata":{"annotations":{"config.linkerd.io/admission-webhooks":"disabled"},"labels":{"app.kubernetes.io/managed-by":"pulumi"},"name":"linkerd"}},"apiVersion":"v1","kind":"Namespace","metadata":{"annotations":{"config.linkerd.io/admission-webhooks":"disabled","kubectl.kubernetes.io/last-applied-configuration":"{\"apiVersion\":\"v1\",\"kind\":\"Namespace\",\"metadata\":{\"annotations\":{\"config.linkerd.io/admission-webhooks\":\"disabled\"},\"labels\":{\"app.kubernetes.io/managed-by\":\"pulumi\"},\"name\":\"linkerd\"}}\n"},"creationTimestamp":"2021-03-18T13:56:48Z","labels":{"app.kubernetes.io/managed-by":"pulumi","linkerd.tree.hnc.x-k8s.io/depth":"0"},"managedFields":[{"apiVersion":"v1","fieldsType":"FieldsV1","fieldsV1":{"f:metadata":{"f:annotations":{".":{},"f:config.linkerd.io/admission-webhooks":{},"f:kubectl.kubernetes.io/last-applied-configuration":{}},"f:labels":{".":{},"f:app.kubernetes.io/managed-by":{}}},"f:status":{"f:phase":{}}},"manager":"pulumi-resource-kubernetes","operation":"Update","time":"2021-03-18T13:56:48Z"},{"apiVersion":"v1","fieldsType":"FieldsV1","fieldsV1":{"f:metadata":{"f:labels":{"f:linkerd.tree.hnc.x-k8s.io/depth":{}}}},"manager":"manager","operation":"Update","time":"2021-03-19T09:05:01Z"}],"name":"linkerd","resourceVersion":"845369","selfLink":"/api/v1/namespaces/linkerd","uid":"d3b20ffe-ec6d-40ff-ba3c-0ba96cf18673"},"spec":{"finalizers":["kubernetes"]},"status":{"phase":"Active"}},"provider":""},"new":{"type":"kubernetes:core/v1:Namespace","urn":"urn:pulumi:dev.cd-lab-nexiot.eu-central-1::eks-cluster-nxc-v1::nx:aws:eks:ControlPlane$kubernetes:core/v1:Namespace::EKSClusterV1-Linkerd2Namespace","custom":true,"id":"linkerd","parent":"urn:pulumi:dev.cd-lab-nexiot.eu-central-1::eks-cluster-nxc-v1::nx:aws:eks:ControlPlane::EKSClusterV1","inputs":{"apiVersion":"v1","kind":"Namespace","metadata":{"annotations":{"config.linkerd.io/admission-webhooks":"disabled"},"labels":{"app.kubernetes.io/managed-by":"pulumi"},"name":"linkerd"}},"outputs":{"__initialApiVersion":"v1","__inputs":{"apiVersion":"v1","kind":"Namespace","metadata":{"annotations":{"config.linkerd.io/admission-webhooks":"disabled"},"labels":{"app.kubernetes.io/managed-by":"pulumi"},"name":"linkerd"}},"apiVersion":"v1","kind":"Namespace","metadata":{"annotations":{"config.linkerd.io/admission-webhooks":"disabled","kubectl.kubernetes.io/last-applied-configuration":"{\"apiVersion\":\"v1\",\"kind\":\"Namespace\",\"metadata\":{\"annotations\":{\"config.linkerd.io/admission-webhooks\":\"disabled\"},\"labels\":{\"app.kubernetes.io/managed-by\":\"pulumi\"},\"name\":\"linkerd\"}}\n"},"creationTimestamp":"2021-03-18T13:56:48Z","labels":{"app.kubernetes.io/managed-by":"pulumi","linkerd.tree.hnc.x-k8s.io/depth":"0"},"managedFields":[{"apiVersion":"v1","fieldsType":"FieldsV1","fieldsV1":{"f:metadata":{"f:annotations":{".":{},"f:config.linkerd.io/admission-webhooks":{},"f:kubectl.kubernetes.io/last-applied-configuration":{}},"f:labels":{".":{},"f:app.kubernetes.io/managed-by":{}}},"f:status":{"f:phase":{}}},"manager":"pulumi-resource-kubernetes","operation":"Update","time":"2021-03-18T13:56:48Z"},{"apiVersion":"v1","fieldsType":"FieldsV1","fieldsV1":{"f:metadata":{"f:labels":{"f:linkerd.tree.hnc.x-k8s.io/depth":{}}}},"manager":"manager","operation":"Update","time":"2021-03-19T09:05:01Z"}],"name":"linkerd","resourceVersion":"845369","selfLink":"/api/v1/namespaces/linkerd","uid":"d3b20ffe-ec6d-40ff-ba3c-0ba96cf18673"},"spec":{"finalizers":["kubernetes"]},"status":{"phase":"Active"}},"provider":""},"logical":true,"provider":"urn:pulumi:dev.cd-lab-nexiot.eu-central-1::eks-cluster-nxc-v1::nx:aws:eks:ControlPlane$pulumi:providers:kubernetes::EKSClusterV1-KubernetesProvider::8878cc8b-eb19-4788-af2a-78e944544481"},"planning":true}}
SyntaxError: Unexpected token a in JSON at position 0
 
failed to parse engine event
event: l":true,"provider":"urn:pulumi:dev.cd-lab-nexiot.eu-central-1::eks-cluster-nxc-v1::pulumi:providers:aws::default_4_3_0::04da6b54-80e4-46f7-96ec-b56ff0331ba9"},"planning":true}}
SyntaxError: Unexpected token l in JSON at position 0

[komalali]

@alex-berger thank you for that! that is super helpful.

@lukehoban I don't think it's the payload from the CLI that is malformed, but more likely how the file tailer is reading it. In any case, yes that is what we need to fix and @alex-berger's feedback has been super helpful in illuminating the issue.

[komalali]

I am still struggling to replicate this issue locally. @lukehoban curious to hear why you think this is a CLI-side error.

[EvanBoyle]

@komalali how about logging the full path of the event file on error as well? Then @alex-berger can share the full contents to inform debugging.

[EvanBoyle]

@komalali I think we'll also need to disable the cleanup logic at the time of logging so that the file doesn't get removed.

[komalali]

Okay, I removed split2. I think it was dropping situations where there was an incomplete message in the buffer. Curious to see if this new implementation helps.