Problem
I am developing a Actions on Google app (intended for the Google Home), using the Actions on Google library for Node.js, hosted on Firebase Google Functions, via Dialogflow. I often, but irregularly (and hard to replicate), encounter an error, forcing the Actions on Google (simulator or Google Home itself) to shut down my app. I route everything from any Dialogflow intent (including fallbacks) to my webhook fulfilment, and - based on the log files - the webhook responds quickly (within ~200ms) and with valid responses (investigating the JSON responses). However, the Actions on Google seems to reject the response and triggers the Dialogflow default text response. My biggest concern, is that it happens at different stages in the conversation, sometimes already at the Welcome event. It is also noticeable that - even though the fulfillment responds in milliseconds (~200), the Actions on Google / Dialogflow takes its time and - what I believe - has a timeout. Below are my explorations into the potential cause. But frankly, I am out of ideas.
-- Edit --
The service seems to run better now - I haven't experience this error. I have changed the code to call admin.firestore() less often, by using a global databse and passing it through. I had a hunch that, potentially the https functions were called simultaneously which might have caused a malformed response somehow.
const database = admin.firestore();
// code
if (!process.env.FUNCTION_NAME || process.env.FUNCTION_NAME === 'functionname') {
exports.functionname = functions.https.onRequest((req, res) => {
require('./functions').functionname(req, res, database);
});
}
I also found a flaw in my intent handeling, which caused no intent to be matched. I've restructured the Dialogflow intents to have less possibility of this no-intent (I basically made a two-step question to determine the user's intention). However, since the webhook did response correctly, I don't believe this was the problem. Still, I find it an odd error - so if anyone has more pointers please!
-- end edit --
Logs
This is a response from the webhook as seen from the Google Functions Log - indicating a send response to the Dialogflow app.
Function execution took 289 ms, finished with status code: 200
Response {
"status": 200,
"headers": {
"content-type": "application/json;charset=utf-8"
},
"body": {
"payload": {
"google": {
"expectUserResponse": true,
"richResponse": {
"items": [{
"simpleResponse": {
"textToSpeech": "Welcome back! Which Widget do you want to work with?"
}
}]
}
}
},
"outputContexts": [{
"name": "****anonymized****/contexts/widget",
"lifespanCount": 1
},
{
"name": "***anonymized****/contexts/_actions_on_google",
"lifespanCount": 99,
"parameters": {
"data": "{\"started\":1552071670}"
}
}
]
}
}
However, this is what the Actions on Google console shows. The textToSpeech response is the default text response where DialogFlow can fall back to in case the fulfilment fails (as suggested by https://medium.com/google-developers/debugging-common-actions-on-google-errors-7c8527378d27)
{
"conversationToken": "[]",
"finalResponse": {
"richResponse": {
"items": [
{
"simpleResponse": {
"textToSpeech": "Sorry! I cannot access my online service. Please try again!"
}
}
]
}
},
"responseMetadata": {
"status": {
"code": 14,
"message": "Webhook error (206)"
},
"queryMatchInfo": {
"queryMatched": true,
"intent": "e0bf4b96-9440-4545-a8a6-d0915cacd34f"
}
}
}
The stackdriver logs also indicate the latter case, where the default response from Dialogflow is received.
Thoughts
I have tried to replicate this error on the simulator, on my phone and on a Google Home. It occurs at different moments, though seems to occur more frequently than before. My three hunches are the following:
- Overload. My Google Functions hosts 8 functions, including the Dialogflow app. Perhaps if the other functions are also called frequently at a given moment, something goes wrong with the Dialogflow app handeling the https requests from Dialogflow (the Google Assistant). However, I do not see how this should happen. I could replicate (sometimes) the problem by invoking the app on two devices with two different accounts. But since it also happens with one account I don't see this can be the only problem. I've followed this tip to reduce overload (https://stackoverflow.com/a/47985480/7053198) but that did not seem to help my issue. Can then the upscaling of Google Functions be a problem here?
- Promise hell. I am using a number of promises (or more callbacks) to communicate with a Firestore database to retreive user data. However, I can invoke these intents quite rapidly, and they resolve nicely - up to a point where they don't. Below is a snippet of such one intent.
- Size of my app. The number of Intents has gotten quite large, and there is a lot of communication between the Google Functions and the Firestore database. I just don't know how this might influence the rejection of the seemingly correct response by Dialogflow.
Intent with promises snippet:
app.intent(I.WIDGETTEST, conv => {
let database = admin.firestore();
let offline = [];
return database.collection('users').doc(conv.user.storage.userId).collection('widgets').get()
.then((snapshot) => {
const promises = [];
snapshot.forEach(doc => {
if (doc.data().active) {
if ((moment().unix()-doc.data().server.seen) > 360){
offline.push(doc.data().name);
}
promises.push(doc.ref.update({'todo.test': true}));
}
});
return Promise.all(promises);
})
.then(()=>{
conv.contexts.set(C.WIDGET, 1);
return conv.ask("Testing in progress. Which Widget do you want to work with now?");
})
.catch((err) => {
console.log(err)
throw err;
});
});
Problem Example Log
For good measure, here three log entries from the stackdriver side of things:
{
"textPayload": "Sending request with post data: {\"user\":{\"userId\":\"***anonymized***\",\"locale\":\"en-US\",\"lastSeen\":\"2019-03-08T18:54:47Z\",\"userStorage\":\"{\\\"data\\\":{\\\"userId\\\":\\\"***anonymized***\\\"}}\",\"idToken\":\"eyJhbGciOiJSUzI1NiIsImtpZCI6ImNmMDIyYTQ5ZTk3ODYxNDhhZDBlMzc5Y2M4NTQ4NDRlMzZjM2VkYzEiLCJ0eXAiOiJKV1QifQ.eyJpc3MiOiJodHRwczovL2FjY291bnRzLmdvb2dsZS5jb20iLCJuYmYiOjE1NTIwNzEzNjAsImF1ZCI6Ijk4NzgxNjU4MTIzMC1ibWVtMm5wcTRsNnE3c2I5MnVpM3BkdGRhMWFmajJvNy5hcHBzLmdvb2dsZXVzZXJjb250ZW50LmNvbSIsInN1YiI6IjEwMjk3OTk3NzIyNTM3NjY4MDEyOSIsImVtYWlsIjoiZGF2aWR2ZXJ3ZWlqQGdtYWlsLmNvbSIsImVtYWlsX3ZlcmlmaWVkIjp0cnVlLCJuYW1lIjoiRCBWZXJ3ZWlqIiwicGljdHVyZSI6Imh0dHBzOi8vbGg2Lmdvb2dsZXVzZXJjb250ZW50LmNvbS8taldtOFd3eE5iS3MvQUFBQUFBQUFBQUkvQUFBQUFBQUFyLUUvNEE2UmJiYVNwem8vczk2LWMvcGhvdG8uanBnIiwiZ2l2ZW5fbmFtZSI6IkQiLCJmYW1pbHlfbmFtZSI6IlZlcndlaWoiLCJpYXQiOjE1NTIwNzE2NjAsImV4cCI6MTU1MjA3NTI2MCwianRpIjoiYjE4MDYwMjc0YmE4MjJhYzFhYzc0MTYwZjI2YWM2MDk3MzBmZDY4ZSJ9.Y9G0qo0Gf28-noF7RYPhtfHRuA7Qo6bCBSuN56Y0AtgIXaQKZjnmYvABIt9u8WQ1qPWwQc3jOLyhfoXIk8j0zhcQ0M0oc7LjkBwVCgFnJHvUAiV5fGEqQa95pZyrZhYmHipTDdwk0UhJHFGJOXAHDPP6oBSHKC9h48jqUjVszz6iEy4frV0XIKIzRR2U2iY6OgJuxPsV0A7xNjvLXiMmwaRUVtlj9CPmiizd3G2PhqD5C54Fy2Qg5ch89qMOA10vNB5B4AX9pmAXHpmtIqFo7ljvAeGAj-pRuqyMllz2awAdvqqOFRERDYfm5Fyh7N0l1OhR2A2XRegsUIL1I1EVPQ\"},\"conversation\":{\"conversationId\":\"ABwppHH8PXibDZg8in1DjbP-caFy67Dtq025k_Uq2ofoPNXKtiPXrbJTmpGVUnVy-aY6H1MeZCFIpQ\",\"type\":\"NEW\"},\"inputs\":[{\"intent\":\"actions.intent.MAIN\",\"rawInputs\":[{\"inputType\":\"KEYBOARD\",\"query\":\"Talk to ***anonymized appname***\"}]}],\"surface\":{\"capabilities\":[{\"name\":\"actions.capability.SCREEN_OUTPUT\"},{\"name\":\"actions.capability.MEDIA_RESPONSE_AUDIO\"},{\"name\":\"actions.capability.AUDIO_OUTPUT\"},{\"name\":\"actions.capability.WEB_BROWSER\"}]},\"isInSandbox\":true,\"availableSurfaces\":[{\"capabilities\":[{\"name\":\"actions.capability.SCREEN_OUTPUT\"},{\"name\":\"actions.capability.AUDIO_OUTPUT\"},{\"name\":\"actions.capability.WEB_BROWSER\"}]}],\"requestType\":\"SIMULATOR\"}.",
"insertId": "120zsprg2nqfayb",
"resource": {
"type": "assistant_action",
"labels": {
"action_id": "actions.intent.MAIN",
"project_id": "***anonymized***",
"version_id": ""
}
},
"timestamp": "2019-03-08T19:01:00.243055001Z",
"severity": "DEBUG",
"labels": {
"channel": "preview",
"source": "AOG_REQUEST_RESPONSE",
"querystream": "GOOGLE_USER"
},
{
"textPayload": "Received response from agent with body: HTTP/1.1 200 OK\r\nServer: nginx/1.13.6\r\nDate: Fri, 08 Mar 2019 19:01:10 GMT\r\nContent-Type: application/json;charset=UTF-8\r\nContent-Length: 330\r\nX-Cloud-Trace-Context: 7761b69610701e0a7d18cbc69eef9bde/3001560133061614360;o=0\r\nGoogle-Actions-API-Version: 2\r\nAccess-Control-Allow-Credentials: true\r\nVia: 1.1 google\r\nAlt-Svc: clear\r\n\r\n{\"conversationToken\":\"[]\",\"finalResponse\":{\"richResponse\":{\"items\":[{\"simpleResponse\":{\"textToSpeech\":\"Sorry! I cannot access my online service. Please try again!\"}}]}},\"responseMetadata\":{\"status\":{\"code\":14,\"message\":\"Webhook error (206)\"},\"queryMatchInfo\":{\"queryMatched\":true,\"intent\":\"e0bf4b96-9440-4545-a8a6-d0915cacd34f\"}}}.",
"insertId": "120zsprg2nqfayc",
"resource": {
"type": "assistant_action",
"labels": {
"project_id": "***anonymized***",
"version_id": "",
"action_id": "actions.intent.MAIN"
}
},
"timestamp": "2019-03-08T19:01:10.376894030Z",
"severity": "DEBUG",
"labels": {
"channel": "preview",
"source": "AOG_REQUEST_RESPONSE",
"querystream": "GOOGLE_USER"
},
"logName": "projects/***anonymized***/logs/actions.googleapis.com%2Factions",
"trace": "projects/987816581230/traces/ABwppHH8PXibDZg8in1DjbP-caFy67Dtq025k_Uq2ofoPNXKtiPXrbJTmpGVUnVy-aY6H1MeZCFIpQ",
"receiveTimestamp": "2019-03-08T19:01:10.389139428Z"
},
{
"textPayload": "MalformedResponse: Webhook error (206)",
"insertId": "1d4bzl9g3lossug",
"resource": {
"type": "assistant_action",
"labels": {
"project_id": "***anonymized***",
"version_id": "",
"action_id": "actions.intent.MAIN"
}
},
"timestamp": "2019-03-08T19:01:10.377231474Z",
"severity": "ERROR",
"labels": {
"channel": "preview",
"source": "JSON_RESPONSE_VALIDATION",
"querystream": "GOOGLE_USER"
},
"logName": "projects/***anonymized***/logs/actions.googleapis.com%2Factions",
"trace": "projects/987816581230/traces/ABwppHH8PXibDZg8in1DjbP-caFy67Dtq025k_Uq2ofoPNXKtiPXrbJTmpGVUnVy-aY6H1MeZCFIpQ",
"receiveTimestamp": "2019-03-08T19:01:10.388395945Z"
}
Help!
Any help or guidance towards unraveling this issue is much apreciated. Let me know if you have experienced this before, have a potential solution or would like to see more details of the code or logs. Many thanks!
