Multiple sequential actions cause asyncio TimeoutError

[tocosastalo]

Rasa version: 1.2.4
Rasa SDK version: 1.2.0
Python version: Python 3.6.9 (Anaconda 4.5.13)
Operating system : Win10, 64bit

Issue:
Multiple sequential actions (I would say 4 and more) in row in one story lead to Task exception was never retrieved error (see traceback).

Story:

## FULL 1b
* want_search
    - action_search_start_print_utter
    - action_search_start_print_utter
    - action_search_start_print_utter
    - action_search_start_print_utter    
    - action_search_start_print_utter

Action:

class ActionSearchStartPrintUtter(Action):
    def name(self):
        return "action_search_start_print_utter"

    def run(self, dispatcher, tracker, domain):
        dispatcher.utter_template("utter_lets_do_it", tracker)
        return []

Command or request that led to error:

[Rasa]
rasa shell --credentials credentials.yml --endpoints endpoints.yml --port 4444  --log-file logs/out.log --debug  --verbose

[SDK]
python -m rasa_sdk --actions action_sdk.actions --verbose --debug

Error (including full traceback):

2019-09-03 21:17:53 INFO     root  - Connecting to channel 'cmdline' which was specified by the '--connector' argument. Any other channels will be ignored. To connect to all given channels, omit the '--connector' argument.  
2019-09-03 21:17:53 INFO     root  - Starting Rasa server on http://localhost:4444
Bot loaded. Type a message and press enter (use '/stop' to exit): 
Your input ->  neco hledam                                                                                      

2019-09-03 21:18:14 WARNING  root  - Could not parse timestamp c1f48ac98a26479687b85d9aa9e1c2ec. Instead current UTC time will be passed to duckling. Error: invalid literal for int() with base 10: 'c1f48ac98a26479687b85d9aa9e1c2ec'
Lets do this
Lets do this
Lets do this
2019-09-03 21:18:22 ERROR    asyncio  - Task exception was never retrieved
future: <Task finished coro=<configure_app.<locals>.run_cmdline_io() done, defined at c:\users\tomas\anaconda3\envs\eqs_chatbot\lib\site-packages\rasa\core\run.py:122> exception=TimeoutError()>
Traceback (most recent call last):
  File "c:\users\tomas\anaconda3\envs\eqs_chatbot\lib\site-packages\rasa\core\run.py", line 126, in run_cmdline_io
    server_url=constants.DEFAULT_SERVER_FORMAT.format(port)
  File "c:\users\tomas\anaconda3\envs\eqs_chatbot\lib\site-packages\rasa\core\channels\console.py", line 138, in record_messages
    async for response in bot_responses:
  File "c:\users\tomas\anaconda3\envs\eqs_chatbot\lib\site-packages\async_generator\_impl.py", line 366, in step
    return await ANextIter(self._it, start_fn, *args)
  File "c:\users\tomas\anaconda3\envs\eqs_chatbot\lib\site-packages\async_generator\_impl.py", line 205, in throw
    return self._invoke(self._it.throw, type, value, traceback)
  File "c:\users\tomas\anaconda3\envs\eqs_chatbot\lib\site-packages\async_generator\_impl.py", line 209, in _invoke
    result = fn(*args)
  File "c:\users\tomas\anaconda3\envs\eqs_chatbot\lib\site-packages\rasa\core\channels\console.py", line 103, in send_message_receive_stream
    async for line in resp.content:
  File "c:\users\tomas\anaconda3\envs\eqs_chatbot\lib\site-packages\aiohttp\streams.py", line 40, in __anext__  
    rv = await self.read_func()
  File "c:\users\tomas\anaconda3\envs\eqs_chatbot\lib\site-packages\aiohttp\streams.py", line 329, in readline  
    await self._wait('readline')
  File "c:\users\tomas\anaconda3\envs\eqs_chatbot\lib\site-packages\aiohttp\streams.py", line 297, in _wait     
    await waiter
  File "c:\users\tomas\anaconda3\envs\eqs_chatbot\lib\site-packages\aiohttp\helpers.py", line 585, in __exit__  
    raise asyncio.TimeoutError from None
concurrent.futures._base.TimeoutError

Rasa SDK output (if needed):

2019-09-03 21:16:20 INFO     rasa_sdk.endpoint  - Action endpoint is up and running. on ('0.0.0.0', 5055)       
2019-09-03 21:18:16 DEBUG    rasa_sdk.executor  - Received request to run 
2019-09-03 21:18:16 DEBUG    rasa_sdk.executor  - Finished running 'action_search_start_print_utter'
127.0.0.1 - - [2019-09-03 21:18:16] "POST /webhook HTTP/1.1" 200 200 0.032939
2019-09-03 21:18:18 DEBUG    rasa_sdk.executor  - Received request to run 
2019-09-03 21:18:18 DEBUG    rasa_sdk.executor  - Finished running 'action_search_start_print_utter'
127.0.0.1 - - [2019-09-03 21:18:18] "POST /webhook HTTP/1.1" 200 200 0.019048
2019-09-03 21:18:20 DEBUG    rasa_sdk.executor  - Received request to run 
2019-09-03 21:18:20 DEBUG    rasa_sdk.executor  - Finished running 'action_search_start_print_utter'
127.0.0.1 - - [2019-09-03 21:18:20] "POST /webhook HTTP/1.1" 200 200 0.018976
2019-09-03 21:18:22 DEBUG    rasa_sdk.executor  - Received request to run 
2019-09-03 21:18:22 DEBUG    rasa_sdk.executor  - Finished running 'action_search_start_print_utter'
127.0.0.1 - - [2019-09-03 21:18:22] "POST /webhook HTTP/1.1" 200 200 0.014997
2019-09-03 21:18:24 DEBUG    rasa_sdk.executor  - Received request to run 
2019-09-03 21:18:24 DEBUG    rasa_sdk.executor  - Finished running 'action_search_start_print_utter'
127.0.0.1 - - [2019-09-03 21:18:24] "POST /webhook HTTP/1.1" 200 200 0.008981

[tocosastalo]

When I change story to:

## FULL 1b
* want_search
    - utter_lets_do_it
    - utter_lets_do_it
    - utter_lets_do_it
    - utter_lets_do_it    
    - utter_lets_do_it

and don't use custom actions, it works properly:

2019-09-03 21:45:21 INFO     root  - Connecting to channel 'cmdline' which was specified by the '--connector' argument. Any other channels will be ignored. To connect to all given channels, omit the '--connector' argument.  
2019-09-03 21:45:21 INFO     root  - Starting Rasa server on http://localhost:4444
Bot loaded. Type a message and press enter (use '/stop' to exit): 
Your input ->  neco hledam                                                                                      

2019-09-03 21:45:28 WARNING  root  - Could not parse timestamp 2eaa916a3aa74cbb99dbfd18e1cfbd6c. Instead current UTC time will be passed to duckling. Error: invalid literal for int() with base 10: '2eaa916a3aa74cbb99dbfd18e1cfbd6c'
Lets do this
Lets do this
Lets do this
Lets do this
Lets do this
Your input ->     

[tocosastalo]

Original story and using run command (which starts socket channel):

rasa run --credentials credentials.yml --endpoints endpoints.yml --log-file logs/out.log

it also works properly.

There is probably problem between rasa sdk and shell.

[sara-tagger]

Thanks for raising this issue, @msamogh will get back to you about it soon✨

Please also check out the docs and the forum in case your issue was raised there too 🤗

[msamogh]

It looks like it could be a bug.

[wochinge]

@msamogh Did you manage to reproduce it? Could you please label the issue accordingly?

[wochinge]

@msamogh What's the state on this? Could you reproduce it?

[msamogh]

@wochinge No, I was not able to reproduce this with this example, but I remember experiencing it when using pdb to debug my Rasa code, and if I lingered for too long in the middle of the code responsible for communicating with the action server, I would get this TimeoutError.

[wochinge]

and if I lingered for too long in the middle of the code responsible for communicating with the action server, I would get this TimeoutError.

well, that also makes sense right? 😄

[msamogh]

Okay I wasn't sure if that was expected behavior. If it is, then no, I was not able to reproduce this.

[wochinge]

Ah, I think it found the problem. @tocosastalo Could it be that these 5 actions run for longer than 10 seconds? Then there is indeed a timeout which is triggered. We could set that higher, but not sure how relevant that is since a bot should respond in < 10 seconds? That's the part in the code which causes the behavior

rasa/rasa/core/channels/console.py

Line 20 in 7a2b7c2

DEFAULT_STREAM_READING_TIMEOUT_IN_SECONDS = 10

[tocosastalo]

@wochinge yes you are right. Timeout is triggered after 10 seconds.

I am using several actions in a sequence in specific cases (for example, if I need to differentiate whether the user has done this intent before (and ask whether use previous result) or whether slots in action have been set, ...):

### Happy 1
* want_search OR enter_search_query 
    - action_preserve_search_slots
    - action_check_last_search
    - slot{"has_last_search": false}
    - action_fill_preserved_search_slots    
    - action_search_start_print_utter
    - search_query_form
    - form{"name": "search_query_form"}
    - form{"name": null}
    - action_fetch_keyword_suggestions
    - action_ask_more_keywords_mode
> check_asked_more_keywords_mode

But I don't mind, because it looks like it works in another channel (I use console channel only for debugging).

[wochinge]

@tocosastalo But did you check the runtime of your actions? If 5 actions take 10 seconds, then it's also quite bad for the users with the other channels and I'd suggest checking if you can make that somehow more efficient.

[tocosastalo]

I would say that generally run mode takes the same action less time than in shell mode in my environment. So users of other channels are not very affected.

Returning to the beginning of the issue, the action was as simple as it could have been - it utters one text-only template:

class ActionSearchStartPrintUtter(Action):
    def name(self):
        return "action_search_start_print_utter"

    def run(self, dispatcher, tracker, domain):
        dispatcher.utter_template("utter_lets_do_it", tracker)
        return []

Story was also very simple:

* want_search
    - action_search_start_print_utter
    - action_search_start_print_utter
    - action_search_start_print_utter
    - action_search_start_print_utter    
    - action_search_start_print_utter

And it hit the timeout limit in shell mode. In run mode it is done in 1 second. I thought it was a bug, but it would be a problem on my side. I think we can close this.

[ShaunHolt]

I'm having same issue using shell. So should I ignore shell and just use run for testing?

[wochinge]

@ShaunHolt This is related to #4606 . There will be fix in the next release #5686

[ShaunHolt]

Thank you. I am enjoying Rasa.  A wonderful learning experience.  Get Outlook for Android On Mon, Apr 27, 2020 at 2:52 AM -0400, "Tobias Wochinger" <notifications@github.com> wrote: @ShaunHolt This is related to #4606 . There will be fix in the next release #5686 — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or unsubscribe.