Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Error when starting R console after launching Positron #5910

Open
strengejacke opened this issue Jan 8, 2025 · 11 comments
Open

Error when starting R console after launching Positron #5910

strengejacke opened this issue Jan 8, 2025 · 11 comments
Labels
area: core Issues related to Core category. area:kallichore Issues related to the new kernel supervisor bug Something isn't working support
Milestone
Future

Comments

@strengejacke
Copy link

System details:

Positron and OS details:

Positron Version: 2025.01.0 (system setup) build 152
Code - OSS Version: 1.95.0
Commit: 66aa3fb
Date: 2025-01-06T02:53:20.465Z
Electron: 32.2.1
Chromium: 128.0.6613.186
Node.js: 20.18.0
V8: 12.8.374.38-electron.0
OS: Windows_NT x64 10.0.26100

Interpreter details:

R 4.4.2

Describe the issue:

When I started Positron, the R console did not launch and I got following error:

Image

The "restart" button did not work, but I could shut down and restart the R console then.
@juliasilge
Copy link
Contributor

Related to #5337

Have you seen this error only once? Or multiple times?

Are you able to share the logs from the "Kernel Supervisor"? Like here:

Image

@juliasilge juliasilge mentioned this issue Jan 8, 2025
Open
@juliasilge juliasilge added the info needed Waiting on information label Jan 8, 2025
@strengejacke
Copy link
Author

Only once. Will report the output from the logs when I see it again

@e-kotov
Copy link

e-kotov commented Jan 8, 2025 •
edited
Loading

If that helps, here's what I get on a Windows machine:

That's me starting Positron and trying to restart R kernel twice:

R 4.4.0 starting.
Kallichore server did not start after 4653ms

R 4.4.0 restarting.
Kallichore server did not start after 3409ms

R 4.4.0 restarting.
Kallichore server did not start after 4311ms

That's what's going on in the output:

2025-01-08 19:47:02.885 [info] Positron Kernel Supervisor activated
2025-01-08 19:47:02.885 [info] Starting Kallichore server c:\Users\user1\AppData\Local\Programs\Positron\resources\app\extensions\positron-supervisor\resources\kallichore\kcserver.exe on port 42983
Waiting for Kallichore server to start (attempt 1, 3633ms)
Waiting for Kallichore server to start (attempt 6, 3904ms)
Waiting for Kallichore server to start (attempt 11, 4171ms)
Waiting for Kallichore server to start (attempt 16, 4438ms)
Kallichore server did not start after 4653ms
Failed to start Kallichore server: Error: Kallichore server did not start after 4653ms
Starting Kallichore server c:\Users\user1\AppData\Local\Programs\Positron\resources\app\extensions\positron-supervisor\resources\kallichore\kcserver.exe on port 61669
Waiting for Kallichore server to start (attempt 1, 2401ms)
Waiting for Kallichore server to start (attempt 6, 2666ms)
Waiting for Kallichore server to start (attempt 11, 2931ms)
Waiting for Kallichore server to start (attempt 16, 3196ms)
Kallichore server did not start after 3409ms
Starting Kallichore server c:\Users\user1\AppData\Local\Programs\Positron\resources\app\extensions\positron-supervisor\resources\kallichore\kcserver.exe on port 43275
Waiting for Kallichore server to start (attempt 1, 3308ms)
Waiting for Kallichore server to start (attempt 6, 3571ms)
Waiting for Kallichore server to start (attempt 11, 3835ms)
Waiting for Kallichore server to start (attempt 16, 4101ms)
Kallichore server did not start after 4311ms

That's on build

Positron Version: 2025.01.0 (user setup) build 39
Code - OSS Version: 1.93.0
Commit: c7ef34fc7078ac7ecf13ff3328605dfba93f3eea
Date: 2024-12-09T02:49:42.315Z
Electron: 30.4.0
Chromium: 124.0.6367.243
Node.js: 20.15.1
V8: 12.4.254.20-electron.0
OS: Windows_NT x64 10.0.17763

UPDTE: in this build, kcserver.exe is NOT quarantined by F-Secure/WithSecure.

With the latest 2025.01.0 (system setup) build 152 I get the #5905 .
UPDATE: In this build kcserver.exe is quarantined by F-Secure/WithSecure.

@juliasilge juliasilge added bug Something isn't working area: core Issues related to Core category. support area:kallichore Issues related to the new kernel supervisor and removed info needed Waiting on information labels Jan 9, 2025
@e-kotov e-kotov mentioned this issue Jan 10, 2025
Open
@ntluong95
Copy link

It sometimes also happen to me, both with R or Python console

@e-kotov
Copy link

e-kotov commented Jan 10, 2025

Latest Windows build (2025.01.0-159) - server is not quarantined by antivirus (as in #5905), but the server does not start on Microsoft Windows Server Version 1809 (OS Build 17763.6659).

Console:

R 4.4.0 starting.
Kallichore server did not start after 3743ms

R 4.4.0 restarting.
Kallichore server did not start after 4138ms

R 4.4.0 restarting.
Kallichore server did not start after 3469ms

Output log

2025-01-10 11:36:36.684 [info] Positron Kernel Supervisor activated
2025-01-10 11:36:36.684 [info] Starting Kallichore server c:\Users\user1\AppData\Local\Programs\Positron\resources\app\extensions\positron-supervisor\resources\kallichore\kcserver.exe on port 63488
Waiting for Kallichore server to start (attempt 1, 2731ms)
Waiting for Kallichore server to start (attempt 6, 2996ms)
Waiting for Kallichore server to start (attempt 11, 3262ms)
Waiting for Kallichore server to start (attempt 16, 3528ms)
Kallichore server did not start after 3743ms
Failed to start Kallichore server: Error: Kallichore server did not start after 3743ms
Starting Kallichore server c:\Users\user1\AppData\Local\Programs\Positron\resources\app\extensions\positron-supervisor\resources\kallichore\kcserver.exe on port 55710
Waiting for Kallichore server to start (attempt 1, 3089ms)
Waiting for Kallichore server to start (attempt 6, 3366ms)
Waiting for Kallichore server to start (attempt 11, 3660ms)
Waiting for Kallichore server to start (attempt 16, 3923ms)
Kallichore server did not start after 4138ms
Starting Kallichore server c:\Users\user1\AppData\Local\Programs\Positron\resources\app\extensions\positron-supervisor\resources\kallichore\kcserver.exe on port 59247
Waiting for Kallichore server to start (attempt 1, 2385ms)
Waiting for Kallichore server to start (attempt 6, 2662ms)
Waiting for Kallichore server to start (attempt 11, 2961ms)
Waiting for Kallichore server to start (attempt 16, 3258ms)
Kallichore server did not start after 3469ms

But running the kcserver.exe manually gets me this:

Image

So I guess it is able to run...

Let me know if you need anything else to debug this.

@juliasilge
Copy link
Contributor

If we get more reports of this, we can try out #5800 as an option to mitigate these kinds of challenges with Windows machine configuration.

@juliasilge juliasilge added this to the Future milestone Jan 15, 2025
@strengejacke
Copy link
Author

I have similar problems with Kallichore on Windows. On my laptop, there was a security note. On my PC at home and office, no security alert, but same problem: Kallichore did not start.

@andrewheiss
Copy link

This just happened to me on macOS, with this error:

R 4.4.2 reconnected.

Kallichore server did not start after 1213ms

This appeared in Positron's error/message dialog:

The terminal process "/Applications/Positron.app/Contents/Resources/app/extensions/positron-supervisor/resources/kallichore/kcserver '--port', '59824', '--token', '/var/folders/17/g3pw3lvj2h30gwm67tbtx98c0000gn/T/kallichore-54e8bd80.token', '--log-level', 'debug', '--log-file', '/var/folders/17/g3pw3lvj2h30gwm67tbtx98c0000gn/T/kallichore-54e8bd80.log'" failed to launch (exit code: 1).
Image

I'm using this version of Positron:

Positron Version: 2025.01.0 (Universal) build 39
Code - OSS Version: 1.93.0
Commit: c7ef34fc7078ac7ecf13ff3328605dfba93f3eea
Date: 2024-12-09T02:49:50.608Z
Electron: 30.4.0
Chromium: 124.0.6367.243
Node.js: 20.15.1
V8: 12.4.254.20-electron.0
OS: Darwin arm64 24.2.0

@jmcphers
Copy link
Collaborator

@andrewheiss Can you share your supervisor output logs? You'll find them under the Output tab in the Panel > choose Kernel Supervisor from the channel list.

@andrewheiss
Copy link

Yep! I can't recreate the timeout again—I don't know how that happened, and it's only happened a couple times, but I am getting a 404 error every time I start an R session, but R ends up working fine:

Image

idk if that's related to the timeout and it might be a different issue. The 404 error does show up in the output log:

Kernel supervisor logs 
2025-01-16 18:45:10.211 [info] Positron Kernel Supervisor activated
2025-01-16 18:45:10.211 [info] Kallichore server PID 32359 is not running
2025-01-16 18:45:10.211 [info] Could not reconnect to Kallichore server at http://localhost:43516. Starting a new server
2025-01-16 18:45:10.211 [info] Starting Kallichore server /Applications/Positron.app/Contents/Resources/app/extensions/positron-supervisor/resources/kallichore/kcserver on port 62599
Waiting for Kallichore server to start (attempt 1, 113ms)
Kallichore 0.1.21 server online with 0 sessions
Kallichore server started in 166ms
Streaming Kallichore server logs from /var/folders/17/g3pw3lvj2h30gwm67tbtx98c0000gn/T/kallichore-e1f94a38.log (log level: debug)
23:45:10 [INFO] Starting Kallichore server at 127.0.0.1:62599
Failed to reconnect to session r-1d0faa03: HTTP 404. 
Creating session: {"sessionId":"r-e8ad9198","sessionName":"R 4.4.2","sessionMode":"console","createdTimestamp":1737071110362,"startReason":"Affiliated r runtime for workspace"}
23:45:10 [INFO] get_session("r-1d0faa03") - X-Span-ID: "08c2810b-790f-4b48-b66a-515d1f44cf27"
23:45:10 [INFO] new_session("r-e8ad9198") - X-Span-ID: "21314ecf-e2a0-4f4a-a70d-031521947038"
23:45:10 [DEBUG] (4) kcserver::server: Created connection file for session r-e8ad9198 at "/var/folders/17/g3pw3lvj2h30gwm67tbtx98c0000gn/T/connection_r-e8ad9198.json"
23:45:10 [DEBUG] (4) kcserver::server: Created log file for session r-e8ad9198 at "/var/folders/17/g3pw3lvj2h30gwm67tbtx98c0000gn/T/kernel_log_r-e8ad9198.txt"
23:45:10 [INFO] start_session("r-e8ad9198") - X-Span-ID: "2fa87a9d-4fd2-4b8c-8d74-0fa43d4fa87a"
23:45:10 [DEBUG] (4) kcserver::kernel_state: [session r-e8ad9198] status 'idle' => 'starting' (start API called)
23:45:10 [DEBUG] (4) kcserver::kernel_session: Starting kernel for session r-e8ad9198: ["/Applications/Positron.app/Contents/Resources/app/extensions/positron-r/resources/ark/ark", "--connection_file", "/var/folders/17/g3pw3lvj2h30gwm67tbtx98c0000gn/T/connection_r-e8ad9198.json", "--log", "/var/folders/17/g3pw3lvj2h30gwm67tbtx98c0000gn/T/kernel-opnJhp/kernel.log", "--startup-file", "/Applications/Positron.app/Contents/Resources/app/extensions/positron-r/resources/scripts/startup.R", "--session-mode", "console", "--", "--interactive", "--no-restore-data", "--quiet"]
23:45:10 [DEBUG] (10) kcserver::kernel_session: End of output stream (kind: Stderr)
23:45:10 [DEBUG] (11) kcserver::kernel_session: End of output stream (kind: Stdout)
23:45:11 [DEBUG] (4) kcserver::kernel_session: [session r-e8ad9198] All ZeroMQ sockets connected successfully
23:45:11 [DEBUG] (4) kcserver::zmq_ws_proxy: [session r-e8ad9198] Starting ZeroMQ-WebSocket proxy
23:45:11 [DEBUG] (4) kcserver::zmq_ws_proxy: [session r-e8ad9198] Forward from 'IOPub' to WebSocket: status
23:45:11 [INFO] [session r-e8ad9198] Connected to heartbeat socket at tcp://127.0.0.1:20023.
23:45:11 [DEBUG] (4) kcserver::kernel_state: [session r-e8ad9198] status 'starting' => 'busy' (kernel_info_request)
23:45:11 [DEBUG] (4) kcserver::zmq_ws_proxy: [session r-e8ad9198] Forward from 'IOPub' to WebSocket: status
23:45:11 [DEBUG] (4) kcserver::kernel_state: [session r-e8ad9198] status 'busy' => 'idle' (kernel_info_request)
23:45:11 [DEBUG] (11) kallichore_api::server: channels_websocket_request for session 'r-e8ad9198'
23:45:11 [DEBUG] (11) kcserver::server: Upgrading channel connection to websocket for session 'r-e8ad9198'
23:45:11 [DEBUG] (11) kcserver::server: Creating session for websocket connection
23:45:11 [DEBUG] (11) kcserver::server: Connection upgraded to websocket for session 'r-e8ad9198'
23:45:11 [INFO] [client r-e8ad9198-0] Connecting to websocket
23:45:11 [INFO] [client r-e8ad9198-0] Got message 7edbdab31a of type comm_info_request; sending to Jupyter socket Shell
23:45:11 [DEBUG] (4) kcserver::zmq_ws_proxy: [session r-e8ad9198] Forward from 'Shell' to WebSocket: comm_info_reply
23:45:11 [DEBUG] (4) kcserver::zmq_ws_proxy: [session r-e8ad9198] Forward from 'IOPub' to WebSocket: status
23:45:11 [DEBUG] (4) kcserver::kernel_state: [session r-e8ad9198] status 'idle' => 'busy' (comm_info_request)
23:45:11 [DEBUG] (4) kcserver::zmq_ws_proxy: [session r-e8ad9198] Forward from 'IOPub' to WebSocket: status
23:45:11 [DEBUG] (4) kcserver::kernel_state: [session r-e8ad9198] status 'busy' => 'idle' (comm_info_request)
23:45:11 [INFO] [client r-e8ad9198-0] Got message 1519f538c6 of type comm_open; sending to Jupyter socket Shell
23:45:11 [INFO] [client r-e8ad9198-0] Got message 7e04643cc3 of type comm_open; sending to Jupyter socket Shell
23:45:11 [DEBUG] (10) kcserver::zmq_ws_proxy: [session r-e8ad9198] Forward from 'IOPub' to WebSocket: status
23:45:11 [DEBUG] (10) kcserver::kernel_state: [session r-e8ad9198] status 'idle' => 'busy' (comm_open)
23:45:11 [INFO] [client r-e8ad9198-0] Got message 7139103449 of type comm_info_request; sending to Jupyter socket Shell
23:45:11 [INFO] [client r-e8ad9198-0] Got message b80c2b6e62 of type comm_open; sending to Jupyter socket Shell
23:45:11 [INFO] [client r-e8ad9198-0] Got message f86656753c of type comm_open; sending to Jupyter socket Shell
23:45:11 [INFO] [client r-e8ad9198-0] Got message c6b7261f44 of type comm_open; sending to Jupyter socket Shell
23:45:11 [INFO] [client r-e8ad9198-0] Got message ed87d897ad of type comm_info_request; sending to Jupyter socket Shell
23:45:11 [INFO] [client r-e8ad9198-0] Got message ed7abf8c94 of type comm_info_request; sending to Jupyter socket Shell
23:45:13 [DEBUG] (10) kcserver::zmq_ws_proxy: [session r-e8ad9198] Forward from 'Shell' to WebSocket: comm_info_reply
23:45:13 [DEBUG] (10) kcserver::zmq_ws_proxy: [session r-e8ad9198] Forward from 'IOPub' to WebSocket: status
23:45:13 [DEBUG] (10) kcserver::kernel_state: [session r-e8ad9198] status 'busy' => 'idle' (comm_open)
23:45:13 [DEBUG] (10) kcserver::zmq_ws_proxy: [session r-e8ad9198] Forward from 'IOPub' to WebSocket: status
23:45:13 [DEBUG] (10) kcserver::kernel_state: [session r-e8ad9198] status 'idle' => 'busy' (comm_open)
23:45:13 [DEBUG] (10) kcserver::zmq_ws_proxy: [session r-e8ad9198] Forward from 'IOPub' to WebSocket: status
23:45:13 [DEBUG] (10) kcserver::kernel_state: [session r-e8ad9198] status 'busy' => 'idle' (comm_open)
23:45:13 [DEBUG] (10) kcserver::zmq_ws_proxy: [session r-e8ad9198] Forward from 'IOPub' to WebSocket: status
23:45:13 [DEBUG] (10) kcserver::kernel_state: [session r-e8ad9198] status 'idle' => 'busy' (comm_info_request)
23:45:13 [DEBUG] (10) kcserver::zmq_ws_proxy: [session r-e8ad9198] Forward from 'IOPub' to WebSocket: status
23:45:13 [DEBUG] (10) kcserver::kernel_state: [session r-e8ad9198] status 'busy' => 'idle' (comm_info_request)
23:45:13 [DEBUG] (10) kcserver::zmq_ws_proxy: [session r-e8ad9198] Forward from 'IOPub' to WebSocket: status
23:45:13 [DEBUG] (10) kcserver::kernel_state: [session r-e8ad9198] status 'idle' => 'busy' (comm_open)
23:45:13 [INFO] [client r-e8ad9198-0] Got message 27f8f24e of type comm_msg; sending to Jupyter socket Shell
23:45:13 [INFO] [client r-e8ad9198-0] Got message 3e3c15e97c of type comm_open; sending to Jupyter socket Shell
23:45:13 [DEBUG] (10) kcserver::zmq_ws_proxy: [session r-e8ad9198] Forward from 'IOPub' to WebSocket: comm_msg
23:45:13 [DEBUG] (10) kcserver::zmq_ws_proxy: [session r-e8ad9198] Forward from 'IOPub' to WebSocket: comm_msg
23:45:13 [DEBUG] (10) kcserver::zmq_ws_proxy: [session r-e8ad9198] Forward from 'IOPub' to WebSocket: comm_msg
23:45:13 [DEBUG] (10) kcserver::zmq_ws_proxy: [session r-e8ad9198] Forward from 'IOPub' to WebSocket: status
23:45:13 [DEBUG] (10) kcserver::kernel_state: [session r-e8ad9198] status 'busy' => 'idle' (comm_open)
23:45:13 [DEBUG] (10) kcserver::zmq_ws_proxy: [session r-e8ad9198] Forward from 'Shell' to WebSocket: comm_info_reply
23:45:13 [DEBUG] (10) kcserver::zmq_ws_proxy: [session r-e8ad9198] Forward from 'Shell' to WebSocket: comm_info_reply
23:45:13 [DEBUG] (10) kcserver::zmq_ws_proxy: [session r-e8ad9198] Forward from 'IOPub' to WebSocket: status
23:45:13 [DEBUG] (10) kcserver::kernel_state: [session r-e8ad9198] status 'idle' => 'busy' (comm_open)
23:45:13 [DEBUG] (10) kcserver::zmq_ws_proxy: [session r-e8ad9198] Forward from 'IOPub' to WebSocket: status
23:45:13 [DEBUG] (10) kcserver::kernel_state: [session r-e8ad9198] status 'busy' => 'idle' (comm_open)
23:45:13 [DEBUG] (10) kcserver::zmq_ws_proxy: [session r-e8ad9198] Forward from 'IOPub' to WebSocket: comm_msg
23:45:13 [DEBUG] (10) kcserver::zmq_ws_proxy: [session r-e8ad9198] Forward from 'IOPub' to WebSocket: status
23:45:13 [DEBUG] (10) kcserver::kernel_state: [session r-e8ad9198] status 'idle' => 'busy' (comm_open)
23:45:13 [DEBUG] (10) kcserver::zmq_ws_proxy: [session r-e8ad9198] Forward from 'IOPub' to WebSocket: status
23:45:13 [DEBUG] (10) kcserver::kernel_state: [session r-e8ad9198] status 'busy' => 'idle' (comm_open)
23:45:13 [DEBUG] (10) kcserver::zmq_ws_proxy: [session r-e8ad9198] Forward from 'IOPub' to WebSocket: comm_msg
23:45:13 [DEBUG] (10) kcserver::zmq_ws_proxy: [session r-e8ad9198] Forward from 'IOPub' to WebSocket: status
23:45:13 [DEBUG] (10) kcserver::kernel_state: [session r-e8ad9198] status 'idle' => 'busy' (comm_info_request)
23:45:13 [DEBUG] (10) kcserver::zmq_ws_proxy: [session r-e8ad9198] Forward from 'IOPub' to WebSocket: status
23:45:13 [DEBUG] (10) kcserver::kernel_state: [session r-e8ad9198] status 'busy' => 'idle' (comm_info_request)
23:45:13 [DEBUG] (10) kcserver::zmq_ws_proxy: [session r-e8ad9198] Forward from 'IOPub' to WebSocket: status
23:45:13 [DEBUG] (10) kcserver::kernel_state: [session r-e8ad9198] status 'idle' => 'busy' (comm_info_request)
23:45:13 [DEBUG] (10) kcserver::zmq_ws_proxy: [session r-e8ad9198] Forward from 'IOPub' to WebSocket: status
23:45:13 [DEBUG] (10) kcserver::kernel_state: [session r-e8ad9198] status 'busy' => 'idle' (comm_info_request)
23:45:13 [DEBUG] (10) kcserver::zmq_ws_proxy: [session r-e8ad9198] Forward from 'IOPub' to WebSocket: status
23:45:13 [DEBUG] (10) kcserver::kernel_state: [session r-e8ad9198] status 'idle' => 'busy' (comm_msg)
23:45:13 [DEBUG] (10) kcserver::zmq_ws_proxy: [session r-e8ad9198] Forward from 'IOPub' to WebSocket: status
23:45:13 [DEBUG] (10) kcserver::kernel_state: [session r-e8ad9198] status 'busy' => 'idle' (comm_msg)
23:45:13 [DEBUG] (10) kcserver::zmq_ws_proxy: [session r-e8ad9198] Forward from 'IOPub' to WebSocket: status
23:45:13 [DEBUG] (10) kcserver::kernel_state: [session r-e8ad9198] status 'idle' => 'busy' (comm_open)
23:45:13 [INFO] [client r-e8ad9198-0] Got message 3d55f712 of type comm_msg; sending to Jupyter socket Shell
23:45:13 [DEBUG] (10) kcserver::zmq_ws_proxy: [session r-e8ad9198] Forward from 'IOPub' to WebSocket: comm_msg
23:45:13 [DEBUG] (10) kcserver::zmq_ws_proxy: [session r-e8ad9198] Forward from 'IOPub' to WebSocket: status
23:45:13 [DEBUG] (10) kcserver::kernel_state: [session r-e8ad9198] status 'busy' => 'idle' (comm_open)
23:45:13 [DEBUG] (10) kcserver::zmq_ws_proxy: [session r-e8ad9198] Forward from 'IOPub' to WebSocket: status
23:45:13 [DEBUG] (10) kcserver::kernel_state: [session r-e8ad9198] status 'idle' => 'busy' (comm_msg)
23:45:13 [DEBUG] (10) kcserver::zmq_ws_proxy: [session r-e8ad9198] Forward from 'IOPub' to WebSocket: status
23:45:13 [DEBUG] (10) kcserver::kernel_state: [session r-e8ad9198] status 'busy' => 'idle' (comm_msg)
23:45:13 [DEBUG] (10) kcserver::zmq_ws_proxy: [session r-e8ad9198] Forward from 'IOPub' to WebSocket: comm_msg
23:45:13 [DEBUG] (10) kcserver::zmq_ws_proxy: [session r-e8ad9198] Forward from 'IOPub' to WebSocket: comm_msg

@jmcphers
Copy link
Collaborator

Kallichore 0.1.21 server online with 0 sessions

This is a pretty old version of the supervisor, which might explain what you're seeing. What version of Positron are you using?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
area: core Issues related to Core category. area:kallichore Issues related to the new kernel supervisor bug Something isn't working support
Projects
None yet
Milestone
Future
Development

No branches or pull requests
6 participants
@andrewheiss @jmcphers @e-kotov @juliasilge @strengejacke @ntluong95