Help server sometimes throws 502s when requesting help in fresh positron session

[nstrayer]

This bug is frustratingly hard to reproduce and seems to affect windows users.

Positron Version: 2024.06.0 (system setup) build 2024.06.0-770
Code - OSS Version: 1.90.0
Commit: 5d79ea68dceb5b734475af851b64cb3c0a323285
Date: 2024-06-14T05:20:19.073Z
Electron: 29.4.0
Chromium: 122.0.6261.156
Node.js: 20.9.0
V8: 12.2.281.27-electron.0
OS: Windows_NT x64 10.0.22631

Sometimes (although not every time) when Positron has been recently started up and a help issue is requested, seemingly from R exclusively, the help pane simply doesn't show anything. When looking at the developer logs there are 502 bad gateway errors for the requested help documentation.
This can be fixed by restarting the R interpreter from the dropdown menu. Another method of fixing is to switch to python and request something from help there, then go back to R.

I can't reproduce this on a mac.

[juliasilge]

Reported in #5604 by a Windows user

Related to #3753, for which we added retries that seem to have reduced the problem

Note

If you as a user continue to see problems (or see different kinds of problems), what is helpful is to change the R kernel log level to trace and share the logs from the R Console attached as a file to an issue.

[HenningLorenzen-ext-bayer]

Details on #5604

• Python help does work
• R help will not show up, even after restarting R or switching to Python and invoking Python help
• I have epxerience this on one specific machine, not on other one so far. Maybe a timing / performance issue?
• log

[juliasilge]

Those kernel logs are really helpful; thank you @HenningLorenzen-ext-bayer!

When I do a successful R help call, I see logs about handling the URL like:

[R]   2024-12-06T21:21:30.523462Z TRACE  Help is handling URL
[R]     at crates/ark/src/browser.rs:44
[R]     in browseURL with url: http://127.0.0.1:14192/library/base/html/data.frame.html
[R] 
[R]   2024-12-06T21:21:30.523518Z  INFO  Sending message to UI comm: Event(Busy(BusyParams { busy: false }))
[R]     at crates/ark/src/ui/sender.rs:50
[R] 
[R]   2024-12-06T21:21:30.523527Z TRACE  ShowHelpUrl(
[R]     ShowHelpUrlParams {
[R]         url: "http://127.0.0.1:14192/library/base/html/data.frame.html",
[R]     },
[R] )
[R]     at crates/ark/src/help/r_help.rs:175
[R]     in handle_event with ShowHelpUrl
[R] 
[R]   2024-12-06T21:21:30.523544Z TRACE  prompt_info(): n_frame = '0'
[R]     at crates/ark/src/interface.rs:847
[R] 
[R]   2024-12-06T21:21:30.523542Z TRACE  Sending frontend event `ShowHelp` with R url 'http://127.0.0.1:14192/library/base/html/data.frame.html' and proxy url 'http://127.0.0.1:53921/library/base/html/data.frame.html'
[R]     at crates/ark/src/help/r_help.rs:200
[R]     in handle_event with ShowHelpUrl

I see the same types of logging in @HenningLorenzen-ext-bayer's log. ✅

Then a little later in the logs, I see messages about proxying the various assets:

[R]   2024-12-06T21:21:30.877412Z  INFO  Proxying URL '"http://localhost:14192/library/base/html/data.frame.html"' path '/library/base/html/data.frame.html' content-type is 'Some("text/html")'
[R]     at crates/ark/src/help_proxy.rs:157
[R] 
[R]   2024-12-06T21:21:31.085619Z  INFO  Proxying URL '"http://localhost:14192/doc/html/prism.css"' path '/doc/html/prism.css' content-type is 'Some("text/css")'
[R]     at crates/ark/src/help_proxy.rs:157
[R] 
[R]   2024-12-06T21:21:31.087016Z  INFO  Proxying URL '"http://localhost:14192/doc/html/katex/katex.css"' path '/doc/html/katex/katex.css' content-type is 'Some("text/css")'
[R]     at crates/ark/src/help_proxy.rs:157
[R] 
[R]   2024-12-06T21:21:31.088842Z  INFO  Proxying URL '"http://localhost:14192/doc/html/R.css"' path '/doc/html/R.css' content-type is 'Some("text/css")'
[R]     at crates/ark/src/help_proxy.rs:157
[R] 
[R]   2024-12-06T21:21:31.091076Z  INFO  Proxying URL '"http://localhost:14192/doc/html/prism.js"' path '/doc/html/prism.js' content-type is 'Some("text/javascript")'
[R]     at crates/ark/src/help_proxy.rs:157
[R] 
[R]   2024-12-06T21:21:31.092624Z  INFO  Proxying URL '"http://localhost:14192/doc/html/katex-config.js"' path '/doc/html/katex-config.js' content-type is 'Some("text/javascript")'
[R]     at crates/ark/src/help_proxy.rs:157
[R] 
[R]   2024-12-06T21:21:31.298774Z  INFO  Proxying URL '"http://localhost:14192/doc/html/katex/katex.js"' path '/doc/html/katex/katex.js' content-type is 'Some("text/javascript")'
[R]     at crates/ark/src/help_proxy.rs:157

I do NOT see messages like this in @HenningLorenzen-ext-bayer's logs. 🚫

@HenningLorenzen-ext-bayer can you confirm you don't see any messages like "Proxying URL" for assets including the CSS and HTML and such? Can you also bring up the developer tools console (via "Developer: Toggle Developer Tools") and see what you see there relevant to the Help URLs? I see messages there like:

 INFO PositronHelpService language runtime server sent show help event for: http://127.0.0.1:53921/library/base/html/data.frame.html

And no errors related to proxying or these URLs.

[HenningLorenzen-ext-bayer]

@HenningLorenzen-ext-bayer can you confirm you don't see any messages like "Proxying URL" for assets including the CSS and HTML and such?

Confirmed.

Can you also bring up the developer tools console (via "Developer: Toggle Developer Tools") and see what you see there relevant to the Help URLs? I see messages there like:

 INFO PositronHelpService language runtime server sent show help event for: http://127.0.0.1:53921/library/base/html/data.frame.html

And no errors related to proxying or these URLs.

This is an excerpt from my DevTools console:

INFO Creating positron.help client 'positron-help-r-3-471ebf7c'...
workbench.desktop.main.js:130831
INFO PositronHelpService language runtime server sent show help event for: http://127.0.0.1:49528/library/stats/html/Chisquare.html
workbench.desktop.main.js:62543
[Extension Host] [HPM] Proxy created: /  -> http://127.0.0.1:49528 (at Object.info (c:\Users\[Redacted]\AppData\Local\Programs\Positron\resources\app\out\vs\workbench\api\node\extensionHostProcess.js:64217:26))
workbench.desktop.main.js:130821
DEBUG Webview(6f8e14ea-f813-4d8a-94f7-9dcf83f40afa): will update content
workbench.desktop.main.js:334971
An iframe which has both allow-scripts and allow-same-origin for its sandbox attribute can escape its sandboxing.
mountTo @ workbench.desktop.main.js:334971
workbench.desktop.main.js:130821
DEBUG Webview(6f8e14ea-f813-4d8a-94f7-9dcf83f40afa): webview ready
Chisquare.html:1
Failed to load resource: the server responded with a status of 502 (Bad Gateway)

[sharon-wang]

@HenningLorenzen-ext-bayer Maybe we can take a closer look at the proxying, in case something is going wrong there.

Could you please try the following:

1. open up the OUTPUT view (if you're having trouble finding it, a shortcut is to run the Output: Focus on Output View command from the Command Prompt)
2. select the Positron Proxy output channel from the dropdown
3. click the gear icon to select Trace level output
4. click the clear icon to clear out any existing output
5. run ?iris or similar in the R console
6. share the Positron Proxy output with us here?

Here's a video showing these steps:

proxy_output.mp4

[HenningLorenzen-ext-bayer]

@sharon-wang

6. share the Positron Proxy output with us here?

2024-12-11 17:05:35.120 [debug] Starting a help proxy server for target: http://127.0.0.1:51380...
2024-12-11 17:05:35.124 [debug] Started proxy server at http://127.0.0.1:51420 for external URI http://127.0.0.1:51420/.
2024-12-11 17:05:35.127 [debug] Finishing proxy server setup for target http://127.0.0.1:51380
	serverOrigin: http://127.0.0.1:51420
	externalUri: http://127.0.0.1:51420/
2024-12-11 17:05:35.672 [trace] onProxyReq - proxy request http://127.0.0.1:51420/library/datasets/html/iris.html -> http://127.0.0.1:51380/library/datasets/html/iris.html
	method: GET
	protocol: http:
	host: 127.0.0.1
	url: /library/datasets/html/iris.html
	headers: {"accept-language":"en-US","accept-encoding":"gzip, deflate, br","sec-fetch-dest":"iframe","sec-fetch-mode":"navigate","sec-fetch-site":"cross-site","accept":"text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.7","user-agent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Positron/1.93.0 Chrome/124.0.6367.243 Electron/30.4.0 Safari/537.36","upgrade-insecure-requests":"1","connection":"close","host":"127.0.0.1:51380"}
	external uri: http://127.0.0.1:51420/
2024-12-11 17:05:41.249 [trace] onProxyRes - proxy response http://127.0.0.1:51380/library/datasets/html/iris.html -> http://127.0.0.1:51420/library/datasets/html/iris.html
	status: 502
	statusMessage: Bad Gateway
	headers: {"content-length":"0","connection":"close","date":"Wed, 11 Dec 2024 16:05:41 GMT"}
	external uri: http://127.0.0.1:51420/
2024-12-11 17:05:41.249 [trace] onProxyRes - skipping response processing for http://127.0.0.1:51420/library/datasets/html/iris.html

[sharon-wang]

Thank you Henning! Between the Positron Proxy output and the kernel log, I think the issue is occurring in Ark.

We're receiving a 502 Bad Gateway from Ark, which seems to be returned here. I don't think we're returning Bad Gateway due to an Error, since I'm not seeing "Error proxying" in Henning's logs. I'd be curious what response status code we're getting here which is not 200 OK. Maybe we can adding some logging in this area for visibility.

From Henning's kernel logs, it looks like Ark tried to setup the "reqwest client" with 3 retries, but then failed and returned the 502 Bad Gateway? Hard to say if we need more retries or if the client is somehow not being configured properly.

@juliasilge would someone more familiar with Ark be able to take a look at this code?

[juliasilge]

I put up posit-dev/ark#654 to add some more logging in there.