Form Gets Stuck randomly in the middle - Predicts action_listen after user input

Hi,

I have a form which works fine for few iterations then suddenly while we are in the middle of the form and the user provides input to the asked question instead of validating and moving on to the next question (even when the correct entity is extracted, which is valid for the question asked), the form predicts ‘action_listen’.

I’m not sure where I’m going wrong. I have added a lot of stories to make sure it has enough training data.

Below is the Rasa Main Server log:

 2020-05-05 19:29:50,907 [DEBUG]  Current tracker state [{'slot_location_0': 1.0, 'slot_slot_current_start_page_2_0': 1.0, 'slot_phone_number_0': 1.0, 'prev_action_listen': 1.0, 'slot_email_0': 1.0, 'intent_another_job_search': 1.0, 'slot_job_alerts_set_0': 1.0, 'slot_slot_current_start_page_0': 1.0, 'slot_name_0': 1.0, 'slot_job_title_0': 1.0}, {'slot_slot_current_start_page_2_0': 1.0, 'slot_phone_number_0': 1.0, 'slot_email_0': 1.0, 'intent_another_job_search': 1.0, 'slot_job_alerts_set_0': 1.0, 'prev_action_reset_job_slots': 1.0, 'slot_slot_current_start_page_0': 1.0, 'slot_name_0': 1.0}]
    2020-05-05 19:29:50,908 [DEBUG]  There is no memorised next action
    2020-05-05 19:29:50,999 [DEBUG]  There is no mapped action for the predicted intent, 'location'.
    2020-05-05 19:29:50,999 [DEBUG]  There is an active form 'job_search_form_part_3'
    2020-05-05 19:29:50,999 [DEBUG]  NLU confidence threshold met, confidence of fallback action set to core threshold (0.4).
    2020-05-05 19:29:50,999 [DEBUG]  Predicted next action using policy_3_FormPolicy
    2020-05-05 19:29:50,999 [DEBUG]  Predicted next action 'action_listen' with confidence 1.00.
    2020-05-05 19:29:51,000 [DEBUG]  Action 'action_listen' ended with events '[]'.
    2020-05-05 19:29:51,029 [DEBUG]  Tracker with sender_id '3200105263356504' stored to database
    2020-05-05 19:29:51,031 [DEBUG]  Deleted lock for conversation '3200105263356504'.
    2020-05-05 19:29:52,026 [WARNI]  Received a message from facebook that we can not handle. Message: {'sender': {'id': '515189448670447'}, 'recipient': {'id': '3200105263356504'}, 'timestamp': 1588706990674, 'message': {'mid': 'm_JIemC4GGJ4GkStPQJd7M65PjAxixUmSPyuQ-ulMOUtUJzCpFZkNX4In0YXKLWyhche8uupu9GfxoLJEjz9x7aw', 'is_echo': True, 'text': 'Okay, what experience range of jobs are you looking for? Note. Please type in years Ex. 3 years, 2.5 years', 'app_id': 1915166928696576}}
    2020-05-05 19:29:55,409 [DEBUG]  Recreating tracker from sender id '3200105263356504'
    2020-05-05 19:29:55,457 [DEBUG]  Received user message '/experience{"experience":"1 year"}' with intent '{'name': 'experience', 'confidence': 1.0}' and entities '[{'entity': 'experience', 'start': 11, 'end': 34, 'value': '1 year'}]'
    2020-05-05 19:29:55,458 [DEBUG]  Current slot values: 
    	email: Mw@m.com
    	experience: 1 year
    	job_alerts_set: no
    	job_title: software engineer
    	job_type: None
    	location: hyderabad
    	max_exp: None
    	min_exp: None
    	name: Mohammed Murtuza Qureshi
    	otp_phone: None
    	phone_number: 6655443322
    	requested_slot: location
    	salary: None
    	slot_current_start_page: 5
    	slot_current_start_page_2: 0
    2020-05-05 19:29:55,458 [DEBUG]  Logged UserUtterance - tracker now has 2308 events.
    2020-05-05 19:29:55,546 [DEBUG]  Current tracker state [{'slot_location_0': 1.0, 'slot_slot_current_start_page_2_0': 1.0, 'slot_phone_number_0': 1.0, 'prev_action_listen': 1.0, 'slot_email_0': 1.0, 'intent_another_job_search': 1.0, 'slot_job_alerts_set_0': 1.0, 'slot_slot_current_start_page_0': 1.0, 'slot_name_0': 1.0, 'slot_job_title_0': 1.0}, {'slot_slot_current_start_page_2_0': 1.0, 'slot_phone_number_0': 1.0, 'slot_email_0': 1.0, 'intent_another_job_search': 1.0, 'slot_job_alerts_set_0': 1.0, 'prev_action_reset_job_slots': 1.0, 'slot_slot_current_start_page_0': 1.0, 'slot_name_0': 1.0}]
    2020-05-05 19:29:55,547 [DEBUG]  There is no memorised next action
    2020-05-05 19:29:55,638 [DEBUG]  There is no mapped action for the predicted intent, 'experience'.
    2020-05-05 19:29:55,638 [DEBUG]  There is an active form 'job_search_form_part_3'
    2020-05-05 19:29:55,638 [DEBUG]  NLU confidence threshold met, confidence of fallback action set to core threshold (0.4).
    2020-05-05 19:29:55,638 [DEBUG]  Predicted next action using policy_3_FormPolicy
    2020-05-05 19:29:55,639 [DEBUG]  Predicted next action 'action_listen' with confidence 1.00.
    2020-05-05 19:29:55,639 [DEBUG]  Action 'action_listen' ended with events '[]'.
    2020-05-05 19:29:55,662 [DEBUG]  Tracker with sender_id '3200105263356504' stored to database
    2020-05-05 19:29:55,664 [DEBUG]  Deleted lock for conversation '3200105263356504'.

Below is the action server log:

2020-05-05 19:29:49 DEBUG    rasa_sdk.executor  - Received request to run 'job_search_form_part_3'
2020-05-05 19:29:49 DEBUG    rasa_sdk.forms  - The form '{'name': 'job_search_form_part_3', 'validate': True, 'rejected': False, 'trigger_message': {'text': '/another_job_search', 'intent': {'name': 'another_job_search', 'confidence': 1.0}, 'intent_ranking': [{'name': 'another_job_search', 'confidence': 1.0}], 'entities': []}}' is active
2020-05-05 19:29:49 DEBUG    rasa_sdk.forms  - Validating user input '{'text': '/location{"location":"hyderabad"}', 'intent': {'name': 'location', 'confidence': 1.0}, 'intent_ranking': [{'name': 'location', 'confidence': 1.0}], 'entities': [{'entity': 'location', 'start': 9, 'end': 33, 'value': 'hyderabad'}]}'
2020-05-05 19:29:49 DEBUG    rasa_sdk.forms  - Trying to extract requested slot 'location' ...
2020-05-05 19:29:49 DEBUG    rasa_sdk.forms  - Got mapping '{'type': 'from_entity', 'entity': 'location', 'intent': [], 'not_intent': [], 'role': None, 'group': None}'
2020-05-05 19:29:49 DEBUG    rasa_sdk.forms  - Successfully extracted 'hyderabad' for requested slot 'location'
2020-05-05 19:29:49 DEBUG    rasa_sdk.forms  - Validating extracted slots: {'location': 'hyderabad'}
2020-05-05 19:29:49 DEBUG    rasa_sdk.forms  - Request next slot 'experience'
2020-05-05 19:29:49 DEBUG    rasa_sdk.executor  - Finished running 'job_search_form_part_3'
2020-05-05 19:39:28 DEBUG    rasa_sdk.executor  - Received request to run 'job_search_form_part_3'
2020-05-05 19:39:28 DEBUG    rasa_sdk.forms  - The form '{'name': 'job_search_form_part_3', 'validate': True, 'rejected': False, 'trigger_message': {'text': '/another_job_search', 'intent': {'name': 'another_job_search', 'confidence': 1.0}, 'intent_ranking': [{'name': 'another_job_search', 'confidence': 1.0}], 'entities': []}}' is active
2020-05-05 19:39:28 DEBUG    rasa_sdk.forms  - Validating user input '{'intent': {'name': 'greet', 'confidence': 0.9996679425239561}, 'entities': [], 'intent_ranking': [{'name': 'greet', 'confidence': 0.9996679425239561}, {'name': 'ask_occupation', 'confidence': 0.000230408812058}, {'name': 'another_job_search', 'confidence': 4.565021299640649e-05}, {'name': 'search', 'confidence': 1.80877268576296e-05}, {'name': 'email', 'confidence': 1.072370923793641e-05}, {'name': 'set_job_alerts', 'confidence': 9.543741725792643e-06}, {'name': 'goodbye', 'confidence': 6.112948085501557e-06}, {'name': 'job_type', 'confidence': 5.148580839886563e-06}, {'name': 'location', 'confidence': 3.8103441966086393e-06}, {'name': 'experience', 'confidence': 2.608964450701023e-06}], 'text': 'Hi'}'
2020-05-05 19:39:28 DEBUG    rasa_sdk.forms  - Trying to extract requested slot 'experience' ...
2020-05-05 19:39:28 DEBUG    rasa_sdk.forms  - Got mapping '{'type': 'from_text', 'intent': [], 'not_intent': []}'
2020-05-05 19:39:28 DEBUG    rasa_sdk.forms  - Successfully extracted 'Hi' for requested slot 'experience'
2020-05-05 19:39:28 DEBUG    rasa_sdk.forms  - Validating extracted slots: {'experience': 'Hi'}
2020-05-05 19:39:28 DEBUG    rasa_sdk.forms  - Request next slot 'experience'

If you notice the last line in the above actions server log at timeslot 19:29 . After requesting for slot ‘experience’ it receive request to run the form like it did previously.

Looks like main server is not communicating with the action server on this occasion to run the form.

One pattern which I noticed is that whenever it gets stuck, it doesn’t reply to subsequently messages as well. But if we message after 10 mins it replies which again can be noticed in the action server log.

Here is the slop mapping code:

def slot_mappings(self) -> Dict[Text, Union[Dict, List[Dict]]]:
    """A dictionary to map required slots to
        - an extracted entity
        - intent: value pairs
        - a whole message
        or a list of them, where a first match will be picked"""

    return {
       "experience" : [self.from_text(),
                        self.from_entity(entity='experience'),
                        self.from_text(intent='experience')],
        "job_type": [self.from_entity(entity="job_type"),
                    self.from_text(intent='job_type'),
                    self.from_text()]    
    }

So, what happens is the mapping works fine in most of the cases but suddenly it stops working. If you see in the above debug log, the bot has predicted the intent ‘experience’ which is mapped to a slot in the form, so ideally it should go on and use the validation method I provided for this question and move to the next question but it stops by predicting the next action as ‘action_listen’ and not saying anything.

It randomly decides not to do it. This happens very randomly, it doesn’t stop like this always. For the exact same inputs, it stops very randomly. Like it works fine for 8-10 conversations, then randomly stops for one.

My question is: Even though the intent/entity is mapped to a slot and I’m in the form and it has predicted the correct intent, why isn’t it working and going forward? It gets stuck without replying anything.

Thank you! Stuck on this for a while!

It seems like the code is not rendering perfectly in the html here.

Just to confirm. This is your form mapping?

def slot_mappings(self) -> Dict[Text, Union[Dict, List[Dict]]]: 
    """
    A dictionary to map required slots to - an extracted entity - intent: value pairs - 
    a whole message or a list of them, where a first match will be picked
    """
    return {
       "experience" : [self.from_text(),
                        self.from_entity(entity='experience'),
                        self.from_text(intent='experience')],
        "job_type": [self.from_entity(entity="job_type"),
                    self.from_text(intent='job_type'),
                    self.from_text()]    
    }

Also … could you share an example of a conversation failing?

yes, thats the slot mapping code.

And yea it happens very randomly on facebook/telegram. Like any channel.

And I’m running this on an Ubuntu Server with 8 GB RAM. And nothing else runs on the server apart from the rasa server and actions server.

/usr/lib/python3.6/asyncio/coroutines.py:110: ResourceWarning: unclosed <ssl.SSLSocket fd=23, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('172.31.18.97', 49210), raddr=('185.60.216.15', 443)>
  return self.gen.send(None)
2020-05-04 15:42:10 WARNING  rasa.core.channels.facebook  - Received a message from facebook that we can not handle. Message: {'sender': {'id': '515189448670447'}, 'recipient': {'id': '3200105263356504'}, 'timestamp': 1588606928579, 'message': {'mid': 'm_xHhQ3FCWndEa5aUK0cgBJZPjAxixUmSPyuQ-ulMOUtUVkwepYiV7Sjxx4Df4mBae8mC5BM1nKSN_t0RqByUVMw', 'is_echo': True, 'text': 'In what domain are you looking for jobs in? Note. It is better to use job functions like digital marketing, business development, web developer, graphic design, etc. Please type or select one.', 'app_id': 1915166928696576}}

Also, above is the code which runs when the form successfully sends a message apart from the below code:

2020-05-04 15:42:08 DEBUG    rasa.core.policies.memoization  - There is a memorised next action 'job_search_form_part_1'
2020-05-04 15:42:08 DEBUG    rasa.core.policies.mapping_policy  - There is no mapped action for the predicted intent, 'email'.
2020-05-04 15:42:08 DEBUG    rasa.core.policies.form_policy  - There is an active form 'job_search_form_part_1'
2020-05-04 15:42:08 DEBUG    rasa.core.policies.fallback  - NLU confidence threshold met, confidence of fallback action set to core threshold (0.4).
2020-05-04 15:42:08 DEBUG    rasa.core.policies.ensemble  - Predicted next action using policy_3_FormPolicy
2020-05-04 15:42:08 DEBUG    rasa.core.processor  - Predicted next action 'action_listen' with confidence 1.00.
2020-05-04 15:42:08 DEBUG    rasa.core.processor  - Action 'action_listen' ended with events '[]'.
2020-05-04 15:42:08 DEBUG    rasa.core.tracker_store  - Tracker with sender_id '3200105263356504' stored to database
2020-05-04 15:42:08 DEBUG    rasa.core.lock_store  - Deleted lock for conversation '3200105263356504'.

Thank you!

Just to confirm, when you run this locally on the terminal, you cannot get the same error to appear even when you copy the text?

Also, what version of Rasa are you using here?

you cannot get the same error to appear even when you copy the text? <-- I didn’t get this point actually. Even when I copy the same text as in the same sequence of conversation? If you mean if this error occurs only on facebook/telegram. Well nop, it occured when I used Rasa X as well.

I updated to the latest 1.10 this Saturday before that have been using 1.9, the error was there from 1.9.

I should have clarified in my previous message. If you take the utterances from the server where things froze and run them locally, are you able to replicate the issue? Are there utterances where it consistently goes wrong and utterances where it consistently works?

Also, could you share your domain.yml and config.yml file? This line in the log is suggesting to me that it is predicting to just listen with a very high confidence.

2020-05-04 15:42:08 DEBUG    rasa.core.processor  - Predicted next action 'action_listen' with confidence 1.00.

Depending on what policy you are using you may need to generate more training examples for the pipeline to figure out that it is not supposed to listen there.

language: en
pipeline:
  - name: WhitespaceTokenizer
  - name: RegexFeaturizer
  - name: LexicalSyntacticFeaturizer
  - name: CountVectorsFeaturizer
  - name: CountVectorsFeaturizer
    analyzer: "char_wb"
    min_ngram: 1
    max_ngram: 4
  - name: DIETClassifier
    epochs: 100
  - name: EntitySynonymMapper


# Configuration for Rasa Core.
# https://rasa.com/docs/rasa/core/policies/
policies:
  - name: MemoizationPolicy
    max_history: 2
  - name: TEDPolicy
    max_history: 2
    epochs: 200
  - name: MappingPolicy
  - name: FormPolicy
  - name: "FallbackPolicy"
    nlu_threshold: 0.4
    core_threshold: 0.4
    fallback_action_name: "action_my_fallback"

domain.yml (15.7 KB)

If you take the utterances from the server where things froze and run them locally, are you able to replicate the issue? Are there utterances where it consistently goes wrong and utterances where it consistently works? <— I can give it a try on local but the thing is, it does this randomly inside the form for any of the questions, so there is no specific utterance where it is happening and its not occurring all the time.

Thank you!

I just noticed something, but this is a guess. You have entities and intents that share the same name. Is there a reason for this? I wonder if there’s something going wrong there. An intent and an entity are two different concepts and I now wonder if this is causing internal confusion.

I can imagine what the job_title entity is referring to but I wonder what the job_title intent is referring to. I might have an intent give_information that contains entities, but I wonder if there’s a reason for having a specific job_title intent.

Well, I just ended keeping them same, no particular reason as such. But what I thought is since they are both under different concepts, it shouldn’t be an issue.

Okay, I’ll just change the names of the intent then. And also should I share the stories file? You might want to go through the stories data and see if it looks correct.

Going through the entire file would take me a tad bit too long. Could you instead share an example of a story in your stories file that contains the form action as it is supposed to happen?

stories - samples.md (12.6 KB)

Please find the sample above. It has like 4-5 stories.

I changed the intent names to give_information and the error still happens. It gets stuck even after extracting location entity.

2020-05-06 10:08:57,109 [WARNI]  Received a message from facebook that we can not handle. Message: {'sender': {'id': '515189448670447'}, 'recipient': {'id': '3200105263356504'}, 'timestamp': 1588759735787, 'message': {'mid': 'm_A_2IvOXHjzTNanwSdVQbLpPjAxixUmSPyuQ-ulMOUtXg2C-czD6e4jHUDr6wviARbfPFyKw9oBPU7rhpn12hLQ', 'is_echo': True, 'text': 'Okay, where do you want to find a job? Please type or select a city name in India. (Workruit Bot currently serving cities in India).', 'app_id': 1915166928696576}}
2020-05-06 10:09:00,712 [DEBUG]  Recreating tracker from sender id '3200105263356504'
2020-05-06 10:09:00,817 [DEBUG]  Received user message '/give_information{"location":"chennai"}' with intent '{'name': 'give_information', 'confidence': 1.0}' and entities '[{'entity': 'location', 'start': 17, 'end': 39, 'value': 'chennai'}]'
2020-05-06 10:09:00,818 [DEBUG]  Current slot values: 
	email: Yqhwu@ha.com
	experience: None
	job_alerts_set: no
	job_title: software engineer
	job_type: None
	location: chennai
	name: Mohammed Murtuza Qureshi
	otp_phone: None
	phone_number: 7799310933
	requested_slot: job_title
	salary: None
	slot_current_start_page: 5
	slot_current_start_page_2: 0
2020-05-06 10:09:00,818 [DEBUG]  Logged UserUtterance - tracker now has 4524 events.
2020-05-06 10:09:00,854 [DEBUG]  Current tracker state [{'slot_slot_current_start_page_2_0': 1.0, 'intent_another_job_search': 1.0, 'slot_location_0': 1.0, 'slot_experience_0': 1.0, 'slot_phone_number_0': 1.0, 'slot_slot_current_start_page_0': 1.0, 'slot_job_title_0': 1.0, 'slot_name_0': 1.0, 'slot_email_0': 1.0, 'slot_job_type_0': 1.0, 'prev_action_listen': 1.0, 'slot_job_alerts_set_0': 1.0}, {'slot_slot_current_start_page_2_0': 1.0, 'intent_another_job_search': 1.0, 'slot_phone_number_0': 1.0, 'slot_slot_current_start_page_0': 1.0, 'slot_name_0': 1.0, 'slot_email_0': 1.0, 'prev_action_reset_job_slots': 1.0, 'slot_job_alerts_set_0': 1.0}]
2020-05-06 10:09:00,855 [DEBUG]  There is a memorised next action 'job_search_form_part_3'
2020-05-06 10:09:00,892 [DEBUG]  There is no mapped action for the predicted intent, 'give_information'.
2020-05-06 10:09:00,893 [DEBUG]  There is an active form 'job_search_form_part_3'
2020-05-06 10:09:00,893 [DEBUG]  NLU confidence threshold met, confidence of fallback action set to core threshold (0.4).
2020-05-06 10:09:00,893 [DEBUG]  Predicted next action using policy_3_FormPolicy
2020-05-06 10:09:00,893 [DEBUG]  Predicted next action 'action_listen' with confidence 1.00.
2020-05-06 10:09:00,893 [DEBUG]  Action 'action_listen' ended with events '[]'.
2020-05-06 10:09:00,927 [DEBUG]  Tracker with sender_id '3200105263356504' stored to database
2020-05-06 10:09:00,931 [DEBUG]  Deleted lock for conversation '3200105263356504'.

Update: So, as suggested, I tried the same code in my local and it seemed to work without any issue. So I think problem on the EC2 instance is that rasa’s main server is failing to communicate with action server at times and its not showing that error in the log aswell.

What should I do to fix this behavior?

The only difference while running in local was, I wasn’t using the SQL tracker I was using in on the EC2 server.

Thank you!