Unable to set slot when using SQL tracker

Hi,

I’m using InMemoryTracker all the while and my chatbot needs some user info before chatting. I passed the info using HTTP POST request to URL http://{{url}}/conversations/test/tracker/events and the body as below

[
    {
        "event": "slot",
        "name": "username",
        "value": "isaac",
        "timestamp": 0
    }
]

It works fine and my custom actions able to retrieve the slot value using tracker.get_slot("username") Now, I’m trying to switch the tracker to PostgresSQL. I added the tracker_store in endpoints.yml as below

tracker_store:
  type: SQL
  dialect: "postgresql"
  url: "localhost"
  port: 5432
  db: "rasa"
  username: "postgres"
  password: "password"

When I use POST request to set the slot, the response looks ok.

{
    "sender_id": "test",
    "slots": {
        "username": "isaac",
        "session_started_metadata": null
    },
    "latest_message": {
        "intent": {},
        "entities": [],
        "text": null,
        "message_id": null,
        "metadata": {}
    },
    "latest_event_time": 1643003770.6138699055,
    "followup_action": null,
    "paused": false,
    "events": [
        {
            "event": "session_started",
            "timestamp": 1643003758.7425978184
        },
        {
            "event": "action",
            "timestamp": 1643003758.7426223755,
            "name": "action_listen",
            "policy": null,
            "confidence": null,
            "action_text": null,
            "hide_rule_turn": false
        },
        {
            "event": "slot",
            "timestamp": 1643003770.6138174534,
            "name": "username",
            "value": "isaac"
        }
    ],
    "latest_input_channel": null,
    "active_loop": {},
    "latest_action": {
        "action_name": "action_listen"
    },
    "latest_action_name": "action_listen"
}

However, my custom action gets null value for the slot. I check via GET request with URL http://{{url}}/conversations/test/tracker, it seems like the slot wasn’t set.

{
    "sender_id": "test",
    "slots": {
        "username": null,
        "session_started_metadata": null
    },
    "latest_message": {
        "intent": {},
        "entities": [],
        "text": null,
        "message_id": null,
        "metadata": {}
    },
    "latest_event_time": 1643004317.804153204,
    "followup_action": null,
    "paused": false,
    "events": [
        {
            "event": "session_started",
            "timestamp": 1643004317.8041362762
        },
        {
            "event": "action",
            "timestamp": 1643004317.804153204,
            "name": "action_listen",
            "policy": null,
            "confidence": null,
            "action_text": null,
            "hide_rule_turn": false
        }
    ],
    "latest_input_channel": null,
    "active_loop": {},
    "latest_action": {
        "action_name": "action_listen"
    },
    "latest_action_name": "action_listen"
}

Below is the debug message from RASA OSS

2022-01-24 14:05:17 DEBUG    rasa.core.lock_store  - Issuing ticket for conversation 'test'.
2022-01-24 14:05:17 DEBUG    rasa.core.lock_store  - Acquiring lock for conversation 'test'.
2022-01-24 14:05:17 DEBUG    rasa.core.lock_store  - Acquired lock for conversation 'test'.
2022-01-24 14:05:17 DEBUG    rasa.core.tracker_store  - Can't retrieve tracker matching sender id 'test' from SQL storage. Returning `None` instead.
2022-01-24 14:05:17 DEBUG    rasa.core.tracker_store  - Tracker with sender_id 'test' stored to database
2022-01-24 14:05:17 DEBUG    rasa.core.processor  - Starting a new session for conversation ID 'test'.
2022-01-24 14:05:17 DEBUG    rasa.core.processor  - Policy prediction ended with events '[]'.
2022-01-24 14:05:17 DEBUG    rasa.core.processor  - Action 'action_session_start' ended with events '[<rasa.shared.core.events.SessionStarted object at 0x7f3a5cf2fc70>, ActionExecuted(action: action_listen, policy: None, confidence: None)]'.
2022-01-24 14:05:17 DEBUG    rasa.core.processor  - Current slot values:
        username: None
        session_started_metadata: None
2022-01-24 14:05:17 DEBUG    rasa.core.tracker_store  - Tracker with sender_id 'test' stored to database
2022-01-24 14:05:17 DEBUG    rasa.core.lock_store  - Deleted lock for conversation 'test'.
2022-01-24 14:05:26 DEBUG    rasa.core.tracker_store  - Recreating tracker from sender id 'test'

If I run the POST request to set slot twice, the slot can be successfully recorded. Same behavior is happening with SQLite. I need help on why first HTTP POST request slot isn’t stored.

Below is my RASA version

Rasa Version      :         2.8.16
Minimum Compatible Version: 2.8.9
Rasa SDK Version  :         2.8.3
Rasa X Version    :         0.42.0
Python Version    :         3.8.10
Operating System  :         Linux-5.4.72-microsoft-standard-WSL2-x86_64-with-glibc2.29

Thanks

A more complete log would be helpful. I see that it’s creating a new tracker for test which would be normal if this is a new session. After that, there should be a message with Received user message ... and it would show whether the slot is extracted and then later in the log if there were tracker storage issues.

1 Like

Here are the complete log. I split into 4 parts to show the log messages after each action.

  1. Start RASA server and call Append events to a tracker API to add slot value for user_name
2022-01-29 01:24:29 INFO     root  - Rasa server is up and running.
2022-01-29 01:24:33 DEBUG    rasa.core.lock_store  - Issuing ticket for conversation 'test'.
2022-01-29 01:24:33 DEBUG    rasa.core.lock_store  - Acquiring lock for conversation 'test'.
2022-01-29 01:24:33 DEBUG    rasa.core.lock_store  - Acquired lock for conversation 'test'.
2022-01-29 01:24:33 DEBUG    rasa.core.tracker_store  - Can't retrieve tracker matching sender id 'test' from SQL storage. Returning `None` instead.
2022-01-29 01:24:33 DEBUG    rasa.core.tracker_store  - Tracker with sender_id 'test' stored to database
2022-01-29 01:24:33 DEBUG    rasa.core.processor  - Starting a new session for conversation ID 'test'.
2022-01-29 01:24:33 DEBUG    rasa.core.processor  - Policy prediction ended with events '[]'.
2022-01-29 01:24:33 DEBUG    rasa.core.processor  - Action 'action_session_start' ended with events '[<rasa.shared.core.events.SessionStarted object at 0x7f0b8646b760>, ActionExecuted(action: action_listen, policy: None, confidence: None)]'.
2022-01-29 01:24:33 DEBUG    rasa.core.processor  - Current slot values: 
	user_name: None
	session_started_metadata: None
2022-01-29 01:24:33 DEBUG    rasa.core.tracker_store  - Tracker with sender_id 'test' stored to database
2022-01-29 01:24:33 DEBUG    rasa.core.lock_store  - Deleted lock for conversation 'test'.
  1. Send message to RASA server and receive None for slot value.
2022-01-29 01:24:51 DEBUG    rasa.core.lock_store  - Issuing ticket for conversation 'test'.
2022-01-29 01:24:51 DEBUG    rasa.core.lock_store  - Acquiring lock for conversation 'test'.
2022-01-29 01:24:51 DEBUG    rasa.core.lock_store  - Acquired lock for conversation 'test'.
2022-01-29 01:24:51 DEBUG    rasa.core.tracker_store  - Recreating tracker from sender id 'test'
2022-01-29 01:24:51 DEBUG    rasa.nlu.classifiers.diet_classifier  - There is no trained model for 'ResponseSelector': The component is either not trained or didn't receive enough training data.
2022-01-29 01:24:51 DEBUG    rasa.nlu.selectors.response_selector  - Adding following selector key to message property: default
2022-01-29 01:24:51 DEBUG    rasa.core.processor  - Received user message 'bye' with intent '{'id': -27639485150761472, 'name': 'goodbye', 'confidence': 0.9999934434890747}' and entities '[]'
2022-01-29 01:24:51 DEBUG    rasa.core.processor  - Logged UserUtterance - tracker now has 3 events.
2022-01-29 01:24:51 DEBUG    rasa.core.policies.memoization  - Current tracker state:
[state 1] user intent: goodbye | previous action name: action_listen
2022-01-29 01:24:51 DEBUG    rasa.core.policies.memoization  - There is no memorised next action
2022-01-29 01:24:51 DEBUG    rasa.core.policies.rule_policy  - Current tracker state:
[state 1] user text: bye | previous action name: action_listen
2022-01-29 01:24:51 DEBUG    rasa.core.policies.rule_policy  - There is no applicable rule.
2022-01-29 01:24:51 DEBUG    rasa.core.policies.rule_policy  - Current tracker state:
[state 1] user intent: goodbye | previous action name: action_listen
2022-01-29 01:24:51 DEBUG    rasa.core.policies.rule_policy  - There is a rule for the next action 'action_hello_world'.
2022-01-29 01:24:51 DEBUG    rasa.core.policies.unexpected_intent_policy  - Querying for intent `goodbye`.
2022-01-29 01:24:51 DEBUG    rasa.core.policies.unexpected_intent_policy  - Query intent index 4 not found in label thresholds - {0: -1.2305365, 3: -1.2668294, 5: -0.6774751, 6: -0.6487709, 7: -1.5989579}. Check for `action_unlikely_intent` prediction will be skipped.
2022-01-29 01:24:51 DEBUG    rasa.core.policies.ted_policy  - TED predicted 'action_listen' based on user intent.
2022-01-29 01:24:51 DEBUG    rasa.core.policies.ensemble  - Made prediction using user intent.
2022-01-29 01:24:51 DEBUG    rasa.core.policies.ensemble  - Added `DefinePrevUserUtteredFeaturization(False)` event.
2022-01-29 01:24:51 DEBUG    rasa.core.policies.ensemble  - Predicted next action using policy_1_RulePolicy.
2022-01-29 01:24:51 DEBUG    rasa.core.processor  - Predicted next action 'action_hello_world' with confidence 1.00.
2022-01-29 01:24:51 DEBUG    rasa.core.actions.action  - Calling action endpoint to run action 'action_hello_world'.
2022-01-29 01:24:51 DEBUG    rasa.core.processor  - Policy prediction ended with events '[<rasa.shared.core.events.DefinePrevUserUtteredFeaturization object at 0x7f0b8646f4f0>]'.
2022-01-29 01:24:51 DEBUG    rasa.core.processor  - Action 'action_hello_world' ended with events '[BotUttered('This is user name testing - None', {"elements": null, "quick_replies": null, "buttons": null, "attachment": null, "image": null, "custom": null}, {}, 1643419491.294226)]'.
2022-01-29 01:24:51 DEBUG    rasa.core.processor  - Current slot values: 
	user_name: None
	session_started_metadata: None
2022-01-29 01:24:51 DEBUG    rasa.core.policies.memoization  - Current tracker state:
[state 1] previous action name: action_listen
2022-01-29 01:24:51 DEBUG    rasa.core.policies.memoization  - There is no memorised next action
2022-01-29 01:24:51 DEBUG    rasa.core.policies.rule_policy  - Current tracker state:
[state 1] user intent: goodbye | previous action name: action_listen
[state 2] user intent: goodbye | previous action name: action_hello_world
2022-01-29 01:24:51 DEBUG    rasa.core.policies.rule_policy  - There is a rule for the next action 'action_listen'.
2022-01-29 01:24:51 DEBUG    rasa.core.policies.unexpected_intent_policy  - Skipping predictions for UnexpecTEDIntentPolicy as either there is no event of type `UserUttered`, event's intent is new and not in domain or there is an event of type `ActionExecuted` after the last `UserUttered`.
2022-01-29 01:24:51 DEBUG    rasa.core.policies.ted_policy  - TED predicted 'action_listen' based on user intent.
2022-01-29 01:24:51 DEBUG    rasa.core.policies.ensemble  - Predicted next action using policy_1_RulePolicy.
2022-01-29 01:24:51 DEBUG    rasa.core.processor  - Predicted next action 'action_listen' with confidence 1.00.
2022-01-29 01:24:51 DEBUG    rasa.core.processor  - Policy prediction ended with events '[]'.
2022-01-29 01:24:51 DEBUG    rasa.core.processor  - Action 'action_listen' ended with events '[]'.
2022-01-29 01:24:51 DEBUG    rasa.core.tracker_store  - Tracker with sender_id 'test' stored to database
2022-01-29 01:24:51 DEBUG    rasa.core.lock_store  - Deleted lock for conversation 'test'.
  1. Repeat sending slot value via Append events to a tracker API
2022-01-29 01:24:59 DEBUG    rasa.core.lock_store  - Issuing ticket for conversation 'test'.
2022-01-29 01:24:59 DEBUG    rasa.core.lock_store  - Acquiring lock for conversation 'test'.
2022-01-29 01:24:59 DEBUG    rasa.core.lock_store  - Acquired lock for conversation 'test'.
2022-01-29 01:24:59 DEBUG    rasa.core.tracker_store  - Recreating tracker from sender id 'test'
2022-01-29 01:24:59 DEBUG    rasa.core.tracker_store  - Tracker with sender_id 'test' stored to database
2022-01-29 01:24:59 DEBUG    rasa.core.lock_store  - Deleted lock for conversation 'test'.

4.Repeat send message to RASA server. Correct slot value is displayed.

2022-01-29 01:25:23 DEBUG    rasa.core.lock_store  - Issuing ticket for conversation 'test'.
2022-01-29 01:25:23 DEBUG    rasa.core.lock_store  - Acquiring lock for conversation 'test'.
2022-01-29 01:25:23 DEBUG    rasa.core.lock_store  - Acquired lock for conversation 'test'.
2022-01-29 01:25:23 DEBUG    rasa.core.tracker_store  - Recreating tracker from sender id 'test'
2022-01-29 01:25:23 DEBUG    rasa.nlu.classifiers.diet_classifier  - There is no trained model for 'ResponseSelector': The component is either not trained or didn't receive enough training data.
2022-01-29 01:25:23 DEBUG    rasa.nlu.selectors.response_selector  - Adding following selector key to message property: default
2022-01-29 01:25:23 DEBUG    rasa.core.processor  - Received user message 'bye' with intent '{'id': -27639485150761472, 'name': 'goodbye', 'confidence': 0.9999934434890747}' and entities '[]'
2022-01-29 01:25:23 DEBUG    rasa.core.processor  - Logged UserUtterance - tracker now has 9 events.
2022-01-29 01:25:23 DEBUG    rasa.core.policies.memoization  - Current tracker state:
[state 1] user intent: goodbye | previous action name: action_listen
2022-01-29 01:25:23 DEBUG    rasa.core.policies.memoization  - There is no memorised next action
2022-01-29 01:25:23 DEBUG    rasa.core.policies.rule_policy  - Current tracker state:
[state 1] user intent: goodbye | previous action name: action_listen
[state 2] user intent: goodbye | previous action name: action_hello_world
[state 3] user text: bye | previous action name: action_listen
2022-01-29 01:25:23 DEBUG    rasa.core.policies.rule_policy  - There is no applicable rule.
2022-01-29 01:25:23 DEBUG    rasa.core.policies.rule_policy  - Current tracker state:
[state 1] user intent: goodbye | previous action name: action_listen
[state 2] user intent: goodbye | previous action name: action_hello_world
[state 3] user intent: goodbye | previous action name: action_listen
2022-01-29 01:25:23 DEBUG    rasa.core.policies.rule_policy  - There is a rule for the next action 'action_hello_world'.
2022-01-29 01:25:23 DEBUG    rasa.core.policies.unexpected_intent_policy  - Querying for intent `goodbye`.
2022-01-29 01:25:23 DEBUG    rasa.core.policies.unexpected_intent_policy  - Query intent index 4 not found in label thresholds - {0: -1.2305365, 3: -1.2668294, 5: -0.6774751, 6: -0.6487709, 7: -1.5989579}. Check for `action_unlikely_intent` prediction will be skipped.
2022-01-29 01:25:23 DEBUG    rasa.core.policies.ted_policy  - TED predicted 'action_listen' based on user intent.
2022-01-29 01:25:23 DEBUG    rasa.core.policies.ensemble  - Made prediction using user intent.
2022-01-29 01:25:23 DEBUG    rasa.core.policies.ensemble  - Added `DefinePrevUserUtteredFeaturization(False)` event.
2022-01-29 01:25:23 DEBUG    rasa.core.policies.ensemble  - Predicted next action using policy_1_RulePolicy.
2022-01-29 01:25:23 DEBUG    rasa.core.processor  - Predicted next action 'action_hello_world' with confidence 1.00.
2022-01-29 01:25:23 DEBUG    rasa.core.actions.action  - Calling action endpoint to run action 'action_hello_world'.
2022-01-29 01:25:23 DEBUG    rasa.core.processor  - Policy prediction ended with events '[<rasa.shared.core.events.DefinePrevUserUtteredFeaturization object at 0x7f0b8624ccd0>]'.
2022-01-29 01:25:23 DEBUG    rasa.core.processor  - Action 'action_hello_world' ended with events '[BotUttered('This is user name testing - John Doe', {"elements": null, "quick_replies": null, "buttons": null, "attachment": null, "image": null, "custom": null}, {}, 1643419523.9740708)]'.
2022-01-29 01:25:23 DEBUG    rasa.core.processor  - Current slot values: 
	user_name: John Doe
	session_started_metadata: None
2022-01-29 01:25:23 DEBUG    rasa.core.policies.memoization  - Current tracker state:
[state 1] previous action name: action_listen
2022-01-29 01:25:23 DEBUG    rasa.core.policies.memoization  - There is no memorised next action
2022-01-29 01:25:23 DEBUG    rasa.core.policies.rule_policy  - Current tracker state:
[state 1] user intent: goodbye | previous action name: action_listen
[state 2] user intent: goodbye | previous action name: action_hello_world
[state 3] user intent: goodbye | previous action name: action_listen
[state 4] user intent: goodbye | previous action name: action_hello_world
2022-01-29 01:25:23 DEBUG    rasa.core.policies.rule_policy  - There is a rule for the next action 'action_listen'.
2022-01-29 01:25:23 DEBUG    rasa.core.policies.unexpected_intent_policy  - Skipping predictions for UnexpecTEDIntentPolicy as either there is no event of type `UserUttered`, event's intent is new and not in domain or there is an event of type `ActionExecuted` after the last `UserUttered`.
2022-01-29 01:25:24 DEBUG    rasa.core.policies.ted_policy  - TED predicted 'action_listen' based on user intent.
2022-01-29 01:25:24 DEBUG    rasa.core.policies.ensemble  - Predicted next action using policy_1_RulePolicy.
2022-01-29 01:25:24 DEBUG    rasa.core.processor  - Predicted next action 'action_listen' with confidence 1.00.
2022-01-29 01:25:24 DEBUG    rasa.core.processor  - Policy prediction ended with events '[]'.
2022-01-29 01:25:24 DEBUG    rasa.core.processor  - Action 'action_listen' ended with events '[]'.
2022-01-29 01:25:24 DEBUG    rasa.core.tracker_store  - Tracker with sender_id 'test' stored to database
2022-01-29 01:25:24 DEBUG    rasa.core.lock_store  - Deleted lock for conversation 'test'.

This problem doesn’t happen when using in-memory tracker store. Hope someone can help.

I think RASA core doesn’t store the slot before the conversation ID is created in tracker store. When setting slot in the first message, the JSON body should be something like this.

[
    {
        "event": "action",
        "name": "action_session_start"
    },
    {
        "event": "session_started"
    },
    {
        "event": "action",
        "name": "action_listen"
    },
    {
        "event": "slot",
        "name": "username",
        "value": "isaac"
    }
]