botman / driver-facebook

BotMan Facebook Messenger Driver
MIT License
71 stars 72 forks source link

Bot not answering custom questions #66

Closed tommiekn closed 5 years ago

tommiekn commented 6 years ago

Hi,

All the suddens some week ago the bot stopped to answer typed messages of customers. Bot works fine only while using the FB menu, if i try to call the same actions typing is not working. Tinker is working fine. I am using the latest botman and driver versions.

@mpociot I reopen this here hopefully is the right place, if you could help would be great.

Thanks!

christophrumpel commented 5 years ago

Hey @tommiekn, please provide some more information on what is not working.

So when someone writes to the bot, the bot is not answering? This can have many reasons. Maybe there is a permission problem with the Facebook APP, there have been many changes lately and many apps had to review again.

Then I would also try to check if the message from the user hits your BotMan application. Try to log incoming request to check that. Then of course please check if there are any errors in your logs.

tommiekn commented 5 years ago

@christophrumpel I have tried pretty much everything possible but still not working, here a recap:

  1. I am using dialogflow middleware
  2. App on facebook is correctly submitted and approved, also after the latest changes
  3. Page has bot app set as primary messaging receiver
  4. Logs shows a call from facebook each time i try to message, but the variables actions etc are empty, for example: [2018-09-05 11:31:28] local.INFO: 2018-09-05 11:09 action: user id: api reply:
  5. If i try to talk with the bot thru the ticker it works with no issues
  6. if i use the Facebook menu to dialog with the bot it answers with no issues
  7. App and laravel are updated to latest version

The bot also send automate messages to subscribed users, functionality that is working with no issues as well.

Copying bellow the first lines on my bootman.php route file, the Log:Info there gives blank values as you see in the log i pasted on point 3 up here.

Consider the bot stopped to answer randomly after months that it was working well with no issues, that's very weird and would make sense if thats a change that happened FB side.

Thought it could be a problem of the middleware as well but the Ticker works well and answer everything perfectly so i would exclude dialogflow as an issue.

Any idea ? :)

Thanks!

`use App\Http\Controllers\BotManController; use BotMan\BotMan\Middleware\ApiAi; use App\Conversations\LatestReleasesConversation; use App\Conversations\NextReleasesConversation; use App\Conversations\ReleaseRemindersConversation; use App\Conversations\ReleaseRemindersStopConversation; use BotMan\BotMan\Storages\Storage; use BotMan\Drivers\Facebook\Extensions\Element as Element; use BotMan\Drivers\Facebook\Extensions\ElementButton as ElementButton; use BotMan\Drivers\Facebook\Extensions\ButtonTemplate as ButtonTemplate; use BotMan\Drivers\Facebook\Extensions\GenericTemplate as GenericTemplate; use BotMan\Drivers\Facebook\Extensions\ListTemplate as ListTemplate; Log::info('Exec bot'); $botman = resolve('botman');

$dialogflow = ApiAi::create('#######')->listenForAction();

// Apply global "received" middleware $botman->middleware->received($dialogflow);

$botman->group(['middleware' => $dialogflow], function($botman2) {

// Apply matching middleware per hears command
$botman2->hears('.*', function ($bot) {

    $user = $bot->getUser();
    if(!empty($userid=$user->getId())){
        $controller = new BotManController;
        $controller->logUser($userid);

        $bot->userStorage()->save([
            'userid' => $userid
        ]);

    }

    //Log::info($bot->getMessage()->getExtras());

    // The incoming message matched the "my_api_action" on Dialogflow
    // Retrieve Dialogflow information:
    $extras = $bot->getMessage()->getExtras();
    $apiReply = $extras['apiReply'];
    $apiAction = $extras['apiAction'];
    $apiIntent = $extras['apiIntent'];

    $bot->typesAndWaits(2);
    Log::info(date("Y-m-d H:m",time())."\n action:".$apiAction."\n user id: ".$userid."\n  api reply: ".$apiReply);

ETC ETC`

christophrumpel commented 5 years ago

Just to make sure I understood it correctly:

  1. The bot is working fine with Facebook for normal hears and replies. There is only a problem when using the DialogFlow Middleware?

  2. The middleware group is working because the requests get inside the group

  3. The problem is that the additional data is empty which you should get from Dialogflow?

I don't see anything wrong with your code. There could be different types of problems and this is difficult to debug.

  1. I hope you made sure there are no errors in your storage/logs/laravel.log file?

What I would check is the ApiApi middleware here https://github.com/botman/botman/blob/2.0/src/Middleware/ApiAi.php#L114-L131

It is used when you use the Dialoflow middleware. Here I would check what Dialogflow send to you application and if the additional data is really missing.

Hope that helps.

tommiekn commented 5 years ago

@christophrumpel almost all correct, but the Middleware works if i queried thru the tinker, it does not work only when querying from Facebook. Thats why i excluded this.

I have put some debug on that method as well and it has nothing, $message and $response are empty.

Theres no errors in log files, and hosting is updated at latest version and composer apps as well.

Other ideas?

tommiekn commented 5 years ago

I believe the problem is between botman and the middleware (dialogflow), i cant see any history on dialogflow if i try to type from Facebook but i can find everything i type thru Tinker or also the menu functions from facebook, that means that only typed messages on facebook doesnt get to the middleware i guess?

christophrumpel commented 5 years ago

I wouldn't compare it to Tinker. Tinker works differently, I am not sure if it even uses the Dialogflow middleware. Please check this simple example that works for me on BotMan Playground: https://playground.botman.io/user/christophrumpel/dialogflow-demo

or I have many DialogFlow examples here in this project from my chatbot book. Please check here again and try a simple setup to make it work first, so you know it is not about your own code. https://github.com/christophrumpel/bcwp-laraconeu-chatbot

tommiekn commented 5 years ago

@christophrumpel Tinker works with the Dialogflow middleware and works with no issues in my app, thats the whole point here.

I have tried your app and it does work with Dialogflow, if i query thru Tinker, if i query thru facebook it does not work, same as my app.

I have done more debug and can confirm 100% all requests from facebook gets to the bot but are empty, because the middleware, i suppose.

[2018-09-19 17:22:55] local.INFO: Bot executed - CLIENT: IP X.X.X.X [2018-09-19 17:22:55] local.INFO: Starting app
[2018-09-19 17:22:58] local.INFO: Message received[ Action:'' | User Id: '' | API Reply Text: '']
[2018-09-19 17:22:58] local.INFO: error action:

This is an example of what i get if i query from Tinker:

[2018-09-19 17:27:31] local.INFO: Bot executed - CLIENT: IP X.X.X.X [2018-09-19 17:27:31] local.INFO: Starting app
[2018-09-19 17:27:31] local.INFO: User exist {"id":1,"created_at":"2018-09-19 16:46:11","updated_at":"2018-09-19 16:46:11","userid":"9999999"}
[2018-09-19 17:27:33] local.INFO: Message received[ Action:'about.hello' | User Id: '9999999' | API Reply Text: 'Hello!']

Content of the message while texting thru the Tinker is the following, if i try from FB all these are empty obviously.

array ( 'apiReply' => 'Hi!', 'apiAction' => 'about.hello', 'apiActionIncomplete' => false, 'apiIntent' => 'about.hello', 'apiParameters' => array ( ), )

To exclude that this is an issue related to Dialogflow i have tried the following base code without Middleware (and doesnt change anything):

`$botman = resolve('botman'); // Apply matching middleware per hears command $botman->hears('foo', function ($bot) { $bot->reply('Hello World'); }); $botman->listen();

$botman->fallback(function($bot) { $bot->reply('Sorry, I did not understand these commands.'); });`

Result: Typing "foo" from facebook make a request but dont match the hears('foo' as nothing get texted back. Using the Tinker works as expected and i get an Hello World

Thanks

tommiekn commented 5 years ago

Also, I have noticed thru the logs that this part of the code:

$bot->getUser();

Gives an exception when someone query from Facebook, but only when using the Facebook menu buttons.

Before, the bot was able to answer while using the buttons as i mentioned at the beginning, and actually if i remove the line that gives error, it answers still. So not sure what changed.

`[2018-09-19 18:29:58] local.ERROR: Error sending payload: (#100) Insufficient permission to access user profile. {"exception":"[object] (BotMan\Drivers\Facebook\Exceptions\FacebookException(code: 0): Error sending payload: (#100) Insufficient permission to access user profile. at botchat/vendor/botman/driver-facebook/src/FacebookDriver.php:503) [stacktrace]

0 botchat/vendor/botman/driver-facebook/src/FacebookDriver.php(460): BotMan\Drivers\Facebook\FacebookDriver->throwExceptionIfResponseNotOk(Object(Symfony\Component\HttpFoundation\Response))

1 botchat/vendor/botman/botman/src/BotMan.php(236): BotMan\Drivers\Facebook\FacebookDriver->getUser(Object(BotMan\BotMan\Messages\Incoming\IncomingMessage))

2 botchat/routes/botman.php(32): BotMan\BotMan\BotMan->getUser()

`

I shouldn't have issues with permissions FB side as the bot is fully authorized on their portal.

The odd thing is that this issue started today after i been editing the app to add some debug and check things, i have deleted the cache that is the only thing i thought may affect this behavior because debug-wise this error should have been there before as well as i didn't changed anything really.

Another odd thing is that the bot is not answering any message since months, after some month working, but checking the messages in the page where i use it normally, i noticed users being able to comunicate with the bot between sept 11 and today, i believe i did updated the webserver that weeks and as well to botman.

Any idea on how to debug this? Kinda out of options.

christophrumpel commented 5 years ago

Hey @tommiekn ,

so regarding the getUser problem, please read here https://github.com/botman/driver-facebook/pull/74

There was change with FB and right now you need to use another method than getUser. This is where the permission problems come from. We are working on a better solution, but for now, you need to use the new method mentioned in the pull.

Regarding the other problems: It is really difficult to debug from here. I don't see any reasons with DialogFlow should not work with FB. The only thing I can think of is that this has to do with the error from the getUser method. So please change that and then try again.

If not, I would recommend you testing with a new botman application and see if you can get it working and then try to analyze what could be wrong in your other application. I can guarantee you that Dialogflow is working fine with Facebook and that there must be a problem in your application.

tommiekn commented 5 years ago

Hi @christophrumpel

Re getUser, problem solved thanks!

Re issues, see my latest message, i have tried already to use a very basic botman file to handle this, with no Dialogflow, everything direct, but it does not work!!

`$botman = resolve('botman'); // Apply matching middleware per hears command $botman->hears('foo', function ($bot) { $bot->reply('Hello World'); }); $botman->listen();

$botman->fallback(function($bot) { $bot->reply('Sorry, I did not understand these commands.'); });`

This works only in the Tinker, facebook gives 0 answers.

christophrumpel commented 5 years ago

Since we were talking about multiple different things now, please explain the problem again. What is here not working with the code? You are writing foo and getting now reply with FB, but with Tinker it is working?

tommiekn commented 5 years ago

@christophrumpel yes exactly, FB does not answer to the foo but Tinker is. The code is the basic one you see up here. So i guess we can exclude that is a problem of my app or middleware?

I am sure that if i setup a FB Menu with FOO as variable there, the bot will receive that, is the same that is happening now, on FB menu works but text input by user doesn't.

Any idea?

christophrumpel commented 5 years ago

hm still so many things that could be wrong. I would try like this:

Hope that helps.

tommiekn commented 5 years ago

Ok, how can i check if the foo message is sent from Fb to the botman application ?

Keep always in consideration one important thing, if the user uses the FB Menu to dialogate with the bot, it works and bot answers. This exclude any issue related to tokens or what so ever. The problem happens only with the user typed messages.

christophrumpel commented 5 years ago

Ah forgot about that, hmm that is strange. Still I would check that by logging all incoming requests. I do that inside the BotManController like:

public function handle()
    {
        info('incoming', request()->all()); // this was added

      // ...

        $botman->listen();
    }

But this only works if you are using this controller and BotMan in Laravel / Studio. After that you will see all incoming request in the laravel.log file.

tommiekn commented 5 years ago

Ok the message arrives only if texting from FB Menu, if i text manually it doesnt get to the bot. What should i check next ?

christophrumpel commented 5 years ago

Ok thats interesting. What events have you activated on the FB app? (Edit Page Subscription Fields ) FB buttons are sent as a postback, normally messages via the messages event. Since you said it already worked I can imagine that you haven't done that. But please check.

tommiekn commented 5 years ago

All events are enabled, please see screenshot attached, is that what you were asking right? screen shot 2018-09-20 at 16 26 29

More debug:

If i text with the FB MENU i see these calls, first one call as "messaging" and then one call as "standby".

[2018-09-20 14:20:34] local.INFO: incoming {"object":"page","entry":[{"id":"ID","time":1537453234248,"messaging":[{"recipient":{"id":"ID"},"timestamp":1537453234248,"sender":{"id":"ID"},"postback":{"payload":"PAYLOAD_NAME","title":"Payload"}}]}]}

[2018-09-20 14:20:34] local.INFO: incoming {"object":"page","entry":[{"id":"ID","time":1537453234248,"standby":[{"recipient":{"id":"ID"},"timestamp":1537453234248,"sender":{"id":"ID"},"postback":{"title":"Payload"}}]}]}

If i message manually, i only see the standby request and not the messaging one:

[2018-09-20 14:24:38] local.INFO: incoming {"object":"page","entry":[{"id":"ID","time":1537453478534,"standby":[{"sender":{"id":"ID"},"recipient":{"id":"ID"},"timestamp":1537453477346,"message":{"mid":"3rUdXAtQMwBlNVYZVP3LzckvSHHpsIkDt_hboDVObPa1qbe-ETrwj47LCGV3vS25UHI5drAfX4NedlayxBpkmw","seq":513554,"text":"hello"}}]}]}

christophrumpel commented 5 years ago

Ok the events are correct. This is really strange. First I would to delete the whole webhook on the FB app and set it up again. (remove it completely) If this is also not working I would try it with a new FB app. Since the request is not coming to BotMan it must be something on FB site.

tommiekn commented 5 years ago

So what you saying is to go to developer.facebook, on the webhooks, remove the subscriptions to each webhook and do it again ?

New fb app isnt much viable as the authorizing process isnt quick.

christophrumpel commented 5 years ago

I mean on the webhook settings, there is this remove button. There I would try to remove it and set it up again.

Still I would try with a new fb app, you as an admin can test it in default mode. I had about 3-4 occasions where I need to delete my FB app and use a new one, due to weird problems on Facebook side. This is not funny I know, but at least you know if it is about the app or something else.

tommiekn commented 5 years ago

I have tried to re do the webhooks and tried with a new test app as well, no luck, now both menu and text actions are working the same, aka it doesn't work anymore.

It is interesting to note that if i try to use $bot->getUserWithFields with any menu button request it gives exception, now, while before these last tests it was working correctly.

I think the messages get delivered but facebook mark as "messaging" the first message and as "standby" the others, i guess because the first message hasnt been answered yet. If i try to use the facebook menu it uses always "messaging".

In this example, this:

incoming {"object":"page","entry":[{"id":"ID","time":1537457946051,"standby":[{"sender":{"id":"ID"},"recipient":{"id":"ID"},"timestamp":1537457944811,"message":{"mid":"zU1EDqTA85IJVMQEnmJLRckvSHHpsIkDt_hboDVObPY2rcsOctelTFtLdttB25uFRO6NtIDnrQJoH63xxyvgOg","seq":513595,"text":"foo"}}]}]}

Doesn't match anything in the botman.php route, and cant retrieve user data, while the user id is actually there in the post.

This is very frustrating.. have i missed something here?

christophrumpel commented 5 years ago

Ok so first the problem with the profile permission (getUser) is different depending on if the FB app is a new one or an older one. This could be the difference that you have been seeing.

I would suggest you take the new FB app and you connect it to a new BotMan Studio application. And there you are testing with the default examples that are already defined in the botman.php. I would recommend you try first to make this work (just the messages, not the menu). I wouldn't try anything else before you can verify that this is working.

tommiekn commented 5 years ago

OK, this is gonna be fun...

I have tried, fresh install of botman studio, new facebook app, two different facebook pages.

Result, same thing than my main app, messages are all "standby".

Could you may try the same thing yourself and see if it works ?

Here some logs :

[2018-09-20 22:53:20] local.INFO: incoming {"object":"page","entry":[{"id":"IDPAGE","time":1537483999708,"messaging":[{"recipient":{"id":"IDPAGE"},"timestamp":1537483999708,"app_roles":{"1817243148398167":["primary_receiver"]}}]}]} [2018-09-20 22:53:20] local.INFO: incoming {"object":"page","entry":[{"id":"IDPAGE","time":1537483999698,"messaging":[{"recipient":{"id":"IDPAGE"},"timestamp":1537483999698,"app_roles":{"1733230816986099":["secondary_receiver"]}}]}]} [2018-09-20 22:53:26] local.INFO: incoming {"object":"page","entry":[{"id":"IDUSER","time":1537484006238,"standby":[{"sender":{"id":"2048357031881015"},"recipient":{"id":"IDUSER"},"timestamp":1537484006196,"read":{"watermark":1537457794917,"seq":0}}]}]} [2018-09-20 22:53:29] local.INFO: incoming {"object":"page","entry":[{"id":"IDUSER","time":1537484008848,"standby":[{"sender":{"id":"2048357031881015"},"recipient":{"id":"IDUSER"},"timestamp":1537484007632,"message":{"mid":"6AXKiEUDW0iX4_9TdSGFS6GVM7gIWFRwxgGF-P6hasojTfnd7ab9qnaCFGRi1shD84nTkc7T9V0I08eK81xM6A","seq":513632,"text":"hi"}}]}]} [2018-09-20 22:53:37] local.INFO: incoming {"object":"page","entry":[{"id":"IDPAGE","time":1537484017185,"standby":[{"sender":{"id":"1576733869023826"},"recipient":{"id":"IDPAGE"},"timestamp":1537484015942,"message":{"mid":"zIacEA0OkLDDja470lZCgMkvSHHpsIkDt_hboDVObPYiu5_3Yoo9_481QS4mnQF3dq5Fce6Oy9ixeNDt2JM94Q","seq":513633,"text":"hi"}}]}]} [2018-09-20 22:53:37] local.INFO: incoming {"object":"page","entry":[{"id":"IDPAGE","time":1537484017173,"standby":[{"sender":{"id":"1576733869023826"},"recipient":{"id":"IDPAGE"},"timestamp":1537484015942,"message":{"mid":"zIacEA0OkLDDja470lZCgMkvSHHpsIkDt_hboDVObPYiu5_3Yoo9_481QS4mnQF3dq5Fce6Oy9ixeNDt2JM94Q","seq":513633,"text":"hi"}}]}]} [2018-09-20 22:54:31] local.INFO: incoming {"object":"page","entry":[{"id":"IDPAGE","time":1537484071377,"messaging":[{"recipient":{"id":"IDPAGE"},"timestamp":1537484071377,"app_roles":{"1733230816986099":[]}}]}]} [2018-09-20 22:55:40] local.INFO: incoming {"object":"page","entry":[{"id":"IDPAGE","time":1537484140182,"standby":[{"sender":{"id":"1576733869023826"},"recipient":{"id":"IDPAGE"},"timestamp":1537484139063,"message":{"mid":"AAHyvB99KV9LSgOQFSrWvMkvSHHpsIkDt_hboDVObPY5ncRsMdx9REBcWbdtXJMjLdxr_ng4Y88wsJelpdw2wg","seq":513634,"text":"hi"}}]}]} [2018-09-20 22:55:40] local.INFO: incoming {"object":"page","entry":[{"id":"IDPAGE","time":1537484140178,"standby":[{"sender":{"id":"1576733869023826"},"recipient":{"id":"IDPAGE"},"timestamp":1537484139063,"message":{"mid":"AAHyvB99KV9LSgOQFSrWvMkvSHHpsIkDt_hboDVObPY5ncRsMdx9REBcWbdtXJMjLdxr_ng4Y88wsJelpdw2wg","seq":513634,"text":"hi"}}]}]}

tommiekn commented 5 years ago

I believe the explanation is here:

https://developers.facebook.com/docs/messenger-platform/reference/webhook-events/standby/

The weird thing is that the app is set as primary receiver on the facebook page settings, and theres no secondary receivers or anything, so not sure how could be that the app isn't the thread owner.

tommiekn commented 5 years ago

Found this as well, so is this a random error?

https://developers.facebook.com/support/bugs/406253556449737/?disable_redirect=0

christophrumpel commented 5 years ago

Hmm this is strange. Never seen this standby before. Can you try to deactivate all the events except messages and postback. These are the primary ones. Then please delete your log file and and send one message to the bot and show me what requests have been logged. When there are too many events activated, it is much more difficult to debug.

tommiekn commented 5 years ago

If i deactivate standby messages i dont receive any message at all in the logs, already tried

christophrumpel commented 5 years ago

Hmm ok, then I think I don't have any more glues. It is definitely something on FB side and not BotMan and probably connected to the standby which I have never seen. I would recommend trying to ask about in the Facebook Developers Group. But I would only ask about the standby and tell that you do not receive normal message events.

I cannot help here anymore and I will close the issue. If you find anything new, please post it here. Wish you all the best.