imsnif / multitask

A mini-CI as a Zellij plugin
MIT License
73 stars 2 forks source link

Plugin creating two instances #7

Closed leakec closed 6 months ago

leakec commented 9 months ago

To re-create this issue:

git clone https://github.com/imsnif/multitask.git
cd multitask
git checkout version_39
cargo build 
cp target/wasm32-wasi/debug/multitask.wasm ~/zellij-plugins

Then run

zellij action launch-or-focus-plugin file:$HOME/zellij-plugins/multitask.wasm --configuration "shell=$SHELL,cwd=`pwd`"

twice. The first time everything should work as intended. The second time and all subsequent times, two instances of the multitask file will open in two different panes, i.e., two instances of the plugin are running. This persists even if I close and re-open a new zellij session.

If I clear the ~/.cache/zellij folder, then the plugin works as intended the first time I re-run it, but again opens two instances afterward.

This is a new issue I'm only seeing with zellij 0.39.0.

leakec commented 9 months ago

@imsnif Any ideas on what may be causing this?

imsnif commented 9 months ago

Does it happen if you give it an absolute path without the $HOME?

leakec commented 9 months ago

@imsnif Yeah, I'm still seeing it even with an absolute path rather than $HOME.

imsnif commented 9 months ago

Hey yeah - I looked into this a little bit. I think some event ordering changed in the recent version and this plugin was relying on this ordering (my bad!) - a good way to fix this might be to make opening the multitask environment atomic. So that if we did it once, we will never do it again until the plugin is reloaded. Maybe some conditional around here: https://github.com/imsnif/multitask/blob/main/src/main.rs#L64

leakec commented 9 months ago

@imsnif I gave this a shot and also added some print statements to get some more info. I'm using a bool on the state to try and ensure we only open the plugin once. Here is the diff:

diff --git a/src/main.rs b/src/main.rs
index ed353ac..09009bd 100644
--- a/src/main.rs
+++ b/src/main.rs
@@ -25,6 +25,7 @@ struct State {
     plugin_id: Option<u32>,
     shell: String,
     cwd: Option<PathBuf>,
+    was_opened: bool,
 }

 impl ZellijPlugin for State {
@@ -45,6 +46,8 @@ impl ZellijPlugin for State {
             Some(s) => Some(PathBuf::from(s)),
             _ => None
         };
+        eprintln!{"RUNNING LOAD for ID {}", self.plugin_id.unwrap()};
+        eprintln!{"Zellij PID: {}",get_plugin_ids().zellij_pid}
         show_self(true);
     }

@@ -61,7 +64,14 @@ impl ZellijPlugin for State {
                     // we clean up our state and start over, allowing the plugin to be triggered by
                     // a keybinding
                     hide_self();
-                    self.start_multitask_env();
+                    eprintln!{"RUNNING PANE UPDATE for ID {}", self.plugin_id.unwrap()};
+                    eprintln!{"Status of was opened: {}", self.was_opened};
+                    if !self.was_opened
+                    {
+                        self.was_opened = true;
+                        eprintln!{"Status of was opened: {}", self.was_opened};
+                        self.start_multitask_env();
+                    }
                 } else if let Some(running_tasks) = &mut self.running_tasks {
                     running_tasks.update_task_status(&pane_manifest);
                     if running_tasks.all_tasks_completed_successfully() {

However, I'm still seeing the same issue.

I checked the log to see the status of my print statements:

DEBUG  |/home/leake/.zellij_plugi| 2023-11-11 09:02:21.773 [id: 2     ] RUNNING LOAD for ID 2 
DEBUG  |/home/leake/.zellij_plugi| 2023-11-11 09:02:21.773 [id: 2     ] Zellij PID: 37983 
ERROR  |???                      | 2023-11-11 09:02:21.773 [screen    ] [/home/leake/.cargo/registry/src/index.crates.io-6f17d22bba15001f/zellij-server-0.39.0/src/screen.rs:822]: a non-fatal error occured

Caused by:
    0: Failed to switch to active tab at position 1 for client id: 2
    1: active tab not found for client 2 
INFO   |zellij_server            | 2023-11-11 09:02:21.774 [async-std/runti] [/home/leake/.cargo/registry/src/index.crates.io-6f17d22bba15001f/zellij-server-0.39.0/src/lib.rs:917]: Compiling plugins using Cranelift 
DEBUG  |/home/leake/.zellij_plugi| 2023-11-11 09:02:21.792 [id: 2     ] RUNNING LOAD for ID 2 
DEBUG  |/home/leake/.zellij_plugi| 2023-11-11 09:02:21.792 [id: 2     ] Zellij PID: 37983 
DEBUG  |/home/leake/.zellij_plugi| 2023-11-11 09:02:21.795 [id: 2     ] RUNNING PANE UPDATE for ID 2 
DEBUG  |/home/leake/.zellij_plugi| 2023-11-11 09:02:21.795 [id: 2     ] Status of was opened: false 
DEBUG  |/home/leake/.zellij_plugi| 2023-11-11 09:02:21.795 [id: 2     ] Status of was opened: true 
DEBUG  |/home/leake/.zellij_plugi| 2023-11-11 09:02:21.795 [id: 2     ] RUNNING PANE UPDATE for ID 2 
DEBUG  |/home/leake/.zellij_plugi| 2023-11-11 09:02:21.795 [id: 2     ] Status of was opened: false 
DEBUG  |/home/leake/.zellij_plugi| 2023-11-11 09:02:21.795 [id: 2     ] Status of was opened: true 

It looks like the call to load was made twice for plugin ID 2, which ultimately means two calls are made to the pane update. I can see within the pane update that the state of was_opened is changed correctly, but when the second pane update fires the was_opened variable is still set to false. I'm guessing there is either:

  1. Something I don't understand here about how the State works. This could definitely be an error on my part as I'm new to Rust and potentially have made some rookie mistake. Maybe using the plugin State wasn't what you had in mind and I misinterpreted your recommendation (sorry if that is the case).
  2. There are two instances of the plugin open, each with its own version of State.

One other interesting thing to note. If I use start-or-reload-plugin rather than launch-or-focus-plugin the issue goes away. In the logs, I also only see one call to load and one call to the pane update. However, it seems like the --configuration is not applied correctly when I re-open the plugin, e.g., if I change the shell variable on subsequent calls to start-or-reaload-plugin it still has the same value it had from the first initial call.

leakec commented 8 months ago

@imsnif I compiled zellij from GitHub using the devel instructions so I could start to dump stack traces and try to figure out why the plugin was being loaded twice. I'm very unfamiliar with the internals of zellij, so I'm doing some speculating in the paragraphs that follow: please take it all with a huge grain of salt. I also have the stack traces from the zellij log at the end if you're interested.

The load_plugin command in zellij-server/src/plugins/wasm_bridge.rs is only being called once. However, when I added a stack trace on get_store in zellij-server/src/lib.rs I saw two separate stack traces, which means that it is getting called twice. I chose get_store since I saw that the plugin looked like it was being compiled twice (I think leading to it being loaded twice and ultimately two multitask windows being loaded).

It looks like create_plugin_environment is called once during start_plugin and then again by clone_instance_for_other_clients (which I think makes sense since each client would need to start the plugin). Is it possible that zellij has itself as a client so it is creating the plugin environment twice?

Click to expand the full stack trace ``` INFO |zellij_server::plugins::w| 2023-12-02 07:17:40.877 [wasm ] [zellij-server/src/plugins/wasm_bridge.rs:123]: Backtrace from load_plugin in WASM bridge: 0: zellij_server::plugins::wasm_bridge::WasmBridge::load_plugin at ./zellij-server/src/plugins/wasm_bridge.rs:123:69 1: zellij_server::plugins::plugin_thread_main at ./zellij-server/src/plugins/mod.rs:187:24 2: zellij_server::init_session::{{closure}} at ./zellij-server/src/lib.rs:844:17 3: std::sys_common::backtrace::__rust_begin_short_backtrace at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/sys_common/backtrace.rs:121:18 4: std::thread::Builder::spawn_unchecked_::{{closure}}::{{closure}} at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/thread/mod.rs:550:17 5: as core::ops::function::FnOnce<()>>::call_once at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/core/src/panic/unwind_safe.rs:271:9 6: std::panicking::try::do_call at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:483:40 7: __rust_try 8: std::panicking::try at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:447:19 9: std::panic::catch_unwind at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panic.rs:137:14 10: std::thread::Builder::spawn_unchecked_::{{closure}} at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/thread/mod.rs:549:30 11: core::ops::function::FnOnce::call_once{{vtable.shim}} at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/core/src/ops/function.rs:507:5 12: as core::ops::function::FnOnce>::call_once at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/alloc/src/boxed.rs:2000:9 13: as core::ops::function::FnOnce>::call_once at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/alloc/src/boxed.rs:2000:9 14: std::sys::unix::thread::Thread::new::thread_start at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/sys/unix/thread.rs:108:17 15: start_thread 16: __clone3 INFO |zellij_server::plugins::p| 2023-12-02 07:17:43.497 [async-std/runti] [zellij-server/src/plugins/plugin_loader.rs:495]: Loaded plugin '/home/leake/.zellij_plugins/multitask.wasm' from cache folder at '/home/leake/.cache/zellij' in 1.815385558s INFO |zellij_server | 2023-12-02 07:17:43.499 [async-std/runti] [zellij-server/src/lib.rs:920]: Backtrace from get_store: 0: zellij_server::get_store at ./zellij-server/src/lib.rs:920:48 1: zellij_server::plugins::plugin_loader::PluginLoader::create_plugin_instance_env_and_subscriptions at ./zellij-server/src/plugins/plugin_loader.rs:773:25 2: zellij_server::plugins::plugin_loader::PluginLoader::create_plugin_environment at ./zellij-server/src/plugins/plugin_loader.rs:551:13 3: zellij_server::plugins::plugin_loader::PluginLoader::start_plugin::{{closure}} at ./zellij-server/src/plugins/plugin_loader.rs:175:32 4: core::result::Result::and_then at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/core/src/result.rs:1372:22 5: zellij_server::plugins::plugin_loader::PluginLoader::start_plugin at ./zellij-server/src/plugins/plugin_loader.rs:171:9 6: zellij_server::plugins::wasm_bridge::WasmBridge::load_plugin::{{closure}} at ./zellij-server/src/plugins/wasm_bridge.rs:195:23 7: as core::future::future::Future>::poll::{{closure}} at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.11.0/src/task/builder.rs:199:17 8: async_std::task::task_locals_wrapper::TaskLocalsWrapper::set_current::{{closure}} at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.11.0/src/task/task_locals_wrapper.rs:60:13 9: std::thread::local::LocalKey::try_with at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/thread/local.rs:446:16 10: std::thread::local::LocalKey::with at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/thread/local.rs:422:9 11: async_std::task::task_locals_wrapper::TaskLocalsWrapper::set_current at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.11.0/src/task/task_locals_wrapper.rs:55:9 12: as core::future::future::Future>::poll at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.11.0/src/task/builder.rs:197:13 13: async_executor::Executor::spawn::{{closure}} at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-executor-1.4.1/src/lib.rs:144:19 14: as core::future::future::Future>::poll at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/core/src/future/future.rs:124:9 15: async_task::raw::RawTask::run at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-task-4.2.0/src/raw.rs:489:20 16: async_task::runnable::Runnable::run at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-task-4.2.0/src/runnable.rs:309:18 17: async_executor::Executor::run::{{closure}}::{{closure}} at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-executor-1.4.1/src/lib.rs:235:21 18: as core::future::future::Future>::poll at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-lite-1.13.0/src/future.rs:529:33 19: async_executor::Executor::run::{{closure}} at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-executor-1.4.1/src/lib.rs:242:31 20: as core::future::future::Future>::poll at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-lite-1.13.0/src/future.rs:529:33 21: async_io::driver::block_on at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-io-1.13.0/src/driver.rs:146:33 22: async_global_executor::reactor::block_on::{{closure}} at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-global-executor-2.3.1/src/reactor.rs:3:18 23: async_global_executor::reactor::block_on at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-global-executor-2.3.1/src/reactor.rs:12:5 24: async_global_executor::threading::thread_main_loop::{{closure}}::{{closure}} at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-global-executor-2.3.1/src/threading.rs:95:17 25: std::thread::local::LocalKey::try_with at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/thread/local.rs:446:16 26: std::thread::local::LocalKey::with at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/thread/local.rs:422:9 27: async_global_executor::threading::thread_main_loop::{{closure}} at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-global-executor-2.3.1/src/threading.rs:89:13 28: std::panicking::try::do_call at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:483:40 29: __rust_try 30: std::panicking::try at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:447:19 31: std::panic::catch_unwind at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panic.rs:137:14 32: async_global_executor::threading::thread_main_loop at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-global-executor-2.3.1/src/threading.rs:88:12 33: core::ops::function::FnOnce::call_once at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/core/src/ops/function.rs:507:5 34: std::sys_common::backtrace::__rust_begin_short_backtrace at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/sys_common/backtrace.rs:121:18 35: std::thread::Builder::spawn_unchecked_::{{closure}}::{{closure}} at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/thread/mod.rs:550:17 36: as core::ops::function::FnOnce<()>>::call_once at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/core/src/panic/unwind_safe.rs:271:9 37: std::panicking::try::do_call at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:483:40 38: __rust_try 39: std::panicking::try at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:447:19 40: std::panic::catch_unwind at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panic.rs:137:14 41: std::thread::Builder::spawn_unchecked_::{{closure}} at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/thread/mod.rs:549:30 42: core::ops::function::FnOnce::call_once{{vtable.shim}} at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/core/src/ops/function.rs:507:5 43: as core::ops::function::FnOnce>::call_once at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/alloc/src/boxed.rs:2000:9 44: as core::ops::function::FnOnce>::call_once at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/alloc/src/boxed.rs:2000:9 45: std::sys::unix::thread::Thread::new::thread_start at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/sys/unix/thread.rs:108:17 46: start_thread 47: __clone3 INFO |zellij_server | 2023-12-02 07:17:43.500 [async-std/runti] [zellij-server/src/lib.rs:921]: Compiling plugins using Cranelift DEBUG |/home/leake/.zellij_plugi| 2023-12-02 07:17:43.576 [id: 1 ] Plugin load backtrace: unsupported backtrace DEBUG |/home/leake/.zellij_plugi| 2023-12-02 07:17:43.577 [id: 1 ] RUNNING LOAD for ID 1 DEBUG |/home/leake/.zellij_plugi| 2023-12-02 07:17:43.578 [id: 1 ] Zellij PID: 45372 ERROR |??? | 2023-12-02 07:17:43.578 [screen ] [zellij-server/src/screen.rs:825]: a non-fatal error occured Caused by: 0: Failed to switch to active tab at position 0 for client id: 2 1: active tab not found for client 2 INFO |zellij_server | 2023-12-02 07:17:43.579 [async-std/runti] [zellij-server/src/lib.rs:920]: Backtrace from get_store: 0: zellij_server::get_store at ./zellij-server/src/lib.rs:920:48 1: zellij_server::plugins::plugin_loader::PluginLoader::create_plugin_instance_env_and_subscriptions at ./zellij-server/src/plugins/plugin_loader.rs:773:25 2: zellij_server::plugins::plugin_loader::PluginLoader::create_plugin_environment at ./zellij-server/src/plugins/plugin_loader.rs:551:13 3: zellij_server::plugins::plugin_loader::PluginLoader::clone_instance_for_other_clients::{{closure}} at ./zellij-server/src/plugins/plugin_loader.rs:720:40 4: core::result::Result::and_then at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/core/src/result.rs:1372:22 5: zellij_server::plugins::plugin_loader::PluginLoader::clone_instance_for_other_clients at ./zellij-server/src/plugins/plugin_loader.rs:718:17 6: zellij_server::plugins::plugin_loader::PluginLoader::start_plugin::{{closure}} at ./zellij-server/src/plugins/plugin_loader.rs:186:17 7: core::result::Result::and_then at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/core/src/result.rs:1372:22 8: zellij_server::plugins::plugin_loader::PluginLoader::start_plugin at ./zellij-server/src/plugins/plugin_loader.rs:171:9 9: zellij_server::plugins::wasm_bridge::WasmBridge::load_plugin::{{closure}} at ./zellij-server/src/plugins/wasm_bridge.rs:195:23 10: as core::future::future::Future>::poll::{{closure}} at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.11.0/src/task/builder.rs:199:17 11: async_std::task::task_locals_wrapper::TaskLocalsWrapper::set_current::{{closure}} at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.11.0/src/task/task_locals_wrapper.rs:60:13 12: std::thread::local::LocalKey::try_with at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/thread/local.rs:446:16 13: std::thread::local::LocalKey::with at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/thread/local.rs:422:9 14: async_std::task::task_locals_wrapper::TaskLocalsWrapper::set_current at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.11.0/src/task/task_locals_wrapper.rs:55:9 15: as core::future::future::Future>::poll at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.11.0/src/task/builder.rs:197:13 16: async_executor::Executor::spawn::{{closure}} at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-executor-1.4.1/src/lib.rs:144:19 17: as core::future::future::Future>::poll at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/core/src/future/future.rs:124:9 18: async_task::raw::RawTask::run at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-task-4.2.0/src/raw.rs:489:20 19: async_task::runnable::Runnable::run at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-task-4.2.0/src/runnable.rs:309:18 20: async_executor::Executor::run::{{closure}}::{{closure}} at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-executor-1.4.1/src/lib.rs:235:21 21: as core::future::future::Future>::poll at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-lite-1.13.0/src/future.rs:529:33 22: async_executor::Executor::run::{{closure}} at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-executor-1.4.1/src/lib.rs:242:31 23: as core::future::future::Future>::poll at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-lite-1.13.0/src/future.rs:529:33 24: async_io::driver::block_on at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-io-1.13.0/src/driver.rs:146:33 25: async_global_executor::reactor::block_on::{{closure}} at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-global-executor-2.3.1/src/reactor.rs:3:18 26: async_global_executor::reactor::block_on at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-global-executor-2.3.1/src/reactor.rs:12:5 27: async_global_executor::threading::thread_main_loop::{{closure}}::{{closure}} at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-global-executor-2.3.1/src/threading.rs:95:17 28: std::thread::local::LocalKey::try_with at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/thread/local.rs:446:16 29: std::thread::local::LocalKey::with at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/thread/local.rs:422:9 30: async_global_executor::threading::thread_main_loop::{{closure}} at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-global-executor-2.3.1/src/threading.rs:89:13 31: std::panicking::try::do_call at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:483:40 32: __rust_try 33: std::panicking::try at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:447:19 34: std::panic::catch_unwind at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panic.rs:137:14 35: async_global_executor::threading::thread_main_loop at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-global-executor-2.3.1/src/threading.rs:88:12 36: core::ops::function::FnOnce::call_once at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/core/src/ops/function.rs:507:5 37: std::sys_common::backtrace::__rust_begin_short_backtrace at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/sys_common/backtrace.rs:121:18 38: std::thread::Builder::spawn_unchecked_::{{closure}}::{{closure}} at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/thread/mod.rs:550:17 39: as core::ops::function::FnOnce<()>>::call_once at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/core/src/panic/unwind_safe.rs:271:9 40: std::panicking::try::do_call at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:483:40 41: __rust_try 42: std::panicking::try at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:447:19 43: std::panic::catch_unwind at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panic.rs:137:14 44: std::thread::Builder::spawn_unchecked_::{{closure}} at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/thread/mod.rs:549:30 45: core::ops::function::FnOnce::call_once{{vtable.shim}} at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/core/src/ops/function.rs:507:5 46: as core::ops::function::FnOnce>::call_once at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/alloc/src/boxed.rs:2000:9 47: as core::ops::function::FnOnce>::call_once at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/alloc/src/boxed.rs:2000:9 48: std::sys::unix::thread::Thread::new::thread_start at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/sys/unix/thread.rs:108:17 49: start_thread 50: __clone3 INFO |zellij_server | 2023-12-02 07:17:43.579 [async-std/runti] [zellij-server/src/lib.rs:921]: Compiling plugins using Cranelift DEBUG |/home/leake/.zellij_plugi| 2023-12-02 07:17:43.602 [id: 1 ] Plugin load backtrace: unsupported backtrace DEBUG |/home/leake/.zellij_plugi| 2023-12-02 07:17:43.604 [id: 1 ] RUNNING LOAD for ID 1 DEBUG |/home/leake/.zellij_plugi| 2023-12-02 07:17:43.604 [id: 1 ] Zellij PID: 45372 DEBUG |/home/leake/.zellij_plugi| 2023-12-02 07:17:43.659 [id: 1 ] RUNNING PANE UPDATE for ID 1 DEBUG |/home/leake/.zellij_plugi| 2023-12-02 07:17:43.659 [id: 1 ] Status of was opened: false DEBUG |/home/leake/.zellij_plugi| 2023-12-02 07:17:43.659 [id: 1 ] Status of was opened: true DEBUG |/home/leake/.zellij_plugi| 2023-12-02 07:17:43.659 [id: 1 ] RUNNING PANE UPDATE for ID 1 DEBUG |/home/leake/.zellij_plugi| 2023-12-02 07:17:43.659 [id: 1 ] Status of was opened: false DEBUG |/home/leake/.zellij_plugi| 2023-12-02 07:17:43.660 [id: 1 ] Status of was opened: true ```
Current git diff to re-create this stack trace if desired ```diff diff --git a/zellij-server/src/lib.rs b/zellij-server/src/lib.rs index 51daeb0e..1f6f57e2 100644 --- a/zellij-server/src/lib.rs +++ b/zellij-server/src/lib.rs @@ -15,6 +15,7 @@ mod terminal_bytes; mod thread_bus; mod ui; +use std::backtrace::Backtrace; use background_jobs::{background_jobs_main, BackgroundJob}; use log::info; use pty_writer::{pty_writer_main, PtyWriteInstruction}; @@ -916,6 +917,7 @@ fn init_session( #[cfg(not(feature = "singlepass"))] fn get_store() -> Store { use wasmer::{BaseTunables, Cranelift, Engine, Pages, Target}; + log::info!("Backtrace from get_store: {}", Backtrace::force_capture()); log::info!("Compiling plugins using Cranelift"); // workaround for https://github.com/bytecodealliance/wasmtime/security/advisories/GHSA-ff4p-7xrq-q5r8 diff --git a/zellij-server/src/plugins/wasm_bridge.rs b/zellij-server/src/plugins/wasm_bridge.rs index bb58d611..badc8893 100644 --- a/zellij-server/src/plugins/wasm_bridge.rs +++ b/zellij-server/src/plugins/wasm_bridge.rs @@ -1,3 +1,4 @@ +use std::backtrace::Backtrace; use super::{PluginId, PluginInstruction}; use crate::plugins::plugin_loader::PluginLoader; use crate::plugins::plugin_map::{AtomicEvent, PluginEnv, PluginMap, RunningPlugin, Subscriptions}; @@ -119,6 +120,7 @@ impl WasmBridge { // returns the plugin id let err_context = move || format!("failed to load plugin"); + log::info!("Backtrace from load_plugin in WASM bridge: {}", Backtrace::force_capture()); let client_id = client_id .or_else(|| { self.connected_clients diff --git a/zellij-tile/src/lib.rs b/zellij-tile/src/lib.rs index 39058c29..1c18042d 100644 --- a/zellij-tile/src/lib.rs +++ b/zellij-tile/src/lib.rs @@ -112,11 +112,13 @@ macro_rules! register_plugin { use std::convert::TryInto; use zellij_tile::shim::plugin_api::action::ProtobufPluginConfiguration; use zellij_tile::shim::prost::Message; + use std::backtrace::Backtrace; let protobuf_bytes: Vec = $crate::shim::object_from_stdin().unwrap(); let protobuf_configuration: ProtobufPluginConfiguration = ProtobufPluginConfiguration::decode(protobuf_bytes.as_slice()).unwrap(); let plugin_configuration: BTreeMap = BTreeMap::try_from(&protobuf_configuration).unwrap(); + eprintln!("Plugin load backtrace: {}", Backtrace::force_capture()); state.borrow_mut().load(plugin_configuration); }); } diff --git a/zellij-utils/src/plugin_api/action.rs b/zellij-utils/src/plugin_api/action.rs index dc8c2938..f1637cca 100644 --- a/zellij-utils/src/plugin_api/action.rs +++ b/zellij-utils/src/plugin_api/action.rs @@ -1,3 +1,4 @@ +use std::backtrace::Backtrace; pub use super::generated_api::api::{ action::{ action::OptionalPayload, Action as ProtobufAction, ActionName as ProtobufActionName, @@ -403,6 +404,8 @@ impl TryFrom for Action { let should_float = payload.should_float; let move_to_focused_tab = payload.move_to_focused_tab; let should_open_in_place = payload.should_open_in_place; + // or forcibly capture the backtrace regardless of environment variable configuration + eprintln!("Backtrace from LaunchOrFocusPlugin action: {}", Backtrace::force_capture()); Ok(Action::LaunchOrFocusPlugin( run_plugin, should_float, ```

EDIT: Also including stack trace from start-or-reload-plugin, which only calls get_store once. As a result, load is only called once and we only get one editor window opening as expected. Maybe what is happening is launch-or-focus-plugin is calling with connected_clients while start-or-reload-plugin is not. Could there be an issue with which clients are passed by the LaunchOrFocusPlugin command?

Log info with stack trace for start or reload plugin ``` INFO |zellij_server::plugins::w| 2023-12-02 08:28:16.855 [wasm ] [zellij-server/src/plugins/wasm_bridge.rs:123]: Backtrace from load_plugin in WASM bridge: 0: zellij_server::plugins::wasm_bridge::WasmBridge::load_plugin at ./zellij-server/src/plugins/wasm_bridge.rs:123:69 1: zellij_server::plugins::plugin_thread_main at ./zellij-server/src/plugins/mod.rs:224:35 2: zellij_server::init_session::{{closure}} at ./zellij-server/src/lib.rs:844:17 3: std::sys_common::backtrace::__rust_begin_short_backtrace at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/sys_common/backtrace.rs:121:18 4: std::thread::Builder::spawn_unchecked_::{{closure}}::{{closure}} at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/thread/mod.rs:550:17 5: as core::ops::function::FnOnce<()>>::call_once at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/core/src/panic/unwind_safe.rs:271:9 6: std::panicking::try::do_call at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:483:40 7: __rust_try 8: std::panicking::try at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:447:19 9: std::panic::catch_unwind at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panic.rs:137:14 10: std::thread::Builder::spawn_unchecked_::{{closure}} at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/thread/mod.rs:549:30 11: core::ops::function::FnOnce::call_once{{vtable.shim}} at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/core/src/ops/function.rs:507:5 12: as core::ops::function::FnOnce>::call_once at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/alloc/src/boxed.rs:2000:9 13: as core::ops::function::FnOnce>::call_once at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/alloc/src/boxed.rs:2000:9 14: std::sys::unix::thread::Thread::new::thread_start at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/sys/unix/thread.rs:108:17 15: start_thread 16: __clone3 INFO |zellij_server::plugins::p| 2023-12-02 08:28:19.480 [async-std/runti] [zellij-server/src/plugins/plugin_loader.rs:495]: Loaded plugin '/home/leake/.zellij_plugins/multitask.wasm' from cache folder at '/home/leake/.cache/zellij' in 1.82081073s INFO |zellij_server | 2023-12-02 08:28:19.483 [async-std/runti] [zellij-server/src/lib.rs:920]: Backtrace from get_store: 0: zellij_server::get_store at ./zellij-server/src/lib.rs:920:48 1: zellij_server::plugins::plugin_loader::PluginLoader::create_plugin_instance_env_and_subscriptions at ./zellij-server/src/plugins/plugin_loader.rs:773:25 2: zellij_server::plugins::plugin_loader::PluginLoader::create_plugin_environment at ./zellij-server/src/plugins/plugin_loader.rs:551:13 3: zellij_server::plugins::plugin_loader::PluginLoader::start_plugin::{{closure}} at ./zellij-server/src/plugins/plugin_loader.rs:175:32 4: core::result::Result::and_then at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/core/src/result.rs:1372:22 5: zellij_server::plugins::plugin_loader::PluginLoader::start_plugin at ./zellij-server/src/plugins/plugin_loader.rs:171:9 6: zellij_server::plugins::wasm_bridge::WasmBridge::load_plugin::{{closure}} at ./zellij-server/src/plugins/wasm_bridge.rs:195:23 7: as core::future::future::Future>::poll::{{closure}} at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.11.0/src/task/builder.rs:199:17 8: async_std::task::task_locals_wrapper::TaskLocalsWrapper::set_current::{{closure}} at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.11.0/src/task/task_locals_wrapper.rs:60:13 9: std::thread::local::LocalKey::try_with at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/thread/local.rs:446:16 10: std::thread::local::LocalKey::with at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/thread/local.rs:422:9 11: async_std::task::task_locals_wrapper::TaskLocalsWrapper::set_current at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.11.0/src/task/task_locals_wrapper.rs:55:9 12: as core::future::future::Future>::poll at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.11.0/src/task/builder.rs:197:13 13: async_executor::Executor::spawn::{{closure}} at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-executor-1.4.1/src/lib.rs:144:19 14: as core::future::future::Future>::poll at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/core/src/future/future.rs:124:9 15: async_task::raw::RawTask::run at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-task-4.2.0/src/raw.rs:489:20 16: async_task::runnable::Runnable::run at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-task-4.2.0/src/runnable.rs:309:18 17: async_executor::Executor::run::{{closure}}::{{closure}} at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-executor-1.4.1/src/lib.rs:235:21 18: as core::future::future::Future>::poll at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-lite-1.13.0/src/future.rs:529:33 19: async_executor::Executor::run::{{closure}} at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-executor-1.4.1/src/lib.rs:242:31 20: as core::future::future::Future>::poll at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-lite-1.13.0/src/future.rs:529:33 21: async_io::driver::block_on at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-io-1.13.0/src/driver.rs:146:33 22: async_global_executor::reactor::block_on::{{closure}} at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-global-executor-2.3.1/src/reactor.rs:3:18 23: async_global_executor::reactor::block_on at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-global-executor-2.3.1/src/reactor.rs:12:5 24: async_global_executor::threading::thread_main_loop::{{closure}}::{{closure}} at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-global-executor-2.3.1/src/threading.rs:95:17 25: std::thread::local::LocalKey::try_with at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/thread/local.rs:446:16 26: std::thread::local::LocalKey::with at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/thread/local.rs:422:9 27: async_global_executor::threading::thread_main_loop::{{closure}} at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-global-executor-2.3.1/src/threading.rs:89:13 28: std::panicking::try::do_call at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:483:40 29: __rust_try 30: std::panicking::try at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:447:19 31: std::panic::catch_unwind at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panic.rs:137:14 32: async_global_executor::threading::thread_main_loop at /home/leake/.cargo/registry/src/github.com-1ecc6299db9ec823/async-global-executor-2.3.1/src/threading.rs:88:12 33: core::ops::function::FnOnce::call_once at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/core/src/ops/function.rs:507:5 34: std::sys_common::backtrace::__rust_begin_short_backtrace at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/sys_common/backtrace.rs:121:18 35: std::thread::Builder::spawn_unchecked_::{{closure}}::{{closure}} at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/thread/mod.rs:550:17 36: as core::ops::function::FnOnce<()>>::call_once at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/core/src/panic/unwind_safe.rs:271:9 37: std::panicking::try::do_call at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:483:40 38: __rust_try 39: std::panicking::try at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panicking.rs:447:19 40: std::panic::catch_unwind at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/panic.rs:137:14 41: std::thread::Builder::spawn_unchecked_::{{closure}} at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/thread/mod.rs:549:30 42: core::ops::function::FnOnce::call_once{{vtable.shim}} at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/core/src/ops/function.rs:507:5 43: as core::ops::function::FnOnce>::call_once at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/alloc/src/boxed.rs:2000:9 44: as core::ops::function::FnOnce>::call_once at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/alloc/src/boxed.rs:2000:9 45: std::sys::unix::thread::Thread::new::thread_start at /rustc/fc594f15669680fa70d255faec3ca3fb507c3405/library/std/src/sys/unix/thread.rs:108:17 46: start_thread 47: __clone3 ```

After looking through these stack traces again, the one from start or reload calls load_plugin on 224 of zellij-server/src/plugins/mod.rs while lanch or focus calls it at line 187. The biggest difference I'm noticing here is cwd and ClientId are None in the former but are values in the later.

Did some more printing and looking at logs today. When reloading a plugin, Some(client_id) is passed in Load vs. None being passed in when calling Reload. Reload is the one that works as expected, i.e., None works as expected but Some(client_id) doesn't. The None value being passed in ultimately results in the client_id being the same as the first connected client, which is correct. The Load method is receiving a client_id method that is different than the connected client, which results in the plugin being loaded twice.

Trying to trace where this comes from: It looks like PluginInstruction::Load is only called on 1346 of zellij-server/src/pty.rs in fill_plugin_cwd; fill_plugin_cwd is only called on line 657 of the same file, which is part of the main pty loop. It looks like this command is only called by functions in zellij-server/src/screen.rs, for example ScreenInstruction::LaunchOrFocusPlugin. This is only called in route_action in zellij-server/src/route.rs. The route_thread_main is the only function calling the route_action, which is started by the zellij server. I'm not sure how this could lead to a client_id of 2, since it seems like the client_id should ultimately be inherited from the route_thread_main's client_id. Unless somehow new_client is being called and giving a new route_thread_main?

Put some prints in route_thread_main today and indeed it is being called again, with a client_id=2 when using launch-or-focus-plugin. It also has client_id=2 when calling start-or-reload-plugin. The difference is start-or-reload-plugin ultimately calls Reload, which passes client_id=None onto the plugin loader, whereas launch-or-focus-plugin ultimately calls Load, which passes the client_id=2 on, which results in the two loads. Why does this route_thread_main have an id of 2? Figured it out, whenever we call a command from within a zellij session using the zellij command, e.g., zellij edit <file>, this also happens. Basically, the zellij command we are running creates a new client.

Coming from the other side (CLI) I see CliAction::LaunchOrFocusPlugin in zellij-utils/src/input/actions.rs Left off here, will continue later.

leakec commented 8 months ago

@imsnif Just sending a gentle reminder for the message above. I'm curious if this could be something in the zellij core that is causing the plugin to be loaded twice.

imsnif commented 8 months ago

Hey, I'm really sorry for taking so long to get to this. As always, I'm incredibly swamped and don't have enough resources to deal with everything that needs to be dealt with in Zellij.

I hope to get to this soon. If you'd like to do some debugging with Zellij itself and find out what's happening, that would be great. I realize this is a tall order though. So if you'd rather wait for me, I can only ask you for your patience and thank you for your consistency. I have not forgotten you, I'm however only one person :/

leakec commented 8 months ago

@imsnif No sweat at all. Just wanted to send a reminder, since I know it's easy for stuff to get buried. Thanks again for all the amazing work you do with zellij!

I'm a bit swamped at work as well (so have had less time for this than I'd like). I can try to do some debugging if I get some spare time over the next few weeks, but would appreciate any help you can provide whenever you have the chance (no rush).

leakec commented 8 months ago

@imsnif Okay, I figured out what is happening, but am not sure of the correct fix. Again, no rush on this, just wanted to put this message here as a nice summary whenever you get around to it (so you don't have to read through my rambling in the full comment).

I'm not familiar enough with the zellij core to know which fix to pursue, but am listing some suggestions that came to mind below:

Click to expand the git diff ```diff diff --git a/zellij-server/src/plugins/mod.rs b/zellij-server/src/plugins/mod.rs index 2086268d..eb2c2300 100644 --- a/zellij-server/src/plugins/mod.rs +++ b/zellij-server/src/plugins/mod.rs @@ -184,7 +184,11 @@ pub(crate) fn plugin_thread_main( client_id, size, cwd, - ) => match wasm_bridge.load_plugin(&run, tab_index, size, cwd.clone(), Some(client_id)) + // The client ID is from the calling action, e.g., zellij action + // launch-or-focus-plugin. Hence, we do not want to actually load the plugin + // for that client_id. As a result, we pass in None, since that will use + // the first connected client as the client_id. + ) => match wasm_bridge.load_plugin(&run, tab_index, size, cwd.clone(), None) { Ok(plugin_id) => { drop(bus.senders.send_to_screen(ScreenInstruction::AddPlugin( ```
leakec commented 7 months ago

@imsnif Just sending a gentle reminder so this doesn't get lost. No rush, on it as I know you are very busy. In the comment above I believe I've identified the issue and have a proposed fix to the Zellij core. If you like the proposed fix let me know and I'll submit it as a PR on the Zellij core.

leakec commented 6 months ago

A recent commit on the zellij core fixed this :)

imsnif commented 6 months ago

I am very happy to hear this @leakec - and you have my sincerest apologies for ignoring this issue for so long. I was honestly meaning to take a deeper look at it in the next week or two.

Thanks for all your hard work and for your patience!

leakec commented 6 months ago

No sweat @imsnif. I know you're super busy, and thank you for all you do for this amazing tool!