Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Slack triggers multiple messages to rasa (does not happen with Telegram/Commandline) #2120

Closed
ewagner70 opened this issue May 15, 2018 · 38 comments
Assignees

Comments

@ewagner70
Copy link

Rasa Core version: 0.9.0a5

Python version: 3.6

Operating system (windows, osx, ...): ubuntu 18.04

Issue: Slack triggers multiple messages to rasa and NO, this does not happen with Telegram and Commandline Interface (!) with the very same trained RASA_NLU and RASA_CORE models (!!)
Please, Rasa-Team: Try to reproduce that with any kind of story!

Content of domain file (if used & relevant):

@akelad
Copy link
Contributor

akelad commented May 18, 2018

Can I ask with what bot you're trying this? And have you definitely tried this with the exact same stories on each channel? Because I looked into this a while ago with the restaurant bot and it happened on the command line as well. But I can take a look again

@ewagner70
Copy link
Author

@akelad yes, definitely ... 100% reproduceable (Telegram and Commandline works, but Slack doesn't). Please note, I'm using the following Slack Subscriptions:

Subscribe to Workspace Events
im_created
message.im

Subscribe to Bot Events
app_mention
message.channels
message.groups
message.im
message.mpim

@akelad
Copy link
Contributor

akelad commented May 22, 2018

ok thanks, we'll take a look

@akelad
Copy link
Contributor

akelad commented May 22, 2018

hey @ewagner70, I just tried to reproduce this by running the moodbot from our examples, and it's behaving completely normally for me. Can you provide some more details as to when this error happens, which bot this is with etc?

@akelad
Copy link
Contributor

akelad commented May 22, 2018

also exactly which features you've enabled

@ewagner70
Copy link
Author

ewagner70 commented May 22, 2018

@akelad,

  • it's my own bot, attached please find the the code incl. Dockerfile for ubuntu 18.04. (in gb.py you need to comment the 2 lines below "#Console Input Channel" and remove comments for the 2 lines below "#Slack Input Channel" and install ngor for webcommunication accordingly)
    PLEASE NOTE AGAIN, THAT THESE ARE THE ONLY CHANGES I DO WHEN COMPARING CONSOLE/TELEGRAM (WORKING) AND SLACK (NOT WORKIGN) !!

  • below please find the multiple messages that I receive (it seems to happen after utter_default of my FormAction is triggered, but don't nail me on that ...!): image

  • "features enabled" - note sure what you mean by that ... if you mean slackbot events subscribed, please see my comment above repeated below:

Subscribe to Workspace Events
im_created
message.im

Subscribe to Bot Events
app_mention
message.channels
message.groups
message.im
message.mpim

@akelad
Copy link
Contributor

akelad commented May 24, 2018

Thanks, I will try to reproduce again with your bot!

@akelad
Copy link
Contributor

akelad commented May 24, 2018

ok i actually reproduced it with the restaurantbot. So the issue is the fact that you're subscribed to Workspace Events:

Subscribe to Workspace Events
im_created
message.im

the bot processes any direct messages you receive/send and so it continues replying to the channel you've specified

@Walter-Ullon
Copy link

Walter-Ullon commented May 24, 2018

@akelad I had this same issue yesterday, and in my Slack app config, I am only subscribed to "Bot Events". At one point, I received 6 messages back from a single query.

Note that this is the first time we experienced this issue.

@akelad
Copy link
Contributor

akelad commented May 24, 2018

Which bot events are you subscribed to exactly? Also does the same conversation with the same model work fine on the command line?

@Walter-Ullon
Copy link

Walter-Ullon commented May 24, 2018

@akelad
screen shot 2018-05-24 at 9 39 29 am

To answer your second question, the same convo worked fine in command line.

@akelad
Copy link
Contributor

akelad commented May 24, 2018

haha i am very lost as to how this is happening. @ewagner70 have you checked whether turning the workplace events off fixes your problem?

@prateekchoudhary
Copy link

prateekchoudhary commented May 24, 2018

@Walter-Ullon, @akelad I too have a similar issue. It works perfectly fine on the console but not with slack.
In the logs I see following getting called repeatedly:

127.0.0.1 - - [2018-05-25 01:31:21] POST /slack/events 200 115 0.007336

I was getting following error sometime back:

if (message.text.startswith(INTENT_MESSAGE_PREFIX) or
AttributeError: 'NoneType' object has no attribute 'startswith'

Which I eventually traced back to rasa core complaining about message being None.

Just to mention - I also have a fallback action and an action which uploads a file to slack. So file starts getting uploaded multiple times and I see a lot of fallback messages.
I haven't subscribed to any workplace event.

@akelad
Copy link
Contributor

akelad commented May 25, 2018

Ok, so I assume the error message you're getting there might have something to do with the uploading file part. Do you still encounter that error message? And if not, does that POST request keep happening repeatedly?

@akelad
Copy link
Contributor

akelad commented May 25, 2018

can one of the people having this problem please post a full trace of their debug log when something like this happens? (so running the bot with the --debug flag)

@prateekchoudhary
Copy link

@akelad I can confirm that uploading file is not a problem nor is the fallback action as I removed all of the functionality and now have a simple greeting intent for which I am receiving 3 responses. I even tried disabling events subscription and re-enabling it all over again.

Here is the DEBUG trace:

2018-05-25 15:54:44 INFO root - Rasa process starting
Using TensorFlow backend.
2018-05-25 15:54:58 WARNING tensorflow - From /home/prateek/anaconda3/lib/python3.6/site-packages/tensorflow/contrib/learn/python/learn/datasets/base.py:198: retry (from tensorflow.contrib.learn.python.learn.datasets.base) is deprecated and will be removed in a future version.
Instructions for updating:
Use the retry module or similar alternatives.
2018-05-25 15:55:01 WARNING tensorflow - From /home/prateek/anaconda3/lib/python3.6/site-packages/keras/backend/tensorflow_backend.py:1305: calling reduce_any (from tensorflow.python.ops.math_ops) with keep_dims is deprecated and will be removed in a future version.
Instructions for updating:
keep_dims is deprecated, use keepdims instead
2018-05-25 15:55:01 WARNING tensorflow - From /home/prateek/anaconda3/lib/python3.6/site-packages/keras/backend/tensorflow_backend.py:1188: calling reduce_sum (from tensorflow.python.ops.math_ops) with keep_dims is deprecated and will be removed in a future version.
Instructions for updating:
keep_dims is deprecated, use keepdims instead
2018-05-25 15:55:02 DEBUG pip.vcs - Registered VCS backend: git
2018-05-25 15:55:03 DEBUG pip.vcs - Registered VCS backend: hg
2018-05-25 15:55:03 DEBUG pip.vcs - Registered VCS backend: svn
2018-05-25 15:55:03 DEBUG pip.vcs - Registered VCS backend: bzr
2018-05-25 15:55:08 INFO rasa_nlu.components - Added 'nlp_spacy' to component cache. Key 'nlp_spacy-en'.
2018-05-25 15:56:06 INFO rasa_nlu.components - Added 'ner_duckling' to component cache. Key 'ner_duckling-en'.
2018-05-25 15:56:06 INFO root - Finished loading agent, starting input channel & server.
2018-05-25 15:58:52 DEBUG rasa_core.tracker_store - Creating a new tracker for id 'XXXXXXQ6L'.
2018-05-25 15:58:53 DEBUG rasa_core.processor - Received user message 'hi' with intent '{'name': 'greet', 'confidence': 0.41084403119300156}' and entities '[]'
2018-05-25 15:58:53 DEBUG rasa_core.processor - Logged UserUtterance - tracker now has 2 events
2018-05-25 15:58:53 DEBUG rasa_core.processor - Current slot values:
category: None
city: None
summary: None
time: None
2018-05-25 15:58:53 DEBUG rasa_core.policies.memoization - Current tracker state [
None
None
None
None
[('intent_greet', 1), ('prev_action_listen', 1)]]
2018-05-25 15:58:53 DEBUG rasa_core.policies.memoization - Used memorised next action '2'
2018-05-25 15:58:55 DEBUG rasa_core.policies.ensemble - Predicted next action using policy_0_MemoizationPolicy
2018-05-25 15:58:55 DEBUG rasa_core.policies.ensemble - Predicted next action 'utter_greet' with prob 1.00.
2018-05-25 15:58:56 DEBUG requests.packages.urllib3.connectionpool - Starting new HTTPS connection (1): slack.com
2018-05-25 15:58:58 DEBUG requests.packages.urllib3.connectionpool - https://slack.com:443 "POST /api/chat.postMessage HTTP/1.1" 200 163
2018-05-25 15:58:59 DEBUG rasa_core.processor - Bot utterance 'BotUttered(text: Hello! How can I help?, data: null)'
2018-05-25 15:58:59 DEBUG rasa_core.processor - Action 'utter_greet' ended with events '[]'
2018-05-25 15:58:59 DEBUG rasa_core.policies.memoization - Current tracker state [
None
None
None
[('intent_greet', 1), ('prev_action_listen', 1)]
[('intent_greet', 1), ('prev_utter_greet', 1)]]
2018-05-25 15:58:59 DEBUG rasa_core.policies.memoization - Used memorised next action '0'
2018-05-25 15:58:59 DEBUG rasa_core.policies.ensemble - Predicted next action using policy_0_MemoizationPolicy
2018-05-25 15:58:59 DEBUG rasa_core.policies.ensemble - Predicted next action 'action_listen' with prob 1.00.
2018-05-25 15:58:59 DEBUG rasa_core.processor - Action 'action_listen' ended with events '[]'
2018-05-25 15:58:59 DEBUG rasa_core.processor - Current topic: None
127.0.0.1 - - [2018-05-25 15:58:59] "POST /webhook HTTP/1.1" 200 115 7.017757
2018-05-25 15:58:59 DEBUG rasa_core.tracker_store - Recreating tracker for id 'XXXXXXQ6L'
2018-05-25 15:58:59 DEBUG rasa_core.processor - Received user message 'hi' with intent '{'name': 'greet', 'confidence': 0.41084403119300156}' and entities '[]'
2018-05-25 15:58:59 DEBUG rasa_core.processor - Logged UserUtterance - tracker now has 6 events
2018-05-25 15:58:59 DEBUG rasa_core.processor - Current slot values:
category: None
city: None
summary: None
time: None
2018-05-25 15:58:59 DEBUG rasa_core.policies.memoization - Current tracker state [
None
None
[('intent_greet', 1), ('prev_action_listen', 1)]
[('intent_greet', 1), ('prev_utter_greet', 1)]
[('intent_greet', 1), ('prev_action_listen', 1)]]
2018-05-25 15:58:59 DEBUG rasa_core.policies.memoization - Used memorised next action '2'
2018-05-25 15:58:59 DEBUG rasa_core.policies.ensemble - Predicted next action using policy_0_MemoizationPolicy
2018-05-25 15:58:59 DEBUG rasa_core.policies.ensemble - Predicted next action 'utter_greet' with prob 1.00.
2018-05-25 15:58:59 DEBUG requests.packages.urllib3.connectionpool - Starting new HTTPS connection (1): slack.com
2018-05-25 15:59:05 DEBUG requests.packages.urllib3.connectionpool - https://slack.com:443 "POST /api/chat.postMessage HTTP/1.1" 200 163
2018-05-25 15:59:05 DEBUG rasa_core.processor - Bot utterance 'BotUttered(text: Hello! How can I help?, data: null)'
2018-05-25 15:59:05 DEBUG rasa_core.processor - Action 'utter_greet' ended with events '[]'
2018-05-25 15:59:05 DEBUG rasa_core.policies.memoization - Current tracker state [
None
[('intent_greet', 1), ('prev_action_listen', 1)]
[('intent_greet', 1), ('prev_utter_greet', 1)]
[('intent_greet', 1), ('prev_action_listen', 1)]
[('intent_greet', 1), ('prev_utter_greet', 1)]]
2018-05-25 15:59:05 DEBUG rasa_core.policies.memoization - Used memorised next action '0'
2018-05-25 15:59:05 DEBUG rasa_core.policies.ensemble - Predicted next action using policy_0_MemoizationPolicy
2018-05-25 15:59:05 DEBUG rasa_core.policies.ensemble - Predicted next action 'action_listen' with prob 1.00.
2018-05-25 15:59:05 DEBUG rasa_core.processor - Action 'action_listen' ended with events '[]'
2018-05-25 15:59:05 DEBUG rasa_core.processor - Current topic: None
127.0.0.1 - - [2018-05-25 15:59:05] "POST /webhook HTTP/1.1" 200 115 6.061916
127.0.0.1 - - [2018-05-25 15:59:05] "POST /webhook HTTP/1.1" 200 115 0.002967
127.0.0.1 - - [2018-05-25 15:59:05] "POST /webhook HTTP/1.1" 200 115 0.001100
127.0.0.1 - - [2018-05-25 15:59:09] "POST /webhook HTTP/1.1" 200 115 0.003286
127.0.0.1 - - [2018-05-25 15:59:09] "POST /webhook HTTP/1.1" 200 115 0.000819
2018-05-25 15:59:58 DEBUG rasa_core.tracker_store - Recreating tracker for id 'XXXXXXQ6L'
2018-05-25 15:59:58 DEBUG rasa_core.processor - Received user message 'hi' with intent '{'name': 'greet', 'confidence': 0.41084403119300156}' and entities '[]'
2018-05-25 15:59:58 DEBUG rasa_core.processor - Logged UserUtterance - tracker now has 10 events
2018-05-25 15:59:58 DEBUG rasa_core.processor - Current slot values:
category: None
city: None
summary: None
time: None
2018-05-25 15:59:58 DEBUG rasa_core.policies.memoization - Current tracker state [
[('intent_greet', 1), ('prev_action_listen', 1)]
[('intent_greet', 1), ('prev_utter_greet', 1)]
[('intent_greet', 1), ('prev_action_listen', 1)]
[('intent_greet', 1), ('prev_utter_greet', 1)]
[('intent_greet', 1), ('prev_action_listen', 1)]]
2018-05-25 15:59:58 DEBUG rasa_core.policies.memoization - Used memorised next action '2'
2018-05-25 15:59:58 DEBUG rasa_core.policies.ensemble - Predicted next action using policy_0_MemoizationPolicy
2018-05-25 15:59:58 DEBUG rasa_core.policies.ensemble - Predicted next action 'utter_greet' with prob 1.00.
2018-05-25 15:59:58 DEBUG requests.packages.urllib3.connectionpool - Starting new HTTPS connection (1): slack.com
2018-05-25 15:59:58 DEBUG requests.packages.urllib3.connectionpool - https://slack.com:443 "POST /api/chat.postMessage HTTP/1.1" 200 163
2018-05-25 15:59:58 DEBUG rasa_core.processor - Bot utterance 'BotUttered(text: Hello! How can I help?, data: null)'
2018-05-25 15:59:58 DEBUG rasa_core.processor - Action 'utter_greet' ended with events '[]'
2018-05-25 15:59:58 DEBUG rasa_core.policies.memoization - Current tracker state [
[('intent_greet', 1), ('prev_utter_greet', 1)]
[('intent_greet', 1), ('prev_action_listen', 1)]
[('intent_greet', 1), ('prev_utter_greet', 1)]
[('intent_greet', 1), ('prev_action_listen', 1)]
[('intent_greet', 1), ('prev_utter_greet', 1)]]
2018-05-25 15:59:58 DEBUG rasa_core.policies.memoization - Used memorised next action '0'
2018-05-25 15:59:59 DEBUG rasa_core.policies.ensemble - Predicted next action using policy_0_MemoizationPolicy
2018-05-25 15:59:59 DEBUG rasa_core.policies.ensemble - Predicted next action 'action_listen' with prob 1.00.
2018-05-25 15:59:59 DEBUG rasa_core.processor - Action 'action_listen' ended with events '[]'
2018-05-25 15:59:59 DEBUG rasa_core.processor - Current topic: None
127.0.0.1 - - [2018-05-25 15:59:59] "POST /webhook HTTP/1.1" 200 115 0.869776
127.0.0.1 - - [2018-05-25 15:59:59] "POST /webhook HTTP/1.1" 200 115 0.001046
127.0.0.1 - - [2018-05-25 16:00:09] "POST /webhook HTTP/1.1" 200 115 0.000818

@akelad
Copy link
Contributor

akelad commented May 25, 2018

it seems it's receiving the message "hi" over and over again... the repeated POSTs should be fine. How are you chatting to the bot, in a direct message with it, or a channel?

@Walter-Ullon
Copy link

Walter-Ullon commented May 25, 2018

Below is the log for a single query for which I received 3 responses. It happens for multiple intents.

Note that this behavior is present when I test with the code deployed in AWS, and when I open my local build using ngrok.

Also note that I'm still using core 0.8.5 (no fallback policy activated).

Of course, everything is going through Slack...

I am talking to the bot (app) in a direct message.

172.18.0.3 - - [2018-05-23 18:12:03] "POST /webhook HTTP/1.0" 200 134 1.828511
172.18.0.3 - - [2018-05-23 18:12:03] "POST /webhook HTTP/1.0" 200 134 0.000551
172.18.0.3 - - [2018-05-23 18:12:03] "POST /webhook HTTP/1.0" 200 134 0.000429
172.18.0.3 - - [2018-05-23 18:12:03] "POST /webhook HTTP/1.0" 200 134 0.000436
172.18.0.3 - - [2018-05-23 18:12:03] "POST /webhook HTTP/1.0" 200 134 0.000445
172.18.0.3 - - [2018-05-23 18:12:03] "POST /webhook HTTP/1.0" 200 134 0.000438
172.18.0.3 - - [2018-05-23 18:12:03] "POST /webhook HTTP/1.0" 200 134 0.000471
172.18.0.3 - - [2018-05-23 18:12:03] "POST /webhook HTTP/1.0" 200 134 0.000469
172.18.0.3 - - [2018-05-23 18:12:03] "POST /webhook HTTP/1.0" 200 134 0.000464
172.18.0.3 - - [2018-05-23 18:12:03] "POST /webhook HTTP/1.0" 200 134 0.000466
172.18.0.3 - - [2018-05-23 18:12:03] "POST /webhook HTTP/1.0" 200 134 0.000437
172.18.0.3 - - [2018-05-23 18:12:03] "POST /webhook HTTP/1.0" 200 134 0.000438
172.18.0.3 - - [2018-05-23 18:12:03] "POST /webhook HTTP/1.0" 200 134 0.000443
172.18.0.3 - - [2018-05-23 18:12:03] "POST /webhook HTTP/1.0" 200 134 0.000438
172.18.0.3 - - [2018-05-23 18:12:03] "POST /webhook HTTP/1.0" 200 134 0.000448
2018-05-23 18:15:56 DEBUG    rasa_core.tracker_store  - Recreating tracker for id 'U9MD2EBEH'
/usr/local/lib/python3.6/site-packages/sklearn/preprocessing/label.py:151: DeprecationWarning: The truth value of an empty array is ambiguous. Returning False, but in future this will result in an error. Use `array.size > 0` to check that an array is not empty.
  if diff:
2018-05-23 18:15:56 DEBUG    rasa_core.processor  - Received user message 'can i have the jpm results for yesterday' with intent '{'name': 'return_recon_results', 'confidence': 0.3163429762275638}' and entities '[{'start': 15, 'end': 18, 'value': 'jpm', 'entity': 'counterparty', 'extractor': 'ner_crf'}, {'start': 31, 'end': 40, 'value': 'yesterday', 'entity': 'recon_date', 'extractor': 'ner_crf'}, {'start': 31, 'end': 40, 'text': 'yesterday', 'value': '2018-05-22T00:00:00.000Z', 'additional_info': {'value': '2018-05-22T00:00:00.000Z', 'grain': 'day', 'others': []}, 'entity': 'time', 'extractor': 'ner_duckling'}]'
2018-05-23 18:15:56 DEBUG    rasa_core.processor  - Logged UserUtterance - tracker now has 109 events
2018-05-23 18:15:56 DEBUG    rasa_core.processor  - Current slot values:
    counterparty: jpm
    rec_side: None
    recon_date: yesterday
    recon_status: None
2018-05-23 18:15:56 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:15:56 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:15:56 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:15:56 DEBUG    rasa_core.policies.memoization  - Current tracker state [
    [('intent_return_recon_results', 1), ('entity_recon_date', 1), ('entity_counterparty', 1), ('prev_action_return_recon_results', 1)]
    [('intent_return_recon_results', 1), ('entity_recon_date', 1), ('entity_counterparty', 1), ('prev_utter_more_results', 1)]
    [('intent_return_recon_results', 1), ('entity_recon_date', 1), ('entity_counterparty', 1), ('slot_counterparty_0', 1), ('slot_recon_date_0', 1), ('prev_action_listen', 1)]]
2018-05-23 18:15:56 DEBUG    rasa_core.policies.memoization  - Used memorised next action '12'
2018-05-23 18:15:56 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:15:56 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:15:56 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:15:56 DEBUG    rasa_core.policies.ensemble  - Predicted next action 'action_return_recon_results' with prob 1.00.
2018-05-23 18:16:00 DEBUG    rasa_core.processor  - Bot utterance 'BotUttered(text: *Recon Results for:* jpm_2018-05-22
 
---------------------------
 
*STATUS:* Incomplete
 
*SOURCE 1:* Geneva_2018-05-22.csv
 
*BROKER:* JPM_2018-05-22.csv
 
*EXEC. TIME:* 3:00 AM
 
*EXEC. BY:* ConnorHogendorn
 
*TOTAL:* 150
 
*PARTIAL:* 0
 
*UNMATCHED 1:* 0
 
*UNMATCHED BROKER:* 0
 
, data: null)'
2018-05-23 18:16:00 DEBUG    rasa_core.processor  - Action 'action_return_recon_results' ended with events '['AllSlotsReset()']'
2018-05-23 18:16:00 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:16:00 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:16:00 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:16:00 DEBUG    rasa_core.policies.memoization  - Current tracker state [
    [('intent_return_recon_results', 1), ('entity_recon_date', 1), ('entity_counterparty', 1), ('prev_utter_more_results', 1)]
    [('intent_return_recon_results', 1), ('entity_recon_date', 1), ('entity_counterparty', 1), ('slot_counterparty_0', 1), ('slot_recon_date_0', 1), ('prev_action_listen', 1)]
    [('intent_return_recon_results', 1), ('entity_recon_date', 1), ('entity_counterparty', 1), ('prev_action_return_recon_results', 1)]]
2018-05-23 18:16:00 DEBUG    rasa_core.policies.memoization  - Used memorised next action '7'
2018-05-23 18:16:00 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:16:00 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:16:00 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:16:00 DEBUG    rasa_core.policies.ensemble  - Predicted next action 'utter_more_results' with prob 1.00.
2018-05-23 18:16:00 DEBUG    rasa_core.processor  - Bot utterance 'BotUttered(text: Please enter a new query to see more results., data: null)'
2018-05-23 18:16:00 DEBUG    rasa_core.processor  - Action 'utter_more_results' ended with events '[]'
2018-05-23 18:16:00 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:16:00 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:16:00 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:16:00 DEBUG    rasa_core.policies.memoization  - Current tracker state [
    [('intent_return_recon_results', 1), ('entity_recon_date', 1), ('entity_counterparty', 1), ('slot_counterparty_0', 1), ('slot_recon_date_0', 1), ('prev_action_listen', 1)]
    [('intent_return_recon_results', 1), ('entity_recon_date', 1), ('entity_counterparty', 1), ('prev_action_return_recon_results', 1)]
    [('intent_return_recon_results', 1), ('entity_recon_date', 1), ('entity_counterparty', 1), ('prev_utter_more_results', 1)]]
2018-05-23 18:16:00 DEBUG    rasa_core.policies.memoization  - Used memorised next action '0'
2018-05-23 18:16:00 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:16:00 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:16:00 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:16:00 DEBUG    rasa_core.policies.ensemble  - Predicted next action 'action_listen' with prob 1.00.
2018-05-23 18:16:00 DEBUG    rasa_core.processor  - Action 'action_listen' ended with events '[]'
2018-05-23 18:16:00 DEBUG    rasa_core.processor  - Current topic: None
172.18.0.3 - - [2018-05-23 18:16:00] "POST /webhook HTTP/1.0" 200 134 4.073520
172.18.0.3 - - [2018-05-23 18:16:00] "POST /webhook HTTP/1.0" 200 134 0.000520
172.18.0.3 - - [2018-05-23 18:16:00] "POST /webhook HTTP/1.0" 200 134 0.000439
172.18.0.3 - - [2018-05-23 18:16:00] "POST /webhook HTTP/1.0" 200 134 0.000477
172.18.0.3 - - [2018-05-23 18:16:00] "POST /webhook HTTP/1.0" 200 134 0.000513
172.18.0.3 - - [2018-05-23 18:16:00] "POST /webhook HTTP/1.0" 200 134 0.000468
172.18.0.3 - - [2018-05-23 18:16:00] "POST /webhook HTTP/1.0" 200 134 0.000454
172.18.0.3 - - [2018-05-23 18:16:00] "POST /webhook HTTP/1.0" 200 134 0.000449
172.18.0.3 - - [2018-05-23 18:16:00] "POST /webhook HTTP/1.0" 200 134 0.000426
172.18.0.3 - - [2018-05-23 18:16:00] "POST /webhook HTTP/1.0" 200 134 0.000425
172.18.0.3 - - [2018-05-23 18:16:00] "POST /webhook HTTP/1.0" 200 134 0.000432
172.18.0.3 - - [2018-05-23 18:16:00] "POST /webhook HTTP/1.0" 200 134 0.000434
172.18.0.3 - - [2018-05-23 18:16:00] "POST /webhook HTTP/1.0" 200 134 0.000947
172.18.0.3 - - [2018-05-23 18:16:00] "POST /webhook HTTP/1.0" 200 134 0.000426
172.18.0.3 - - [2018-05-23 18:16:00] "POST /webhook HTTP/1.0" 200 134 0.000518
172.18.0.3 - - [2018-05-23 18:16:00] "POST /webhook HTTP/1.0" 200 134 0.000429
172.18.0.3 - - [2018-05-23 18:16:00] "POST /webhook HTTP/1.0" 200 134 0.000643
172.18.0.3 - - [2018-05-23 18:16:00] "POST /webhook HTTP/1.0" 200 134 0.000509
172.18.0.3 - - [2018-05-23 18:16:00] "POST /webhook HTTP/1.0" 200 134 0.000689
2018-05-23 18:16:01 DEBUG    rasa_core.tracker_store  - Recreating tracker for id 'U9MD2EBEH'
/usr/local/lib/python3.6/site-packages/sklearn/preprocessing/label.py:151: DeprecationWarning: The truth value of an empty array is ambiguous. Returning False, but in future this will result in an error. Use `array.size > 0` to check that an array is not empty.
  if diff:
2018-05-23 18:16:01 DEBUG    rasa_core.processor  - Received user message 'can i have the jpm results for yesterday' with intent '{'name': 'return_recon_results', 'confidence': 0.3163429762275638}' and entities '[{'start': 15, 'end': 18, 'value': 'jpm', 'entity': 'counterparty', 'extractor': 'ner_crf'}, {'start': 31, 'end': 40, 'value': 'yesterday', 'entity': 'recon_date', 'extractor': 'ner_crf'}, {'start': 31, 'end': 40, 'text': 'yesterday', 'value': '2018-05-22T00:00:00.000Z', 'additional_info': {'value': '2018-05-22T00:00:00.000Z', 'grain': 'day', 'others': []}, 'entity': 'time', 'extractor': 'ner_duckling'}]'
2018-05-23 18:16:01 DEBUG    rasa_core.processor  - Logged UserUtterance - tracker now has 118 events
2018-05-23 18:16:01 DEBUG    rasa_core.processor  - Current slot values:
    counterparty: jpm
    rec_side: None
    recon_date: yesterday
    recon_status: None
2018-05-23 18:16:01 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:16:01 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:16:01 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:16:01 DEBUG    rasa_core.policies.memoization  - Current tracker state [
    [('intent_return_recon_results', 1), ('entity_recon_date', 1), ('entity_counterparty', 1), ('prev_action_return_recon_results', 1)]
    [('intent_return_recon_results', 1), ('entity_recon_date', 1), ('entity_counterparty', 1), ('prev_utter_more_results', 1)]
    [('intent_return_recon_results', 1), ('entity_recon_date', 1), ('entity_counterparty', 1), ('slot_counterparty_0', 1), ('slot_recon_date_0', 1), ('prev_action_listen', 1)]]
2018-05-23 18:16:01 DEBUG    rasa_core.policies.memoization  - Used memorised next action '12'
2018-05-23 18:16:01 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:16:01 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:16:01 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:16:01 DEBUG    rasa_core.policies.ensemble  - Predicted next action 'action_return_recon_results' with prob 1.00.
2018-05-23 18:16:08 DEBUG    rasa_core.processor  - Bot utterance 'BotUttered(text: *Recon Results for:* jpm_2018-05-22
 
---------------------------
 
*STATUS:* Incomplete
 
*SOURCE 1:* Geneva_2018-05-22.csv
 
*BROKER:* JPM_2018-05-22.csv
 
*EXEC. TIME:* 3:00 AM
 
*EXEC. BY:* ConnorHogendorn
 
*TOTAL:* 150
 
*PARTIAL:* 0
 
*UNMATCHED 1:* 0
 
*UNMATCHED BROKER:* 0
 
, data: null)'
2018-05-23 18:16:08 DEBUG    rasa_core.processor  - Action 'action_return_recon_results' ended with events '['AllSlotsReset()']'
2018-05-23 18:16:08 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:16:08 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:16:08 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:16:08 DEBUG    rasa_core.policies.memoization  - Current tracker state [
    [('intent_return_recon_results', 1), ('entity_recon_date', 1), ('entity_counterparty', 1), ('prev_utter_more_results', 1)]
    [('intent_return_recon_results', 1), ('entity_recon_date', 1), ('entity_counterparty', 1), ('slot_counterparty_0', 1), ('slot_recon_date_0', 1), ('prev_action_listen', 1)]
    [('intent_return_recon_results', 1), ('entity_recon_date', 1), ('entity_counterparty', 1), ('prev_action_return_recon_results', 1)]]
2018-05-23 18:16:08 DEBUG    rasa_core.policies.memoization  - Used memorised next action '7'
2018-05-23 18:16:08 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:16:08 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:16:08 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:16:08 DEBUG    rasa_core.policies.ensemble  - Predicted next action 'utter_more_results' with prob 1.00.
2018-05-23 18:16:08 DEBUG    rasa_core.processor  - Bot utterance 'BotUttered(text: Is there anything else?, data: null)'
2018-05-23 18:16:08 DEBUG    rasa_core.processor  - Action 'utter_more_results' ended with events '[]'
2018-05-23 18:16:08 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:16:08 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:16:08 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:16:08 DEBUG    rasa_core.policies.memoization  - Current tracker state [
    [('intent_return_recon_results', 1), ('entity_recon_date', 1), ('entity_counterparty', 1), ('slot_counterparty_0', 1), ('slot_recon_date_0', 1), ('prev_action_listen', 1)]
    [('intent_return_recon_results', 1), ('entity_recon_date', 1), ('entity_counterparty', 1), ('prev_action_return_recon_results', 1)]
    [('intent_return_recon_results', 1), ('entity_recon_date', 1), ('entity_counterparty', 1), ('prev_utter_more_results', 1)]]
2018-05-23 18:16:08 DEBUG    rasa_core.policies.memoization  - Used memorised next action '0'
2018-05-23 18:16:08 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:16:08 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:16:08 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:16:08 DEBUG    rasa_core.policies.ensemble  - Predicted next action 'action_listen' with prob 1.00.
2018-05-23 18:16:08 DEBUG    rasa_core.processor  - Action 'action_listen' ended with events '[]'
2018-05-23 18:16:08 DEBUG    rasa_core.processor  - Current topic: None
172.18.0.3 - - [2018-05-23 18:16:08] "POST /webhook HTTP/1.0" 200 134 7.424847
172.18.0.3 - - [2018-05-23 18:16:08] "POST /webhook HTTP/1.0" 200 134 0.000545
172.18.0.3 - - [2018-05-23 18:16:08] "POST /webhook HTTP/1.0" 200 134 0.000497
172.18.0.3 - - [2018-05-23 18:16:08] "POST /webhook HTTP/1.0" 200 134 0.000460
172.18.0.3 - - [2018-05-23 18:16:08] "POST /webhook HTTP/1.0" 200 134 0.000464
172.18.0.3 - - [2018-05-23 18:16:08] "POST /webhook HTTP/1.0" 200 134 0.000433
172.18.0.3 - - [2018-05-23 18:16:08] "POST /webhook HTTP/1.0" 200 134 0.000446
172.18.0.3 - - [2018-05-23 18:16:08] "POST /webhook HTTP/1.0" 200 134 0.000443
172.18.0.3 - - [2018-05-23 18:16:08] "POST /webhook HTTP/1.0" 200 134 0.000427
172.18.0.3 - - [2018-05-23 18:16:08] "POST /webhook HTTP/1.0" 200 134 0.000431
172.18.0.3 - - [2018-05-23 18:16:08] "POST /webhook HTTP/1.0" 200 134 0.000423
172.18.0.3 - - [2018-05-23 18:16:08] "POST /webhook HTTP/1.0" 200 134 0.000544
172.18.0.3 - - [2018-05-23 18:16:08] "POST /webhook HTTP/1.0" 200 134 0.000533
172.18.0.3 - - [2018-05-23 18:16:08] "POST /webhook HTTP/1.0" 200 134 0.000629
172.18.0.3 - - [2018-05-23 18:16:09] "POST /webhook HTTP/1.0" 200 134 0.000677
172.18.0.3 - - [2018-05-23 18:16:09] "POST /webhook HTTP/1.0" 200 134 0.000701
2018-05-23 18:17:05 DEBUG    rasa_core.tracker_store  - Recreating tracker for id 'U9MD2EBEH'
/usr/local/lib/python3.6/site-packages/sklearn/preprocessing/label.py:151: DeprecationWarning: The truth value of an empty array is ambiguous. Returning False, but in future this will result in an error. Use `array.size > 0` to check that an array is not empty.
  if diff:
2018-05-23 18:17:05 DEBUG    rasa_core.processor  - Received user message 'can i have the jpm results for yesterday' with intent '{'name': 'return_recon_results', 'confidence': 0.3163429762275638}' and entities '[{'start': 15, 'end': 18, 'value': 'jpm', 'entity': 'counterparty', 'extractor': 'ner_crf'}, {'start': 31, 'end': 40, 'value': 'yesterday', 'entity': 'recon_date', 'extractor': 'ner_crf'}, {'start': 31, 'end': 40, 'text': 'yesterday', 'value': '2018-05-22T00:00:00.000Z', 'additional_info': {'value': '2018-05-22T00:00:00.000Z', 'grain': 'day', 'others': []}, 'entity': 'time', 'extractor': 'ner_duckling'}]'
2018-05-23 18:17:05 DEBUG    rasa_core.processor  - Logged UserUtterance - tracker now has 127 events
2018-05-23 18:17:05 DEBUG    rasa_core.processor  - Current slot values:
    counterparty: jpm
    rec_side: None
    recon_date: yesterday
    recon_status: None
2018-05-23 18:17:05 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:17:05 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:17:05 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:17:05 DEBUG    rasa_core.policies.memoization  - Current tracker state [
    [('intent_return_recon_results', 1), ('entity_recon_date', 1), ('entity_counterparty', 1), ('prev_action_return_recon_results', 1)]
    [('intent_return_recon_results', 1), ('entity_recon_date', 1), ('entity_counterparty', 1), ('prev_utter_more_results', 1)]
    [('intent_return_recon_results', 1), ('entity_recon_date', 1), ('entity_counterparty', 1), ('slot_counterparty_0', 1), ('slot_recon_date_0', 1), ('prev_action_listen', 1)]]
2018-05-23 18:17:05 DEBUG    rasa_core.policies.memoization  - Used memorised next action '12'
2018-05-23 18:17:05 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:17:05 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:17:05 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:17:05 DEBUG    rasa_core.policies.ensemble  - Predicted next action 'action_return_recon_results' with prob 1.00.
2018-05-23 18:17:06 DEBUG    rasa_core.processor  - Bot utterance 'BotUttered(text: *Recon Results for:* jpm_2018-05-22
 
---------------------------
 
*STATUS:* Incomplete
 
*SOURCE 1:* Geneva_2018-05-22.csv
 
*BROKER:* JPM_2018-05-22.csv
 
*EXEC. TIME:* 3:00 AM
 
*EXEC. BY:* ConnorHogendorn
 
*TOTAL:* 150
 
*PARTIAL:* 0
 
*UNMATCHED 1:* 0
 
*UNMATCHED BROKER:* 0
 
, data: null)'
2018-05-23 18:17:06 DEBUG    rasa_core.processor  - Action 'action_return_recon_results' ended with events '['AllSlotsReset()']'
2018-05-23 18:17:06 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:17:06 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:17:06 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:17:06 DEBUG    rasa_core.policies.memoization  - Current tracker state [
    [('intent_return_recon_results', 1), ('entity_recon_date', 1), ('entity_counterparty', 1), ('prev_utter_more_results', 1)]
    [('intent_return_recon_results', 1), ('entity_recon_date', 1), ('entity_counterparty', 1), ('slot_counterparty_0', 1), ('slot_recon_date_0', 1), ('prev_action_listen', 1)]
    [('intent_return_recon_results', 1), ('entity_recon_date', 1), ('entity_counterparty', 1), ('prev_action_return_recon_results', 1)]]
2018-05-23 18:17:06 DEBUG    rasa_core.policies.memoization  - Used memorised next action '7'
2018-05-23 18:17:06 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:17:06 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:17:06 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:17:06 DEBUG    rasa_core.policies.ensemble  - Predicted next action 'utter_more_results' with prob 1.00.
2018-05-23 18:17:06 DEBUG    rasa_core.processor  - Bot utterance 'BotUttered(text: Please enter a new query to see more results., data: null)'
2018-05-23 18:17:06 DEBUG    rasa_core.processor  - Action 'utter_more_results' ended with events '[]'
2018-05-23 18:17:06 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:17:06 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:17:06 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:17:06 DEBUG    rasa_core.policies.memoization  - Current tracker state [
    [('intent_return_recon_results', 1), ('entity_recon_date', 1), ('entity_counterparty', 1), ('slot_counterparty_0', 1), ('slot_recon_date_0', 1), ('prev_action_listen', 1)]
    [('intent_return_recon_results', 1), ('entity_recon_date', 1), ('entity_counterparty', 1), ('prev_action_return_recon_results', 1)]
    [('intent_return_recon_results', 1), ('entity_recon_date', 1), ('entity_counterparty', 1), ('prev_utter_more_results', 1)]]
2018-05-23 18:17:06 DEBUG    rasa_core.policies.memoization  - Used memorised next action '0'
2018-05-23 18:17:06 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:17:06 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:17:06 DEBUG    rasa_core.featurizers  - Feature 'entity_time' (value: '1.0') could not be found in feature map. Make sure you added all intents and entities to the domain
2018-05-23 18:17:06 DEBUG    rasa_core.policies.ensemble  - Predicted next action 'action_listen' with prob 1.00.
2018-05-23 18:17:06 DEBUG    rasa_core.processor  - Action 'action_listen' ended with events '[]'
2018-05-23 18:17:06 DEBUG    rasa_core.processor  - Current topic: None

@akelad
Copy link
Contributor

akelad commented May 25, 2018

ok and your running this over command line or with a custom python script? if it's a custom python script could you post it here?

@Walter-Ullon
Copy link

@akelad The logs above were pulled from the machine after sending commands through Slack. Is that what you're asking? I don't have a custom script for running these commands. When using the terminal (i.e. no Slack in between) this issue does not appear. Happy to do a zoom with you and walk through it if it would help.

@akelad
Copy link
Contributor

akelad commented May 25, 2018

No sorry, I meant the connection to slack, is it with python -m rasa_core.run -c slack or are you doing it like this: https://core.rasa.com/connectors.html#id2

@Walter-Ullon
Copy link

Oh, sorry. Just the command below. No custom script.

python -m rasa_core.run -d models/dialogue -u models/nlu/current -p 5002 -c slack --credentials slack_credentials.yml

@prateekchoudhary
Copy link

prateekchoudhary commented May 25, 2018

@akelad Extremely sorry for having parallel conversations. I am conversing with the bot app, here is how my slack credential file looks like:

slack_token: "xoxb-XXX........."
slack_channel: "XVBGTVR.."

@ewagner70
Copy link
Author

@akelad sorry for not responding earlier ... got back from an European business trip this evening. I've reduced slack bot subscriptions down to:

**Bot Events**
app_mention
message.im

but to no avail ... even reducing further down to only 1 of the 2 above message will still trigger multiple responses after the 3rd message ... any potential relation to that issue #393 from howdyai/botkit?

@prateekchoudhary
Copy link

ok, so for someone looking for a quick fix - In case of duplicate message response by bot I found that request.json contains repeated values for key event_id.

{'token': 'XX....', 'team_id': '....', 'api_app_id': '....', 'event': {'type': 'message', 'user': '.....', 'text': 'hi', 'ts': '1527324547.000005', 'channel': '....', 'event_ts': '1527324547.000005', 'channel_type': 'im'}, 'type': 'event_callback', 'event_id': 'EvAKKCCQ86', 'event_time': 1527324547, 'authed_users': ['...']}

if I track this using a list, this is what I get.
['EvAKKCCQ86', 'EvAKKCCQ86', 'EqVFS5VR56', 'EeBXG1F5HP', 'EvAKKCCQ86', 'E2BRGBB5PPJ']
this corresponds to one message 'Hi' with event_id: 'EvAKKCCQ86'
resulting in total 3 user_messages with same event_id. The bot thinks of it as 3 separate user messages and generates 3 responses with event_id as 'E2BRGBB5PPJ', 'EqVFS5VR56 and 'EeBXG1F5HP'

for the time being, I just ignore the duplicate event_id requests and it works.

@ewagner70
Copy link
Author

@prateekchoudhary thx for your workaround hint!
Would you dare sharing some "hotfix" code which repairs that behavior in the respective rasa_core module until rasa team has a fix ready/deployed?
@akelad you might consider re-classification as "bug" ...

@prateekchoudhary
Copy link

@ewagner70 Sure! I have had a marathon 40 hrs trying to debug this. Also it would be helpful if you let me know if this actually worked for you. If this 'hotfix' works, we can develop further on this.
I would still like to wait for official rasa team to come back on this.
In slack.py file class SlackInput
declare a list in __init__
self.slack_events_id = [] #using lists is a terrible idea as this can quickly grow
Then in def webhook() should be fairly simple to check using a duplicate flag.

            duplicate = False
            if 'event_id' in output:
              if output['event_id'] in self.slack_events_id:
                duplicate = True 
              else:
                self.slack_events_id.append(output['event_id'])
                duplicate = False
            if "challenge" in output:
                return make_response(output.get("challenge"), 200,
                                     {"content_type": "application/json"})
            elif self._is_user_message(output) and not duplicate:
                text = output['event']['text']
                sender_id = output.get('event').get('user')
            else:
                return make_response()

in the try block edit as below:

          try:
              if not duplicate:
                    out_channel = SlackBot(self.slack_token)
                    user_msg = UserMessage(text, out_channel, sender_id)
                    on_new_message(user_msg)

@ewagner70
Copy link
Author

ewagner70 commented May 26, 2018

@prateekchoudhary thx alot ... yes, it "works as designed" (slackbot API still sends multiple messages, but slack.py in rasa_core ignores the duplicates and yes, an ever growing list should not be a sustainable solution - but I don't have any other suggestion yet).

A small improvement suggestion, Prateek: as the messages are only sent a few times (I think 3-4 times), the list could be amended with a counter and once either the counter reaches a certain threshold or a certain timeframe passes (1 hour or so) the list-entry then gets deleted.

As hotfix for the time being ok and I fully concur that Rasa Team should come up with a sustainable solution (!) - especially if they reproduce that error with their own bots.
Kindest regards, Eric

@akelad
Copy link
Contributor

akelad commented May 31, 2018

thanks for all your effort/info guys, sadly we still haven't been able to reproduce this, but we're working on a solution based on your idea here. We'll keep you updated.

@naoko
Copy link
Contributor

naoko commented Jun 11, 2018

I think I see why...
I was having this problem sometimes and looked around and this is what Slack is doing :) no wonder it doesn't happen on other integration.
This behavior is documented here: https://api.slack.com/events-api#errors
Per doc, slack will re-deliver message if it meets "Failure conditions" (which also listed there).
One of the condition is that if your server took longer than 3 seconds to respond.
So if your server responds fast enough you won't see this behavior.
It also says, setting the header to include X-Slack-No-Retry: 1 if you don't want the message to re-deliver.
So I've modified the code like this

                elif self._is_user_message(output):
                    if not request.headers.environ.get('HTTP_X_SLACK_RETRY_NUM'):
                        text = output['event']['text']
                        sender_id = output.get('event').get('user')
                    else:
                        logger.warning("Received retry #{} request from slack due to {}".format(
                            request.headers.environ.get('HTTP_X_SLACK_RETRY_NUM'),
                            request.headers.environ.get('HTTP_X_SLACK_RETRY_REASON')))
                        return Response(status=201, headers={'X-Slack-No-Retry': 1})

and it seems to be successful except that Slack will still send max retry (3 times) regardless of value specified in the header.

I'm more than happy to make PR if this is an acceptable solution.

@ewagner70
Copy link
Author

@naoko - thank you very much for your further insights! any idea, why the SlackBot still sends 3 times (due to SSL-Certificate of ngrok, or?)
regarding PR, I'll leave that up to the rasa_core team. @tmbo @akelad any progress on rasa_core team side?

@naoko
Copy link
Contributor

naoko commented Jun 11, 2018

@ewagner70 , that would depend on your app/server. In my case, the error was the timeout (took me longer than 3 sec to reply cause I was tracing).
If you add the above code in rasa_core.channel.slack.py around this line: https://github.com/RasaHQ/rasa_core/blob/master/rasa_core/channels/slack.py#L122

for a 2nd request (RETRY_NUM = 1) it will output to logger reason why slack thinks it is a failure.
or just print(request.headers.environ.get('HTTP_X_SLACK_RETRY_REASON')) and see

@akelad
Copy link
Contributor

akelad commented Jun 12, 2018

@naoko we actually got that same information from the slack team as well. I haven't had time to look into it again yet, sorry! but yes, please create a PR with that fix and i'll take a look at it

@naoko
Copy link
Contributor

naoko commented Jun 13, 2018

@akelad , I've posted PR. thank you for reviewing!

@devansh1497
Copy link

@naoko I have tried your method and made the necessary changes to rasa_core.channels.slack.py but I still am getting multiple responses...
PS I am retrieving information of an API so it takes around 5-6 seconds every time I fetch the results...
I really need a fix for it :'(

@naoko
Copy link
Contributor

naoko commented Jul 6, 2018

@devansh1497 , are u using current master? or you modified the source on older version?
either way, can u locate the code where you receive callback from slack? and see what are these 2 values?

request.headers.environ.get('HTTP_X_SLACK_RETRY_NUM')
request.headers.environ.get('HTTP_X_SLACK_RETRY_REASON')

@useready-andyv
Copy link
Contributor

This seems to be a breaking fix for slack. While the idea and logic is perfect, I do not see any output in slack channel after taking the latest source. The same code without retires works. Looking into this deeper as this is an issue for me just like @devansh1497 - API takes more than 3 secs.

@useready-andyv
Copy link
Contributor

Got the issue, specific to one scenario. When the user posts a message in a channel, and not directly chatting with a bot, the channel is not being passed in. Got fix working on my local env, will add tests and raise a PR.

@tmbo tmbo transferred this issue from RasaHQ/rasa_core Mar 21, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

7 participants