Conversation does not work when require_delivery is true on express server

[KarlisJ]

It is inportant to me that I run my messenger bot on my own express server.

I have implemented botkit+express following this stackexchange answer by @jonchurch and it is working. I can receive and send back messages.

The problem (as for lot of developers as I can see) start when I create conversation. Consider this example:

convo.addQuestion('1', function(response, convo){
	convo.say('Cool, you said: ' + response.text);
	convo.next();
});
convo.addQuestion('2',  function(response, convo){
	convo.say('Cool2, you said: ' + response.text);
	convo.next();
});

I would expect the conversation like this:

bot:1
me:a
bot: cool, you said: a
bot: 2
....

but what I got was:

bot:1
me:a
bot:2
me: b
bot: cool, you said: a
bot: coll, you said:b

So I added require_delivery: true. However that breaks the conversation:

bot:1
me:a
//and at this point we are stuck until I restart the server

I found a lot of issues when require_delivery: true breaks conversations. The latest resolve was pointing out that there is need to update handleWebhookPayload function. I chencked the repository and found exact code that was suggested. After two days that leaves me out of options.

Here is full code how I set up my bot with express server.
index.js:

require('dotenv').config();

var Botkit = require('botkit');
var controller = Botkit.facebookbot({
	debug: true,
	access_token: process.env.access_token,
	verify_token: process.env.verify_token,
	require_delivery: true,
})

var db = require(__dirname + '/models/db');
db.connect( function( err ) {
  if(err){
	 console.log('Could not connect to Mongo database: ' + err);
  } else{
		var webserver= require(__dirname + '/components/express_webserver.js')(controller);
		//routes for web part
		require('./bot/index')(controller);
	}
});

express_webserver.js:

var express = require('express');
var bodyParser = require('body-parser');
var querystring = require('querystring');
var debug = require('debug')('botkit:webserver');

module.exports = function(controller, bot) {
	var webserver = express();
    webserver.use(bodyParser.json());
    webserver.use(bodyParser.urlencoded({ extended: true }));

    webserver.use(express.static('public'));
    webserver.listen(process.env.port || 3000,  null, function() {
    console.log('Express webserver configured and listening at ',
            process.env.HOSTNAME || 'http://localhost/' + ':' + process.env.PORT || 3000);
    });
    require('./routes/facebook-webhook')(webserver, controller)
   require('./facebook_setup')(controller);
   controller.webserver = webserver;

    return webserver;
}

facebook-webhook.js:

module.exports = function(webserver, controller) {

   webserver.post('/facebook/receive', function(req, res) {
       res.status(200);
        res.send('ok');

        var bot = controller.spawn({});
        controller.handleWebhookPayload(req, res, bot);
   });
    webserver.get('/facebook/receive', function(req, res) {
        if (req.query['hub.mode'] == 'subscribe') {
            if (req.query['hub.verify_token'] == controller.config.verify_token) {
                res.send(req.query['hub.challenge']);
            } else {
                res.send('OK');
            }
        }
    });
}

facebook_setup.js:

var Request = require('request');

module.exports = function (controller) {
  Request.post('https://graph.facebook.com/me/subscribed_apps?access_token=' + controller.config.access_token,
    function (err, res, body) {
      if (err) {
        controller.log('Could not subscribe to page messages')
      }
      else {
        controller.log('Successfully subscribed to Facebook events:', body)
        console.log('Botkit can now receive messages')

       controller.startTicking()
      }
    })
}

and bot/index.js:

module.exports = function(controller){
	controller.hears(['hello'], 'message_received', function(bot, message) {
		bot.startConversation(message, function(err, convo){
			convo.addQuestion('1', function(response, convo){
				convo.say('Cool, you said: ' + response.text);
				convo.next();
			});
			convo.addQuestion('2',  function(response, convo){
				convo.say('Cool2, you said: ' + response.text);
				convo.next();
			});
		});
	});
}

I will appreciate any help or guidence

[jonchurch]

Hmm, investigating if this is an issue with the server code I supplied.

Using just your index.js I am indeed able to reproduce this. @benbrown any idea what is going on here?

After starting this convo, and responding to the first question, the bot is jumping straight to the next question, and then queueing the responses (Cool, you said ... and Cool2, you said ... both have the appropriate responses too).

So far as I know that is unexpected behavior.

UPDATE:
Okay it seems to me that what is happening is the messages are being added to the queue, Q1 goes before Q2, and then when Q1 executes, it adds it's convo.say to the stack of messages about to go out. This is confusing to me, and I don't like it. Will confer with others to see if I'm missing something here, i.e. hopefully we are both just doin it wrong lol.

Solution to your initial problem: convo.sayFirst()(docs) will make your code execute as you wish, without require_delivery: true. Not sure how I usually avoid this, and am scratching my head at this moment. But! Here is your solution.

cc @peterswimm cc @ouadie-lahdioui cc @colestrode cc @tylermachado anybody want to comment on creating dynamic conversations but avoiding this issue? I know I'm just missing something simple here...

Update 2:
Part of what is happening is we are disregarding the thread system here. Threads are basically buckets of messages and questions, and using the default thread as we are here (when addQuestion/Message are called without the thread arg as we are above, everything get stuffed into the default thread). So everything is being stuffed into that thread, which is messy. Another way could be using threads.

[KarlisJ]

I investigated further and found something of interest. It isn't actually issue with express. I tried to connect with botkit methods as found in messenger guide and I experience the same behavior.

I checked my webhooks, seems ok:
Selected events: messages, messaging_postbacks, messaging_optins, message_deliveries

Also from @jonchurh answer it seems to be related to my newest issue

[jonchurch]

@KarlisJ are you on our slack team? dev4slack?

I'd hop onto there for some live support if you'd like. Lots of bot devs in there who could help you achieve whatever you're trying to do, with their real world advice!

I'd try channels #botkit, and #botkit-conversations

[KarlisJ]

@jonchurch just joined your slack team. Wanted to give more update.

I do not understand how you managed to use sayFirst()? I really do not think that is it a valid solution because I am experiencing the same problem with say() and ask(). There is no askFirst() :)

My code for conversation now:

bot.createConversation(message, function(err, convo){
	convo.addMessage('Lets start conversation', 'default');
	convo.addQuestion(require('./questions').categories(),function(response, convo){
		if(!require('./questions').incategories() ){
			convo.say('sorry, but I we do not have category' + response.text+'!');
			convo.repeat();
		}else{
			convo.ask(require('./questions').subcategories(response.text), function(){}, {key: 'subcat'});
		}
		convo.next();
	}, {key: 'cat'}, 'default');
	
	convo.addQuestion('please send us image', function(response, convo){
		console.log(util.inspect(response, false, null))
	},{key: 'image'},'default')
	
	convo.activate();
});

I will not be so easy to reproducate it but the idea should be understandable. With this code either convo.say() or convo.ask() does not take any affect. Here is full log:

Initializing Botkit v0.5.4
info: ** No persistent storage method specified! Data may be lost when process shuts down.
debug: Setting up a handler for spawned
debug: Setting up a handler for heard_trigger
debug: Setting up a handler for command_triggered
debug: Setting up a handler for remote_command_end
debug: Setting up a handler for message_received
debug: Setting up a handler for message_received
debug: Setting up a handler for message_received
debug: Setting up a handler for message_received
debug: Setting up a handler for message_received
Express webserver configured and listening at http://localhost/:3000
debug: RECEIVED MESSAGE
debug: CUSTOM FIND CONVO 1504643719566329 1504643719566329
debug: I HEARD [ 'test' ]
debug: CREATED A CONVO FOR 1504643719566329 1504643719566329
debug: Setting up a handler for end
info: Successfully subscribed to Facebook events: {"success":true}
Botkit can now receive messages
debug: WEBHOOK SUCCESS { recipient_id: '1504643719566329',
message_id: 'mid.$cAAbU-Z6qxbVi44To2Fcsj-gzlNOQ' }
debug: WEBHOOK SUCCESS { recipient_id: '1504643719566329',
message_id: 'mid.$cAAbU-Z6qxbVi44TutFcsj-mqyekC' }
debug: RECEIVED MESSAGE
debug: CUSTOM FIND CONVO 1504643719566329 1504643719566329
debug: FOUND EXISTING CONVO!
debug: HANDLING MESSAGE IN CONVO { text: 'Pet/animals',
user: '1504643719566329',
channel: '1504643719566329',
page: '1845038982415879',
timestamp: 1497639141805,
seq: 22296,
is_echo: undefined,
mid: 'mid.$cAAbU-Z6qxbVi44UJrVcsj_BMuUFe',
sticker_id: undefined,
attachments: undefined,
quick_reply: { payload: 'Pet/animals' },
type: 'user_message' }
debug: WEBHOOK SUCCESS { recipient_id: '1504643719566329',
message_id: 'mid.$cAAbU-Z6qxbVi44UR51csj_J3fiYY' }
debug: RECEIVED MESSAGE
debug: CUSTOM FIND CONVO 1504643719566329 1504643719566329
debug: FOUND EXISTING CONVO!
debug: HANDLING MESSAGE IN CONVO { text: undefined,
user: '1504643719566329',
channel: '1504643719566329',
page: '1845038982415879',
timestamp: 1497639156036,
seq: 22300,
is_echo: undefined,
mid: 'mid.$cAAbU-Z6qxbVi44VBRFcsj_zclFdn',
sticker_id: undefined,
attachments: [ { type: 'image', payload: [Object] } ],
quick_reply: undefined,
type: 'user_message' }
{ text: '',
user: '1504643719566329',
channel: '1504643719566329',
page: '1845038982415879',
timestamp: 1497639156036,
seq: 22300,
is_echo: undefined,
mid: 'mid.$cAAbU-Z6qxbVi44VBRFcsj_zclFdn',
sticker_id: undefined,
attachments:
[ { type: 'image',
payload: { url: 'https://scontent.xx.fbcdn.net/v/t34.0-12/19251133_1185130018299592_1431263138_n.jpg?_nc_ad=z-m&oh=0e46411151061ba83458a4f08189e93b&oe=5945EB08' } } ],
quick_reply: undefined,
type: 'user_message',
question: 'please send us image' }
debug: RECEIVED MESSAGE
debug: CUSTOM FIND CONVO 1504643719566329 1504643719566329
debug: FOUND EXISTING CONVO!
debug: HANDLING MESSAGE IN CONVO { text: 'Dghj',
user: '1504643719566329',
channel: '1504643719566329',
page: '1845038982415879',
timestamp: 1497639162462,
seq: 22303,
is_echo: undefined,
mid: 'mid.$cAAbU-Z6qxbVi44VaXlcskASUFg5W',
sticker_id: undefined,
attachments: undefined,
quick_reply: undefined,
type: 'user_message' }
{ text: 'Dghj',
user: '1504643719566329',
channel: '1504643719566329',
page: '1845038982415879',
timestamp: 1497639162462,
seq: 22303,
is_echo: undefined,
mid: 'mid.$cAAbU-Z6qxbVi44VaXlcskASUFg5W',
sticker_id: undefined,
attachments: undefined,
quick_reply: undefined,
type: 'user_message',
question: 'please send us image' }
debug: RECEIVED MESSAGE
debug: CUSTOM FIND CONVO 1504643719566329 1504643719566329
debug: FOUND EXISTING CONVO!
debug: HANDLING MESSAGE IN CONVO { text: 'Fhhjnfj',
user: '1504643719566329',
channel: '1504643719566329',
page: '1845038982415879',
timestamp: 1497639168354,
seq: 22305,
is_echo: undefined,
mid: 'mid.$cAAbU-Z6qxbVi44VxYlcskApWAr5A',
sticker_id: undefined,
attachments: undefined,
quick_reply: undefined,
type: 'user_message' }
{ text: 'Fhhjnfj',
user: '1504643719566329',
channel: '1504643719566329',
page: '1845038982415879',
timestamp: 1497639168354,
seq: 22305,
is_echo: undefined,
mid: 'mid.$cAAbU-Z6qxbVi44VxYlcskApWAr5A',
sticker_id: undefined,
attachments: undefined,
quick_reply: undefined,
type: 'user_message',
question: 'please send us image' }
debug: RECEIVED MESSAGE
debug: CUSTOM FIND CONVO 1504643719566329 1504643719566329
debug: FOUND EXISTING CONVO!
debug: HANDLING MESSAGE IN CONVO { text: 'Gvjkihf',
user: '1504643719566329',
channel: '1504643719566329',
page: '1845038982415879',
timestamp: 1497639171899,
seq: 22307,
is_echo: undefined,
mid: 'mid.$cAAbU-Z6qxbVi44V_O1cskA3N6wcB',
sticker_id: undefined,
attachments: undefined,
quick_reply: undefined,
type: 'user_message' }
{ text: 'Gvjkihf',
user: '1504643719566329',
channel: '1504643719566329',
page: '1845038982415879',
timestamp: 1497639171899,
seq: 22307,
is_echo: undefined,
mid: 'mid.$cAAbU-Z6qxbVi44V_O1cskA3N6wcB',
sticker_id: undefined,
attachments: undefined,
quick_reply: undefined,
type: 'user_message',
question: 'please send us image' }

however if I comment out the last question (send us image) then the logic works fine.

Another note - in both cases (with and without last question) the conversation never ends. I added

convo.on('end',function(convo) {
	console.log('conversation has benn ended');
});

just before convo.activate() but nothing gets logged in console. here is botkit debug console (last question is coomented out):

You can see that in debugs as well. After aswering last question bot get stuck on last question (I did couple of random strings there).

[pascalwhoop]

I'm debugging this right now as well. Using facebook, but writing my code in Typescript.

I have two handlers and while the first one works, the second one doesn't want to work

My code

export function listenToAll(controller: Controller) {
    controller.on("message_received", messageReceivedCb);
    controller.hears("add (.*) [d]rug", ["message_received"], addDrugCb);
}

export function messageReceivedCb(bot, message: BotkitFacebookMessage) {
    if (message.text) {
        bot.reply(message, `you said ${message.text}`);
    }
}

export function addDrugCb(bot: Bot, message: BotkitFacebookMessage) {
    bot.startConversation(message, (err, convo) => {
        convo.ask(MSGS.TAKE_DRUG_OFFICIAL_NAME, (response, convo) => {
            convo.say("cool I like that drug");
            convo.next();
        });

    });
}

EDIT realizing the code might seem odd xD it's for a drug adherence MVP, the convo.say response is because of a frustrated developer making his day a bit more fun :-P

The top one works which calls this function

 worker.say = function(message, cb) {
            botkit.middleware.send.run(worker, message, function(err, worker, message) {
                if (err) {
                    botkit.log('Error in worker.say: ' + err);
                } else {
                    worker.send(message, cb);
                }
            });
        };

and my message gets delivered. But the conversation.ask calls this code

this.addMessage = function(message, thread) {
            if (!thread) {
                thread = this.thread;
            }
            if (typeof(message) == 'string') {
                message = {
                    text: message,
                    channel: this.source_message.channel,
                };
            } else {
                message.channel = this.source_message.channel;
            }

            if (!this.threads[thread]) {
                this.threads[thread] = [];
            }
            this.threads[thread].push(message);

            // this is the current topic, so add it here as well
            if (this.thread == thread) {
                this.messages.push(message);
            }
        };

Which pushes the message into the this.messages array but the message never gets delivered.

I assume this has something to do with

botkit.tick = function() {
        for (var t = 0; t < botkit.tasks.length; t++) {
            botkit.tasks[t].tick();
        }
        for (var t = botkit.tasks.length - 1; t >= 0; t--) {
            if (!botkit.tasks[t].isActive()) {
                botkit.tasks.splice(t, 1);
            }
        }


        this.trigger('tick', []);

    };

or rather

botkit.startTicking = function() {
        if (!botkit.tickInterval) {
            // set up a once a second tick to process messages
            botkit.tickInterval = setInterval(function() {
                botkit.tick();
            }, 1500);
        }
    };

never actually ticking in my code.

Looking into it, the startTicking gets called in this function facebook_botkit.setupWebserver which we of course don't call if we use express ourselves. So we need to call this I assume. Let's clear this up in the docs. Will write again when I know more. Has been driving me nuts this one.

[pascalwhoop]

Sure enough @KarlisJ @jonchurch

// hook up facebook bot controllers
listenToAll(controller);
addAuthenticationMiddleware(controller);
controller.startTicking(); // <<< this one did it for me. 

[KarlisJ]

@pascalwhoop we have controller.startTicking() in file facebook_setup.js

It is 2 AM where I am so I really could not understand code in your first comment however after your second comment I went through Facebook.js file in botkit code and compared with our version. It really seems that we are doing everything as needed. I could only notice that we call controller.startTicking() later than it is done in facebook_botkit.setupWebserver. I will investigate that in the moorning and update here. Just wanted to point out that we have controller.startTicking().

[KarlisJ]

I know it saturday but I am kind of out of time with this project so I wanted to update on issue :)

Slept of the frustration, had a great breakfast and started everything from scratch. I started with botkit-starter-facebook bot and set it up (without botkit studio) and debuged from there.

First of all - conversations does not get stuck. I was missing convo.next() in callback of my last question.

Secondly, require_delivery: true is not an issue with botkit-starter-facebook. I compared the code and I can only suggest that the problem before was with the order of calling controller.startTicking(). I will look into thsis deeper so we could understand the reason but in future I will just start and expande the project from botkit-starter-facebook.

What still holds true is the issue with order. From what I was able to debug the problems is that either convo.say() and convo.ask() that are added in callbacks of convo.addQuestion() are not inserted into the queue but simply added at the end of queue. Consider this exaple:

controller.hears(['color'], 'message_received', function(bot, message) {
	bot.startConversation(message, function(err, convo) {
		convo.say('This is an example of using convo.ask with a single callback.');
		
		convo.ask('What is your favorite color?', function(response, convo) {
			convo.setVar('color',response.text);
			convo.say('Cool, I like ' + response.text + ' too!');
			convo.next();
		});
		convo.ask('Why  do you like {{vars.color}} color?', function(response, convo){
			convo.next();
		});
		convo.say('Ok bye');
	});
});

The order in conversation is:

bot:What is your favorite color?
me: Green
bot: Why do you like green color?
bot: ok bye
bot: Cool, I like Green too!