Slots getting reset too early when using Sessions

Hi,

I’ve trying out the new session management in Rasa. I’m using Rasa v1.6.0. I overwrote the action_session_start in my actions to save one Slot but reset al the other slots. However, I’m noticing that after every message from the user, it’s running action_session_start and I think it may be resetting my slots prematurely.

I have the following configured in my domain.yml:

session_config:
  session_expiration_time: 30
  carry_over_slots_to_new_session: true

Here is an example (with names/messages hidden):

2020-01-14 15:58:17,979 [DEBUG]  Recreating tracker from sender id 'USER'
2020-01-14 15:58:17,979 [DEBUG]  The latest session for conversation ID 'USER' has expired.
2020-01-14 15:58:17,979 [DEBUG]  Starting a new session for conversation ID 'USER'.
2020-01-14 15:58:17,979 [DEBUG]  Calling action endpoint to run action 'action_session_start'.
2020-01-14 15:58:19,119 [DEBUG]  Action 'action_session_start' ended with events '[<rasa.core.events.SessionStarted object at 0x000001D97D77B0F0>, <rasa.core.events.SlotSet object at 0x000001D97D77B1D0>, <rasa.core.events.ActionExecuted object at 0x000001D97D77B208>]'.
2020-01-14 15:58:19,119 [DEBUG]  Current slot values: 
	requested_slot: None
	UNIQUE_SLOT: None
	user: USER
	verify_UNIQUE_SLOT: False
2020-01-14 15:58:19,135 [DEBUG]  Tracker with sender_id 'USER' stored to database
2020-01-14 15:58:19,369 [DEBUG]  Received user message 'I am looking for some information' with intent '{'name': 'get_UNIQUE_SLOT', 'confidence': 0.6397166219639688}' and entities '[]'
2020-01-14 15:58:19,385 [DEBUG]  Logged UserUtterance - tracker now has 15 events.
2020-01-14 15:58:19,385 [DEBUG]  NLU confidence threshold met, confidence of fallback action set to core threshold (0.4).
2020-01-14 15:58:19,448 [DEBUG]  There is a memorised next action '55'
2020-01-14 15:58:19,448 [DEBUG]  There is no active form
2020-01-14 15:58:19,448 [DEBUG]  Predicted next action using policy_2_MemoizationPolicy
2020-01-14 15:58:19,448 [DEBUG]  Predicted next action 'UNIQUE_SLOT_form' with confidence 1.00.
2020-01-14 15:58:19,494 [DEBUG]  Calling action endpoint to run action 'UNIQUE_SLOT_form'.
2020-01-14 15:58:20,619 [DEBUG]  Action 'target_form' ended with events '[BotUttered('What <redacted> do you have questions about?', {"elements": null, "quick_replies": null, "buttons": null, "attachment": null, "image": null, "custom": null}, {"user": "USER"}, 1579046300.6199453), <rasa.core.events.Form object at 0x000001D97D7A1BE0>, <rasa.core.events.SlotSet object at 0x000001D97D7A1EF0>]'.
2020-01-14 15:58:20,635 [DEBUG]  Current slot values: 
	requested_slot: target
	target: None
	user: USER
	verify_UNIQUE_SLOT: False
2020-01-14 15:58:20,635 [DEBUG]  NLU confidence threshold met, confidence of fallback action set to core threshold (0.4).
2020-01-14 15:58:20,682 [DEBUG]  There is a memorised next action '55'
2020-01-14 15:58:20,682 [DEBUG]  There is an active form 'UNIQUE_SLOT_form'
2020-01-14 15:58:20,682 [DEBUG]  There is no mapped action for the predicted intent, 'get_UNIQUE_SLOT'.
2020-01-14 15:58:20,682 [DEBUG]  Predicted next action using policy_3_FormPolicy
2020-01-14 15:58:20,682 [DEBUG]  Predicted next action 'action_listen' with confidence 1.00.
2020-01-14 15:58:20,682 [DEBUG]  Action 'action_listen' ended with events '[]'.
2020-01-14 15:58:20,698 [DEBUG]  Tracker with sender_id 'USER' stored to database
2020-01-14 15:58:20,698 [DEBUG]  Deleted lock for conversation 'USER'.
2020-01-14 15:58:26,389 [DEBUG]  Recreating tracker from sender id 'USER'
2020-01-14 15:58:26,396 [DEBUG]  The latest session for conversation ID 'USER' has expired.
2020-01-14 15:58:26,401 [DEBUG]  Starting a new session for conversation ID 'USER'.
2020-01-14 15:58:26,407 [DEBUG]  Calling action endpoint to run action 'action_session_start'.
2020-01-14 15:58:27,543 [DEBUG]  Action 'action_session_start' ended with events '[<rasa.core.events.SessionStarted object at 0x000001D97D7A1C50>, <rasa.core.events.SlotSet object at 0x000001D97D7A1CF8>, <rasa.core.events.ActionExecuted object at 0x000001D97D7A18D0>]'.
2020-01-14 15:58:27,559 [DEBUG]  Current slot values: 
	requested_slot: None
	UNIQUE_SLOT: None
	user: USER
	verify_UNIQUE_SLOT: False
2020-01-14 15:58:27,559 [DEBUG]  Tracker with sender_id 'USER' stored to database
2020-01-14 15:58:27,574 [DEBUG]  Received user message 'UNIQUE_SLOT_VALUE' with intent '{'name': 'get_UNIQUE_SLOT', 'confidence': 0.6856936460511168}' and entities '[{'start': 0, 'end': 12, 'value': 'UNIQUE_SLOT_VALUE', 'entity': 'target', 'confidence': 0.9978285519580659, 'extractor': 'CRFEntityExtractor'}]'
2020-01-14 15:58:27,574 [DEBUG]  Current slot values: 
	requested_slot: None
	UNQIUE_SLOT: UNIQUE_SLOT_VALUE
	user: USER
	verify_UNIQUE_SLOT: False
2020-01-14 15:58:27,574 [DEBUG]  Logged UserUtterance - tracker now has 16 events.
2020-01-14 15:58:27,637 [DEBUG]  NLU confidence threshold met, confidence of fallback action set to core threshold (0.4).
2020-01-14 15:58:27,637 [DEBUG]  There is a memorised next action '55'
2020-01-14 15:58:27,652 [DEBUG]  There is no active form
2020-01-14 15:58:27,652 [DEBUG]  Predicted next action using policy_2_MemoizationPolicy
2020-01-14 15:58:27,652 [DEBUG]  Predicted next action 'UNIQUE_SLOT_form' with confidence 1.00.
2020-01-14 15:58:27,652 [DEBUG]  Calling action endpoint to run action 'UNQIUE_SLOT_form'.
2020-01-14 15:58:28,934 [DEBUG]  Action 'target_form' ended with events '[BotUttered('I need you to clarify the <redacted>
2020-01-14 15:58:28,949 [DEBUG]  Current slot values: 
	requested_slot: target
	UNQIUE_SLOT: None
	user: USER
	verify_UNIQUE_SLOT: True
2020-01-14 15:58:28,949 [DEBUG]  NLU confidence threshold met, confidence of fallback action set to core threshold (0.4).
2020-01-14 15:58:28,965 [DEBUG]  There is a memorised next action '55'
2020-01-14 15:58:28,965 [DEBUG]  There is an active form 'UNIQUE_SLOT_form'
2020-01-14 15:58:28,965 [DEBUG]  There is no mapped action for the predicted intent, 'get_UNIQUE_SLOT'.
2020-01-14 15:58:28,965 [DEBUG]  Predicted next action using policy_3_FormPolicy
2020-01-14 15:58:29,027 [DEBUG]  Predicted next action 'action_listen' with confidence 1.00.
2020-01-14 15:58:29,074 [DEBUG]  Action 'action_listen' ended with events '[]'.
2020-01-14 15:58:29,090 [DEBUG]  Tracker with sender_id 'USER' stored to database
2020-01-14 15:58:29,090 [DEBUG]  Deleted lock for conversation 'USER'.
2020-01-14 15:58:37,231 [DEBUG]  Recreating tracker from sender id 'USER'
2020-01-14 15:58:37,231 [DEBUG]  The latest session for conversation ID 'USER' has expired.
2020-01-14 15:58:37,231 [DEBUG]  Starting a new session for conversation ID 'USER'.
2020-01-14 15:58:37,231 [DEBUG]  Calling action endpoint to run action 'action_session_start'.
2020-01-14 15:58:38,387 [DEBUG]  Action 'action_session_start' ended with events '[<rasa.core.events.SessionStarted object at 0x000001D97D7C5BA8>, <rasa.core.events.SlotSet object at 0x000001D97D7C5860>, <rasa.core.events.ActionExecuted object at 0x000001D97D7C5A90>]'.
2020-01-14 15:58:38,387 [DEBUG]  Current slot values: 
	requested_slot: None
	UNIQUE_SLOT_VALUE: None
	user: USER
	verify_UNIQUE_SLOT: False

The section that I noticed was at 2020-01-14 15:58:28,949 the verify_UNIQUE_SLOTis set to True and ends the conversation but then at 2020-01-14 15:58:38,387, which is just 10 miliseconds later, when a new USER message comes in the verify_UNIQUE_SLOT is set to False. I’ve checked my slot verification and it appears to be okay, so I’m not sure why this is happening. This is causing the bot to go into a loop of continuously prompting the user for the same information over and over.

I’m also not sure why I keep seeing these two lines repeated at the start of every new message from the user:

2020-01-14 15:58:37,231 [DEBUG]  The latest session for conversation ID 'USER' has expired.
2020-01-14 15:58:37,231 [DEBUG]  Starting a new session for conversation ID 'USER'.

Shouldn’t the session only be reset after 30 minutes? I had tested it on a smaller example before and it was working so I’m surprised to see this happening.

Maybe I’m missing something?

Thanks

I filed a bug for this, since I’m having a very similar issue: Rasa restarts session while filling slots with a form and deletes slots · Issue #5091 · RasaHQ/rasa · GitHub

Thanks! I’ll keep an eye on this issue.