Rasa + Redis removes the lock 10 seconds after the start of the call

Rasa Open Source
1

Hi!

We observe the following behavior: rasa predicts the correct step in the conversation, but instead of performing an action, rasa removes the conversation lock and takes no further action. Here is part of the log:

{"asctime": "2022-05-25 07:00:34,086", "levelname": "DEBUG", "name": "rasa.core.actions.action", "message": "Get response from Action Server timeLaps: 2.457s action action_transfer-to-operator_get-transfer-to-operator for sender: 1111: '{'events': [{'name': 'vdn', 'value': '111222', 'event': 'slot', 'timestamp': None}, {'name': 'working-hours-agent', 'value': None, 'event': 'slot', 'timestamp': None}, {'name': 'agent', 'value': None, 'event': 'slot', 'timestamp': None}], 'responses': []}'"}
{"asctime": "2022-05-25 07:00:34,086", "levelname": "DEBUG", "name": "rasa.core.processor", "message": "Sender: '1111'-> Policy prediction ended with events '[<rasa.shared.core.events.DefinePrevUserUtteredFeaturization object at 0x7f35f045afd0>]'."}
{"asctime": "2022-05-25 07:00:34,086", "levelname": "DEBUG", "name": "rasa.core.processor", "message": "Sender: '1111'-> Action 'action_transfer-to-operator_get-transfer-to-operator' ended with events '[<rasa.shared.core.events.SlotSet object at 0x7f35f04e4cd0>, <rasa.shared.core.events.SlotSet object at 0x7f35f04e4340>, <rasa.shared.core.events.SlotSet object at 0x7f35f04e4c70>]'."}
{"asctime": "2022-05-25 07:00:34,087", "levelname": "DEBUG", "name": "rasa.core.processor", "message": "Sender: '1111' -> Current slot values: ..."}
{"asctime": "2022-05-25 07:00:34,095", "levelname": "DEBUG", "name": "rasa.core.policies.rule_policy", "message": "Current tracker state:\n[state 1] sender: 1111 | previous action name: action_listen\n[state 2] sender: 1111 | previous action name: utter_hello_timeOfDay\n[state 3] sender: 1111 | previous action name: action_technical-actions_is-slot-in-list-segment-vip-platinum-no-infl\n[state 4] sender: 1111 | previous action name: utter_next_pt\n[state 5] sender: 1111 | user intent: alarm_after | previous action name: action_listen\n[state 6] sender: 1111 | user intent: alarm_after | previous action name: action_technical-actions_copy-slot-alarms-pretense-alarm-after\n[state 7] sender: 1111 | user intent: alarm_after | previous action name: action_technical-actions_copy-slot-alarms-sms-after\n[state 8] sender: 1111 | user intent: alarm_after | previous action name: utter_alarm_after\n[state 9] sender: 1111 | user intent: transfer_to_operator | previous action name: action_redirect-intent_get-redirect-intent-transfer-to-operator\n[state 10] sender: 1111 | user intent: transfer_to_operator | previous action name: action_listen\n[state 11] sender: 1111 | user intent: transfer_to_operator | previous action name: action_transfer-to-operator_get-transfer-to-operator | slots: {'vdn': (1.0, 1.0)}"}
{"asctime": "2022-05-25 07:00:34,243", "levelname": "DEBUG", "name": "rasa.core.policies.rule_policy", "message": "There is a rule for the next action 'utter_condition_transfer_to_operator'."}
{"asctime": "2022-05-25 07:00:34,257", "levelname": "DEBUG", "name": "rasa.core.policies.ted_policy", "message": "TED predicted 'action_intent-entry_get-intent-entry-by-session-ksd-detalizaciya-kak-zakazat' based on user intent."}
{"asctime": "2022-05-25 07:00:34,261", "levelname": "DEBUG", "name": "rasa.core.policies.ted_policy", "message": "Sender: '1111' -> Current tracker state:\n[state 1] sender: 1111 | previous action name: action_listen\n[state 2] sender: 1111 | previous action name: action_listen | slots: {'vdn': (1.0, 1.0)}"}
{"asctime": "2022-05-25 07:00:34,264", "levelname": "DEBUG", "name": "rasa.core.policies.memoization", "message": "Sender: '1111' -> Current tracker state:\n[state 1] sender: 1111 | previous action name: action_listen\n[state 2] sender: 1111 | previous action name: action_listen | slots: {'vdn': (1.0, 1.0)}"}
{"asctime": "2022-05-25 07:00:34,265", "levelname": "DEBUG", "name": "rasa.core.policies.memoization", "message": "Sender: '1111' -> There is no memorised next action"}
{"asctime": "2022-05-25 07:00:34,265", "levelname": "DEBUG", "name": "rasa.core.policies.ensemble", "message": "Sender: '1111' -> Predicted next action using policy_0_RulePolicy."}
{"asctime": "2022-05-25 07:00:34,265", "levelname": "DEBUG", "name": "rasa.core.processor", "message": "Sender: '1111' -> Predicted next action 'utter_condition_transfer_to_operator' with confidence 1.00."}


{"asctime": "2022-05-25 07:00:36,831", "levelname": "DEBUG", "name": "rasa.core.lock_store", "message": "Deleted lock for conversation '1111'."}

The next steps should be as follows:

  1. Calling the nlg server (we have a separate server for responses) to get the text of the utter
  2. And then predicting action_listen, but for some reason this doesn’t happen.

Here is the rule:

version: '2.0'
rules:
  - rule: transfer_to_operator
    steps:
      - intent: transfer_to_operator
      - action: action_transfer-to-operator_get-transfer-to-operator
      - action: utter_condition_transfer_to_operator

We also use Redis as a lock store. And we noticed that the lock is deleted 10 seconds after the start of the conversation:

{"asctime": "2022-05-25 07:00:26,822", "levelname": "DEBUG", "name": "rasa.core.lock_store", "message": "Issuing ticket for conversation '1111'."}
...
{"asctime": "2022-05-25 07:00:36,831", "levelname": "DEBUG", "name": "rasa.core.lock_store", "message": "Deleted lock for conversation '1111'."}

What could be the reason of such behaviour?

2

The redis lock store behavior you describe is normal and not an issue (the lock should be very brief, only when the tracker store is updated).

It also looks like your rule is working correctly. Sounds like the issue is your NLG server is not being called. Can you show your endpoints.yml config for the nlg server.