RocketChat / Apps.Rasa

Integration between Rocket.Chat and the RASA Chatbot platform
17 stars 12 forks source link

RASA dialog breaking after only a few responses #13

Open bmwas opened 3 years ago

bmwas commented 3 years ago

Hello,

Thank you for this great library

I have integrated RASA as an app with one bot (bot1) serving as a live agent. Now, when I send a trigger (e.g. Hello) through an external service (i.e SMS) the RASA bot or live agent is able to respond once but the ensuing responses break (i.e. not submitted to twilio for sms delivery). Through an omnichannel manager account, I can see that the bot is responding correctly but for some reason the last response is not sent out to twilio for sms delivery. I have cross checked whether the bot is responding properly via a shell and everything seems to be okay from the RASA side. My observation is that if the last response is not sent out to twilio then rocketchat eventually crashes (Please see below).

I am particularly curios on this message printed below "The selected department and the current room department are the same [error-forwarding-chat-same-department] " and I was wondering whether this information might be useful. FYI - I have also tried this bot with a department where it's the only live agent to make sure this is issue is not occurring due to a routing error.

Any insights on this would be much appreciated. Thank you!

I20201231-03:15:31.613(-5)? The App 646b8e7d-f1e1-419e-9478-10d0f5bc74d9 is requesting from the outter webs: { I20201231-03:15:31.613(-5)? appId: '646b8e7d-f1e1-419e-9478-10d0f5bc74d9', I20201231-03:15:31.614(-5)? method: 'post', I20201231-03:15:31.614(-5)? url: 'http://localhost:5001/webhooks/rest/webhook', I20201231-03:15:31.614(-5)? request: { I20201231-03:15:31.614(-5)? headers: { 'Content-Type': 'application/json' }, I20201231-03:15:31.614(-5)? data: { sender: 'aAyCH2kSKuiiuk7ky', message: 'hello' }, I20201231-03:15:31.614(-5)? params: {}, I20201231-03:15:31.614(-5)? content: '{"sender":"aAyCH2kSKuiiuk7ky","message":"hello"}', I20201231-03:15:31.614(-5)? npmRequestOptions: {} I20201231-03:15:31.614(-5)? } I20201231-03:15:31.614(-5)? } I20201231-03:15:31.976(-5)? The App 646b8e7d-f1e1-419e-9478-10d0f5bc74d9 is getting the username: "bot1" I20201231-03:15:31.978(-5)? The App 646b8e7d-f1e1-419e-9478-10d0f5bc74d9 is getting the roomById: "aAyCH2kSKuiiuk7ky" I20201231-03:15:31.983(-5)? The App 646b8e7d-f1e1-419e-9478-10d0f5bc74d9 is creating a new message. I20201231-03:15:45.668(-5)? The App 646b8e7d-f1e1-419e-9478-10d0f5bc74d9 is requesting from the outter webs: { I20201231-03:15:45.669(-5)? appId: '646b8e7d-f1e1-419e-9478-10d0f5bc74d9', I20201231-03:15:45.669(-5)? method: 'post', I20201231-03:15:45.669(-5)? url: 'http://localhost:5001/webhooks/rest/webhook', I20201231-03:15:45.669(-5)? request: { I20201231-03:15:45.669(-5)? headers: { 'Content-Type': 'application/json' }, I20201231-03:15:45.669(-5)? data: { sender: 'aAyCH2kSKuiiuk7ky', message: 'i am not well' }, I20201231-03:15:45.669(-5)? params: {}, I20201231-03:15:45.670(-5)? content: '{"sender":"aAyCH2kSKuiiuk7ky","message":"i am not well"}', I20201231-03:15:45.670(-5)? npmRequestOptions: {} I20201231-03:15:45.670(-5)? } I20201231-03:15:45.670(-5)? } I20201231-03:15:46.701(-5)? The App 646b8e7d-f1e1-419e-9478-10d0f5bc74d9 is getting the username: "bot1" I20201231-03:15:46.704(-5)? The App 646b8e7d-f1e1-419e-9478-10d0f5bc74d9 is getting the roomById: "aAyCH2kSKuiiuk7ky" I20201231-03:15:46.714(-5)? The App 646b8e7d-f1e1-419e-9478-10d0f5bc74d9 is creating a new message. W20201231-03:25:52.063(-5)? (STDERR) === UnHandledPromiseRejection === W20201231-03:25:52.064(-5)? (STDERR) errorClass [Error]: The selected department and the current room department are the same [error-forwarding-chat-same-department] W20201231-03:25:52.064(-5)? (STDERR) at app/livechat/server/lib/Helper.js:287:9 W20201231-03:25:52.064(-5)? (STDERR) at /home/Benson/.meteor/packages/promise/.0.11.2.1b943fq.17dl++os+web.browser+web.browser.legacy+web.cordova/npm/node_modules/meteor-promise/fiber_pool.js:43:40 { W20201231-03:25:52.064(-5)? (STDERR) isClientSafe: true, W20201231-03:25:52.064(-5)? (STDERR) error: 'error-forwarding-chat-same-department', W20201231-03:25:52.064(-5)? (STDERR) reason: 'The selected department and the current room department are the same', W20201231-03:25:52.065(-5)? (STDERR) details: { function: 'forwardRoomToDepartment' }, W20201231-03:25:52.065(-5)? (STDERR) errorType: 'Meteor.Error' W20201231-03:25:52.065(-5)? (STDERR) } W20201231-03:25:52.065(-5)? (STDERR) --------------------------------- W20201231-03:25:52.065(-5)? (STDERR) Errors like this can cause oplog processing errors. W20201231-03:25:52.066(-5)? (STDERR) Setting EXIT_UNHANDLEDPROMISEREJECTION will cause the process to exit allowing your service to automatically restart the process W20201231-03:25:52.066(-5)? (STDERR) Future node.js versions will automatically exit the process W20201231-03:25:52.066(-5)? (STDERR) ================================= => Exited with code: 1 => Your application is crashing. Waiting for file change.

murtaza98 commented 3 years ago

Hey @bmwas

error-forwarding-chat-same-department <- Ideally, this error should actually take only when we are using the handover endpoint(ref). By any chance are u using this?

If not, then could u provide some more info by following the below 2 steps, it will help me to debug the issue

  1. Goto app logs (Administration -> Apps -> Rasa -> Click 3 dots -> View Logs). Here expand some of the latest executePostMessageSentHandler and see if there is some unusual logs eg errors, warnings, etc
  2. Currently u are using the app in synchronous mode. Do u mind trying the app in Asynchronous / Callback Mode. More info about this mode is available in the docs here on github

Please let me know what u find, Thanks! :smile:

bmwas commented 3 years ago

@murtaza98 Thank you so much for your response.

As for your forwarding question, I am not doing the forwarding/handover at this point as the intention is to have the bot complete most of the dialog and then possibly in the next step add a handover action.

I have generated the logs as requested - please see below. Also, I have grabbed another console printout that shows the first two responses of the dialog are successful but the third response is not returned to the sms number which in a strange way I can see the bot responded once I login as the omnichannel account manager but the third response is not sent back to Twilio. Thank you so much!

REQUESTED LOGS BEGIN HERE

Instance: BLGhLXfXhJQLrKTEt debug: 2021-01-01T06:06:58.819Z Caller: anonymous OR constructor [ "executePostMessageSent is being called..." ] debug: 2021-01-01T06:06:58.918Z Caller: anonymous OR constructor [ "'executePostMessageSent' was successfully called! The result is:", null ]

Instance: BLGhLXfXhJQLrKTEt debug: 2021-01-01T06:06:58.953Z Caller: anonymous OR constructor [ "executePostMessageSent is being called..." ] debug: 2021-01-01T06:06:58.954Z Caller: anonymous OR constructor [ "'executePostMessageSent' was successfully called! The result is:", null ]

January 1, 2021 1:07 AM: "executePostMessageSent" (1091ms) Instance: BLGhLXfXhJQLrKTEt debug: 2021-01-01T06:07:07.471Z Caller: anonymous OR constructor [ "executePostMessageSent is being called..." ] debug: 2021-01-01T06:07:08.562Z Caller: anonymous OR constructor [ "'executePostMessageSent' was successfully called! The result is:", null ]

January 1, 2021 1:07 AM: "executePostMessageSent" (1ms) Instance: BLGhLXfXhJQLrKTEt debug: 2021-01-01T06:07:08.575Z Caller: anonymous OR constructor [ "executePostMessageSent is being called..." ] debug: 2021-01-01T06:07:08.576Z Caller: anonymous OR constructor [ "'executePostMessageSent' was successfully called! The result is:", null ]

CONSOLE PRINTOUT BEGINS HERE

==============

SMS to omnichannel - "hello"


Console output

I20210101-00:29:18.916(-5)? The App 646b8e7d-f1e1-419e-9478-10d0f5bc74d9 is requesting from the outter webs: { I20210101-00:29:18.916(-5)? appId: '646b8e7d-f1e1-419e-9478-10d0f5bc74d9', I20210101-00:29:18.916(-5)? method: 'post', I20210101-00:29:18.916(-5)? url: 'http://localhost:5001/webhooks/rest/webhook', I20210101-00:29:18.917(-5)? request: { I20210101-00:29:18.917(-5)? headers: { 'Content-Type': 'application/json' }, I20210101-00:29:18.917(-5)? data: { sender: 'w8H8K6qgM93K4T6hS', message: 'hello' }, I20210101-00:29:18.917(-5)? params: {}, I20210101-00:29:18.917(-5)? content: '{"sender":"w8H8K6qgM93K4T6hS","message":"hello"}', I20210101-00:29:18.917(-5)? npmRequestOptions: {} I20210101-00:29:18.929(-5)? } I20210101-00:29:18.929(-5)? } I20210101-00:29:18.974(-5)? The App 646b8e7d-f1e1-419e-9478-10d0f5bc74d9 is getting the username: "bot1" I20210101-00:29:18.976(-5)? The App 646b8e7d-f1e1-419e-9478-10d0f5bc74d9 is getting the roomById: "w8H8K6qgM93K4T6hS" I20210101-00:29:18.985(-5)? The App 646b8e7d-f1e1-419e-9478-10d0f5bc74d9 is creating a new message.

BOT response to SMS number "How are you?"


Console output

I20210101-00:29:18.974(-5)? The App 646b8e7d-f1e1-419e-9478-10d0f5bc74d9 is getting the username: "bot1" I20210101-00:29:18.976(-5)? The App 646b8e7d-f1e1-419e-9478-10d0f5bc74d9 is getting the roomById: "w8H8K6qgM93K4T6hS" I20210101-00:29:18.985(-5)? The App 646b8e7d-f1e1-419e-9478-10d0f5bc74d9 is creating a new message. I20210101-00:31:48.280(-5)? The App 646b8e7d-f1e1-419e-9478-10d0f5bc74d9 is requesting from the outter webs: { I20210101-00:31:48.280(-5)? appId: '646b8e7d-f1e1-419e-9478-10d0f5bc74d9', I20210101-00:31:48.280(-5)? method: 'post', I20210101-00:31:48.280(-5)? url: 'http://localhost:5001/webhooks/rest/webhook', I20210101-00:31:48.280(-5)? request: { I20210101-00:31:48.280(-5)? headers: { 'Content-Type': 'application/json' }, I20210101-00:31:48.280(-5)? data: { sender: 'w8H8K6qgM93K4T6hS', message: 'i am ok' }, I20210101-00:31:48.280(-5)? params: {}, I20210101-00:31:48.281(-5)? content: '{"sender":"w8H8K6qgM93K4T6hS","message":"i am ok"}', I20210101-00:31:48.281(-5)? npmRequestOptions: {} I20210101-00:31:48.281(-5)? } I20210101-00:31:48.281(-5)? } I20210101-00:31:49.315(-5)? The App 646b8e7d-f1e1-419e-9478-10d0f5bc74d9 is getting the username: "bot1" I20210101-00:31:49.317(-5)? The App 646b8e7d-f1e1-419e-9478-10d0f5bc74d9 is getting the roomById: "w8H8K6qgM93K4T6hS" I20210101-00:31:49.327(-5)? The App 646b8e7d-f1e1-419e-9478-10d0f5bc74d9 is creating a new message.


NO response from BOT anymore BUT - the response is actually posted on the omnichannel as I've checked through the omnichannel account manager BUT the last response is never sent to twilio/sms.