Message is not matching listener as expected

[aoberoi]

Description

This issue is to track the problem first described in #500. In that issue, a bug was uncovered with the attachment formatting, and fixed. But @mininobu is still having a problem with a listener (created by the hubot-broadlink-rm script package) not matching messages it is meant to match. The key details are in this comment

Requirements (place an x in each of the [ ])

• I've read and understood the Contributing guidelines and have done my best effort to follow them.
• I've read and agree to the Code of Conduct.
• I've searched for any related issues and avoided creating a duplicate issue.

---

Bug Report

Filling out the following details about bugs will help us solve your issue sooner.

Reproducible in:

hubot-slack version: 4.5.2

node version: 8.11.3

OS version(s): Raspbian 9.1（Raspberry Pi 3)

Steps to reproduce:

1. execute hubot bin/hubot --adapter slack
2. wait for hubot to connect to Slack RTM
3. Send a message from IFTTT
   　　IFTTT "that" info
   Which channel? => Direct Message / @homebot
   Message => send tv:on
   ※The message was sent from the Android application of IFTTT.
4. A message arrives from IFTTT to Slack (it is confirmed that it will be displayed by the Slack application)
5. The listener never executes (according to logs) and the RM Mini never receives the command.

Expected result:

RM Mini to operate.

Actual result:

RM Mini is idle.

Attachments:

DEBUG Received text message in channel: XXXXXXXXX, from: undefined (bot)
DEBUG No listeners executed; falling back to catch-all

[aoberoi]

@mininobu the information you have given about the functionality working when triggered by manually using Slack to send the message (as a human), and not working when the message is originating from the IFTTT webhook, is very helpful.

can you check the logs once again when triggering the command using the Slack client to see what comes after the log line you shared already?

DEBUG Received text message in channel: XXXXXXXXX, from: XXXXXXXXX (human)

After this line, I'd expect another line that looks similar to the following:

DEBUG Message XXXXX matched regex XXXXXX; listener.options = XXXXXX

If this line exists, can you share the contents? Please mask any sensitive data or IDs you don't want to share. I think understanding the structure of those values will be important in debugging further.

[mininobu]

@aoberoi
Thank you for creating Issue.
I'm sorry I did not contact you sooner.

can you check the logs once again when triggering the command using the Slack client to see what comes after the log line you shared already?

OK.
The logs that were displayed after that are as follows.

[Sat Jul 07 2018 12:49:16 GMT+0000 (UTC)] DEBUG Received text message in channel: XXXXXXXXX, from: XXXXXXXXX (human)
[Sat Jul 07 2018 12:49:16 GMT+0000 (UTC)] DEBUG Message 'homebot send tvvol:down' matched regex //^\s*[@]?homebot[:,]?\s*(?:send(((\s+[[(]\s*(((\d+)\s*(ms|s|m|h|d|seconds?|minutes?|hours?|days?|秒|分|時間|日)\s*後?)|((\d{1,2})\s*[:時]\s*(((\d{1,2})\s*分?)|(半))?))\s*(([-+])\s*(\d+)\s*(ms|s|m|h|d|seconds?|minutes?|hours?|days?|秒|分|時間|日)\s*後?)?\s*[\])])?\s+((([0-9a-z:]+)[(]([^()]*)[)])|(([0-9a-z:]+)(@[0-9a-z:]+)?))(([[(]\s*(\d+)\s*(ms|s|m|h|d|seconds?|minutes?|hours?|days?|秒|分|時間|日)\s*後?\s*[\])])?\*(\d+))?)+)$)//; listener.options = { id: null }
[Sat Jul 07 2018 12:49:16 GMT+0000 (UTC)] DEBUG Executing listener callback for Message 'homebot send tvvol:down'
[Sat Jul 07 2018 12:49:16 GMT+0000 (UTC)] DEBUG SlackClient#send() room: XXXXXXXXX, message: sent tvvol:down

Just to be sure, after logging in hubot, share all logs until RM - mini 3 runs.

pi@raspberrypi:~/homebot $ bin/hubot --adapter slack
audited 372 packages in 9.45s
found 22 vulnerabilities (12 low, 2 moderate, 8 high)
  run `npm audit fix` to fix them, or `npm audit` for details
[Sat Jul 07 2018 12:48:55 GMT+0000 (UTC)] DEBUG Loading adapter slack
[Sat Jul 07 2018 12:48:58 GMT+0000 (UTC)] INFO hubot-slack adapter v4.5.2
warn: SlackDataStore is deprecated and will be removed in the next major version. See project documentation for a migration guide.
warn: SlackDataStore is deprecated and will be removed in the next major version. See project documentation for a migration guide.
[Sat Jul 07 2018 12:48:58 GMT+0000 (UTC)] DEBUG RtmClient initialized with options: undefined
[Sat Jul 07 2018 12:48:58 GMT+0000 (UTC)] DEBUG RtmClient#start() with options: {}
[Sat Jul 07 2018 12:48:58 GMT+0000 (UTC)] DEBUG SlackBot#authenticated() Found self in RTM start data
[Sat Jul 07 2018 12:48:58 GMT+0000 (UTC)] INFO Logged in as @homebot in workspace home
[Sat Jul 07 2018 12:48:59 GMT+0000 (UTC)] INFO Connected to Slack RTM
[Sat Jul 07 2018 12:48:59 GMT+0000 (UTC)] DEBUG Loading scripts from /home/pi/homebot/scripts
[Sat Jul 07 2018 12:48:59 GMT+0000 (UTC)] DEBUG Parsing help for /home/pi/homebot/scripts/example.coffee
[Sat Jul 07 2018 12:48:59 GMT+0000 (UTC)] DEBUG Loading scripts from /home/pi/homebot/src/scripts
[Sat Jul 07 2018 12:48:59 GMT+0000 (UTC)] DEBUG Loading external-scripts from npm packages
[Sat Jul 07 2018 12:49:00 GMT+0000 (UTC)] DEBUG Parsing help for /home/pi/homebot/node_modules/hubot-broadlink-rm/src/broadlink-rm.coffee
[Sat Jul 07 2018 12:49:01 GMT+0000 (UTC)] DEBUG Parsing help for /home/pi/homebot/node_modules/hubot-diagnostics/src/diagnostics.coffee
[Sat Jul 07 2018 12:49:01 GMT+0000 (UTC)] DEBUG Parsing help for /home/pi/homebot/node_modules/hubot-help/src/help.coffee
[Sat Jul 07 2018 12:49:01 GMT+0000 (UTC)] DEBUG Parsing help for /home/pi/homebot/node_modules/hubot-google-images/src/google-images.coffee
[Sat Jul 07 2018 12:49:01 GMT+0000 (UTC)] DEBUG Parsing help for /home/pi/homebot/node_modules/hubot-google-translate/src/google-translate.coffee
[Sat Jul 07 2018 12:49:01 GMT+0000 (UTC)] DEBUG Parsing help for /home/pi/homebot/node_modules/hubot-pugme/src/pugme.coffee
[Sat Jul 07 2018 12:49:01 GMT+0000 (UTC)] DEBUG Parsing help for /home/pi/homebot/node_modules/hubot-maps/src/maps.coffee
[Sat Jul 07 2018 12:49:01 GMT+0000 (UTC)] INFO hubot-redis-brain: Using default redis on localhost:6379
[Sat Jul 07 2018 12:49:01 GMT+0000 (UTC)] DEBUG Parsing help for /home/pi/homebot/node_modules/hubot-redis-brain/src/redis-brain.coffee
[Sat Jul 07 2018 12:49:01 GMT+0000 (UTC)] DEBUG Parsing help for /home/pi/homebot/node_modules/hubot-rules/src/rules.coffee
[Sat Jul 07 2018 12:49:01 GMT+0000 (UTC)] DEBUG Parsing help for /home/pi/homebot/node_modules/hubot-shipit/src/shipit.coffee
[Sat Jul 07 2018 12:49:01 GMT+0000 (UTC)] DEBUG hubot-redis-brain: Successfully connected to Redis
[Sat Jul 07 2018 12:49:01 GMT+0000 (UTC)] INFO hubot-redis-brain: Data for hubot brain retrieved from Redis
[Sat Jul 07 2018 12:49:01 GMT+0000 (UTC)] DEBUG SlackBot#presenceSub() Subscribing to presence for 4 users
Discovered Broadlink RM device at XXX.XXX.XXX.XXX (XX:XX:XX:XX:XX:XX)
[Sat Jul 07 2018 12:49:02 GMT+0000 (UTC)] DEBUG Received presence update message for users: XXXXXXXXX with status: active
[Sat Jul 07 2018 12:49:02 GMT+0000 (UTC)] DEBUG Received presence update message for users: USLACKBOT with status: away
[Sat Jul 07 2018 12:49:02 GMT+0000 (UTC)] DEBUG No listeners executed; falling back to catch-all
[Sat Jul 07 2018 12:49:02 GMT+0000 (UTC)] DEBUG No listeners executed; falling back to catch-all
[Sat Jul 07 2018 12:49:16 GMT+0000 (UTC)] DEBUG Received text message in channel: XXXXXXXXX, from: XXXXXXXXX (human)
[Sat Jul 07 2018 12:49:16 GMT+0000 (UTC)] DEBUG Message 'homebot send tvvol:down' matched regex //^\s*[@]?homebot[:,]?\s*(?:send(((\s+[[(]\s*(((\d+)\s*(ms|s|m|h|d|seconds?|minutes?|hours?|days?|秒|分|時間|日)\s*後?)|((\d{1,2})\s*[:時]\s*(((\d{1,2})\s*分?)|(半))?))\s*(([-+])\s*(\d+)\s*(ms|s|m|h|d|seconds?|minutes?|hours?|days?|秒|分|時間|日)\s*後?)?\s*[\])])?\s+((([0-9a-z:]+)[(]([^()]*)[)])|(([0-9a-z:]+)(@[0-9a-z:]+)?))(([[(]\s*(\d+)\s*(ms|s|m|h|d|seconds?|minutes?|hours?|days?|秒|分|時間|日)\s*後?\s*[\])])?\*(\d+))?)+)$)//; listener.options = { id: null }
[Sat Jul 07 2018 12:49:16 GMT+0000 (UTC)] DEBUG Executing listener callback for Message 'homebot send tvvol:down'
[Sat Jul 07 2018 12:49:16 GMT+0000 (UTC)] DEBUG SlackClient#send() room: XXXXXXXXX, message: sent tvvol:down

Thank you.

[mininobu]

@aoberoi
I downgraded hubot - slack and found that it works correctly on ver4.4.0.
We share the debug log in ver4.4.0 and the debug log in ver4.5.0.
I'm glad if you can use it as a reference.

hubot-slack ver 4.4.0 debug log

pi@raspberrypi:~/homebot $ bin/hubot --adapter slack
audited 390 packages in 19.634s
found 22 vulnerabilities (12 low, 2 moderate, 8 high)
  run `npm audit fix` to fix them, or `npm audit` for details
[Sun Jul 08 2018 05:52:55 GMT+0000 (UTC)] DEBUG Loading adapter slack
[Sun Jul 08 2018 05:52:58 GMT+0000 (UTC)] DEBUG slack rtm client options: undefined
warn: SlackDataStore is deprecated and will be removed in the next major version. See project documentation for a migration guide.
warn: SlackDataStore is deprecated and will be removed in the next major version. See project documentation for a migration guide.
[Sun Jul 08 2018 05:52:59 GMT+0000 (UTC)] DEBUG slack rtm start with options: {}
[Sun Jul 08 2018 05:53:00 GMT+0000 (UTC)] INFO Logged in as homebot of home
[Sun Jul 08 2018 05:53:00 GMT+0000 (UTC)] INFO Slack client now connected
[Sun Jul 08 2018 05:53:00 GMT+0000 (UTC)] DEBUG Loading scripts from /home/pi/homebot/scripts
[Sun Jul 08 2018 05:53:00 GMT+0000 (UTC)] DEBUG Parsing help for /home/pi/homebot/scripts/example.coffee
[Sun Jul 08 2018 05:53:00 GMT+0000 (UTC)] DEBUG Loading scripts from /home/pi/homebot/src/scripts
[Sun Jul 08 2018 05:53:00 GMT+0000 (UTC)] DEBUG Loading external-scripts from npm packages
[Sun Jul 08 2018 05:53:02 GMT+0000 (UTC)] DEBUG Parsing help for /home/pi/homebot/node_modules/hubot-broadlink-rm/src/broadlink-rm.coffee
[Sun Jul 08 2018 05:53:02 GMT+0000 (UTC)] DEBUG Parsing help for /home/pi/homebot/node_modules/hubot-diagnostics/src/diagnostics.coffee
[Sun Jul 08 2018 05:53:03 GMT+0000 (UTC)] DEBUG Parsing help for /home/pi/homebot/node_modules/hubot-help/src/help.coffee
[Sun Jul 08 2018 05:53:03 GMT+0000 (UTC)] DEBUG Parsing help for /home/pi/homebot/node_modules/hubot-google-images/src/google-images.coffee
[Sun Jul 08 2018 05:53:03 GMT+0000 (UTC)] DEBUG Parsing help for /home/pi/homebot/node_modules/hubot-google-translate/src/google-translate.coffee
[Sun Jul 08 2018 05:53:03 GMT+0000 (UTC)] DEBUG Parsing help for /home/pi/homebot/node_modules/hubot-pugme/src/pugme.coffee
[Sun Jul 08 2018 05:53:04 GMT+0000 (UTC)] DEBUG Parsing help for /home/pi/homebot/node_modules/hubot-maps/src/maps.coffee
[Sun Jul 08 2018 05:53:04 GMT+0000 (UTC)] INFO hubot-redis-brain: Using default redis on localhost:6379
[Sun Jul 08 2018 05:53:04 GMT+0000 (UTC)] DEBUG Parsing help for /home/pi/homebot/node_modules/hubot-redis-brain/src/redis-brain.coffee
[Sun Jul 08 2018 05:53:04 GMT+0000 (UTC)] DEBUG Parsing help for /home/pi/homebot/node_modules/hubot-rules/src/rules.coffee
[Sun Jul 08 2018 05:53:04 GMT+0000 (UTC)] DEBUG Parsing help for /home/pi/homebot/node_modules/hubot-shipit/src/shipit.coffee
[Sun Jul 08 2018 05:53:04 GMT+0000 (UTC)] DEBUG hubot-redis-brain: Successfully connected to Redis
[Sun Jul 08 2018 05:53:04 GMT+0000 (UTC)] INFO hubot-redis-brain: Data for hubot brain retrieved from Redis
Discovered Broadlink RM device at XXX.XXX.XXX.XXX (XX:XX:XX:XX:XX:XX)
[Sun Jul 08 2018 05:53:23 GMT+0000 (UTC)] DEBUG Received message: 'homebot send tvvol:down' in channel: DM, from: IFTTT
[Sun Jul 08 2018 05:53:23 GMT+0000 (UTC)] DEBUG Message 'homebot send tvvol:down' matched regex //^\s*[@]?homebot[:,]?\s*(?:send(((\s+[[(]\s*(((\d+)\s*(ms|s|m|h|d|seconds?|minutes?|hours?|days?|秒|分|時間|日)\s*後?)|((\d{1,2})\s*[:時]\s*(((\d{1,2})\s*分?)|(半))?))\s*(([-+])\s*(\d+)\s*(ms|s|m|h|d|seconds?|minutes?|hours?|days?|秒|分|時間|日)\s*後?)?\s*[\])])?\s+((([0-9a-z:]+)[(]([^()]*)[)])|(([0-9a-z:]+)(@[0-9a-z:]+)?))(([[(]\s*(\d+)\s*(ms|s|m|h|d|seconds?|minutes?|hours?|days?|秒|分|時間|日)\s*後?\s*[\])])?\*(\d+))?)+)$)//; listener.options = { id: null }
[Sun Jul 08 2018 05:53:23 GMT+0000 (UTC)] DEBUG Executing listener callback for Message 'homebot send tvvol:down'
[Sun Jul 08 2018 05:53:23 GMT+0000 (UTC)] DEBUG Sending to XXXXXXXXX: sent tvvol:down

hubot-slack 4.5.0 debug log

pi@raspberrypi:~/homebot $ bin/hubot --adapter slack
audited 391 packages in 17.477s
found 22 vulnerabilities (12 low, 2 moderate, 8 high)
  run `npm audit fix` to fix them, or `npm audit` for details
[Sun Jul 08 2018 05:47:45 GMT+0000 (UTC)] DEBUG Loading adapter slack
[Sun Jul 08 2018 05:47:50 GMT+0000 (UTC)] INFO hubot-slack adapter v4.5.0
warn: SlackDataStore is deprecated and will be removed in the next major version. See project documentation for a migration guide.
warn: SlackDataStore is deprecated and will be removed in the next major version. See project documentation for a migration guide.
[Sun Jul 08 2018 05:47:50 GMT+0000 (UTC)] DEBUG RtmClient initialized with options: undefined
[Sun Jul 08 2018 05:47:50 GMT+0000 (UTC)] DEBUG RtmClient#start() with options: {}
[Sun Jul 08 2018 05:47:56 GMT+0000 (UTC)] DEBUG SlackBot#authenticated() Found self in RTM start data
[Sun Jul 08 2018 05:47:56 GMT+0000 (UTC)] INFO Logged in as @homebot in workspace home
[Sun Jul 08 2018 05:47:57 GMT+0000 (UTC)] INFO Connected to Slack RTM
[Sun Jul 08 2018 05:47:57 GMT+0000 (UTC)] DEBUG Loading scripts from /home/pi/homebot/scripts
[Sun Jul 08 2018 05:47:57 GMT+0000 (UTC)] DEBUG Parsing help for /home/pi/homebot/scripts/example.coffee
[Sun Jul 08 2018 05:47:57 GMT+0000 (UTC)] DEBUG Loading scripts from /home/pi/homebot/src/scripts
[Sun Jul 08 2018 05:47:57 GMT+0000 (UTC)] DEBUG Loading external-scripts from npm packages
[Sun Jul 08 2018 05:47:59 GMT+0000 (UTC)] DEBUG Parsing help for /home/pi/homebot/node_modules/hubot-broadlink-rm/src/broadlink-rm.coffee
[Sun Jul 08 2018 05:47:59 GMT+0000 (UTC)] DEBUG Parsing help for /home/pi/homebot/node_modules/hubot-diagnostics/src/diagnostics.coffee
[Sun Jul 08 2018 05:47:59 GMT+0000 (UTC)] DEBUG Parsing help for /home/pi/homebot/node_modules/hubot-help/src/help.coffee
[Sun Jul 08 2018 05:47:59 GMT+0000 (UTC)] DEBUG Parsing help for /home/pi/homebot/node_modules/hubot-google-images/src/google-images.coffee
[Sun Jul 08 2018 05:48:00 GMT+0000 (UTC)] DEBUG Parsing help for /home/pi/homebot/node_modules/hubot-google-translate/src/google-translate.coffee
[Sun Jul 08 2018 05:48:00 GMT+0000 (UTC)] DEBUG Parsing help for /home/pi/homebot/node_modules/hubot-pugme/src/pugme.coffee
[Sun Jul 08 2018 05:48:00 GMT+0000 (UTC)] DEBUG Parsing help for /home/pi/homebot/node_modules/hubot-maps/src/maps.coffee
[Sun Jul 08 2018 05:48:00 GMT+0000 (UTC)] INFO hubot-redis-brain: Using default redis on localhost:6379
[Sun Jul 08 2018 05:48:00 GMT+0000 (UTC)] DEBUG Parsing help for /home/pi/homebot/node_modules/hubot-redis-brain/src/redis-brain.coffee
[Sun Jul 08 2018 05:48:00 GMT+0000 (UTC)] DEBUG Parsing help for /home/pi/homebot/node_modules/hubot-rules/src/rules.coffee
[Sun Jul 08 2018 05:48:00 GMT+0000 (UTC)] DEBUG Parsing help for /home/pi/homebot/node_modules/hubot-shipit/src/shipit.coffee
[Sun Jul 08 2018 05:48:00 GMT+0000 (UTC)] DEBUG hubot-redis-brain: Successfully connected to Redis
[Sun Jul 08 2018 05:48:00 GMT+0000 (UTC)] INFO hubot-redis-brain: Data for hubot brain retrieved from Redis
[Sun Jul 08 2018 05:48:00 GMT+0000 (UTC)] DEBUG SlackBot#presenceSub() Subscribing to presence for 4 users
[Sun Jul 08 2018 05:48:03 GMT+0000 (UTC)] DEBUG Received presence update message for users: XXXXXXXXX with status: active
[Sun Jul 08 2018 05:48:03 GMT+0000 (UTC)] DEBUG Received presence update message for users: USLACKBOT with status: away
[Sun Jul 08 2018 05:48:03 GMT+0000 (UTC)] DEBUG No listeners executed; falling back to catch-all
[Sun Jul 08 2018 05:48:03 GMT+0000 (UTC)] DEBUG No listeners executed; falling back to catch-all
Discovered Broadlink RM device at XXX.XXX.XXX.XXX (XX:XX:XX:XX:XX:XX)
[Sun Jul 08 2018 05:48:38 GMT+0000 (UTC)] DEBUG Received text message in channel: XXXXXXXXX, from: undefined (bot)
[Sun Jul 08 2018 05:48:38 GMT+0000 (UTC)] ERROR An error occurred while processing an RTM event: a is not defined.

[aoberoi]

@mininobu thanks for providing so much information! it would be useful if you could give a log like those in your last message but for v4.5.2. the log you provided only points out the issue we already solved in #500.

[aoberoi]

okay i've been debugging with @shanedewael and we think we understand the root cause! there's no need to provide us with any more logs, we're working on a patch with a fix.

[aoberoi]

for the record, it turns out the IFTTT sends messages with no text, and instead uses a single attachment with a pretext (and fallback) assigned to the value you build for the body text. the code did not anticipate this structure, so it would try concatenating undefined with "\n" + attachment_text, which resulted in "undefined\nsend tvvol:down". that string would not match the pattern that hubot-broadlink-rm was using to attach its behavior to hubot. we've fixed this by detecting when text is undefined and using the empty string in its place.