[Bug]: Blocking IO calls on Async routes

[amadolid]

Operating System

Ubuntu

Versions

Jac 0.13.5 | Python 3.12.13 | Jac-scale 0.2.13

Steps to Reproduce

We default to async routes even tho all of our IO calls uses blocking IO modules.
ByLLM also blocking
Any long blocking IO calls (ex: sleep) will hangup the server.

Expected

Proper Async Implementation

[amadolid]

Example

Prints

I have added this logs to show when it started and finished

Jac

main.Jac

import from uuid { uuid4 }
import from threading { current_thread }
import from time { sleep, time }
import os;

import from byllm.llm { Model }

glob llm = Model(model_name=os.environ.get("LLM_MODEL", "gpt-4o"));

obj TestChildNode {
    has val: str = "";
}

node TestNode {
    has id: int;
    has list_val: list = [];
    has set_val: set = set();
    has dict_val: dict = {};
    has child: TestChildNode = TestChildNode();
}

walker :pub add {

    has id: int;
    has tracker: str;

    can enter with Root entry {
        print(f"tracker {self.tracker} is running in {current_thread().name}");
        here ++> TestNode(id=self.id);
    }
}

walker :pub add_with_long_blocking_io_1 {
    has id: int;
    has tracker: str;

    def generate_10_random_words -> str by llm;

    can enter with Root entry {
        print(f"tracker {self.tracker} is running in {current_thread().name}");
        print(f"tracker {self.tracker} started to generate");
        now = time();
        _ = self.generate_10_random_words();
        print(f"tracker {self.tracker} generate for {time() - now}");
        here ++> TestNode(id=self.id);
    }
}

walker :pub add_with_long_blocking_io_2 {
    has id: int;
    has tracker: str;

    can enter with Root entry {
        print(f"tracker {self.tracker} is running in {current_thread().name}");
        print(f"tracker {self.tracker} started to sleep");
        sleep(5);
        print(f"tracker {self.tracker} slept for 5 seconds");
        here ++> TestNode(id=self.id);
    }
}

walker :pub get {

    has id: int;

    can enter with Root entry {
        visit [-->];
    }

    can enter2 with TestNode entry {
        here.id = self.id;
        report here;
    }
}

walker :pub get2 {}
walker :pub get3 {
    can enter with Root entry {
        sleep(15);
        report current_thread().name;
    }
}

walker :pub clean {
    can enter with Root entry {
        visit [-->];
    }
}

Test

test.py - (I added tracker on query params so I can print it without using await, body requires await)

from requests import post
from concurrent.futures import ThreadPoolExecutor

with ThreadPoolExecutor(max_workers=10) as exec:
    for i in range(3):
        exec.submit(post, f"http://localhost:8000/walker/add?tracker={i}", json={
            "id": i,
            "tracker": str(i)
        })
    
    for i in range(3):
        id = i + 3
        exec.submit(post, f"http://localhost:8000/walker/add_with_long_blocking_io_1?tracker={id}", json={
            "id": id,
            "tracker": str(id)
        })

    for i in range(3):
        id = i + 6
        exec.submit(post, f"http://localhost:8000/walker/add_with_long_blocking_io_2?tracker={id}", json={
            "id": id,
            "tracker": str(id)
        })

Logs

tracker 1 started: 1775977591.7063165
tracker 1 is running in MainThread
tracker 1 completed in 0.003945112228393555 seconds: 1775977591.7102616
--------------------------------------------------------
tracker 0 started: 1775977591.7118695
tracker 0 is running in MainThread
tracker 0 completed in 0.0021538734436035156 seconds: 1775977591.7140234
--------------------------------------------------------
  127.0.0.1:59078 - "POST /walker/add?tracker=1 HTTP/1.1" 200
  127.0.0.1:59088 - "POST /walker/add?tracker=0 HTTP/1.1" 200
tracker 4 started: 1775977591.72317
tracker 4 is running in MainThread
tracker 4 started to generate
15:06:31 - LiteLLM:INFO: utils.py:3995 - 
LiteLLM completion() model= gpt-5.1; provider = azure
INFO - 
LiteLLM completion() model= gpt-5.1; provider = azure
15:06:35 - LiteLLM:INFO: utils.py:1656 - Wrapper: Completed Call, calling success_handler
INFO - Wrapper: Completed Call, calling success_handler
tracker 4 generate for 3.285001039505005
tracker 4 completed in 3.2875423431396484 seconds: 1775977595.0107124
--------------------------------------------------------
tracker 5 started: 1775977595.0109563
tracker 5 is running in MainThread
tracker 5 started to generate
15:06:35 - LiteLLM:INFO: utils.py:3995 - 
LiteLLM completion() model= gpt-5.1; provider = azure
INFO - 
LiteLLM completion() model= gpt-5.1; provider = azure
15:06:36 - LiteLLM:INFO: utils.py:1656 - Wrapper: Completed Call, calling success_handler
INFO - Wrapper: Completed Call, calling success_handler
tracker 5 generate for 1.4873270988464355
tracker 5 completed in 1.4901318550109863 seconds: 1775977596.5010881
--------------------------------------------------------
tracker 2 started: 1775977596.5013404
tracker 2 is running in MainThread
tracker 2 completed in 0.0019681453704833984 seconds: 1775977596.5033085
--------------------------------------------------------
tracker 3 started: 1775977596.5034785
tracker 3 is running in MainThread
tracker 3 started to generate
15:06:36 - LiteLLM:INFO: utils.py:3995 - 
LiteLLM completion() model= gpt-5.1; provider = azure
INFO - 
LiteLLM completion() model= gpt-5.1; provider = azure
15:06:37 - LiteLLM:INFO: utils.py:1656 - Wrapper: Completed Call, calling success_handler
INFO - Wrapper: Completed Call, calling success_handler
tracker 3 generate for 1.2779717445373535
tracker 3 completed in 1.280564546585083 seconds: 1775977597.784043
--------------------------------------------------------
tracker 6 started: 1775977597.7842891
tracker 6 is running in MainThread
tracker 6 started to sleep
tracker 6 slept for 5 seconds
tracker 6 completed in 6.775551795959473 seconds: 1775977604.559841
--------------------------------------------------------
tracker 7 started: 1775977604.5601907
tracker 7 is running in MainThread
tracker 7 started to sleep
tracker 7 slept for 5 seconds
tracker 7 completed in 5.002992153167725 seconds: 1775977609.5631828
--------------------------------------------------------
  127.0.0.1:59104 - "POST /walker/add_with_long_blocking_io_1?tracker=4 HTTP/1.1" 200
  127.0.0.1:59110 - "POST /walker/add_with_long_blocking_io_1?tracker=5 HTTP/1.1" 200
  127.0.0.1:59118 - "POST /walker/add?tracker=2 HTTP/1.1" 200
  127.0.0.1:59126 - "POST /walker/add_with_long_blocking_io_1?tracker=3 HTTP/1.1" 200
  127.0.0.1:59130 - "POST /walker/add_with_long_blocking_io_2?tracker=6 HTTP/1.1" 200
  127.0.0.1:59142 - "POST /walker/add_with_long_blocking_io_2?tracker=7 HTTP/1.1" 200
tracker 8 started: 1775977609.585058
tracker 8 is running in MainThread
tracker 8 started to sleep
tracker 8 slept for 5 seconds
tracker 8 completed in 5.002724885940552 seconds: 1775977614.5877829
--------------------------------------------------------
  127.0.0.1:59154 - "POST /walker/add_with_long_blocking_io_2?tracker=8 HTTP/1.1" 200

[amadolid]

As you may see, since we are using async routes without any non-blocking modules, it can't switch context.
It was able to consume/receive the requests concurrently since in that part, it's still proper async, after that, everything is blocking.
It runs in MainThread and run requests one by one, not concurrently.

If we want to implement async routes, we MUST also implement async end to end.

• Propagate async/await
• Use non blocking io modules for IO calls

Else use sync routes or open thread manually

[amadolid]

Additional Prints

test.py with waiting logs

from requests import post
from concurrent.futures import ThreadPoolExecutor
from time import time

def run(walker, id):
    now = time()
    print(f"tracker {id} requested at {now}")
    res = post(f"http://localhost:8000/walker/{walker}?tracker={id}", json={
        "id": id,
        "tracker": str(id)
    })
    res.raise_for_status()
    print(f"tracker {id} waited for {time() - now}")


with ThreadPoolExecutor(max_workers=10) as exec:
    for i in range(3):
        exec.submit(run, "add", i)
    
    for i in range(3):
        id = i + 3
        exec.submit(run, "add_with_long_blocking_io_1", id)

    for i in range(3):
        id = i + 6
        exec.submit(run, "add_with_long_blocking_io_2", id)

App Logs

** tracker 1 received at 1776006968.278075
** tracker 0 received at 1776006968.2790449
tracker 1 started: 1776006968.2798622
tracker 1 is running in MainThread
tracker 1 completed in 0.007778167724609375 seconds: 1776006968.2876403
--------------------------------------------------------
** tracker 2 received at 1776006968.2880766
** tracker 4 received at 1776006968.288408
** tracker 3 received at 1776006968.288686
** tracker 5 received at 1776006968.2889862
  127.0.0.1:39168 - "POST /walker/add?tracker=1 HTTP/1.1" 200
tracker 0 started: 1776006968.2944682
tracker 0 is running in MainThread
tracker 0 completed in 0.0022401809692382812 seconds: 1776006968.2967083
--------------------------------------------------------
  127.0.0.1:39158 - "POST /walker/add?tracker=0 HTTP/1.1" 200
** tracker 6 received at 1776006968.3013015
** tracker 7 received at 1776006968.3017104
** tracker 8 received at 1776006968.3020487
tracker 2 started: 1776006968.302533
tracker 2 is running in MainThread
tracker 2 completed in 0.0024585723876953125 seconds: 1776006968.3049915
--------------------------------------------------------
tracker 4 started: 1776006968.3051872
tracker 4 is running in MainThread
tracker 4 started to generate
23:16:08 - LiteLLM:INFO: utils.py:3995 - 
LiteLLM completion() model= gpt-5.1; provider = azure
INFO - 
LiteLLM completion() model= gpt-5.1; provider = azure
23:16:10 - LiteLLM:INFO: utils.py:1656 - Wrapper: Completed Call, calling success_handler
INFO - Wrapper: Completed Call, calling success_handler
tracker 4 generate for 2.4508368968963623
tracker 4 completed in 2.4547488689422607 seconds: 1776006970.759936
--------------------------------------------------------
tracker 3 started: 1776006970.7601986
tracker 3 is running in MainThread
tracker 3 started to generate
23:16:10 - LiteLLM:INFO: utils.py:3995 - 
LiteLLM completion() model= gpt-5.1; provider = azure
INFO - 
LiteLLM completion() model= gpt-5.1; provider = azure
23:16:12 - LiteLLM:INFO: utils.py:1656 - Wrapper: Completed Call, calling success_handler
INFO - Wrapper: Completed Call, calling success_handler
tracker 3 generate for 1.4995980262756348
tracker 3 completed in 1.502671718597412 seconds: 1776006972.2628703
--------------------------------------------------------
tracker 5 started: 1776006972.2631228
tracker 5 is running in MainThread
tracker 5 started to generate
23:16:12 - LiteLLM:INFO: utils.py:3995 - 
LiteLLM completion() model= gpt-5.1; provider = azure
INFO - 
LiteLLM completion() model= gpt-5.1; provider = azure
23:16:13 - LiteLLM:INFO: utils.py:1656 - Wrapper: Completed Call, calling success_handler
INFO - Wrapper: Completed Call, calling success_handler
tracker 5 generate for 1.2398898601531982
tracker 5 completed in 1.2429840564727783 seconds: 1776006973.5061069
--------------------------------------------------------
  127.0.0.1:39180 - "POST /walker/add?tracker=2 HTTP/1.1" 200
  127.0.0.1:39194 - "POST /walker/add_with_long_blocking_io_1?tracker=4 HTTP/1.1" 200
  127.0.0.1:39206 - "POST /walker/add_with_long_blocking_io_1?tracker=3 HTTP/1.1" 200
  127.0.0.1:39222 - "POST /walker/add_with_long_blocking_io_1?tracker=5 HTTP/1.1" 200
tracker 6 started: 1776006973.5241413
tracker 6 is running in MainThread
tracker 6 started to sleep
tracker 6 slept for 5 seconds
tracker 6 completed in 5.004390716552734 seconds: 1776006978.528532
--------------------------------------------------------
tracker 7 started: 1776006978.5288298
tracker 7 is running in MainThread
tracker 7 started to sleep
tracker 7 slept for 5 seconds
tracker 7 completed in 5.005027532577515 seconds: 1776006983.5338573
--------------------------------------------------------
tracker 8 started: 1776006983.5341682
tracker 8 is running in MainThread
tracker 8 started to sleep
tracker 8 slept for 5 seconds
tracker 8 completed in 5.003642559051514 seconds: 1776006988.5378108
--------------------------------------------------------
  127.0.0.1:39224 - "POST /walker/add_with_long_blocking_io_2?tracker=6 HTTP/1.1" 200
  127.0.0.1:39234 - "POST /walker/add_with_long_blocking_io_2?tracker=7 HTTP/1.1" 200
  127.0.0.1:39244 - "POST /walker/add_with_long_blocking_io_2?tracker=8 HTTP/1.1" 200

Test Logs

tracker 0 requested at 1776006968.272174
tracker 1 requested at 1776006968.272602
tracker 2 requested at 1776006968.2736669
tracker 3 requested at 1776006968.2742734
tracker 4 requested at 1776006968.2750611
tracker 5 requested at 1776006968.275611
tracker 6 requested at 1776006968.276787
tracker 7 requested at 1776006968.2772126
tracker 8 requested at 1776006968.278271
tracker 1 waited for 0.024338722229003906
tracker 0 waited for 0.030243873596191406
tracker 2 waited for 5.250070333480835
tracker 4 waited for 5.248792886734009
tracker 3 waited for 5.249734878540039
tracker 5 waited for 5.248530149459839
tracker 6 waited for 20.27437973022461
tracker 7 waited for 20.274076461791992
tracker 8 waited for 20.27321696281433

---

As you may see here, requests was received concurrently. However, beyond that is blocking and causing server to hangup