search

microsoft / BotFramework-Hubot

Hubot adapter for botframework
MIT License
111 stars 40 forks source link

Hubot not able to respond #43

Open wsoula opened 5 years ago

wsoula commented 5 years ago

My hubot is registered with bot services and I can correctly send a message to it and get a response:

[Thu Nov 08 2018 18:04:28 GMT+0000 (UTC)] INFO hubot-botframework-adapter: onBotEvents
[Thu Nov 08 2018 18:04:28 GMT+0000 (UTC)] INFO hubot-botframework-adapter: Handling activity Channel:                            webchat; type: message
[Thu Nov 08 2018 18:04:28 GMT+0000 (UTC)] INFO hubot-botframework-middleware: creating middleware...
[Thu Nov 08 2018 18:04:28 GMT+0000 (UTC)] INFO hubot-botframework-middleware: TextMiddleware toReceivable
[Thu Nov 08 2018 18:04:28 GMT+0000 (UTC)] DEBUG Message 'orly' matched regex //orly/i/; listener.options = { id: null }
[Thu Nov 08 2018 18:04:28 GMT+0000 (UTC)] DEBUG Executing listener callback for Message 'orly'
[Thu Nov 08 2018 18:04:28 GMT+0000 (UTC)] INFO hubot-botframework-adapter: send
[Thu Nov 08 2018 18:04:28 GMT+0000 (UTC)] INFO hubot-botframework-adapter: reply
[Thu Nov 08 2018 18:04:28 GMT+0000 (UTC)] INFO hubot-botframework-middleware: creating middleware...
[Thu Nov 08 2018 18:04:28 GMT+0000 (UTC)] INFO hubot-botframework-middleware: TextMiddleware toSendable

But after I add it to the Team and channel and send a message to the bot it tries to respond but no response is getting back to me:

[Thu Nov 08 2018 18:05:48 GMT+0000 (UTC)] INFO hubot-botframework-adapter: onBotEvents
[Thu Nov 08 2018 18:05:48 GMT+0000 (UTC)] INFO hubot-botframework-adapter: Handling activity Channel:                            msteams; type: message
[Thu Nov 08 2018 18:05:48 GMT+0000 (UTC)] INFO hubot-botframework-middleware: creating middleware...
[Thu Nov 08 2018 18:05:48 GMT+0000 (UTC)] INFO hubot-msteams: toReceivable
[Thu Nov 08 2018 18:05:48 GMT+0000 (UTC)] DEBUG Message 'Sparky orly' matched regex //orly/i/; listener.options = { id: null }
[Thu Nov 08 2018 18:05:48 GMT+0000 (UTC)] DEBUG Executing listener callback for Message 'Sparky orly'
[Thu Nov 08 2018 18:05:48 GMT+0000 (UTC)] INFO hubot-botframework-adapter: send
[Thu Nov 08 2018 18:05:48 GMT+0000 (UTC)] INFO hubot-botframework-adapter: reply
[Thu Nov 08 2018 18:05:48 GMT+0000 (UTC)] INFO hubot-botframework-middleware: creating middleware...
[Thu Nov 08 2018 18:05:48 GMT+0000 (UTC)] INFO hubot-msteams: toSendable

I had this working yesterday, then I changed the name of my hubot and it would never work again. I changed the name back but it still doesnt work. I tried making a new app in app studio and removing the old app and changing the id of the app and the version of the app. I don't have permissions to create a new bot so I couldnt try that. I don't know where to look to find what the error is, the channel page has no error for MS Teams except when I uninstall the app when it says I don't have permissions to do something. Can anyone help point me to what I can look at to troubleshoot this issue, its really hard to know what the issue is when I don't get an error anywhere. Thanks a lot!

MatSFT commented 5 years ago

Hi, could you try setting this environment variable before you launch your bot and see if you get any additional error messages? NODE_DEBUG=botbuilder

wsoula commented 5 years ago

I only get one new line in the beginning saying message received:

ChatConnector: message received.
[Thu Nov 08 2018 20:19:52 GMT+0000 (UTC)] INFO hubot-botframework-adapter: onBotEvents
[Thu Nov 08 2018 20:19:52 GMT+0000 (UTC)] INFO hubot-botframework-adapter: Handling activity Channel:                            msteams; type: message
[Thu Nov 08 2018 20:19:52 GMT+0000 (UTC)] INFO hubot-botframework-middleware: creating middleware...
[Thu Nov 08 2018 20:19:53 GMT+0000 (UTC)] INFO hubot-msteams: toReceivable
[Thu Nov 08 2018 20:19:53 GMT+0000 (UTC)] DEBUG Message 'Sparky orly' matched regex //orly/i/; listener.options = { id: null }
[Thu Nov 08 2018 20:19:53 GMT+0000 (UTC)] DEBUG Executing listener callback for Message 'Sparky orly'
[Thu Nov 08 2018 20:19:53 GMT+0000 (UTC)] INFO hubot-botframework-adapter: send
[Thu Nov 08 2018 20:19:53 GMT+0000 (UTC)] INFO hubot-botframework-adapter: reply
[Thu Nov 08 2018 20:19:53 GMT+0000 (UTC)] INFO hubot-botframework-middleware: creating middleware...
[Thu Nov 08 2018 20:19:53 GMT+0000 (UTC)] INFO hubot-msteams: toSendable
wsoula commented 5 years ago

I added NODE_DEBUG=botbuilder and DEBUG='*' and I have this 404 in stderr which seems suspicious:

Thu, 08 Nov 2018 21:26:19 GMT connect:dispatcher query  : /api/messages
Thu, 08 Nov 2018 21:26:19 GMT connect:dispatcher expressInit  : /api/messages
Thu, 08 Nov 2018 21:26:19 GMT connect:dispatcher anonymous  : /api/messages
Thu, 08 Nov 2018 21:26:19 GMT connect:dispatcher query  : /api/messages
Thu, 08 Nov 2018 21:26:19 GMT connect:dispatcher jsonParser  : /api/messages
Thu, 08 Nov 2018 21:26:19 GMT body-parser:json content-type "application/json; charset=utf-8"
Thu, 08 Nov 2018 21:26:19 GMT body-parser:json content-encoding "identity"
Thu, 08 Nov 2018 21:26:19 GMT body-parser:json read body
Thu, 08 Nov 2018 21:26:19 GMT body-parser:json parse body
Thu, 08 Nov 2018 21:26:19 GMT body-parser:json parse json
Thu, 08 Nov 2018 21:26:19 GMT connect:dispatcher urlencodedParser  : /api/messages
Thu, 08 Nov 2018 21:26:19 GMT body-parser:urlencoded body already parsed
Thu, 08 Nov 2018 21:26:19 GMT connect:dispatcher multipart  : /api/messages
Thu, 08 Nov 2018 21:26:19 GMT connect:dispatcher router  : /api/messages
Thu, 08 Nov 2018 21:26:19 GMT express:router dispatching POST /api/messages (/api/messages)
Thu, 08 Nov 2018 21:26:19 GMT express:router matched post /api/messages
Thu, 08 Nov 2018 21:26:19 GMT finalhandler cannot 404 after headers sent
wsoula commented 5 years ago

Although I get the same thing going through the web chat and that returns a response:

Thu, 08 Nov 2018 21:29:49 GMT connect:dispatcher query  : /api/messages
Thu, 08 Nov 2018 21:29:49 GMT connect:dispatcher expressInit  : /api/messages
Thu, 08 Nov 2018 21:29:49 GMT connect:dispatcher anonymous  : /api/messages
Thu, 08 Nov 2018 21:29:49 GMT connect:dispatcher query  : /api/messages
Thu, 08 Nov 2018 21:29:49 GMT connect:dispatcher jsonParser  : /api/messages
Thu, 08 Nov 2018 21:29:49 GMT body-parser:json content-type "application/json; charset=utf-8"
Thu, 08 Nov 2018 21:29:49 GMT body-parser:json content-encoding "identity"
Thu, 08 Nov 2018 21:29:49 GMT body-parser:json read body
Thu, 08 Nov 2018 21:29:49 GMT body-parser:json parse body
Thu, 08 Nov 2018 21:29:49 GMT body-parser:json parse json
Thu, 08 Nov 2018 21:29:49 GMT connect:dispatcher urlencodedParser  : /api/messages
Thu, 08 Nov 2018 21:29:49 GMT body-parser:urlencoded body already parsed
Thu, 08 Nov 2018 21:29:49 GMT connect:dispatcher multipart  : /api/messages
Thu, 08 Nov 2018 21:29:49 GMT connect:dispatcher router  : /api/messages
Thu, 08 Nov 2018 21:29:49 GMT express:router dispatching POST /api/messages (/api/messages)
Thu, 08 Nov 2018 21:29:49 GMT express:router matched post /api/messages
Thu, 08 Nov 2018 21:29:49 GMT finalhandler cannot 404 after headers sent
wsoula commented 5 years ago

When I use the webchat I get a message about it being sent:

ChatConnector: message received.
[Thu Nov 08 2018 21:29:49 GMT+0000 (UTC)] INFO hubot-botframework-adapter: onBotEvents
[Thu Nov 08 2018 21:29:49 GMT+0000 (UTC)] INFO hubot-botframework-adapter: Handling activity Channel:                            webchat; type: message
[Thu Nov 08 2018 21:29:49 GMT+0000 (UTC)] INFO hubot-botframework-middleware: creating middleware...
[Thu Nov 08 2018 21:29:49 GMT+0000 (UTC)] INFO hubot-botframework-middleware: TextMiddleware toReceivable
[Thu Nov 08 2018 21:29:49 GMT+0000 (UTC)] DEBUG Message 'orly' matched regex //orly/i/; listener.options = { id: null }
[Thu Nov 08 2018 21:29:49 GMT+0000 (UTC)] DEBUG Executing listener callback for Message 'orly'
[Thu Nov 08 2018 21:29:49 GMT+0000 (UTC)] INFO hubot-botframework-adapter: send
[Thu Nov 08 2018 21:29:49 GMT+0000 (UTC)] INFO hubot-botframework-adapter: reply
[Thu Nov 08 2018 21:29:49 GMT+0000 (UTC)] INFO hubot-botframework-middleware: creating middleware...
[Thu Nov 08 2018 21:29:49 GMT+0000 (UTC)] INFO hubot-botframework-middleware: TextMiddleware toSendable
ChatConnector: sending message.
wsoula commented 5 years ago

Is it possible I'm running in to this issue where once you setup a bot service you can never change it again without creating a new bot? https://github.com/OfficeDev/BotBuilder-MicrosoftTeams/issues/103 I did change the name of the bot when it is built.

MatSFT commented 5 years ago

No, you are definitely receiving the message and sending it back so it doesn't look like that is an issue.

I recently ran and setup a new hubot with my teams client and it worked properly so I'm not sure what the problem in your situation is. Did you create an app package and sideload your bot in teams?

https://docs.microsoft.com/en-us/microsoftteams/platform/concepts/apps/apps-upload

wsoula commented 5 years ago

Yeah I set that all up and the issue is something in the persistent brain from when I changed his name. I'm trying to find the offending entry in the brain, but when I started the bot with a blank brain it worked properly. I'll update here if I find what was causing the issue

wsoula commented 5 years ago

Its something in here, when justReceivedResponse is set to true, which it is in my brain, it reads teamsResponse, if I remove justReceivedResponse then it works fine. If I just remove teamsResponse there is an error thrown because it sees justReceivedResponse and then tries to read teamsResponse[1] which doesn't exist. These are the lines I am talking about https://github.com/Microsoft/BotFramework-Hubot/blob/master/src/msteams-middleware.coffee#L161-L166 Just leaving this here for anyone else that might come across this.

"teamsResponse": [
            {
                "address": {
                    "bot": {
                        "id": "<redacted>",
                        "name": "Sparkybot"
                    },
                    "channelId": "msteams",
                    "conversation": {
                        "conversationType": "channel",
                        "id": <redacted>",
                        "isGroup": true
                    },
                    "id": "<redacted>",
                    "serviceUrl": "https://smba.trafficmanager.net/amer/",
                    "user": {
                        "aadObjectId": "<redacted>",
                        "id": "<redacted>",
                        "name": "WSoula"
                    }
                },
                "type": "typing"
            },
            {
                "address": {
                    "bot": {
                        "id": "<redacted>",
                        "name": "Sparkybot"
                    },
                    "channelId": "msteams",
                    "conversation": {
                        "conversationType": "channel",
                        "id": "<redacted>",
                        "isGroup": true
                    },
                    "id": "<redacted>",
                    "serviceUrl": "https://smba.trafficmanager.net/amer/",
                    "user": {
                        "aadObjectId": "<redacted>",
                        "id": "<redacted>",
                        "name": "WSoula"
                    }
                },
                "attachments": [
                    {
                        "contentType": "image/gif",
                        "contentUrl": "http://i.imgur.com/<redacted>.gif",
                        "name": "<redacted>"
                    }
                ],
                "text": "<redacted>",
                "type": "message"
            }
        ]
MatSFT commented 5 years ago

Did you pull the hubot-botframework adapter from NPM? These changes shouldn't be in the latest version 0.10.1.

wsoula commented 5 years ago

I am installing from master because I was hitting the dependency issue that was just fixed, so I had to clone and then fix the package.json to take care of this: https://github.com/Microsoft/BotFramework-Hubot/issues/42

MatSFT commented 5 years ago

Gotcha! Instead of master pull from the release tag and you should be good to go https://github.com/Microsoft/BotFramework-Hubot/tree/v0.10.1

wsoula commented 5 years ago

Wont that have the same issue since botbuilder is locked to greater than 3.5.0 so it will get 4.0.0? https://github.com/Microsoft/BotFramework-Hubot/blob/v0.10.1/package.json#L19

MatSFT commented 5 years ago

It definitely will but if you apply the botbuilder version fix to that code, you will not be facing this weird issue above.

But yes, until we push a new NPM the adapter is broken because of the v4 botbuilder update

wsoula commented 5 years ago

Oh yeah that makes sense. I tested that and it does indeed fix the issue as well.

MatSFT commented 5 years ago

I want to keep this open since there is still a bug somewhere in the next version of the teams adapter we want to ship here.

esell commented 5 years ago

Not sure if it is related, but my brand new bot is only able to respond via direct chat. @'ing it in a Teams channel doesn't seem to work. I see /api/messages being hit, nothing comes back though.

Logs from a message sent in the Teams channel (no response):

  express:router query  : /api/messages +1ms
  express:router expressInit  : /api/messages +0ms
  express:router <anonymous>  : /api/messages +1ms
  express:router query  : /api/messages +0ms
  express:router jsonParser  : /api/messages +0ms
  body-parser:json content-type "application/json; charset=utf-8" +1ms
  body-parser:json content-encoding "identity" +2ms
  body-parser:json read body +0ms
  body-parser:json parse body +9ms
  body-parser:json parse json +0ms
  express:router urlencodedParser  : /api/messages +1ms
  body-parser:urlencoded body already parsed +0ms
  express:router multipart  : /api/messages +0ms
ChatConnector: message received.
[Thu Jun 13 2019 15:35:31 GMT+0000 (UTC)] INFO hubot-botframework-adapter: onBotEvents
[Thu Jun 13 2019 15:35:31 GMT+0000 (UTC)] INFO hubot-botframework-adapter: Handling activity Channel: msteams; type: message
[Thu Jun 13 2019 15:35:31 GMT+0000 (UTC)] INFO hubot-botframework-middleware: creating middleware...
[Thu Jun 13 2019 15:35:31 GMT+0000 (UTC)] INFO hubot-msteams: toReceivable
  finalhandler cannot 404 after headers sent +139ms

Logs from a message sent in a direct chat (successful response):

  express:router query  : /api/messages +0ms
  express:router expressInit  : /api/messages +0ms
  express:router <anonymous>  : /api/messages +1ms
  express:router query  : /api/messages +0ms
  express:router jsonParser  : /api/messages +0ms
  body-parser:json content-type "application/json; charset=utf-8" +0ms
  body-parser:json content-encoding "identity" +0ms
  body-parser:json read body +0ms
  body-parser:json parse body +1ms
  body-parser:json parse json +0ms
  express:router urlencodedParser  : /api/messages +0ms
  body-parser:urlencoded body already parsed +0ms
  express:router multipart  : /api/messages +0ms
ChatConnector: message received.
[Thu Jun 13 2019 15:35:57 GMT+0000 (UTC)] INFO hubot-botframework-adapter: onBotEvents
[Thu Jun 13 2019 15:35:57 GMT+0000 (UTC)] INFO hubot-botframework-adapter: Handling activity Channel: msteams; type: message
[Thu Jun 13 2019 15:35:57 GMT+0000 (UTC)] INFO hubot-botframework-middleware: creating middleware...
[Thu Jun 13 2019 15:35:57 GMT+0000 (UTC)] INFO hubot-msteams: toReceivable
  finalhandler cannot 404 after headers sent +2ms
[Thu Jun 13 2019 15:35:57 GMT+0000 (UTC)] INFO hubot-botframework-adapter: send
[Thu Jun 13 2019 15:35:57 GMT+0000 (UTC)] INFO hubot-botframework-adapter: reply
[Thu Jun 13 2019 15:35:57 GMT+0000 (UTC)] INFO hubot-botframework-middleware: creating middleware...
[Thu Jun 13 2019 15:35:57 GMT+0000 (UTC)] INFO hubot-msteams: toSendable
ChatConnector: sending message.
ChatConnector: sending message.
prvns133t commented 5 years ago

I see the same issue. Did anyone manage to fix this issue?