Bot stops responding to FB messenger after first conversation

[sbose78]

Hi,
I tried out the tutorial which echoes messages and returns /stats on demand.

1. I configured webhooks, page access token,etc
2. sent a message from the page admin user to the page.
3. received the echoed message ( I've quoted the logs below )
4. all subsequent messages stop triggering the echoed response.
5. I generate new page access token and configure it ( this triggers a hot reboot I'm guessing ).
6. again the echo works just once.

2016-10-19T05:26:10.317081+00:00 app[web.1]: webhook event triggered
2016-10-19T05:26:10.317946+00:00 app[web.1]: message_received event triggered
2016-10-19T05:26:10.334459+00:00 heroku[router]: at=info method=POST path="/webhook" host=dry-badlands-98286.herokuapp.com request_id=dba605a0-a213-4eec-bfcb-ed487faf5d6c fwd="66.220.158.104" dyno=web.1 connect=0ms service=37ms status=200 bytes=228
2016-10-19T05:26:10.628800+00:00 app[web.1]: Sending "Does this work?"
2016-10-19T05:26:10.807635+00:00 app[web.1]: Successfully started typing indicator.
2016-10-19T05:26:10.830356+00:00 app[web.1]: Successfully started typing indicator.
2016-10-19T05:26:11.107588+00:00 app[web.1]: Successfully sent message.
2016-10-19T05:26:13.404081+00:00 app[web.1]: webhook event triggered
2016-10-19T05:26:13.430081+00:00 app[web.1]: Webhook received unknown messagingEvent:  { sender: { id: '1025933884186196' },
2016-10-19T05:26:13.430083+00:00 app[web.1]:   recipient: { id: '292396247443853' },
2016-10-19T05:26:13.430084+00:00 app[web.1]:   timestamp: 0,
2016-10-19T05:26:13.430085+00:00 app[web.1]:   delivery: 
2016-10-19T05:26:13.430085+00:00 app[web.1]:    { mids: [ 'mid.1476854771032:fe4c1f6064' ],
2016-10-19T05:26:13.430086+00:00 app[web.1]:      watermark: 1476854771032,
2016-10-19T05:26:13.430087+00:00 app[web.1]:      seq: 190 } }
2016-10-19T05:26:13.423084+00:00 heroku[router]: at=info method=POST path="/webhook" host=dry-badlands-98286.herokuapp.com request_id=509e1065-ea5d-4c19-9349-7adcab6619a9 fwd="66.220.158.96" dyno=web.1 connect=0ms service=31ms status=400 bytes=247
2016-10-19T05:26:14.003210+00:00 app[web.1]: webhook event triggered
2016-10-19T05:26:14.003723+00:00 app[web.1]: Webhook received unknown messagingEvent:  { sender: { id: '1025933884186196' },
2016-10-19T05:26:14.003725+00:00 app[web.1]:   recipient: { id: '292396247443853' },
2016-10-19T05:26:14.003726+00:00 app[web.1]:   timestamp: 0,
2016-10-19T05:26:14.003727+00:00 app[web.1]:   delivery: 
2016-10-19T05:26:14.003727+00:00 app[web.1]:    { mids: [ 'mid.1476854771032:fe4c1f6064' ],
2016-10-19T05:26:14.003728+00:00 app[web.1]:      watermark: 1476854771032,
2016-10-19T05:26:14.003728+00:00 app[web.1]:      seq: 190 } }
2016-10-19T05:26:14.007697+00:00 heroku[router]: at=info method=POST path="/webhook" host=dry-badlands-98286.herokuapp.com request_id=79648972-d217-4aeb-a682-1d2075eafb34 fwd="173.252.124.70" dyno=web.1 connect=1ms service=3ms status=400 bytes=247
2016-10-19T05:26:14.555618+00:00 app[web.1]: webhook event triggered
2016-10-19T05:26:14.556168+00:00 app[web.1]: Webhook received unknown messagingEvent:  { sender: { id: '1025933884186196' },
2016-10-19T05:26:14.556169+00:00 app[web.1]:   recipient: { id: '292396247443853' },
2016-10-19T05:26:14.556170+00:00 app[web.1]:   timestamp: 0,
2016-10-19T05:26:14.556170+00:00 app[web.1]:   delivery: 
2016-10-19T05:26:14.556171+00:00 app[web.1]:    { mids: [ 'mid.1476854771032:fe4c1f6064' ],
2016-10-19T05:26:14.556171+00:00 app[web.1]:      watermark: 1476854771032,
2016-10-19T05:26:14.556172+00:00 app[web.1]:      seq: 190 } }
2016-10-19T05:26:14.548078+00:00 heroku[router]: at=info method=POST path="/webhook" host=dry-badlands-98286.herokuapp.com request_id=48831492-12e2-4309-82b5-5a25904dd2a6 fwd="173.252.124.83" dyno=web.1 connect=0ms service=2ms status=400 bytes=247
2016-10-19T05:26:15.180407+00:00 app[web.1]: webhook event triggered
2016-10-19T05:26:15.181326+00:00 app[web.1]: Webhook received unknown messagingEvent:  { sender: { id: '1025933884186196' },
2016-10-19T05:26:15.181328+00:00 app[web.1]:   recipient: { id: '292396247443853' },
2016-10-19T05:26:15.181329+00:00 app[web.1]:   timestamp: 0,
2016-10-19T05:26:15.181329+00:00 app[web.1]:   delivery: 
2016-10-19T05:26:15.181330+00:00 app[web.1]:    { mids: [ 'mid.1476854771032:fe4c1f6064' ],
2016-10-19T05:26:15.181331+00:00 app[web.1]:      watermark: 1476854771032,
2016-10-19T05:26:15.181332+00:00 app[web.1]:      seq: 190 } }
2016-10-19T05:26:15.191608+00:00 heroku[router]: at=info method=POST path="/webhook" host=dry-badlands-98286.herokuapp.com request_id=aca29eed-46e5-4b05-9e9a-272173b1ead1 fwd="173.252.124.78" dyno=web.1 connect=0ms service=3ms status=400 bytes=247
2016-10-19T05:26:16.309126+00:00 app[web.1]: webhook event triggered
2016-10-19T05:26:16.309889+00:00 app[web.1]: Webhook received unknown messagingEvent:  { sender: { id: '1025933884186196' },
2016-10-19T05:26:16.309891+00:00 app[web.1]:   recipient: { id: '292396247443853' },
2016-10-19T05:26:16.309892+00:00 app[web.1]:   timestamp: 0,
2016-10-19T05:26:16.309893+00:00 app[web.1]:   delivery: 
2016-10-19T05:26:16.309893+00:00 app[web.1]:    { mids: [ 'mid.1476854771032:fe4c1f6064' ],
2016-10-19T05:26:16.309894+00:00 app[web.1]:      watermark: 1476854771032,
2016-10-19T05:26:16.309895+00:00 app[web.1]:      seq: 190 } }
2016-10-19T05:26:16.313548+00:00 heroku[router]: at=info method=POST path="/webhook" host=dry-badlands-98286.herokuapp.com request_id=377c271a-da9d-4b57-af6c-b6117e5b81f3 fwd="173.252.124.77" dyno=web.1 connect=0ms service=4ms status=400 bytes=247
2016-10-19T05:26:20.114836+00:00 app[web.1]: webhook event triggered
2016-10-19T05:26:20.115274+00:00 app[web.1]: Webhook received unknown messagingEvent:  { sender: { id: '1025933884186196' },
2016-10-19T05:26:20.115276+00:00 app[web.1]:   recipient: { id: '292396247443853' },
2016-10-19T05:26:20.115276+00:00 app[web.1]:   timestamp: 0,
2016-10-19T05:26:20.115277+00:00 app[web.1]:   delivery: 
2016-10-19T05:26:20.115277+00:00 app[web.1]:    { mids: [ 'mid.1476854771032:fe4c1f6064' ],
2016-10-19T05:26:20.115278+00:00 app[web.1]:      watermark: 1476854771032,
2016-10-19T05:26:20.115278+00:00 app[web.1]:      seq: 190 } }
2016-10-19T05:26:20.107655+00:00 heroku[router]: at=info method=POST path="/webhook" host=dry-badlands-98286.herokuapp.com request_id=0a17f2a3-4c66-4ce0-b850-5cd079b325d8 fwd="173.252.124.26" dyno=web.1 connect=0ms service=3ms status=400 bytes=247

And then , after about half an hour, the echo happens again and again for the same message ( almost endlessly ):

2016-10-19T06:03:23.942830+00:00 heroku[router]: at=info method=POST path="/webhook" host=dry-badlands-98286.herokuapp.com request_id=4198b440-b8cf-4aa8-8203-54a5e1ea1158 fwd="173.252.120.115" dyno=web.1 connect=0ms service=2ms status=400 bytes=247
2016-10-19T06:03:23.951121+00:00 app[web.1]: webhook event triggered
2016-10-19T06:03:23.951502+00:00 app[web.1]: Webhook received unknown messagingEvent:  { sender: { id: '1025933884186196' },
2016-10-19T06:03:23.951505+00:00 app[web.1]:   recipient: { id: '292396247443853' },
2016-10-19T06:03:23.951506+00:00 app[web.1]:   timestamp: 0,
2016-10-19T06:03:23.951506+00:00 app[web.1]:   delivery: 
2016-10-19T06:03:23.951507+00:00 app[web.1]:    { mids: [ 'mid.1476854771032:fe4c1f6064' ],
2016-10-19T06:03:23.951508+00:00 app[web.1]:      watermark: 1476854771032,
2016-10-19T06:03:23.951508+00:00 app[web.1]:      seq: 190 } }
2016-10-19T06:03:23.951960+00:00 app[web.1]: message_received event triggered
2016-10-19T06:03:23.957755+00:00 app[web.1]: Error: Can't set headers after they are sent.
2016-10-19T06:03:23.957757+00:00 app[web.1]:     at ServerResponse.OutgoingMessage.setHeader (_http_outgoing.js:346:11)
2016-10-19T06:03:23.957757+00:00 app[web.1]:     at ServerResponse.header (/app/node_modules/express/lib/response.js:719:10)
2016-10-19T06:03:23.957759+00:00 app[web.1]:     at ServerResponse.contentType (/app/node_modules/express/lib/response.js:552:15)
2016-10-19T06:03:23.957760+00:00 app[web.1]:     at ServerResponse.sendStatus (/app/node_modules/express/lib/response.js:340:8)
2016-10-19T06:03:23.957761+00:00 app[web.1]:     at ServerResponse.res.success (/app/node_modules/bottr/lib/response-middleware.js:5:11)
2016-10-19T06:03:23.957761+00:00 app[web.1]:     at /app/node_modules/bottr/lib/facebook-messenger-client.js:64:15
2016-10-19T06:03:23.957762+00:00 app[web.1]:     at Array.forEach (native)
2016-10-19T06:03:23.957763+00:00 app[web.1]:     at /app/node_modules/bottr/lib/facebook-messenger-client.js:60:27
2016-10-19T06:03:23.957763+00:00 app[web.1]:     at Array.forEach (native)
2016-10-19T06:03:23.957765+00:00 app[web.1]:     at FacebookMessengerClient.handleEvent (/app/node_modules/bottr/lib/facebook-messenger-client.js:59:16)
2016-10-19T06:03:23.957766+00:00 app[web.1]:     at FacebookMessengerClient.<anonymous> (/app/node_modules/bottr/lib/facebook-messenger-client.js:35:12)
2016-10-19T06:03:23.957767+00:00 app[web.1]:     at Event.next (/app/node_modules/bottr/lib/event.js:16:14)
2016-10-19T06:03:23.957768+00:00 app[web.1]:     at EventEmitter.emit (/app/node_modules/bottr/lib/event-emitter.js:28:9)
2016-10-19T06:03:23.957768+00:00 app[web.1]:     at Bot.trigger (/app/node_modules/bottr/lib/bot.js:49:26)
2016-10-19T06:03:23.957769+00:00 app[web.1]:     at Bot.handleWebhookRequest (/app/node_modules/bottr/lib/bot.js:44:8)
2016-10-19T06:03:23.957770+00:00 app[web.1]:     at Layer.handle [as handle_request] (/app/node_modules/express/lib/router/layer.js:95:5)
2016-10-19T06:03:24.053247+00:00 app[web.1]: Sending "hi"
2016-10-19T06:03:24.329363+00:00 app[web.1]: Successfully started typing indicator.
2016-10-19T06:03:24.332173+00:00 app[web.1]: Successfully started typing indicator.
2016-10-19T06:03:24.374676+00:00 app[web.1]: Successfully sent message.

[jcampbell05]

@sbose78 Did you check the echo_webhook by any chance, I think if you uncheck that it will stop it continually sending stuff like this. We should probably add a filter into the Bottr Facebook client to detect that webhook

[sbose78]

Hi @jcampbell05 ,
Did you mean 'message_echoes' ? I never turned it on.

I'm just wondering if the problem is here:
https://github.com/Bottr-js/Bottr/blob/master/lib/session.js#L6

  this.queue.concurrency = 1

Or
https://github.com/Bottr-js/Bottr/blob/master/lib/session.js#L16
with the way the session send queue is being handled/emptied.

( this is with respect to the problem that after the first message nothing gets echoed )

[jcampbell05]

@sbose78 It could be, do you have any ideas on how we could improve this? We just need a basic queue for sending messages one by one.