josh-berry / tab-stash

Firefox extension to save and restore tabs as bookmarks. Clear your tabs, clear your mind.
https://josh-berry.github.io/tab-stash/
Mozilla Public License 2.0
801 stars 45 forks source link

Tab state mismatch -> invalid tab id. #321

Closed sbn-purchark closed 1 year ago

sbn-purchark commented 1 year ago

System Details

Windows 10 FF latest stable Tab Stash latest stable

Installed Browser Extensions:

Happens with a clean FF profile with only Tab Stash with no changes to FF or Tab Stash defaults.

Describe the Bug

I have this PHP web app, it has a backup/restore page, about 50% of the time when I close the tab after doing a backup, the tab momentary disappears from the unstashed tabs and then it comes back. Clicking on it or deleting it results in an invalid tab id error, then it's gone. Reloading tab stash UI will also clear it out.

Steps to Reproduce

The PHP web app is obviously doing something odd (it wouldn't be the only thing), there is no additional detail in the console logs besides the affected lines/files in the code when I attempt to delete it. I actually need some logging when I close the tab, but there is nothing.

It only happens if I actually do a backup, just visiting and closing the page does not cause an issue.

Maybe some wonky JS on the page. I would appreciate any pointers for what to look at, on that side of things.

Impact

I've ignored this for a some time now and it has persisted through numerous software updates. It doesn't really bother me and I should automate the backups in the background anyways.

Additional Details

19:14:34.157 Error: Invalid tab ID: 26 button.js:6606:11 19:14:34.161 Uncaught (in promise) Error: Invalid tab ID: 26 undefined


Readers: If you are also experiencing this bug, please vote for it by giving the ORIGINAL POST a thumbs-up using the :smiley: button. You are welcome to leave comments and discuss the issue if you have more details to add, but "Me too!" comments are not counted by the voting system.

josh-berry commented 1 year ago

Very strange! This sort of thing can happen if Tab Stash's view of what's open gets out of sync with the browser's, but I have not seen something like this happen before.

The only thing I can think of, off the top of my head, is that the backup/restore page you mentioned is doing something weird at unload time that is disturbing the state of the tab, AND Firefox is sending events to Tab Stash in the wrong order (e.g. it says the tab is closed, and THEN says the tab has been updated). In the page itself, I would look at window-level events like onUnload, beforeUnload, pageHide, etc.

On the Tab Stash side, there is unfortunately not a lot of logging to catch these kinds of things, but I can look into adding some additional logs for the next release, and hopefully that will help narrow it down.

I'll be curious to hear what you find!

sbn-purchark commented 1 year ago

The words "unload" or "pagehide" do not exist in the code. So far all I've found is a window load in this 3rd party JS behavior script which does stuff with CSS (Using CSS selectors to apply Javascript behaviours)...

https://pastie.io/pbyllc.js

I didn't think to disable JS last time, and yes that prevents the issue. The site also does some AJAX to insert new content on the page instead of refreshing.

Removing behavior.js entirely from the picture also prevents the issue, so it's in there somewhere.

josh-berry commented 1 year ago

Yeah, I don't see anything in there that could lead to the kind of weirdness you're seeing with Tab Stash, though that code itself is ... very quaint. I would guess there is probably some other bit of code that depends on behavior.js which is causing the problem.

sbn-purchark commented 1 year ago

I was thinking along the same lines. Boring accounting software, definitely feels quaint. They keep it up2date enough to work on current OS.

KarboniteKream commented 1 year ago

I'm seeing a similar problem, quite often. I can't really say it's due to some specific page or web application, nor can I reliably reproduce it. If you can add some additional logs, that would be helpful.

I can also install a custom version of the extension from a temporary branch, if you're willing to add a bunch of debug logs, to help investigate.

sbn-purchark commented 1 year ago

I noticed that having more tabs opened made it more likely the bug would occur and closing all but the backup page seems to stop it from occurring.

sbn-purchark commented 1 year ago

Just saw a Twitch "unstashed tab" which I had closed earlier today, hitting the X gave the usual error. I have more tabs open than usual lately.

josh-berry commented 1 year ago

@KarboniteKream Much appreciated! For you and anyone else who wants to help with debugging, I just pushed some changes to master with some tracing / extra debug logs, and also a way to dump what Tab Stash thinks the state of the world is.

Here's what I would suggest:

  1. Build Tab Stash following the README
  2. Load your build into your browser following the instructions in the contributing guidelines
  3. Open the Tab Stash UI in a tab (right-click the extension icon and choose "Show Stashed Tabs in a Tab")
  4. Open the inspector on that tab and in the JS console, set trace.model = true and trace.tabs = true
  5. Reproduce the problem
  6. You should get a bunch of console logs showing the various tab/window events that Tab Stash was processing. When the crash happens, you should also get some additional info on the state of Tab Stash at the time of the crash, and the state after recovery/reload. (Comparing those two states might help shed some light on what was wrong/missing.)

There is also a global variable, model, which you can use to poke around what Tab Stash sees as the state of the world. You can use anything hanging off of model to do basically anything that Tab Stash can do, but in particular, model.tabs.dumpState() will report info on what Tab Stash sees as your open tabs/windows.

One important note, though: the logs are not redacted in any way, and GitHub is accessible by anyone on the Internet, so just keep that in mind before posting any logs in the issue—you may want to read through them and scrub any URLs, page titles, etc. you're not comfortable sharing in public.

Hope this helps, I'll be curious to hear what you find!

sbn-purchark commented 1 year ago

I was able reproduce with a clean FF instance with only this extension installed and closing that one particular app tab. This will be good. I'll be trying this out real soon.

KarboniteKream commented 1 year ago

Thank you! I've built and installed it, and I'll submit some redacted logs after I can reproduce it a few times.

sbn-purchark commented 1 year ago

Failed to reproduce in clean default Linux FF in the Ubuntu desktop (latest) virtual machine where I built tab-stash. It seems to happen more likely when the system/browser is under more load so here's the log from my current state of FF on Windows 10. Tab 66 is the one.

I used the current LTS node/npm pre-built for the build.

https://pastie.io/ysdvlm.yml

Going to try a clean FF profile on Windows 10 next since I easily reproduced there earlier.

What do you prefer for log/file uploads? Is there an easy way to do that with github that I'm missing?

sbn-purchark commented 1 year ago

Here is the clean FF profile repro on Windows including dumpState()

https://pastie.io/cpecbj.groovy

I wanted to do a dump state between the backup finish and close tab, but it does not seems to want to fail with that added delay. It fails a lot easier if I don't pause between backup finish and tab close, again pointing at some relationship to browser performance. I'd probably have a hard time reproducing if my PC wasn't way overdue for an upgrade.

josh-berry commented 1 year ago

@sbn-purchark Thanks, both of those logs are helpful. I have a suspicion it's either a problem with events getting delivered in the wrong order, OR a problem with how Tab Stash is loading its model initially—in both sets of logs, I see that the same tab is getting created, then removed, then created again.

I added a few more logs in master; can you pull and try one more time, but this time, instead of setting the trace. variables before the test, just add ?trace=model,tabs to the end of Tab Stash's URL (so it looks like moz-extension://.../stash-list.html?trace=model,tabs). With the new commit in master, this will turn on tracing at the very beginning (before the page load starts) so I can see when/how the model is loading itself.

What do you prefer for log/file uploads? Is there an easy way to do that with github that I'm missing?

Anything is fine; there is https://gist.github.com/ if you like, or I think you can just drag/drop files directly into the comment box.

sbn-purchark commented 1 year ago

How did I forget to try drag-in-drop. Thanks!

I saw your reply, posting what I had done in case it's useful...

I can also easily reproduce by rapidly open & closing that backup page. Not even doing the backup.

Just that page, I was not able reproduce using a different page in the same app using that method.

console-export-2023-2-5_14-38-20.txt

Here's the "backup page" source in the browser: page source.txt (Course minus the JS loaded in from other files)

sbn-purchark commented 1 year ago

console-export-2023-2-5_15-21-20.txt

I used the rapid technique.

josh-berry commented 1 year ago

Yup, I can see clearly what happened now. Firefox is delivering events out of order, AND is reporting outdated information when Tab Stash is trying to recover.

We see the tab get created here:

15:19:50.096 [tabs] event tabCreated window 1 tab 172 about:blank 
Object { id: 172, index: 1, windowId: 1, highlighted: true, active: true, attention: false, pinned: false, status: "complete", hidden: false, discarded: false, … }
debug.ts:34:34

Then it is almost immediately removed (within maybe 0.1 seconds) here:

15:19:50.175 [tabs] event tabRemoved 172 debug.ts:34:34
15:19:50.175 [tabs] event ...tabRemoved 172 
Object { window: Proxy, index: 1 }
debug.ts:34:34

But then, slightly after that, we see an "updated" event for the removed tab:

15:19:50.249 [tabs] event tabUpdated 172 undefined 
Object { isArticle: true }
debug.ts:34:34

There's a bug in the error handling (which I will fix), so we don't actually see this error in the log, but this update actually fails, because the tab no longer exists. The error handler code triggers a reload of the model:

15:19:50.249 [tabs] (Re-)loading the model debug.ts:34:34
15:19:50.256 [tabs] event tabCreated window 1 tab 163 moz-extension://d84dff77-e49b-4023-b1c5-baef863b3358/stash-list.html?trace=model,tabs 
Object { id: 163, index: 0, windowId: 1, highlighted: true, active: true, attention: false, pinned: false, status: "complete", hidden: false, discarded: false, … }
debug.ts:34:34
15:19:50.256 [tabs] event tabCreated window 1 tab 172 https://erp/admin/backups.php? 
Object { id: 172, index: 1, windowId: 1, highlighted: false, active: false, attention: false, pinned: false, status: "loading", hidden: false, discarded: false, … }
debug.ts:34:34
15:19:50.257 [tabs] Model (re-)load finished; seen events since load started = false debug.ts:34:34

And during that reload, we can see that Firefox wrongly tells us that tab 172 still exists (the tabCreated event above is artificial—the model reload populates the model by calling the same code that handles the event). This can also be seen in your dumpState() call after you closed the tab.

Then, when you try to close the non-existent tab 5 seconds later, we see the crash:

15:19:55.475 [tabs] removing tabs 
Array [ 172 ]
debug.ts:34:34
15:19:55.478 Error: Invalid tab ID: 172 oops.ts:30:10

The crash triggers another reload of the model and, this time as expected, the tab no longer appears in dumpState().

sbn-purchark commented 1 year ago

Cool, glad I could help!

sbn-purchark commented 1 year ago

I did one more test to see how it looks with that error handling change... console-export-2023-2-5_16-16-37.txt

Error: Got change event for unknown tab 181 is the additional crash message I got when the state mismatch happens.

josh-berry commented 1 year ago

Yup, that's what I would expect—good to confirm, though!

KarboniteKream commented 1 year ago

It took me a while to get it to reproduce, but here's my log as well (I removed a bunch of stuff, and replaced URL and tab titles): https://gist.github.com/KarboniteKream/99d4d1f2e88778d59ba9be6f555010e2

Seems like my case is similar, it receives tabUpdated after tabRemoved. This happened while closing some tabs, without any interaction with Tab Stash, but I have the sidebar open at all times. I've also had cases where the error happens when clicking on a tab in the sidebar, but I haven't reproduced that one yet.

EDIT: Got another reproduction, this time exactly the same as the issue reported by @sbn-purchark: https://gist.github.com/KarboniteKream/8cced38fbd0c9d391a92fbba66cfbe4d

josh-berry commented 1 year ago

@sbn-purchark @KarboniteKream I just pushed a workaround/fix for this to master; instead of seeing the crash in the UI, you should only see a warning get logged to the JS console (and then the tab should actually disappear in the UI like it's supposed to). Let me know if it works for you?

KarboniteKream commented 1 year ago

Thanks! I'll test it out during the week. If my understanding is correct, it's not possible to completely fix this issue due to Firefox reporting the wrong state? Or does your commit actually prevent the zombie tab from showing up?

josh-berry commented 1 year ago

@KarboniteKream It should stop the crash AND prevent the zombie tab from showing up. So Tab Stash should now work correctly, even though Firefox is still doing the wrong thing.

KarboniteKream commented 1 year ago

Understood, thank you very much!

sbn-purchark commented 1 year ago

Tested and functions as described for the two methods I came up to reproduce it.

BTW, I started having it happen to random pages too lately.

KarboniteKream commented 1 year ago

I've been using the new build today and it seems to work well. 👍

EDIT: Actually an error just popped up while I was writing this reply. Unfortunately I didn't have tracing on, but the error is Got activated event for unknown tab 499. So I guess there's another method that needs to be adjusted.

And another zombie tab (498) showed up at the same time, that threw an error when closing. I'll turn trace debug back on, and report back.

KarboniteKream commented 1 year ago

Apart from the above issue, I can no longer reproduce any errors.

josh-berry commented 1 year ago

Glad to hear it! Did you ever get a trace for the Got activated event for unknown tab error?

KarboniteKream commented 1 year ago

No luck yet 😞

KarboniteKream commented 1 year ago

I was able to reproduce the error, but I have no idea why. I got the trace about tab 468 which failed to activate, but there was no "created" event at any point, so the trace looks kinda useless: https://gist.github.com/KarboniteKream/6fc8dc7c433f29c15da2adb46ce916e9

I don't really remember what I was doing to trigger this, but I did briefly open the developer console, perhaps that caused some issues.

josh-berry commented 1 year ago

@KarboniteKream That's mystifying. I can't think of any reason why the developer tools would matter; AFAIK they're not exposed to extensions as tabs/windows at all.

This seems like it might be a different bug, though, since there weren't any other tab creation/removal events near the time of the onActivated event.

I'll go ahead and close this bug out, but if you see the Got activated event for unknown tab crash again, please feel free to open a new bug. Next time you see it, it might be interesting to ask the browser what it knows about that particular tab, and compare with what Tab Stash's model shows. You can do await browser.tabs.get(<id>) in Tab Stash's JS console to get the browser's info, and model.tabs.dumpState().tabs[<id>] will give you the Tab Stash side of things. They should look pretty much the same.

KarboniteKream commented 1 year ago

I reproduced the activated error again (I was also messing with Dev Tools in another tab). I checked what you suggested, and both the browser and Tab Stash have no information about that tab. I'll open a new issue in case I manage to figure out exact steps to reproduce it.

EDIT: Figured it out. I'll open an issue.

tomasklaen commented 1 year ago

I keep getting leftover ghost tabs in tab stash for tabs I've already closed. When I try to close them by clicking on X in tab stash list, it crashes with these details:

Browser: Mozilla Firefox 116.0.3 20230815173142 (win x86-64)
Extension: Tab Stash 2.12.1 (normal)

Invalid tab ID: 86
Invalid tab ID: 86

I think it's the same issue? I get it every couple of days (1-2 times per week), it always happens on the last tab in the tab stash list after I close it with Ctrl+W shortcut (triggered by StrokesPlus.net app gesture, but I don't think that matters).

It's been happening since forever, I was just lazy to report until now.

josh-berry commented 1 year ago

@tomasklaen Seems pretty likely, yeah. When the next release comes out, hopefully it will be fixed. Sorry for the annoyance!