tauri icon indicating copy to clipboard operation
tauri copied to clipboard

[bug] Tauri's JavaScript shell Command skips stdout lines when large amounts of data is printed

Open mauritzn opened this issue 1 year ago • 14 comments

Describe the bug

When running a command using Tauri's shell Command that returns a lot of data some lines get skipped in stdout and the process seems to keep running indefinitely in the background, preventing future Commands and also sometimes preventing the app from refreshing properly. From my testing around 20,000+ lines in stdout causes the problem appear.

Reproduction

https://github.com/mauritzn/tauri-shell-bug

This repo was made as a minimal reproduction of this bug. It includes a Python script (__print_numbers.py) which prints numbers until 250,000 numbers have been printed, it starts by printing started and ends by printing done.

The amount of numbers the Python script prints can be changed in the script, usually 20,000 is enough for the bug to appear, but I made the default 250,000 since it was still bearable and should be more than enough for the bug to appear.

I recommend running it using npm run tauri dev, this is mainly due to the automatic finding of the Python file, since it looks for it at the current execution path (feel free to change this). Running it as a built binary also works, but make sure that the __print_numbers.py file is in the same directory.

Expected behavior

Everything outputted from the CLI application ran using Command would be accessible.

Platform and versions

[✔] Environment
    - OS: Windows 10.0.22631 X64
    ✔ WebView2: 123.0.2420.65
    ✔ MSVC:
        - Visual Studio Build Tools 2022
        - Visual Studio Community 2019
    ✔ rustc: 1.77.1 (7cf61ebde 2024-03-27)
    ✔ cargo: 1.77.1 (e52e36006 2024-03-26)
    ✔ rustup: 1.27.0 (bbb9276d2 2024-03-08)
    ✔ Rust toolchain: stable-x86_64-pc-windows-msvc (default)
    - node: 20.10.0
    - npm: 10.5.0
    - bun: 1.1.0

[-] Packages
    - tauri [RUST]: 1.6.1
    - tauri-build [RUST]: 1.5.1
    - wry [RUST]: 0.24.7
    - tao [RUST]: 0.16.8
    - @tauri-apps/api [NPM]: 1.5.3
    - @tauri-apps/cli [NPM]: 1.5.11

[-] App
    - build-type: bundle
    - CSP: unset
    - distDir: ../dist
    - devPath: http://localhost:1420/
    - bundler: Vite

Stack trace

No response

Additional context

Here is a demo video of the issues that occur: https://www.youtube.com/watch?v=5XgFhfV7Luw


Expected behavior demo video: https://www.youtube.com/watch?v=tGq4u8yW4tI

This demo show that no matter how many times Command is used:

  • The app state doesn't freeze (modifying index.html / main.ts refreshes the app properly)
  • Future processes aren't halted (new processes always finish and output correctly)
  • All lines outputted to stdout are present (no missing numbers)

This is the expected behavior of Command, but this is not the behavior of Command when more than ~20,000+ lines are outputted to stdout.


Edit: Updated minimal reproduction repo to tauri 1.6.1 and the bug still occurs. Updated Platform and versions section with current information.

mauritzn avatar Aug 23 '23 18:08 mauritzn

@amrbashir Hi, sorry for the ping, I'm not sure if you are the right person to ask but I was wondering if this issue has been missed, it's already been 8 months since I first sent this issue and it still persists without any comments, sadly this bug is a blocking issue for an application I'm working on.

mauritzn avatar Apr 02 '24 19:04 mauritzn

Hey sorry for the long delay, this fell out of my radar, will see if I can get back to it soon.

amrbashir avatar Apr 02 '24 22:04 amrbashir

Had a bit of time to test this a bit and seems like the events are lost because the internal event loop proxy is full/busy handling previous events and we ignore that error hence the skipped events. I don't have a solution in mind yet and I am not sure when I can investigate further, for now I'd recommend either using Rust to do this logic.

amrbashir avatar Apr 30 '24 22:04 amrbashir

Alright well glad to know that a likely cause has been found. Now when you recommend using Rust as a way around this are you referring to something like creating a Tauri command that would handle command execution instead of relying on Tauri's built in JavaScript shell Command?

mauritzn avatar May 01 '24 02:05 mauritzn

I went ahead and created a simple workaround using invoke and Tauri's Rust commands.

I'm sure this workaround isn't perfect since my Rust knowledge is very lacking, but it does seem to work even for really large command outputs (I tested up to 10 million output lines and it worked perfectly).

Workaround branch: https://github.com/mauritzn/tauri-shell-bug/tree/invoke-workaround

TLDR main workaround details:

  • Uses invoke("print_py_numbers", { pythonScriptPath }) rather than new Command("python-test", [pythonScriptPath]).execute().
  • Runs the command directly in Rust using Command::new("python").arg(python_script_path).output(), rather than relying on Tauri's implementation.

One thing I did notice was that if you used the new Command method (the Tauri JS Command method) first and then tried to use the workaround method after it wouldn't respond, I'm guessing that the Rust-to-JS messaging channel that invoke also uses is still full/busy with the previous request? (could be completely wrong about this)

mauritzn avatar May 01 '24 03:05 mauritzn

gonna close this as duplicate of #8177 since they are the same underlying issue

amrbashir avatar May 07 '24 14:05 amrbashir

Looks like we can't fix https://github.com/tauri-apps/tauri/issues/8177 easily, so I will just fix this issue for now, try https://github.com/tauri-apps/tauri/pull/9698 and see if it fixes it for you

Also thanks for the awesome repro as always, made it much easier to debug and test changes ❤️

amrbashir avatar May 07 '24 23:05 amrbashir

I tried applying the patch to the reproduction repo, but I'm having some trouble getting it to install the patch, I keep getting:

$ cargo update
    Updating crates.io index
    Updating git repository `https://github.com/tauri-apps/tauri`
warning: skipping duplicate package `api` found at `C:\Users\<USER>\.cargo\git\checkouts\tauri-9dcc2f9152472c1a\c5b3751\examples\web\core\api`
warning: skipping duplicate package `app` found at `C:\Users\<USER>\.cargo\git\checkouts\tauri-9dcc2f9152472c1a\c5b3751\tooling\cli\node\test\jest\fixtures\app\src-tauri`
error: invalid inline table
expected `}`
  --> ..\..\..\.cargo\git\checkouts\tauri-9dcc2f9152472c1a\c5b3751\tooling\cli\templates\plugin\with-api\examples\tauri-app\src-tauri\Cargo.toml:14:16
   |
14 | tauri-build = {{ tauri_build_dep }}
   |                ^
   |

I'm not sure if I applied it correctly, I tried doing it the same way as with the asset protocol fix. Here is my Cargo.toml file:

[package]
name = "tauri-shell-bug"
version = "0.0.0"
description = "A Tauri App"
authors = ["you"]
edition = "2021"

# See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html

[build-dependencies]
tauri-build = { version = "1", features = [] }

[dependencies]
tauri = { git = "https://github.com/tauri-apps/tauri", branch = "fix/shell/retry-emits", features = [  "path-all", "shell-execute", "fs-exists", "shell-open", "devtools"] }
serde = { version = "1", features = ["derive"] }
serde_json = "1"
regex = "1.10.4"

[features]
# This feature is used for production builds or when a dev server is not specified, DO NOT REMOVE!!
custom-protocol = ["tauri/custom-protocol"]

I've tried remove Cargo.lock and running cargo clean, but that didn't help. Do I need to clean up C:\Users\<USER>\.cargo\git\checkouts\*, or am I just doing something wrong with the install?

mauritzn avatar May 08 '24 00:05 mauritzn

try cloning the repo locally

git clone https://github.com/tauri-apps/tauri --branch fix/shell/retry-emits
tauri = { path = "path/to/local/repo/core/tauri", features = [  "path-all", "shell-execute", "fs-exists", "shell-open", "devtools"] }

amrbashir avatar May 08 '24 00:05 amrbashir

Alright that worked I got it installed and while the patch does fix output disappearing it still handles very poorly.

Also the output is different, every line now has an extra line added to it, which is fine if you are using events since you can easily trim it out, but when you use .execute() and get the whole stdout as a string you get gaps between lines.

Expected output: Screenshot 2024-05-08 035948

Output with patch: Screenshot 2024-05-08 035940


But a bigger issue is that command reruns are still not possible when using .execute(), when you use events you are now able to rerun them (most of the time...). Any reloads caused by changes in the file still prevents future Command executions both for .execute() and events.

Using .execute() once will the prevent any future executions from Invoke, .execute() and Command using events.

And while most of the time reruns are possible when using events, sometimes it also prevents any future executions, just like .execute().

For those interested here are the timing difference using Rust for command execution. From what I remember before the patch Command was ~12 seconds, but that was with around half the output missing. So this result seems about right for the full output now being present.

Using Rust with Invoke .. :  ~ 2 seconds
Using Command with Execute: ~ 28 seconds
Using Command with Events : ~ 28 seconds

mauritzn avatar May 08 '24 01:05 mauritzn

With the latest commit to fix/shell/retry-emits (d4a6bc9da3ee9c4df981f02699600ef8ba8e1a4c), I'm now able to run .execute() one more time after the first one, but I'm no longer able to rerun using events. Once the first event based one has finished all future execution is prevented.

To call Command insanely fragile when it comes to large stdout outputs feels like a bit of an understatement. Is this an issue that is only present of Windows? Just wondering since you mentioned this in #8177:

I spent today looking into this and unfortunately, we can't fix this easily, the Windows OS sets limits for the event loop to only handle 10,000 messages at a time, I tried implementing a queue for failed events but it has a limitation of:

mauritzn avatar May 08 '24 02:05 mauritzn

Also the output is different, every line now has an extra line added to it, which is fine if you are using events since you can easily trim it out, but when you use .execute() and get the whole stdout as a string you get gaps between lines.

This seems like a regression from https://github.com/tauri-apps/tauri/pull/6519, we fixed the Rust implementation but didn't update the JS API to accommodate it

Using Rust with Invoke .. :  ~ 2 seconds
Using Command with Execute: ~ 28 seconds
Using Command with Events : ~ 28 seconds

We should be able to improve Command with Execute speed, right now it is implemented based on the Command with Events variant but it should be handled in Rust instead.

amrbashir avatar May 08 '24 15:05 amrbashir

I have opened https://github.com/tauri-apps/tauri/pull/9706 to improve the performance and fix the exrta new lines, should also fix not being able to rerun the commands but let's wait until both PRs are merged.

amrbashir avatar May 08 '24 16:05 amrbashir

Alright I'll give it a go once it has been merged 👍

mauritzn avatar May 08 '24 20:05 mauritzn

Well I tried to run it now that both patches have been merged but I must be doing something wrong since none of the patches seem to have worked? I'm still getting double newlines when using Execute from Command and it's still much slower than using the direct Invoke -> Rust workaround (both of which was supposed to be fixed with #9706). Events/Execute are also still quite unreliable.

So I'm really wondering if any of the patched code is running on my setup. Am I wrong in my assumption that I was suppose to use branch 1.x? It seemed that both patches got merged to that branch.

I've tried using { git = "https://github.com/tauri-apps/tauri", branch = "1.x", ... } and using { path = "C:/Users/<USER>/.cargo/git/checkouts/tauri_1.x__manual_clone/core/tauri", ... }

mauritzn avatar May 29 '24 02:05 mauritzn

That's probably because you're using the JS api from NPM and the fix hasn't been released yet, if you're using 1.x branch, try using the global import const { Command } = window.__TAURI__.shell

amrbashir avatar May 29 '24 15:05 amrbashir

Ahh alright, didn't think that would affect it, execute from Command now works perfectly and the speed is pretty much the same as using invoke -> Rust, invoke is around 1.3s while Execute is around 1.6s.

Using events is still extremely slow and unreliable, getting it to work more than 1 time is almost impossible. Also after using events execute and invoke both break.

Events also do not output anything until they close completely now. In the past you'd get output during command run but now it has to finish before anything come out. Which makes it work essentially the same as execute, rendering it kind of redundant. It takes roughly 26s for events to produce an output.

mauritzn avatar May 29 '24 17:05 mauritzn

Using events is still extremely slow and unreliable, getting it to work more than 1 time is almost impossible.

Nothing can be done on this part unfortunately, at least in v2 it should be faster but usually this type of application is better handled in rust.

Also after using events execute and invoke both break.

Can't reproduce

Events also do not output anything until they close completely now. In the past you'd get output during command run but now it has to finish before anything come out. Which makes it work essentially the same as execute, rendering it kind of redundant. It takes roughly 26s for events to produce an output.

I can't reproduce this using your repo.

amrbashir avatar May 29 '24 23:05 amrbashir

Events also do not output anything until they close completely now. In the past you'd get output during command run but now it has to finish before anything come out. Which makes it work essentially the same as execute, rendering it kind of redundant. It takes roughly 26s for events to produce an output.

I can't reproduce this using your repo.

Ahh whoops, I made some changes in my local repo copy to allow for easier output verification (outputs how many total lines exist at the end), so I stopped logging each line as soon as they arrived, my bad... It is returning each line as expected, sorry about that, should have caught my error there.

Also after using events execute and invoke both break.

Can't reproduce

Here is a video demonstrating: https://www.youtube.com/watch?v=0egAFoGlL7k

I was able to reproduce this with and without the changes I made to repo.

mauritzn avatar May 30 '24 00:05 mauritzn

Could you push your changes to the repo above? I will try to see what's going on

amrbashir avatar May 30 '24 01:05 amrbashir

Alright I've pushed the changes I made to the invoke-workaround branch of the repo.

mauritzn avatar May 30 '24 02:05 mauritzn

Were you able to reproduce it?

mauritzn avatar Jun 05 '24 15:06 mauritzn

Sorry I totally forgot, but I just gave it a try and I can still use all 3 versions multiple times and in different order as well.

amrbashir avatar Jun 05 '24 18:06 amrbashir

Are you running it on Windows 11? Trying to figure out why my events are still a buggy mess ':D

mauritzn avatar Jun 05 '24 18:06 mauritzn

Yeah I am on Win 11

amrbashir avatar Jun 05 '24 21:06 amrbashir

Alright I'll mess around a bit on an fresh Windows VM later and report back

mauritzn avatar Jun 05 '24 21:06 mauritzn

I don't understand why I'm still not able to reliably use events, I'm still having the issue in a completely fresh Windows 11 VM. I was able to get events to run 2 times one time, but the rest of the times it failed to run a second time.

Here is a demo video of it working 2 times: https://www.youtube.com/watch?v=g6etWkInBKg Here is a demo video of it only working once: https://www.youtube.com/watch?v=eF5Iv_-Cfxg

This is running a fresh clone of tauri-shell-bug > invoke-workaround

Any idea what could be going on? Or is my machine just cursed at this point? ':D

mauritzn avatar Jun 06 '24 05:06 mauritzn

I can't really say where the issue might be, maybe try using https://github.com/crabnebula-dev/devtools and see if the invoke call makes it to the Rust side or not

amrbashir avatar Jun 06 '24 15:06 amrbashir

Okay... uhmm... Sorry, but I can't seem to get the devtools to import using the 1.x branch... It works fine if I use the cargo package (v1.6.8).

Using 1.x: image

Using cargo version (v1.6.8): image

I tried to manually pass the types to it to fix the {unknown} issue, but that just threw even more errors about type mismatches...

At this point unless someone else is also able to reproduce this I'm just about ready to call it a day, since I don't make use of events in any of my current applications I don't really have the will to keep debugging it when everything keeps fighting back ':D

mauritzn avatar Jun 06 '24 17:06 mauritzn

you'll need to change the version under [dependencies] to 1.6.8 but then add a new section like this

[patch.crates-io]
tauri = { git = "https://github.com/tauri-apps/tauri", branch = "1.x" }

or if using a local repo

[patch.crates-io]
tauri = { path = "path/to/tauri-repo/core/tauri" }

then run cargo update inside src-tauri

you may need to add a patch for tauri-build as well

amrbashir avatar Jun 06 '24 17:06 amrbashir