sublimehq / sublime_text

Issue tracker for Sublime Text
https://www.sublimetext.com
807 stars 39 forks source link

`on_exit` executes very late, `plugin_unloaded` executes on startup #6388

Open giampaolo opened 4 months ago

giampaolo commented 4 months ago

Description of the bug

I'm using on_exit event to save session data on disk, but it turns out on_exit executes VERY late, like 3-5 secs after ST terminated. During this time I can start a new instance of ST. This is a problem because a typical use case of on_exit is to flush session data to a file on ST termination (see https://github.com/sublimehq/sublime_text/issues/10), and read / reload that file on ST startup. In this case on_exit simply cannot be relied upon. Since it fires up so late, it can easily lead to data corruption, as the old ST process will overwrite session data of the new ST process. To me this looks like a potentially critical bug, which also happen to be quite hard to spot.

In addition, it seems that plugin_unloaded() is erroneously executed on ST startup.

Steps to reproduce

1) put the following code in any ST plugin under User/:

import os
import sublime_plugin

def sync_file(fobj):
    # Synchronizes (writes) cached file writes to disk. Equivalent to
    # `sync --data /path/to/file` command on Linux.
    fobj.flush()
    os.fdatasync(fobj.fileno())

def plugin_loaded():
    with open(os.path.expanduser("~/out.txt"), "a") as f:
        print(f"pid={os.getpid()}, plugin_loaded", file=f)
        sync_file(f)

def plugin_unloaded():
    with open(os.path.expanduser("~/out.txt"), "a") as f:
        print(f"pid={os.getpid()}, plugin_unloaded", file=f)
        sync_file(f)

class Event(sublime_plugin.EventListener):
    def on_exit(self):
        with open(os.path.expanduser("~/out.txt"), "a") as f:
            print(f"pid={os.getpid()}, on_exit", file=f)
            sync_file(f)

2) open a shell and watch events as they occur with tail -f ~/out.txt command 3) Stop ST 4) Start another instance of ST

Expected behavior

The order of events I would expect is:

<<<ST TERMNINATES HERE>>>
pid=36500, on_exit
<<<ST STARTS HERE>>>
pid=36627, plugin_loaded

...or:

<<<ST TERMNINATES HERE>>>
pid=36500, plugin_unloaded
pid=36500, on_exit
<<<ST STARTS HERE>>>
pid=36627, plugin_loaded

Actual behavior

Instead I get:

<<<ST TERMNINATES HERE>>>
<<<ST STARTS HERE>>>
pid=36627, plugin_unloaded
pid=36627, plugin_loaded
pid=36500, on_exit

This shows 2 problems:

Sublime Text build number

4175

Operating system & version

Linux Ubuntu 22.04

Possible solutions I see

evandrocoan commented 4 months ago

I am running on Windows with 4175, and I do not see this behavior, although I do not see the plugin unloaded to be called:

import os
import sublime_plugin

def plugin_loaded():
    with open(os.path.expanduser("~/out.txt"), "a") as f:
        print(f"pid={os.getpid()}, plugin_loaded", file=f, flush=True)

def plugin_unloaded():
    with open(os.path.expanduser("~/out.txt"), "a") as f:
        print(f"pid={os.getpid()}, plugin_unloaded", file=f, flush=True)

class Event(sublime_plugin.EventListener):
    def on_exit(self):
        with open(os.path.expanduser("~/out.txt"), "a") as f:
            print(f"pid={os.getpid()}, on_exit", file=f, flush=True)

Output:

pid=13104, plugin_loaded
pid=13104, on_exit
pid=20936, plugin_loaded
pid=20936, on_exit

Are you sure Sublime Text had exited after you closed it? Can you run ps aux | grep sublime after you exit it?

Can you try this version with flush=True?

giampaolo commented 4 months ago

Are you sure Sublime Text had exited after you closed it?

The ST window closes, but plugin_host process still remains up for some seconds. This is in line with the ST doc, which states "[on_exit is] called once after the API has shut down, immediately before the plugin_host process exits":

$ watch -n 3 'ps aux | grep subl'
giampao+   97682  0.0  0.0   9364  3360 pts/0    S+   11:46   0:00 watch -n 3 ps aux | grep subl
giampao+   97696  0.0  0.0  86744  2400 ?        Sl   11:46   0:00 /opt/sublime_text/crash_handler --no-rate-limit
giampao+   97780  7.5  0.1 163528 41528 ?        Sl   11:46   0:00 /opt/sublime_text/plugin_host-3.3 97691 /opt/sub
giampao+   97783 15.0  0.2 418944 80696 ?        Sl   11:46   0:00 /opt/sublime_text/plugin_host-3.8 97691 /opt/sub
giampao+   97797 19.5  0.4 681084 143068 ?       Sl   11:46   0:00 /home/giampaolo/.cache/sublime-text/Package Stor

Can you try this version with flush=True?

My test code above uses flush=True already.

giampaolo commented 4 months ago

FWIW, here's a workaround I came up with. Use on_close + check that there's no ST windows:

import sublime
import sublime_plugin

class ExitEvent(sublime_plugin.EventListener):
    executed = False

    def on_close(self, view):
        if not sublime.windows():
            if not self.executed:
                call_exit_fun()
                self.executed = True

This is called immediately when I press alt+F4. Still, this is probably not 100% reliable. If there's 3 tabs open on_close() will be called 3 times, but since there's no window left (view.window() is None) there's no way to tell whether this is the last view being closed (which is when you want to fire up your callback).

FichteFoll commented 4 months ago

Just to confirm, you can also reproduce this in safe mode, i.e. with no other plugins defining an on_exit hook and potentially delaying execution of yours?

Edit: Obviously it will be hard to reproduce the startup thing since there will be no plugins when an instance is launched in safe mode, but it should suffice to check on_exit call times

giampaolo commented 4 months ago

I've just tried --safe-mode and on_exit seems to be called immediately (but I can't of course verify what happens on restart).

I then switched back to my default ST, and proceeded to uninstall all my packages from Package Control.sublime-settings (except for Package Control, which keeps being reinstalled automatically). I also removed all plugins from my User/ directory. This way I can reproduce the issue again:

pid=397266, plugin_unloaded
pid=397266, plugin_loaded
pid=397129, on_exit
giampaolo commented 4 months ago

If it's of any help: I took a look on ps aux after terminating ST. /opt/sublime_text/plugin_host-3.3 and /opt/sublime_text/plugin_host-3.8 processes remains alive for some seconds after closing ST. on_exit executes when they disappear. So perhaps the question here is why plugin_hosts remain alive for so long after ST termination.

I have tried using strace (sudo strace -p 401390) against both plugin_host processes, to observe what they did after ST termination, but I didn't notice anything unusual.

futex(0x74736c397000, FUTEX_WAIT_BITSET|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANY) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x74736c397000, FUTEX_WAIT_BITSET|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANY) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x74736c397000, FUTEX_WAIT_BITSET|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANY) = 0
futex(0x74736c397000, FUTEX_WAIT_BITSET|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANY) = 0
futex(0x57d489c35190, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x74736c397000, FUTEX_WAIT_BITSET|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANY) = 0

<<<<<< QUIT ST >>>>>>
<<<<<< WAIT SOME SECONDS >>>>>>

futex(0x74736c385000, FUTEX_WAKE, 1)    = 0
openat(AT_FDCWD, "/home/giampaolo/out.txt", O_WRONLY|O_CREAT|O_APPEND|O_CLOEXEC, 0666) = 3
fstat(3, {st_mode=S_IFREG|0664, st_size=8439, ...}) = 0
lseek(3, 0, SEEK_END)                   = 8439
ioctl(3, TCGETS, 0x7ffc8079c7d0)        = -1 ENOTTY (Inappropriate ioctl for device)
lseek(3, 0, SEEK_CUR)                   = 8439
ioctl(3, TCGETS, 0x7ffc8079c6e0)        = -1 ENOTTY (Inappropriate ioctl for device)
lseek(3, 0, SEEK_CUR)                   = 8439
getpid()                                = 401390
write(3, "pid=401390, on_exit\n", 20)   = 20
close(3)                                = 0
unlink("/home/giampaolo/.config/sublime-text/Log/plugin_host-3.8-on_exit.log") = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/opt/sublime_text/Lib/python38/sublime_plugin.py", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=84710, ...}) = 0
ioctl(3, TCGETS, 0x7ffc8079bb50)        = -1 ENOTTY (Inappropriate ioctl for device)
lseek(3, 0, SEEK_CUR)                   = 0
fcntl(3, F_DUPFD_CLOEXEC, 0)            = 4
fcntl(4, F_GETFL)                       = 0x8000 (flags O_RDONLY|O_LARGEFILE)
newfstatat(4, "", {st_mode=S_IFREG|0644, st_size=84710, ...}, AT_EMPTY_PATH) = 0
read(4, "# Don't evaluate type annotation"..., 4096) = 4096
close(4)                                = 0
lseek(3, 0, SEEK_SET)                   = 0
read(3, "# Don't evaluate type annotation"..., 8192) = 8192
read(3, "pass\n\n\ndef unload_plugin(modulen"..., 8192) = 8192
read(3, "ommands(view_id):\n    view = sub"..., 8192) = 8192
read(3, "_id)\n\n    check_text_change_list"..., 8192) = 8192
read(3, "\n    run_window_callbacks('on_ne"..., 8192) = 8192
close(3)                                = 0
futex(0x57d488a78710, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x74736dc3d910, FUTEX_WAIT_BITSET|FUTEX_CLOCK_REALTIME, 401393, NULL, FUTEX_BITSET_MATCH_ANY) = 0
getpid()                                = 401390
exit_group(0)                           = ?
+++ exited with 0 +++
evandrocoan commented 4 months ago

I also removed all plugins from my User/ directory. This way I can reproduce the issue again

Can you try renaming your ~/.config/sublime-text directory to something else instead of trying to uninstall all packages?

A clean ~/.config/sublime-text should be equivalent to --safe-mode unless the problem is with a default package from Sublime Text. I don't know if --safe-mode also disables default packages or just user-land packages.

FichteFoll commented 4 months ago

--safe-mode disables user packages, not system packages. It's like ST was run for the first time.

evandrocoan commented 4 months ago

Thanks for clarifying. Until he tests this, we can assume something in his sublime installation is causing this, as with --safe-mode, the problem does not happen.

giampaolo commented 4 months ago

OK this is quite interesting. Removing /User directory did indeed solve the problem. After many attempts (delete all User files, then re-add them one by one) I finally figured out the culprit. It's this option in Preferences.sublime-settings:

"gtk_client_side_window_decorations": false,

If I remove this line on_exit executes immediately. Or to put it in another way: this option makes plugin_host terminate much later.

evandrocoan commented 4 months ago

Thanks for investigating and reporting back. This discovery should help other users, too. We can leave this problem to the Sublime Text development team to fix, as it should now be simple for them to reproduce.

BenjaminSchaaf commented 3 months ago

I can't reproduce this issue with that setting. That setting also has zero effect on the plugin hosts; they don't read it nor act on it. Neither do I see how GTK could have any effect here.