[Spawner / ProgressAPI] only flushing events once the server is ready

JupyterHub
21

Ok i did some more reading. I wrongly assumed that in tornado all repsponse length must be known before flushing the socket so content-length header can be set.
I guess the design here is different:

  1. get() must not return until spawner has finished start() method
  2. with every new progress message it will immediately return new data throught the socket to the browser without finishing http request (headers are sent immediately) then data chunk by chunk

I guess this is the design. For some reason - due to proxy in between or changes in how tornado works this chunked responses are not working in my and @nibheis case

UPDATE:
After long debugging i’ve narrowed down the issue to the configurable-http-proxy which blocks progress API from returing chunked data properly. When accessing progress api directly through 8081 port (jhub) it works as expected.

22

OK I get that. Of course I had implemented a progress() method for testing, with debug logs to be sure it was actually called ; from what I remember during my debugging sessions, progress was called after start_transient_service() returned. I get messages, at least the default message {"progress": 0, "message": "Server requested"} - in loop when progress() throws an exception, and then another one for the final user redirection, but once again, only when my progress() fails.

23

I still not convinced about making start_transient_service command async. It is called in start() which is definitively async (looping on await asyncio.sleep(1) until the new server can be poll()ed) - and I know that my progress() is called.
I’ll do some more testing on that today if time permits.

24

Hi @lflis,
What do you mean exactly by

accessing progress api directly through 8081 port (jhub)

?

How can I test that? Well, I’ll dig a bit on my side, looks like we’re on different timezones :rofl:

25

That is very strange. Does it work when you run JupyterHub locally on your workstation without any reverse proxy? Because progress bar works out-of-the-box in most of the cases.

26

That makes sense because start_transient_service blocks the whole code execution until the command returns and the first opportunity for the progress method to execute is when it hits the await asyncio.sleep(1) line.

For instance if we you have your start_transient_service method as follows

def start_transient_service(self, command, unit, host, home_directory):
        """
        Start a systemd transient service with given paramters
        """
        <emit a progress event here saying assigning systemd unit to host>
        self._query_proxy('ASSIGN', unit, host)
        <emit a progress event here saying sshing into the host to start a systemd container>
        rc, out, err = self._run_command("/usr/bin/sudo /sbin/unfreeze_user {}; /usr/bin/sudo {}".format(home_directory, command), host, sudo = False)
        if rc == 0: 
           <emit a progress event here saying systemd container started successfully>
           return True
        self._query_proxy('REMOVE', unit, host)
        return False

If you dont make start_transient_service a co-routine, the three events that are added will be flushed only after the method returns.

27

How long do your launches usually take?

The progress API is an EventStream which is a bit like a one-way websocket. Data is sent line by line on an open connection, there is no content-length.

this jupyterhub config contains a jupyterhub_config that defines a simple spawner that spends most of start in an asyncio.sleep, and a progress method that yields an event every second.

these can be run with:

docker run --platform linux/amd64 --rm -v $PWD:/io -p 8000:8000 jupyterhub/jupyterhub-demo:3.1.1 jupyterhub -f /io/jupyterhub_config.py

(same results for latest jupyterhub 4.0.2)

and then launch the server and connect to the progress API:

python3 start-server.py

which produces the output:

2023-08-29 09:10:25,147 Starting server test-user
2023-08-29 09:10:25,439 Server test-user is pending spawn
2023-08-29 09:10:25,472 Progress 0%: Server requested
2023-08-29 09:10:25,472 Progress 10%: 0.0s...
2023-08-29 09:10:26,473 Progress 20%: 1.0s...
2023-08-29 09:10:27,475 Progress 30%: 2.0s...
2023-08-29 09:10:28,478 Progress 40%: 3.0s...
2023-08-29 09:10:29,482 Progress 50%: 4.0s...
2023-08-29 09:10:30,496 Progress 60%: 5.0s...
2023-08-29 09:10:31,504 Progress 70%: 6.0s...
2023-08-29 09:10:32,512 Progress 80%: 7.0s...
2023-08-29 09:10:33,519 Progress 90%: 8.0s...
2023-08-29 09:10:34,533 Progress 100%: 9.1s...
2023-08-29 09:10:35,369 Progress 100%: Server ready at /user/test-user/
2023-08-29 09:10:35,369 Stopping server test-user
2023-08-29 09:10:35,852 Server test-user stopped

showing that progress events are delivered immediately, even while the request to start is still outstanding.

I believe this eliminates configurable-http-proxy as the culprit, though it is still possible that nginx or another layer in between is configured in such a way as to prevent event streams from working properly. That would be unusual, as it is pretty standard for nginx to be in front and for progress to work fine.

Sharing logs (e.g. with --debug) may help. It can also help to add log lines to your start and progress methods to see where contexts change. Looking at the code above, we can at least be certain that no events will be produced during poll (which has no await) or during start_transient_service. But if you’re in the await asyncio.sleep(), then progress ought to be responsive.

It is totally reasonable to have blocking calls, as long as they always return promptly. If there’s any waiting involved, it’s likely that they should be async. But if the methods always return within e.g. 10-100ms, then you aren’t blocking the hub too much. It’s probably worth checking how long your balancer calls are blocking, because they are blocking the whole Hub. If these are the culprit, the simplest way to make them async is with a single thread via ThreadPoolExecutor.

To make any single blocking call awaitable:

with ThreadPoolExecutor(1) as pool:
    host = await asyncio.wrap_future(pool.submit(self.balancer.service_running, self.unit_name, self.ip))

or create a single-thread pool as an instance attribute to avoid recreating threads, or even create a shared pool, to use across all Spawners (probably best).

28

My environment: Rocky 8 with Python 3.9, CHP 0.3.0, JupyterHUB 4.0.2

@mahendrapaipuri the test which confirmed my suspicions was run on pure jupyterhub with nginx proxy switched off. Jupiter hub api is available on port 8081 (jhub instance) and also on port 8000 routed by configurable-http-proxy
Result:

  • 8081 works,
  • 8000 (chp) is stuck, headers are not sent. I guess CHP is buffering the response here until end of response is sent

I guess if progress was websocket based it would work fine (as terminal websockets are ok with CHP), however chunked responses for some reason are blocked here until the end of response

I will dig into CHP internals to see what is going on. I assume this must be something specific to my linux distro. I also plan to try npm implementation of CHP which i guess will be fine
I found some older test instance of JupiterHUB here where progress is working fine with CHP

29

I would suggest you to upgrade CHP. Version 0.3.0 seems a bit old. We are on version 4.5.4 right now.

30

4.5.4 is npm based implementation from your git right?
0.3.0 is the newest python based implementation
i’ll try npm then

31

:slight_smile: we are not that far away. I just sometimes work weird hours if i need to figure things out.

What i did:

  • modify spawner so it takes more time to complete spawn (ie 10 min)
  • login to the hub, press f12, set network request view and launch notebook
  • in the network debugger you will see GET request to progress api
  • use left click and copy request as curl
  • paste the curl commandline on the server where hub is running but replace host with 127.0.0.1 and port with 8000 then 8081, remember to add -N option to curl
32

Status after some more investigations.

I am still running on python 3.11 / jupyterhub 3.1.1 / nginx / configurable-http-proxy@4.5.5
What I changed in my code:

  • implemented a functional progress()
  • added 3 events for progress():
  1. when host ip is set
  2. before running the ssh command
  3. after running the ssh command
  • made start_transient_service(), service_running(), stop_service() and _run_command() methods async
  • added many debug lines (especially before yield in progress())
  • recorded the Network traffic in Chrome during spawn
  • tail -f on the hub logs

Here are my findings:

  • hub logs (debug lines from the code) show that progress() is called and loops on coming events and yields the json messages (over 3 iterations ~ 3s), as soon as the spawn process starts.
  • Chrome logs show the progress traffic with status “pending” during the spawn wait…
  • … then, when the spawn process is complete, all events are briefly displayed and user is redirected. At this moment, all 5 messages (3 from me + the default ones) appear in Chrome’s Network logs, all within 100 ms, and status is set to 200.

I also checked access.log and error.log from nginx and I saw nothing special ; the request to the progress API gets recorded (in access.log) at the end of the spawning process, when the status is set to 200 in Chrome’s network tab - which makes sense.

The conclusion is still that all progress messages are accumulating and are only flushed once, at the end of the spawning process.

33

@nibheis did you have chance to do the test with curl?
Which proxy version are you using with jupyterhub? (configurabe-http-proxy?)

34

I can confirm that problem is SOLVED by switching from python based configurable-http-proxy to npm based one.

35

Try with the config @minrk shared. Also maybe put asyncio.sleep() before and after you start the systemd container starting command. Also could you share your new code after making those changes?

@lflis Yes, we are using CHP from npm dist.

36

We’re using configurable-http-proxy@4.5.5 from npm, as stated above. Not tested with with curl yet ; but this is planned.

37

We’ve been using configurabe-http-proxy from npm since 2019 - and I still can’t have progress() working correctly.

38

Here’s the result from using @minrk 's config ; IMO, the most interesting test I did lately.

2023-08-30 10:08:57,985 Starting server test-user
2023-08-30 10:08:58,178 Server test-user is pending spawn
2023-08-30 10:08:58,199 Progress 0%: Server requested
2023-08-30 10:08:58,200 Progress 10%: 0.0s...
2023-08-30 10:08:59,204 Progress 20%: 1.0s...
2023-08-30 10:09:00,205 Progress 30%: 2.0s...
2023-08-30 10:09:01,206 Progress 40%: 3.0s...
2023-08-30 10:09:02,210 Progress 50%: 4.0s...
2023-08-30 10:09:03,211 Progress 60%: 5.0s...
2023-08-30 10:09:04,214 Progress 70%: 6.0s...
2023-08-30 10:09:05,217 Progress 80%: 7.0s...
2023-08-30 10:09:06,218 Progress 90%: 8.0s...
2023-08-30 10:09:07,221 Progress 100%: 9.0s...
2023-08-30 10:09:08,225 Progress 110%: 10.0s...
2023-08-30 10:09:09,228 Progress 120%: 11.0s...
2023-08-30 10:09:10,232 Progress 130%: 12.0s...
2023-08-30 10:09:11,237 Progress 140%: 13.0s...
2023-08-30 10:09:12,241 Progress 150%: 14.0s...
2023-08-30 10:09:13,245 Progress 160%: 15.0s...
2023-08-30 10:09:14,249 Progress 170%: 16.0s...
2023-08-30 10:09:15,252 Progress 180%: 17.1s...
2023-08-30 10:09:16,256 Progress 190%: 18.1s...
2023-08-30 10:09:38,537 Progress 100%: Spawn failed: Server at http://127.0.0.1:42365/user/test-user/ didn't respond in 30 seconds
Traceback (most recent call last):
  File "/etc/jupyterhub/test_progress/start_server.py", line 123, in <module>
    main()
  File "/etc/jupyterhub/test_progress/start_server.py", line 117, in main
    start_server(session, hub_url, user)
  File "/etc/jupyterhub/test_progress/start_server.py", line 79, in start_server
    raise ValueError(f"{log_name} never started!")
ValueError: test-user never started!

While it eventually fails, it shows that progress() works as expected - at least locally, connecting to the hub directly (127.0.0.1:8000).

This is what I get using the proper hub URL:

2023-08-30 10:20:37,579 Starting server test-user
2023-08-30 10:20:37,907 Server test-user is pending spawn
2023-08-30 10:21:18,252 Progress 0%: Server requested
2023-08-30 10:21:18,254 Progress 10%: 0.0s...
2023-08-30 10:21:18,254 Progress 20%: 1.0s...
2023-08-30 10:21:18,255 Progress 30%: 2.0s...
2023-08-30 10:21:18,255 Progress 40%: 3.0s...
2023-08-30 10:21:18,256 Progress 50%: 4.0s...
2023-08-30 10:21:18,256 Progress 60%: 5.0s...
2023-08-30 10:21:18,256 Progress 70%: 6.0s...
2023-08-30 10:21:18,256 Progress 80%: 7.0s...
2023-08-30 10:21:18,257 Progress 90%: 8.0s...
2023-08-30 10:21:18,257 Progress 100%: 9.0s...
2023-08-30 10:21:18,257 Progress 110%: 10.0s...
2023-08-30 10:21:18,258 Progress 120%: 11.0s...
2023-08-30 10:21:18,258 Progress 130%: 12.0s...
2023-08-30 10:21:18,258 Progress 140%: 13.0s...
2023-08-30 10:21:18,259 Progress 150%: 14.0s...
2023-08-30 10:21:18,259 Progress 160%: 15.0s...
2023-08-30 10:21:18,259 Progress 170%: 16.1s...
2023-08-30 10:21:18,259 Progress 180%: 17.1s...
2023-08-30 10:21:18,260 Progress 190%: 18.1s...
2023-08-30 10:21:18,260 Progress 100%: Spawn failed: Server at http://127.0.0.1:38097/user/test-user/ didn't respond in 30 seconds
Traceback (most recent call last):
  File "/etc/jupyterhub/test_progress/start_server_https.py", line 123, in <module>
    main()
  File "/etc/jupyterhub/test_progress/start_server_https.py", line 117, in main
    start_server(session, hub_url, user)
  File "/etc/jupyterhub/test_progress/start_server_https.py", line 79, in start_server
    raise ValueError(f"{log_name} never started!")
ValueError: test-user never started!

All progress messages appears in one shot when the spawn eventually fails. The main difference here is that start_server.py connects to the hub via nginx (nginx is proxying for the hub and managing the SSL layer)

My guess is that my nginx config is missing something that would let the progress notification go back to the user’s browser as they are generated. Am I going in the right direction?

EDIT: I have not looked into it, but I’m mostly sure the spawn fails because there are no single user server module installed on this server (it’s just a hub) - I don’t think it is relevant in this test anyway.

39

This is our nginx.conf which is working fine

server {

        listen       80 default_server;
        listen       [::]:80 default_server;
        server_name  _;
        # redirect to ssl
        return 301 https://jh93.devel.cyfronet.pl$request_uri;
       
    }

map $http_upgrade $connection_upgrade {
    default upgrade;
    ''      close;
}
upstream jupyter {
    keepalive 384; # max number of keep-alive connections
    server 127.0.0.1:8000;
}


server {



         listen       443 ssl default_server;

        server_name  _;

        ssl on;
        ssl_certificate "/etc/pki/nginx/server.pem";
        ssl_certificate_key "/etc/pki/nginx/server.key";
      
        ssl_session_cache shared:SSL:1m;
        ssl_session_timeout  10m;
        ssl_ciphers PROFILE=SYSTEM;
        ssl_prefer_server_ciphers on;
	client_max_body_size 1024M;

    
      location / {

        proxy_set_header Host $host;
        proxy_set_header X-Real-IP $remote_addr;
        proxy_http_version 1.1;
        proxy_set_header Upgrade $http_upgrade;
        proxy_set_header X-Scheme $scheme;
        proxy_buffering off;
        proxy_set_header X-Forwarded-Proto https;
        proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
	proxy_pass http://jupyter;
	proxy_set_header Connection $connection_upgrade;

    }



    error_page   500 502 503 504  /50x.html;
        location = /50x.html {
            root   /usr/share/nginx/html;
        }
}
40

Here is the complete solution (in my case) :

  1. Use configurable-http-proxy from npm (4.5.x) and not the Python version (0.3.0 from pypi) - as reported by @lflis .
  2. In nginx’s proxy configuration, add proxy_buffering off; to enable chunk response transfer (see git - Enabling nginx Chunked Transfer Encoding - Server Fault)

So, in the end, nothing wrong with my spawner - still I got the opportunity to improve it a lot (more async methods, etc.), thanks to your valuable inputs. Thank you everyone :grinning: