NodeError - write after end

[andreslavariega]

Hello I have this error, it is a sporadic error, it usually happens when the iteration is in progress.

  "type": "**NodeError**",
  "message": "**write after end**",

I use asterisk 16, mosquitto version 1.5.7, yarn run v1.22.19, node v14.19.3.

Thanks for your support.

[1655145086834] INFO  (Dialogflow-AudioServer/2182 on desarrollo-rtp-server): Got a message sending to dialogflow-asterisk/1655145077.103/events

[1655145086857] ERROR (Dialogflow-AudioServer/2182 on desarrollo-rtp-server): Got an error from dialogflow

id: "1655145077.103"
err: {
  "type": "NodeError",
  "message": "write after end",
  "stack":
      Error [ERR_STREAM_WRITE_AFTER_END]: write after end
          at new NodeError (internal/errors.js:322:7)
          at ClientHttp2Stream.Writable.write (internal/streams/writable.js:292:11)
          at /usr/src/asterisk-dialogflow-rtp-audioserver/node_modules/@grpc/grpc-js/build/src/call-stream.js:603:38
          at runMicrotasks (<anonymous>)
          at processTicksAndRejections (internal/process/task_queues.js:95:5)
  "code": "ERR_STREAM_WRITE_AFTER_END"

[danjenkins]

When does this happen? Looks like we're writing to the GRPC dialogflow stream after it's been closed...

[andreslavariega]

Sorry for the delay, I was doing more testing and connecting to a sip trunk.

In some tests I see this log, it happens when it takes a while to respond by voice.

[1655420972453] INFO  (Asterisk-Dialogflow-ARI-Bridge/9629 on matrix): got a message
    topic: "dialogflow-asterisk/1655420962.304/events"
    payload: {
      "transcript": {
        "speechWordInfo": [],
        "messageType": "END_OF_SINGLE_UTTERANCE",
        "transcript": "",
        "isFinal": false,
        "confidence": 0,
        "stability": 0,
        "speechEndOffset": {
          "seconds": "9",
          "nanos": 30000000
        }
      },
      "intent": null
    }
[1655420972522] INFO  (Asterisk-Dialogflow-ARI-Bridge/9629 on matrix): got a message
    topic: "dialogflow-asterisk/1655420962.304/events"
    payload: {
      "transcript": null,
      "intent": {
        "fulfillmentMessages": [],
        "outputContexts": [],
        "queryText": "",
        "speechRecognitionConfidence": 0,
        "action": "",
        "parameters": null,
        "allRequiredParamsPresent": false,
        "fulfillmentText": "",
        "webhookSource": "",
        "webhookPayload": null,
        "intent": null,
        "intentDetectionConfidence": 0,
        "diagnosticInfo": null,
        "languageCode": "es",
        "sentimentAnalysisResult": null,
        "knowledgeAnswers": null
      }
    }
(node:9629) UnhandledPromiseRejectionWarning: TypeError: Cannot read property 'fields' of null
    at Bridge.<anonymous> (/usr/src/asterisk-dialogflow-ari-bridge/index.js:86:63)
    at Bridge.emit (events.js:400:28)
    at Bridge.receivedDialogFlowEvent (/usr/src/asterisk-dialogflow-ari-bridge/lib/Bridge.js:31:14)
    at MqttClient.<anonymous> (/usr/src/asterisk-dialogflow-ari-bridge/index.js:29:28)
    at MqttClient.emit (events.js:400:28)
    at MqttClient._handlePublish (/usr/src/asterisk-dialogflow-ari-bridge/node_modules/async-mqtt/node_modules/mqtt/lib/client.js:1547:12)
    at MqttClient._handlePacket (/usr/src/asterisk-dialogflow-ari-bridge/node_modules/async-mqtt/node_modules/mqtt/lib/client.js:535:12)
    at work (/usr/src/asterisk-dialogflow-ari-bridge/node_modules/async-mqtt/node_modules/mqtt/lib/client.js:438:12)
    at Writable.writable._write (/usr/src/asterisk-dialogflow-ari-bridge/node_modules/async-mqtt/node_modules/mqtt/lib/client.js:452:5)
    at doWrite (/usr/src/asterisk-dialogflow-ari-bridge/node_modules/readable-stream/lib/_stream_writable.js:409:139)
    at writeOrBuffer (/usr/src/asterisk-dialogflow-ari-bridge/node_modules/readable-stream/lib/_stream_writable.js:398:5)
    at Writable.write (/usr/src/asterisk-dialogflow-ari-bridge/node_modules/readable-stream/lib/_stream_writable.js:307:11)
    at Socket.ondata (internal/streams/readable.js:731:22)
    at Socket.emit (events.js:400:28)
    at addChunk (internal/streams/readable.js:293:12)
    at readableAddChunk (internal/streams/readable.js:267:9)
(node:9629) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 2)

[andreslavariega]

Hi, i review the log and I comparated with mqtt events and i see this event from dialogFlow. This happens when I have a call established, and the audio on the dialogflow side is long (maybe 15 seconds). When dialogFlow finishes speaking I want to respond and that is when the error "ERR_STREAM_WRITE_AFTER_END" appears.

In my conf is this.

singleUtterance: true.

[1694809334507] INFO  (Dialogflow-AudioServer/29856 on desarrollo-rtp-server): Dialogflow data
    id: "1694809302.1293"
    body: {
      "transcript": {
        "speechWordInfo": [],
        "messageType": "END_OF_SINGLE_UTTERANCE",
        "transcript": "",
        "isFinal": false,
        "confidence": 0,
        "stability": 0,
        "speechEndOffset": {
          "seconds": "9",
          "nanos": 30000000
        }
      },
      "intent": null
    }

and after I see this log

 id: "1694809302.1293"
    err: {
      "type": "NodeError",
      "message": "write after end",
      "stack":
          Error [ERR_STREAM_WRITE_AFTER_END]: write after end
              at new NodeError (internal/errors.js:322:7)
              at ClientHttp2Stream.Writable.write (internal/streams/writable.js:292:11)
              at /usr/src/asterisk-dialogflow-rtp-audioserver/node_modules/@grpc/grpc-js/build/src/call-stream.js:603:38
              at runMicrotasks (<anonymous>)
              at processTicksAndRejections (internal/process/task_queues.js:95:5)
      "code": "ERR_STREAM_WRITE_AFTER_END"
    }

[danjenkins]

Yeah it looks like we're writing to the dialogflow stream after its finished - the streams are short in length so we have to make sure we write to the right one at the right time otherwise we end up writing to a stream object thats ended. I haven't got much time to work on this at the moment. First thing to look at would be whether dialogflow expects less than 59 seconds of audio now? https://github.com/nimbleape/asterisk-dialogflow-rtp-audioserver/blob/master/lib/DialogFlowConnector.js#L51-L142 gets called every 59 seconds by the setupTimer function