Hello, my simple authentication Bot was working fine on Socket.io channel. I decided to add a mongoDB tracker store just like the documentation sugests us to.
I added this code on my endpoints.yaml
tracker_store:
type: mongod
url: mongodb://localhost:27017
db: rasa
username:
password:
The credentials.yaml
rest:
socketio:
user_message_evt: user_uttered
bot_message_evt: bot_uttered
session_persistence: false
rasa:
url: "http://localhost:5002/api"
When testing the socket.io channel, the bot stoped working. The Form did not begin and i have no idea where should i begin to investigate. Here are the logs on my mongodb server.
2020-02-06T14:04:24.494-0300 I CONTROL [main] Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'
2020-02-06T14:04:27.393-0300 I CONTROL [initandlisten] MongoDB starting : pid=16336 port=27017 dbpath=C:\data\db\ 64-bit host=DDSDSC022174
2020-02-06T14:04:27.394-0300 I CONTROL [initandlisten] targetMinOS: Windows 7/Windows Server 2008 R2
2020-02-06T14:04:27.394-0300 I CONTROL [initandlisten] db version v4.2.0
2020-02-06T14:04:27.394-0300 I CONTROL [initandlisten] git version: a4b751dcf51dd249c5865812b390cfd1c0129c30
2020-02-06T14:04:27.394-0300 I CONTROL [initandlisten] allocator: tcmalloc
2020-02-06T14:04:27.394-0300 I CONTROL [initandlisten] modules: none
2020-02-06T14:04:27.394-0300 I CONTROL [initandlisten] build environment:
2020-02-06T14:04:27.395-0300 I CONTROL [initandlisten] distmod: 2012plus
2020-02-06T14:04:27.395-0300 I CONTROL [initandlisten] distarch: x86_64
2020-02-06T14:04:27.395-0300 I CONTROL [initandlisten] target_arch: x86_64
2020-02-06T14:04:27.395-0300 I CONTROL [initandlisten] options: {}
2020-02-06T14:04:27.747-0300 I STORAGE [initandlisten] Detected data files in C:\data\db\ created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'.
2020-02-06T14:04:27.764-0300 I STORAGE [initandlisten] wiredtiger_open config: create,cache_size=3037M,cache_overflow=(file_max=0M),session_max=33000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),statistics_log=(wait=0),verbose=[recovery_progress,checkpoint_progress],
2020-02-06T14:04:28.482-0300 I STORAGE [initandlisten] WiredTiger message [1581008668:482374][16336:140714263404112], txn-recover: Recovering log 8 through 9
2020-02-06T14:04:28.848-0300 I STORAGE [initandlisten] WiredTiger message [1581008668:847421][16336:140714263404112], txn-recover: Recovering log 9 through 9
2020-02-06T14:04:29.209-0300 I STORAGE [initandlisten] WiredTiger message [1581008669:209421][16336:140714263404112], txn-recover: Main recovery loop: starting at 8/37632 to 9/256
2020-02-06T14:04:29.986-0300 I STORAGE [initandlisten] WiredTiger message [1581008669:986117][16336:140714263404112], txn-recover: Recovering log 8 through 9
2020-02-06T14:04:30.388-0300 I STORAGE [initandlisten] WiredTiger message [1581008670:388225][16336:140714263404112], txn-recover: Recovering log 9 through 9
2020-02-06T14:04:30.664-0300 I STORAGE [initandlisten] WiredTiger message [1581008670:664233][16336:140714263404112], txn-recover: Set global recovery timestamp: (0,0)
2020-02-06T14:04:31.326-0300 I RECOVERY [initandlisten] WiredTiger recoveryTimestamp. Ts: Timestamp(0, 0)
2020-02-06T14:04:32.399-0300 I STORAGE [initandlisten] Timestamp monitor starting
2020-02-06T14:04:32.504-0300 I CONTROL [initandlisten]
2020-02-06T14:04:32.505-0300 I CONTROL [initandlisten] ** WARNING: Access control is not enabled for the database.
2020-02-06T14:04:32.507-0300 I CONTROL [initandlisten] ** Read and write access to data and configuration is unrestricted.
2020-02-06T14:04:32.508-0300 I CONTROL [initandlisten]
2020-02-06T14:04:32.509-0300 I CONTROL [initandlisten] ** WARNING: This server is bound to localhost.
2020-02-06T14:04:32.510-0300 I CONTROL [initandlisten] ** Remote systems will be unable to connect to this server.
2020-02-06T14:04:32.511-0300 I CONTROL [initandlisten] ** Start the server with --bind_ip <address> to specify which IP
2020-02-06T14:04:32.512-0300 I CONTROL [initandlisten] ** addresses it should serve responses from, or with --bind_ip_all to
2020-02-06T14:04:32.512-0300 I CONTROL [initandlisten] ** bind to all interfaces. If this behavior is desired, start the
2020-02-06T14:04:32.513-0300 I CONTROL [initandlisten] ** server with --bind_ip 127.0.0.1 to disable this warning.
2020-02-06T14:04:32.539-0300 I CONTROL [initandlisten]
2020-02-06T14:04:33.461-0300 I SHARDING [initandlisten] Marking collection local.system.replset as collection version: <unsharded>
2020-02-06T14:04:33.804-0300 I STORAGE [initandlisten] Flow Control is enabled on this deployment.
2020-02-06T14:04:33.999-0300 I SHARDING [initandlisten] Marking collection admin.system.roles as collection version: <unsharded>
2020-02-06T14:04:34.221-0300 I COMMAND [initandlisten] command admin.system.roles command: find { find: "system.roles", $db: "admin" } planSummary: EOF keysExamined:0 docsExamined:0 cursorExhausted:1 numYields:0 nreturned:0 reslen:107 locks:{ ReplicationStateTransition: { acquireCount: { w: 1 } }, Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 2 } }, Mutex: { acquireCount: { r: 1 } } } storage:{ data: { bytesRead: 125 } } protocol:op_msg 218ms
2020-02-06T14:04:34.325-0300 I SHARDING [initandlisten] Marking collection admin.system.version as collection version: <unsharded>
2020-02-06T14:04:34.688-0300 I SHARDING [initandlisten] Marking collection local.startup_log as collection version: <unsharded>
2020-02-06T14:04:53.187-0300 W FTDC [initandlisten] Failed to initialize Performance Counters for FTDC: WindowsPdhError: PdhExpandCounterPathW failed with 'O objeto especificado não foi encontrado no computador.' for counter '\Processor(_Total)\% Idle Time'
2020-02-06T14:04:53.335-0300 I FTDC [initandlisten] Initializing full-time diagnostic data capture with directory 'C:/data/db/diagnostic.data'
2020-02-06T14:04:53.480-0300 I NETWORK [initandlisten] Listening on 127.0.0.1
2020-02-06T14:04:53.483-0300 I NETWORK [initandlisten] waiting for connections on port 27017
2020-02-06T14:04:53.506-0300 I SHARDING [LogicalSessionCacheRefresh] Marking collection config.system.sessions as collection version: <unsharded>
2020-02-06T14:04:53.559-0300 I SHARDING [LogicalSessionCacheReap] Marking collection config.transactions as collection version: <unsharded>
2020-02-06T14:13:52.884-0300 I NETWORK [listener] connection accepted from 127.0.0.1:63082 #1 (1 connection now open)
2020-02-06T14:13:52.922-0300 I NETWORK [conn1] received client metadata from 127.0.0.1:63082 conn1: { driver: { name: "PyMongo", version: "3.10.1" }, os: { type: "Windows", name: "Windows 10", architecture: "AMD64", version: "10.0.18362-SP0" }, platform: "CPython 3.7.3.final.0" }
2020-02-06T14:13:52.926-0300 I NETWORK [listener] connection accepted from 127.0.0.1:63083 #2 (2 connections now open)
2020-02-06T14:13:52.928-0300 I NETWORK [conn2] received client metadata from 127.0.0.1:63083 conn2: { driver: { name: "PyMongo", version: "3.10.1" }, os: { type: "Windows", name: "Windows 10", architecture: "AMD64", version: "10.0.18362-SP0" }, platform: "CPython 3.7.3.final.0" }
2020-02-06T14:14:54.068-0300 I WRITE [LogicalSessionCacheRefresh] update config.system.sessions command: { q: { _id: { id: UUID("c9fcbbc9-3dd1-4c44-98df-50fddd9a609a"), uid: BinData(0, E3B0C44298FC1C149AFBF4C8996FB92427AE41E4649B934CA495991B7852B855) } }, u: { $currentDate: { lastUse: true } }, multi: false, upsert: true } planSummary: IDHACK keysExamined:0 docsExamined:0 nMatched:0 nModified:0 upsert:1 keysInserted:2 numYields:1 locks:{ ParallelBatchWriterMode: { acquireCount: { r: 2 } }, ReplicationStateTransition: { acquireCount: { w: 2 } }, Global: { acquireCount: { w: 2 } }, Database: { acquireCount: { w: 2 } }, Collection: { acquireCount: { w: 2 } }, Mutex: { acquireCount: { r: 2 } } } flowControl:{ acquireCount: 2 } storage:{} 385ms
2020-02-06T14:14:54.068-0300 I COMMAND [LogicalSessionCacheRefresh] command config.$cmd command: update { update: "system.sessions", ordered: false, allowImplicitCollectionCreation: false, writeConcern: { w: "majority", wtimeout: 15000 }, $db: "config" } numYields:1 reslen:171 locks:{ ParallelBatchWriterMode: { acquireCount: { r: 3 } }, ReplicationStateTransition: { acquireCount: { w: 3 } }, Global: { acquireCount: { r: 1, w: 2 } }, Database: { acquireCount: { w: 2 } }, Collection: { acquireCount: { w: 2 } }, Mutex: { acquireCount: { r: 2 } } } flowControl:{ acquireCount: 2 } storage:{} protocol:op_msg 425ms
2020-02-06T14:20:19.441-0300 I SHARDING [conn2] Marking collection rasa.conversations as collection version: <unsharded>
2020-02-06T14:20:20.650-0300 I COMMAND [conn2] command rasa.conversations command: find { find: "conversations", filter: { sender_id: "ed91dfe2bc2d464f95594efc565a4c41" }, limit: 1, singleBatch: true, lsid: { id: UUID("c9fcbbc9-3dd1-4c44-98df-50fddd9a609a") }, $db: "rasa", $readPreference: { mode: "primaryPreferred" } } planSummary: IXSCAN { sender_id: 1 } keysExamined:0 docsExamined:0 cursorExhausted:1 numYields:0 nreturned:0 queryHash:DF31B675 planCacheKey:549F859F reslen:107 locks:{ ReplicationStateTransition: { acquireCount: { w: 1 } }, Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } }, Mutex: { acquireCount: { r: 1 } } } storage:{ data: { bytesRead: 300 } } protocol:op_msg 1324ms
2020-02-06T14:20:21.390-0300 I WRITE [conn2] update rasa.conversations command: { q: { sender_id: "ed91dfe2bc2d464f95594efc565a4c41" }, u: { $set: { sender_id: "ed91dfe2bc2d464f95594efc565a4c41", slots: { autenticado: "False", cpf: null, data_nascimento: null, nome_completo: null, requested_slot: null }, latest_message: { intent: {}, entities: [], text: null, message_id: null, metadata: {} }, latest_event_time: null, followup_action: "action_listen", paused: false, latest_input_channel: null, active_form: {}, latest_action_name: null }, $push: { events: { $each: [] } } }, multi: false, upsert: true } planSummary: IXSCAN { sender_id: 1 } keysExamined:0 docsExamined:0 nMatched:0 nModified:0 upsert:1 keysInserted:2 numYields:0 queryHash:DF31B675 planCacheKey:549F859F locks:{ ParallelBatchWriterMode: { acquireCount: { r: 1 } }, ReplicationStateTransition: { acquireCount: { w: 1 } }, Global: { acquireCount: { w: 1 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { w: 1 } }, Mutex: { acquireCount: { r: 2 } } } flowControl:{ acquireCount: 1 } storage:{ data: { bytesRead: 196 } } 481ms
2020-02-06T14:20:21.455-0300 I COMMAND [conn2] command rasa.$cmd command: update { update: "conversations", ordered: true, lsid: { id: UUID("c9fcbbc9-3dd1-4c44-98df-50fddd9a609a") }, $db: "rasa", $readPreference: { mode: "primary" } } numYields:0 reslen:111 locks:{ ParallelBatchWriterMode: { acquireCount: { r: 2 } }, ReplicationStateTransition: { acquireCount: { w: 2 } }, Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { w: 1 } }, Mutex: { acquireCount: { r: 2 } } } flowControl:{ acquireCount: 1 } storage:{} protocol:op_msg 634ms
2020-02-06T14:21:39.801-0300 I NETWORK [conn2] end connection 127.0.0.1:63083 (1 connection now open)
2020-02-06T14:21:39.819-0300 I NETWORK [conn1] end connection 127.0.0.1:63082 (0 connections now open)
Here are my rasa logs:
2020-02-06 14:12:35,339 [DEBUG] Available web server routes:
/conversations/<conversation_id>/messages POST add_message
/conversations/<conversation_id>/tracker/events POST append_events
/webhooks/rasa GET custom_webhook_RasaChatInput.health
/webhooks/rasa/webhook POST custom_webhook_RasaChatInput.receive
/webhooks/rest GET custom_webhook_RestInput.health
/webhooks/rest/webhook POST custom_webhook_RestInput.receive
/model/test/intents POST evaluate_intents
/model/test/stories POST evaluate_stories
/conversations/<conversation_id>/execute POST execute_action
/domain GET get_domain
/socket.io OPTIONS handle_request
/ GET hello
/model PUT load_model
/model/parse POST parse
/conversations/<conversation_id>/predict POST predict
/conversations/<conversation_id>/tracker/events PUT replace_events
/conversations/<conversation_id>/story GET retrieve_story
/conversations/<conversation_id>/tracker GET retrieve_tracker
/webhooks/socketio GET socketio_webhook.health
/status GET status
/model/predict POST tracker_predict
/model/train POST train
/model DELETE unload_model
/version GET version
2020-02-06 14:12:35,343 [INFO ] Starting Rasa server on http://localhost:5005
2020-02-06 14:12:35,346 [DEBUG] Using the default number of Sanic workers (1).
2020-02-06 14:12:35,351 [INFO ] Enabling coroutine debugging. Loop id 2229533468264.
2020-02-06 14:12:36,297 [DEBUG] Extracted model to 'C:\Users\CAIO~1.GUI\AppData\Local\Temp\tmppge8_wx3'.
2020-02-06 14:12:59,474 [INFO ] NumExpr defaulting to 4 threads.
2020-02-06 14:13:38,399 [INFO ] Entry Point [tensor2tensor.envs.tic_tac_toe_env:TicTacToeEnv] registered with id [T2TEnv-TicTacToeEnv-v0]
2020-02-06 14:13:53,028 [DEBUG] Connected to MongoTrackerStore.
2020-02-06 14:13:53,031 [DEBUG] Connected to lock store 'InMemoryLockStore'.
2020-02-06 14:13:53,263 [DEBUG] Extracted model to 'C:\Users\CAIO~1.GUI\AppData\Local\Temp\tmp6volq2uu'.
2020-02-06 14:13:53,459 [DEBUG] Using yaml library: c:\users\caio.guimaraes\appdata\local\continuum\anaconda3\lib\site-packages\ruamel\yaml\__init__.py
2020-02-06 14:13:57,938 [DEBUG] Instantiated NLG to 'TemplatedNaturalLanguageGenerator'.
2020-02-06 14:19:54,176 [DEBUG] User ed91dfe2bc2d464f95594efc565a4c41 connected to socketIO endpoint.
2020-02-06 14:19:54,414 [DEBUG] User ed91dfe2bc2d464f95594efc565a4c41 connected to socketIO endpoint.
2020-02-06 14:20:21,456 [DEBUG] Starting a new session for conversation ID 'ed91dfe2bc2d464f95594efc565a4c41'.
2020-02-06 14:20:21,502 [DEBUG] Action 'action_session_start' ended with events '[<rasa.core.events.SessionStarted object at 0x0000020723C82470>, <rasa.core.events.ActionExecuted object at 0x0000020723C828D0>]'.
2020-02-06 14:20:21,507 [DEBUG] Current slot values:
autenticado: False
cpf: None
data_nascimento: None
nome_completo: None
requested_slot: None
2020-02-06 14:20:22,806 [DEBUG] Received user message 'olá' with intent '{'name': 'saudacoes', 'confidence': 0.982362687587738}' and entities '[]'
2020-02-06 14:20:22,832 [DEBUG] Logged UserUtterance - tracker now has 4 events.
2020-02-06 14:20:22,837 [DEBUG] Current tracker state [None, None, None, {'slot_autenticado_0': 1.0}, {'intent_saudacoes': 1.0, 'prev_action_listen': 1.0, 'slot_autenticado_0': 1.0}]
2020-02-06 14:20:22,865 [DEBUG] There is a memorised next action '16'
2020-02-06 14:20:23,987 [DEBUG] There is no active form
2020-02-06 14:20:23,990 [DEBUG] Predicted next action using policy_0_MemoizationPolicy
2020-02-06 14:20:24,013 [DEBUG] Predicted next action 'utter_saudar' with confidence 1.00.
2020-02-06 14:20:24,015 [DEBUG] Action 'utter_saudar' ended with events '[BotUttered('Olá, eu sou o Bot Virtual, eu sou responsável pelo agendamento de consultas médicas. Você gostaria de agendar uma?', {"elements": null, "quick_replies": null, "buttons": null, "attachment": null, "image": null, "custom": null}, {}, 1581009624.015588)]'.
2020-02-06 14:20:24,105 [DEBUG] Current tracker state [None, None, {'slot_autenticado_0': 1.0}, {'intent_saudacoes': 1.0, 'prev_action_listen': 1.0, 'slot_autenticado_0': 1.0}, {'intent_saudacoes': 1.0, 'slot_autenticado_0': 1.0, 'prev_utter_saudar': 1.0}]
2020-02-06 14:20:24,107 [DEBUG] There is a memorised next action '0'
2020-02-06 14:20:24,117 [DEBUG] There is no mapped action for the predicted intent, 'saudacoes'.
2020-02-06 14:20:24,118 [DEBUG] There is no active form
2020-02-06 14:20:24,120 [DEBUG] Predicted next action using policy_0_MemoizationPolicy
2020-02-06 14:20:24,122 [DEBUG] Predicted next action 'action_listen' with confidence 1.00.
2020-02-06 14:20:24,124 [DEBUG] Action 'action_listen' ended with events '[]'.
2020-02-06 14:20:24,134 [DEBUG] Deleted lock for conversation 'ed91dfe2bc2d464f95594efc565a4c41'.
2020-02-06 14:20:36,904 [DEBUG] Received user message 'sim por favor' with intent '{'name': 'afirmar', 'confidence': 0.9921248555183411}' and entities '[]'
2020-02-06 14:20:36,907 [DEBUG] Logged UserUtterance - tracker now has 8 events.
2020-02-06 14:20:36,909 [DEBUG] Current tracker state [{'slot_autenticado_0': 1.0}, {'prev_action_listen': 1.0, 'slot_autenticado_0': 1.0}, {'intent_saudacoes': 1.0, 'prev_action_listen': 1.0, 'slot_autenticado_0': 1.0}, {'intent_saudacoes': 1.0, 'slot_autenticado_0': 1.0, 'prev_utter_saudar': 1.0}, {'prev_action_listen': 1.0, 'intent_afirmar': 1.0, 'slot_autenticado_0': 1.0}]
2020-02-06 14:20:36,910 [DEBUG] There is no memorised next action
2020-02-06 14:20:36,920 [DEBUG] There is no active form
2020-02-06 14:20:36,921 [DEBUG] Predicted next action using policy_1_KerasPolicy
2020-02-06 14:20:36,924 [DEBUG] Predicted next action 'action_listen' with confidence 0.33.
2020-02-06 14:20:36,927 [DEBUG] Action 'action_listen' ended with events '[]'.
2020-02-06 14:20:36,993 [DEBUG] Deleted lock for conversation 'ed91dfe2bc2d464f95594efc565a4c41'.
2020-02-06 14:21:08,745 [DEBUG] User ed91dfe2bc2d464f95594efc565a4c41 disconnected from socketIO endpoint.
Thanks in Advance!