Bot stopped working after approximately 24 hours, appears to be on the rasa server side (as oppose to the action server)

Hi, I am new to Rasa. I recently built a Facebook Messenger bot, first time using Rasa. All looked good and I’ve been testing it quite intensely (by having my son playing with it). However, it stops working after about 24 hours. The utterances that invokes custom actions would stop getting a response. When I looked at the log on the rasa server, I get the following:

2020-01-20 04:40:26,431 [ERROR] Encountered an exception while running action ‘action_multiplication_table_challenge’. Bot will continue, but the actions events are lost. Please check the logs of your action server for more information.

Initially I thought it’s an issue with action server. However, I wasn’t able to determine if there was anything wrong. The action server is in a docker container, and when I looked at the docker log there was no error. It just seems that the action server was not receiving any request. I then tried to curl the action server. I wasn’t able to construct the full payload to run my custom action but I was able to see that the action server received the request and apparently responded appropriately.

So, my suspicion shifted to the Rasa server. I kept the action server in the state where I left it when the bot stopped responding to custom actions, and I restarted the rasa server. Low and behold, everything was working.

Has anyone encountered similar situation and know why this is happening?

Thanks!

By the way, it happened two days in a row…

Hi @eugenelin89,

The 2nd time it happened, was the issue again triggered by a custom action?

Yes, in fact, both times were triggered by custom actions.

Did more stress testing under debug mode. Was just able to bring it to the same state when custom action stopped responding. Interesting observation: Using a different Facebook user account and everything still working. It is just failing for the Facebook user that I was doing stress testing with.

Log for the failing request:

2020-01-20 23:35:55,589 [DEBUG] Recreating tracker for id ‘2422564777865934’ 2020-01-20 23:35:55,749 [DEBUG] Received user message ‘17’ with intent ‘{‘name’: ‘answer’, ‘confidence’: 0.973506510257721}’ and entities ‘[{‘start’: 0, ‘end’: 2, ‘value’: ‘17’, ‘entity’: ‘integer_answer’, ‘confidence’: 0.7800877713410326, ‘extractor’: ‘CRFEntityExtractor’}]’ 2020-01-20 23:35:55,750 [DEBUG] Current slot values: a_b_ans: 1,0,0 q_num: 7 score: 0 start_time: 1579562803.7872338 2020-01-20 23:35:55,750 [DEBUG] Logged UserUtterance - tracker now has 5058 events 2020-01-20 23:35:55,831 [DEBUG] Current tracker state [{‘slot_start_time_0’: 1.0, ‘entity_integer_answer’: 1.0, ‘slot_a_b_ans_0’: 1.0, ‘intent_answer’: 1.0, ‘slot_score_0’: 1.0, ‘slot_q_num_0’: 1.0, ‘prev_action_listen’: 1.0}, {‘slot_start_time_0’: 1.0, ‘entity_integer_answer’: 1.0, ‘slot_a_b_ans_0’: 1.0, ‘intent_answer’: 1.0, ‘slot_score_0’: 1.0, ‘prev_action_multiplication_table_challenge’: 1.0, ‘slot_q_num_0’: 1.0}, {‘slot_start_time_0’: 1.0, ‘entity_integer_answer’: 1.0, ‘slot_a_b_ans_0’: 1.0, ‘intent_answer’: 1.0, ‘slot_score_0’: 1.0, ‘slot_q_num_0’: 1.0, ‘prev_action_listen’: 1.0}, {‘slot_start_time_0’: 1.0, ‘entity_integer_answer’: 1.0, ‘slot_a_b_ans_0’: 1.0, ‘intent_answer’: 1.0, ‘slot_score_0’: 1.0, ‘prev_action_multiplication_table_challenge’: 1.0, ‘slot_q_num_0’: 1.0}, {‘slot_start_time_0’: 1.0, ‘entity_integer_answer’: 1.0, ‘slot_a_b_ans_0’: 1.0, ‘intent_answer’: 1.0, ‘slot_score_0’: 1.0, ‘slot_q_num_0’: 1.0, ‘prev_action_listen’: 1.0}] 2020-01-20 23:35:55,832 [DEBUG] There is no memorised next action 2020-01-20 23:35:55,903 [DEBUG] Feature ‘entity_integer_answer’ (value: ‘1.0’) could not be found in feature map. Make sure you added all intents and entities to the domain 2020-01-20 23:35:55,904 [DEBUG] Feature ‘entity_integer_answer’ (value: ‘1.0’) could not be found in feature map. Make sure you added all intents and entities to the domain 2020-01-20 23:35:55,904 [DEBUG] Feature ‘entity_integer_answer’ (value: ‘1.0’) could not be found in feature map. Make sure you added all intents and entities to the domain 2020-01-20 23:35:55,904 [DEBUG] Feature ‘entity_integer_answer’ (value: ‘1.0’) could not be found in feature map. Make sure you added all intents and entities to the domain 2020-01-20 23:35:55,905 [DEBUG] Feature ‘entity_integer_answer’ (value: ‘1.0’) could not be found in feature map. Make sure you added all intents and entities to the domain 2020-01-20 23:35:55,911 [DEBUG] Predicted next action using policy_1_KerasPolicy 2020-01-20 23:35:55,912 [DEBUG] Predicted next action ‘action_multiplication_table_challenge’ with confidence 1.00. 2020-01-20 23:35:55,931 [DEBUG] Calling action endpoint to run action ‘action_multiplication_table_challenge’. 2020-01-20 23:35:56,017 [ERROR] Encountered an exception while running action ‘action_multiplication_table_challenge’. Bot will continue, but the actions events are lost. Please check the logs of your action server for more information. 2020-01-20 23:35:56,018 [DEBUG] Failed to execute custom action. Traceback (most recent call last): File “/build/lib/python3.6/site-packages/rasa/core/actions/action.py”, line 494, in run json=json_body, method=“post”, timeout=DEFAULT_REQUEST_TIMEOUT File “/usr/local/lib/python3.6/asyncio/coroutines.py”, line 110, in next return self.gen.send(None) File “/build/lib/python3.6/site-packages/rasa/utils/endpoints.py”, line 150, in request resp.status, resp.reason, await resp.content.read() rasa.utils.endpoints.ClientResponseError: 413, Request Entity Too Large, body=‘b’\r\n413 Request Entity Too Large\r\n\r\n

413 Request Entity Too Large

\r\n
nginx/1.10.3 (Ubuntu)\r\n\r\n\r\n’’

The above exception was the direct cause of the following exception:

Traceback (most recent call last): File “/build/lib/python3.6/site-packages/rasa/core/processor.py”, line 503, in _run_action events = await action.run(output_channel, nlg, tracker, self.domain) File “/usr/local/lib/python3.6/asyncio/coroutines.py”, line 110, in next return self.gen.send(None) File “/build/lib/python3.6/site-packages/rasa/core/actions/action.py”, line 517, in run raise Exception(“Failed to execute custom action.”) from e Exception: Failed to execute custom action. 2020-01-20 23:35:56,021 [DEBUG] Action ‘action_multiplication_table_challenge’ ended with events ‘[]’ 2020-01-20 23:35:56,022 [DEBUG] Current slot values: a_b_ans: 1,0,0 q_num: 7 score: 0 start_time: 1579562803.7872338 2020-01-20 23:35:56,107 [DEBUG] Current tracker state [{‘slot_start_time_0’: 1.0, ‘entity_integer_answer’: 1.0, ‘slot_a_b_ans_0’: 1.0, ‘intent_answer’: 1.0, ‘slot_score_0’: 1.0, ‘prev_action_multiplication_table_challenge’: 1.0, ‘slot_q_num_0’: 1.0}, {‘slot_start_time_0’: 1.0, ‘entity_integer_answer’: 1.0, ‘slot_a_b_ans_0’: 1.0, ‘intent_answer’: 1.0, ‘slot_score_0’: 1.0, ‘slot_q_num_0’: 1.0, ‘prev_action_listen’: 1.0}, {‘slot_start_time_0’: 1.0, ‘entity_integer_answer’: 1.0, ‘slot_a_b_ans_0’: 1.0, ‘intent_answer’: 1.0, ‘slot_score_0’: 1.0, ‘prev_action_multiplication_table_challenge’: 1.0, ‘slot_q_num_0’: 1.0}, {‘slot_start_time_0’: 1.0, ‘entity_integer_answer’: 1.0, ‘slot_a_b_ans_0’: 1.0, ‘intent_answer’: 1.0, ‘slot_score_0’: 1.0, ‘slot_q_num_0’: 1.0, ‘prev_action_listen’: 1.0}, {‘slot_start_time_0’: 1.0, ‘entity_integer_answer’: 1.0, ‘slot_a_b_ans_0’: 1.0, ‘intent_answer’: 1.0, ‘slot_score_0’: 1.0, ‘prev_action_multiplication_table_challenge’: 1.0, ‘slot_q_num_0’: 1.0}] 2020-01-20 23:35:56,108 [DEBUG] There is no memorised next action 2020-01-20 23:35:56,160 [DEBUG] Feature ‘entity_integer_answer’ (value: ‘1.0’) could not be found in feature map. Make sure you added all intents and entities to the domain 2020-01-20 23:35:56,161 [DEBUG] Feature ‘entity_integer_answer’ (value: ‘1.0’) could not be found in feature map. Make sure you added all intents and entities to the domain 2020-01-20 23:35:56,162 [DEBUG] Feature ‘entity_integer_answer’ (value: ‘1.0’) could not be found in feature map. Make sure you added all intents and entities to the domain 2020-01-20 23:35:56,162 [DEBUG] Feature ‘entity_integer_answer’ (value: ‘1.0’) could not be found in feature map. Make sure you added all intents and entities to the domain 2020-01-20 23:35:56,162 [DEBUG] Feature ‘entity_integer_answer’ (value: ‘1.0’) could not be found in feature map. Make sure you added all intents and entities to the domain 2020-01-20 23:35:56,167 [DEBUG] There is no mapped action for the predicted intent, ‘answer’. 2020-01-20 23:35:56,168 [DEBUG] Predicted next action using policy_1_KerasPolicy 2020-01-20 23:35:56,168 [DEBUG] Predicted next action ‘action_listen’ with confidence 1.00. 2020-01-20 23:35:56,169 [DEBUG] Action ‘action_listen’ ended with events ‘[]’ 2020-01-20 23:35:56,226 [DEBUG] Deleted lock for conversation ‘2422564777865934’.

Log for the working request using a different Facebook user:

2020-01-20 23:36:21,003 [DEBUG] Recreating tracker for id ‘2693248870743672’ 2020-01-20 23:36:21,012 [DEBUG] Received user message ‘3’ with intent ‘{‘name’: ‘answer’, ‘confidence’: 0.973506510257721}’ and entities ‘[{‘start’: 0, ‘end’: 1, ‘value’: ‘3’, ‘entity’: ‘integer_answer’, ‘confidence’: 0.7800877713410326, ‘extractor’: ‘CRFEntityExtractor’}]’ 2020-01-20 23:36:21,013 [DEBUG] Current slot values: a_b_ans: 3,1,3 q_num: 2 score: 1 start_time: 1579563304.9819882 2020-01-20 23:36:21,014 [DEBUG] Logged UserUtterance - tracker now has 213 events 2020-01-20 23:36:21,017 [DEBUG] Current tracker state [{‘slot_start_time_0’: 1.0, ‘entity_integer_answer’: 1.0, ‘slot_a_b_ans_0’: 1.0, ‘intent_answer’: 1.0, ‘slot_score_0’: 1.0, ‘slot_q_num_0’: 1.0, ‘prev_action_listen’: 1.0}, {‘slot_start_time_0’: 1.0, ‘entity_integer_answer’: 1.0, ‘slot_a_b_ans_0’: 1.0, ‘intent_answer’: 1.0, ‘slot_score_0’: 1.0, ‘prev_action_multiplication_table_challenge’: 1.0, ‘slot_q_num_0’: 1.0}, {‘slot_start_time_0’: 1.0, ‘entity_integer_answer’: 1.0, ‘slot_a_b_ans_0’: 1.0, ‘intent_answer’: 1.0, ‘slot_score_0’: 1.0, ‘slot_q_num_0’: 1.0, ‘prev_action_listen’: 1.0}, {‘slot_start_time_0’: 1.0, ‘entity_integer_answer’: 1.0, ‘slot_a_b_ans_0’: 1.0, ‘intent_answer’: 1.0, ‘slot_score_0’: 1.0, ‘prev_action_multiplication_table_challenge’: 1.0, ‘slot_q_num_0’: 1.0}, {‘slot_start_time_0’: 1.0, ‘entity_integer_answer’: 1.0, ‘slot_a_b_ans_0’: 1.0, ‘intent_answer’: 1.0, ‘slot_score_0’: 1.0, ‘slot_q_num_0’: 1.0, ‘prev_action_listen’: 1.0}] 2020-01-20 23:36:21,018 [DEBUG] There is no memorised next action 2020-01-20 23:36:21,021 [DEBUG] Feature ‘entity_integer_answer’ (value: ‘1.0’) could not be found in feature map. Make sure you added all intents and entities to the domain 2020-01-20 23:36:21,022 [DEBUG] Feature ‘entity_integer_answer’ (value: ‘1.0’) could not be found in feature map. Make sure you added all intents and entities to the domain 2020-01-20 23:36:21,023 [DEBUG] Feature ‘entity_integer_answer’ (value: ‘1.0’) could not be found in feature map. Make sure you added all intents and entities to the domain 2020-01-20 23:36:21,023 [DEBUG] Feature ‘entity_integer_answer’ (value: ‘1.0’) could not be found in feature map. Make sure you added all intents and entities to the domain 2020-01-20 23:36:21,024 [DEBUG] Feature ‘entity_integer_answer’ (value: ‘1.0’) could not be found in feature map. Make sure you added all intents and entities to the domain 2020-01-20 23:36:21,029 [DEBUG] Predicted next action using policy_1_KerasPolicy 2020-01-20 23:36:21,029 [DEBUG] Predicted next action ‘action_multiplication_table_challenge’ with confidence 1.00. 2020-01-20 23:36:21,030 [DEBUG] Calling action endpoint to run action ‘action_multiplication_table_challenge’. 2020-01-20 23:36:21,065 [DEBUG] Action ‘action_multiplication_table_challenge’ ended with events ‘[‘BotUttered(text: Correct!, data: {“elements”: null, “quick_replies”: null, “buttons”: null, “attachment”: null, “image”: null, “custom”: null}, metadata: {})’, ‘BotUttered(text: (3) 2 X 1 = ?, data: {“elements”: null, “quick_replies”: null, “buttons”: null, “attachment”: null, “image”: null, “custom”: null}, metadata: {})’, ‘SlotSet(key: a_b_ans, value: 2,1,2)’, ‘SlotSet(key: q_num, value: 3)’, ‘SlotSet(key: score, value: 2)’, ‘SlotSet(key: start_time, value: 1579563304.9819882)’]’ 2020-01-20 23:36:21,066 [DEBUG] Current slot values: a_b_ans: 2,1,2 q_num: 3 score: 2 start_time: 1579563304.9819882 2020-01-20 23:36:21,823 [DEBUG] Current tracker state [{‘slot_start_time_0’: 1.0, ‘entity_integer_answer’: 1.0, ‘slot_a_b_ans_0’: 1.0, ‘intent_answer’: 1.0, ‘slot_score_0’: 1.0, ‘prev_action_multiplication_table_challenge’: 1.0, ‘slot_q_num_0’: 1.0}, {‘slot_start_time_0’: 1.0, ‘entity_integer_answer’: 1.0, ‘slot_a_b_ans_0’: 1.0, ‘intent_answer’: 1.0, ‘slot_score_0’: 1.0, ‘slot_q_num_0’: 1.0, ‘prev_action_listen’: 1.0}, {‘slot_start_time_0’: 1.0, ‘entity_integer_answer’: 1.0, ‘slot_a_b_ans_0’: 1.0, ‘intent_answer’: 1.0, ‘slot_score_0’: 1.0, ‘prev_action_multiplication_table_challenge’: 1.0, ‘slot_q_num_0’: 1.0}, {‘slot_start_time_0’: 1.0, ‘entity_integer_answer’: 1.0, ‘slot_a_b_ans_0’: 1.0, ‘intent_answer’: 1.0, ‘slot_score_0’: 1.0, ‘slot_q_num_0’: 1.0, ‘prev_action_listen’: 1.0}, {‘slot_start_time_0’: 1.0, ‘entity_integer_answer’: 1.0, ‘slot_a_b_ans_0’: 1.0, ‘intent_answer’: 1.0, ‘slot_score_0’: 1.0, ‘prev_action_multiplication_table_challenge’: 1.0, ‘slot_q_num_0’: 1.0}] 2020-01-20 23:36:21,824 [DEBUG] There is no memorised next action 2020-01-20 23:36:21,827 [DEBUG] Feature ‘entity_integer_answer’ (value: ‘1.0’) could not be found in feature map. Make sure you added all intents and entities to the domain 2020-01-20 23:36:21,828 [DEBUG] Feature ‘entity_integer_answer’ (value: ‘1.0’) could not be found in feature map. Make sure you added all intents and entities to the domain 2020-01-20 23:36:21,828 [DEBUG] Feature ‘entity_integer_answer’ (value: ‘1.0’) could not be found in feature map. Make sure you added all intents and entities to the domain 2020-01-20 23:36:21,829 [DEBUG] Feature ‘entity_integer_answer’ (value: ‘1.0’) could not be found in feature map. Make sure you added all intents and entities to the domain 2020-01-20 23:36:21,829 [DEBUG] Feature ‘entity_integer_answer’ (value: ‘1.0’) could not be found in feature map. Make sure you added all intents and entities to the domain 2020-01-20 23:36:21,835 [DEBUG] There is no mapped action for the predicted intent, ‘answer’. 2020-01-20 23:36:21,836 [DEBUG] Predicted next action using policy_1_KerasPolicy 2020-01-20 23:36:21,836 [DEBUG] Predicted next action ‘action_listen’ with confidence 1.00. 2020-01-20 23:36:21,837 [DEBUG] Action ‘action_listen’ ended with events ‘[]’ 2020-01-20 23:36:21,841 [DEBUG] Deleted lock for conversation ‘2693248870743672’.

I suspect that when Rasa server is sending request to the Action Server, the payload is too big and triggered the error at the http level, thus the error log:

rasa.utils.endpoints.ClientResponseError: 413, Request Entity Too Large

Wondering if it’s possible that the data is carrying the full conversation history? Is there a way to view the actual payload getting sent to the action server?

After investigating further, I believe it is the number of events that keeps on growing as the user continue to send message. In the failure case above:

[DEBUG] Logged UserUtterance - tracker now has 5058 events

It appears that Rasa sends all events in history of the user to the action server.

I’m not sure if the error is with rasa server or your actions file since this error is very common if there is something wrong in your actions.py file.

You can try clearing the events table in your database.

You’re right. The issue is with the HTTP server that hosts the action server. When the payload gets too big it cuts off the request. It’s something I am able to configure on Nginx.