Timeout error appears without even 10 seconds passing

[brunoais]

I'm at commit: 78abe792f681c2ffd0b3cb813002feadba300a36 Renpy is latest stable (Ren'Py 8.2.3.24061702)

I'm in linux.

When I activate the warp functionality (Alt+Shift+E) on a line of code, it opens Ren'py and successfully connects to the server running in vscode.

However, after connecting and while still connected, the:

Timed out trying to connect to Ren'Py window. Is the socket client running?

Appears.

The logs from the autorun.py script:

renpy warp script started
connected to renpy warp socket server

Any idea what is really happening here? How can it connect successfully but cause the timeout?

[furudean]

Could you provide both the logs from the output menu please? Enable debug logging as well

[brunoais]

The logs with trace active. The path to renpy is censored for privacy reasons.

2024-07-24 10:22:29.652 [info] launch_renpy: {"file":"/path/to/renpy/testingVN/game/scripts/script-main.rpy","line":53}
2024-07-24 10:22:29.655 [debug] game root: /path/to/renpy/testingVN
2024-07-24 10:22:29.655 [info] opening new ren'py window
2024-07-24 10:22:29.655 [debug] status bar state: {"starting_processes":1,"running_processes":0,"is_follow_cursor":false}
2024-07-24 10:22:29.656 [debug] raw sdk path: /path/to/renpy/
2024-07-24 10:22:29.763 [debug] check rpe: ["/path/to/renpy/testingVN/game/renpy_warp_1.8.1254_8258a2c5bf.rpe"]
2024-07-24 10:22:30.273 [info] uninstalled rpes: ["/path/to/renpy/testingVN/game/renpy_warp_1.8.1254_8258a2c5bf.rpe"]
2024-07-24 10:22:30.291 [info] wrote rpe to /path/to/renpy/testingVN/game/renpy_warp_1.8.1254_8258a2c5bf.rpe
2024-07-24 10:22:30.300 [info] socket server listening on :40112
2024-07-24 10:22:30.318 [info] executing subshell: WARP_ENABLED='1' WARP_WS_PORT='40112' RENPY_EDIT_PY='/path/to/renpy/launcher/Visual Studio Code (System).edit.py' /path/to/renpy/renpy.sh '/path/to/renpy/testingVN' --warp scripts/script.rpy:54
2024-07-24 10:22:30.320 [info] created process 1853
2024-07-24 10:22:30.320 [debug] status bar state: {"starting_processes":1,"running_processes":1,"is_follow_cursor":false}
2024-07-24 10:22:30.320 [info] waiting for process to connect to socket
2024-07-24 10:22:30.320 [info] waiting for socket connection from renpy window...
2024-07-24 10:22:30.323 [error] timed out waiting for socket
2024-07-24 10:22:30.323 [debug] status bar state: {"starting_processes":0,"running_processes":1,"is_follow_cursor":false}
2024-07-24 10:22:30.856 [debug] child pids for 1853: []

[furudean]

I'm struggling to reproduce this. What's strange to me is that it seems to time out almost immediately, to judge from the timestamp. It's supposed to wait for a while until throwing that error message but you get it very quickly.

[brunoais]

I think I should add more debugging logs. Where can I add them to give more information? I can see where it writes the "timed out waiting for socket" and the message for the UI but I'm struggling a bit to spot the exact way everything interconnects. Maybe the type of the exception can help? It seems like it never tries to get the type of the exception.

[furudean]

I would start to look in https://github.com/furudean/vscode-renpy-warp/blob/main/src/lib/socket.ts

I think I agree that the logs are a bit lacking here, especially after this promise resolves. It's possible the server shuts down or some error is thrown and we're simply not catching it after the fact. This can probably be done with additional event listeners.

[furudean]

socket.on('error') or something similar

[brunoais]

Problem of lack of visibility is here: This exception is never logged or recorded. It's just suppressed.

With that, the issue is explained. It's looking for the pid of dash in the ppid hierarchy but it's not there. It's not there because flatpak-spawn doesn't fork and exec, instead it sends a dbus message for a delegate program outside the sandbox to do that in its stead.

I believe the pid check is designed to make sure the correct window is connected to the correct editor and it is definitely a nice system to do that.

As a workaround, I ask for permission to change additional_headers={"pid": str(os.getpid())}, so it gets the pid by default but allowed an env var to override it. I think that would be the least intrusive way. Opinions?

[furudean]

I think it can be even simpler. Instead of using the pid, we could generate a random ID and pass it to the process via an environment variable. The new process can phone back home with this and say "I'm this process you started". This will avoid having to dig through process trees and the like and will work on all platforms. It will probably be a bit faster as well.

[brunoais]

Yeah, sounds like a good possibility.

I'll try that locally and then do a PR. Another possibility could be messing with environment.txt but when I see how it's implemented... I'm not as interested. Your option with the NONCE is much better sounding.

I'll try that and then I can make a PR.

[furudean]

It's easy to pass environment variables to the process, in fact, we already do it here

https://github.com/furudean/vscode-renpy-warp/blob/e57b592ec2f33e889fe3978c56fa7dc31e5c0e99/src/lib/launch.ts#L171-L177

[brunoais]

Never mind, I got distracted with my own values for when I design these kinds of programs. It's just that I always want to make whatever I do interoperable as well as viable with other competing addons/extensions/mods, etc...

So you don't stay guessing, in this case, your extension ends up monopolize or require being the one starting renpy, otherwise, it won't run at all, even if just because the client doesn't know how to connect to the server. I have some ideas how it might be done otherwise but I'd need to test them first.

Back in topic, for the current architecture, it's just adding one entry in that add_env function call.

[furudean]

I don't dislike the idea about having the editor be able to "pick up" running processes after the RPE is installed, though it's a fair bit more technical and a pretty significant rewrite, so it sounds like a new issue.