Browser Cannot Conntect to Zotero/BBT Hangs during startup

[despdx]

For people joining this issue, you can submit a log either by going to Help => Better BibTeX Debug log, or Help => Send log to fle.io. I really need logs because I cannot yet reproduce the problem, and I need clues to the cause.

If those don't work, and you're on a Mac or Linux, there's another way to capture a debug log

On MacOS, you can get a log by starting Zotero with

/Applications/Zotero.app/Contents/MacOS/zotero -jsconsole -purgecaches -ZoteroDebugText > $HOME/BBT.txt

or on Linux

zotero -P BBTTEST -jsconsole -purgecaches -ZoteroDebugText > $HOME/BBT.txt

Let Zotero start to the point where you have reproduced the problem, then you can shut Zotero down. In both cases, there will be a file BBT.txt in your home directory. You can attach it here, or email it to emiliano.heyns@iris-advies.com`.

Another option, if you're on Linux or Mac and willing to share a full copy of your Zotero profile, I could try to reproduce the problem with that. I don't have access to a Windows machine unfortunately. And I really need a way to reproduce this. To get this copy:

zip $HOME/Zotero.zip $HOME/Zotero

and mail that to emiliano.heyns@iris-advies.com

What I know so far

There is a Zotero method BBT must call. I call it at a time that Zotero has declared it safe to call it. Yet that Zotero method hangs when I do, hanging BBT in the process. Calling it also appears to take down the connector, when these two things have nothing to do with each other. I currently have a workaround in place that helps for some people, not for others, and I cannot reproduce this problem myself, and it's pretty goddamn hard to fix a ghost bug that I cannot see, and that given where it happens, just shouldn't be able to happen.

related Zotero forums threads

https://forums.zotero.org/discussion/comment/463327#Comment_463327 https://forums.zotero.org/discussion/comment/463326#Comment_463326 https://forums.zotero.org/discussion/comment/463324#Comment_463324

[retorquere]

RUY8E96J-euc/6.7.203.2887.6378-7: BBT startup took 00:00:05.185 after waiting 00:00:23.863 for zotero QE2WV8GQ-euc/6.7.203.2887.6378-7: BBT startup took 00:00:05.185 after waiting 00:00:23.863 for zotero

So the bulk of the time is still spent waiting for Zotero. I don't know how long Zotero is busy before or after BBTs startup, new build is incoming to log that. I'm also getting a Windows machine later today. I don't currently have one so that means I can never replicate for Windows.

[github-actions[bot]]

:robot: this is your friendly neighborhood build bot announcing test build 6.7.203.2887.6382 ("log idle")

This update may name other issues, but the build just dropped here is for you; it just means problems already fixed in other issues have been folded into the work we are doing here. Install in Zotero by downloading test build 6.7.203.2887.6382, opening the Zotero "Tools" menu, selecting "Add-ons", open the gear menu in the top right, and select "Install Add-on From File...".

[mjthoraval]

New one: 68K53T59-euc/6.7.203.2887.6382-7

• 3 minutes to load the header
• plus 5 minutes to load the Citation key column

-> So 8 minutes in total to load the Citation key column.

And normal restart: LEYDJBEN-euc/6.7.203.2887.6382-7

[github-actions[bot]]

:robot: this is your friendly neighborhood build bot announcing test build 6.7.203.2887.6385 ("hold idle events")

This update may name other issues, but the build just dropped here is for you; it just means problems already fixed in other issues have been folded into the work we are doing here. Install in Zotero by downloading test build 6.7.203.2887.6385, opening the Zotero "Tools" menu, selecting "Add-ons", open the gear menu in the top right, and select "Install Add-on From File...".

[mjthoraval]

3EVTPXAQ-euc/6.7.203.2887.6385-7

[mjthoraval]

Another one with the sync disabled: IY6WIBTQ-euc/6.7.203.2887.6385-7 And a normal restart: 3XGDWEU7-euc/6.7.203.2887.6385-7

[retorquere]

Interesting:

• IY6WIBTQ shows database activity while BBT is starting up, and then BBT startup took 00:05:18.394 after waiting 00:07:56.551 for zotero
• 3XGDWEU7 has no DB activity and then BBT startup took 00:00:07.661 after waiting 00:00:21.645 for zotero

and it is consistently the database attach that causes these long startup times.

What do you mean by

with the sync disabled

?

[github-actions[bot]]

:robot: this is your friendly neighborhood build bot announcing test build 6.7.203.2887.6388 ("attach in transaction")

This update may name other issues, but the build just dropped here is for you; it just means problems already fixed in other issues have been folded into the work we are doing here. Install in Zotero by downloading test build 6.7.203.2887.6388, opening the Zotero "Tools" menu, selecting "Add-ons", open the gear menu in the top right, and select "Install Add-on From File...".

[mjthoraval]

What do you mean by

with the sync disabled

I have disabled this option:

I understand that it can pollute the debug log for Zotero, and it can also affect loading performances, as it starts syncing during startup. So the devs usually prefer logs without syncing.

3EVTPXAQ-euc/6.7.203.2887.6385-7 (with syncing) took more than 10 minutes to load BBT...

[mjthoraval]

It seems that this has put BBT into the broken state (the Citation key column does not come out).

I was still able to send you a debug log: Send debug log to file.io: JL8C95HS-fio-HQHheDsr3LqJ

I will try again after dinner.

[mjthoraval]

A simple restart first: J9P6JPL6-euc/6.7.203.2887.6388-7

[mjthoraval]

I have reduced the time pressing Ctrl+Page Down to 1 minute. It has also crashed BBT:

Send debug log to file.io: PIJVQTX6-fio-vCYwWmzcx2Zh

[github-actions[bot]]

:robot: this is your friendly neighborhood build bot announcing test build 6.7.203.2887.6389 ("OK, wait for transactions to finish then")

This update may name other issues, but the build just dropped here is for you; it just means problems already fixed in other issues have been folded into the work we are doing here. Install in Zotero by downloading test build 6.7.203.2887.6389, opening the Zotero "Tools" menu, selecting "Add-ons", open the gear menu in the top right, and select "Install Add-on From File...".

[mjthoraval]

5 minutes: PEMRVNMW-euc/6.7.203.2887.6389-7 The Debug ID is: D888904307

Normal: U2GU68NT-euc/6.7.203.2887.6389-7 The Debug ID is: D1200806120

[github-actions[bot]]

:robot: this is your friendly neighborhood build bot announcing test build 6.7.203.2887.6391 ("OK, wait for Zotero to finish this monster transaction")

This update may name other issues, but the build just dropped here is for you; it just means problems already fixed in other issues have been folded into the work we are doing here. Install in Zotero by downloading test build 6.7.203.2887.6391, opening the Zotero "Tools" menu, selecting "Add-ons", open the gear menu in the top right, and select "Install Add-on From File...".

[mjthoraval]

5 minutes: L5NZW2QB-euc/6.7.203.2887.6391-7 Normal: RPJ74TE4-euc/6.7.203.2887.6391-7

[retorquere]

Yeah so it's down to: BBT startup took 00:00:02.974 after waiting 00:13:12.028 for Zotero. So the time BBT took to start up is .just under 3 seconds after waiting for 13(!) minutes for Zotero to be ready, because I'm purposely doing nothing until Zotero is ready. I don't know how to account for it only taking 5 minutes from your test? That's not what the timestamps in the log indicate.

I'll see what I can get from the Zotero crew.

[github-actions[bot]]

:robot: this is your friendly neighborhood build bot announcing test build 6.7.203.2887.6392 ("run Zotero init in parallel")

This update may name other issues, but the build just dropped here is for you; it just means problems already fixed in other issues have been folded into the work we are doing here. Install in Zotero by downloading test build 6.7.203.2887.6392, opening the Zotero "Tools" menu, selecting "Add-ons", open the gear menu in the top right, and select "Install Add-on From File...".

[retorquere]

5 minutes: L5NZW2QB-euc/6.7.203.2887.6391-7 Normal: RPJ74TE4-euc/6.7.203.2887.6391-7

And the difference between those scenarios is whether you have sync enabled? Maybe I should just suspend sync during startup.

[mjthoraval]

Sorry, I have shortened the explanations in the recent tests. To clarify the test procedure:

• I disable the automatic sync, so that it does not interfere with the startup of Zotero.
• I also do not trigger it manually, so that there should not be any sync operation in the reports I send you, to simplify as much as possible.
• The 5 minutes I mention is the time I continuously press on Ctrl+Page Down just after opening Zotero.
• The times that you measure are the recovery times. I reported them earlier, to give you some idea of what I was seeing. But I understand that you have more detailed information from the logs. And I also gave up checking the loading times of Zotero and BBT when it went over 10 minutes...
• In more recent tests, I have also included the simpler procedure, where I do not do anything during startup. I do not press on Ctrl+Page Down and just wait until I can see the Citation key column in the Items Tree. This is what I describe as "5 minutes" (of Ctrl+Page Down) vs "Normal" (no Ctrl+Page Down). So the continuous switching between tabs is the culprit here. I would need to test separately for the influence of allowing the automatic sync to run during startup.

So the steps described above:

The closest torturing steps I could get were:

• Open 10 tabs.
• Close and reopen Zotero
• While reopening, keep pressing Ctrl+Page Down for 5 minutes

-> During that time, and for a few minutes after, it looked like the Citation key column would not load. But after waiting a few minutes, it still came back and worked properly. So if you keep Zotero busy, you can temporarily prevent BBT from loading.

I have focused on these steps, because it shows that I can delay the startup of BBT (as a consequence of the long delay for opening Zotero) as long as I want.

My interpretation is that Zotero tries to perform all the operation that it can register, without any safety fuse to forget old operations that are probably meaningless when they are finally performed. That would explain why the accumulation of 5 minutes of instructions to switch between tabs and load them end up in more than 10 minutes to recover. But I have no idea how it actually works, so this is just guessing.

To be fair, this test case is probably not something that would really need to be optimized against, as it is quite far from realistic usage. But I have noticed that the recent versions of the betas are significantly slower to load. I guess that it is related to all the additional layers that add to the loading time: new UI, new header of the Item Pane, preview, automatic extraction of references, figures, equations, automatic extraction of table of content, ... With all these extra loads, whenever one of these steps has troubles, it can delay the whole loading process. So the test case is designed to push the limits to something easier to quantify than the extra 10 or 20 seconds observed to start Zotero.

Let me know if I should continue doing these tests, or if the simple "Normal" restart process is sufficient for optimizing the startup of Zotero and loading of BBT.

[retorquere]

• The 5 minutes I mention is the time I continuously press on Ctrl+Page Down just after opening Zotero.

I don't know what this does

• The times that you measure are the recovery times

Not really I think? The times I measure are just various steps in the BBT startup.

• the loading times of Zotero and BBT when it went over 10 minutes...

This is really just the Zotero startup time. It takes 13 minutes on your system from the time that BBT is told it can start to the time that it can actually safely install translators and access the database in that last test.

• So the continuous switching between tabs

ah that's the Ctrl+Page Down?

is the culprit here. I would need to test separately for the influence of allowing the automatic sync to run during startup.

That would be really helpful. If sync works OK, but tab switching triggers this, then they'll have an easier time figuring this out. Strange though, because it's their database access and the translators install which are the massive delays, and I don't see how that interacts with tab switching. But if that's something that happens even without BBT installed, the Zotero crew will want to get on that.

[mjthoraval]

Yes, Ctrl+Page Down is the shortcut for switching to the next tab. It is cyclic, so the tab after the last one is the first one, i.e. the library tab. So it just continuously cycles through the tabs if I keep pressing the shortcut.

I have tested the "5 minutes" procedure with all plugins disabled, included BBT, and doing a Restart with Logging Enabled. Here is a debug output obtained: The Debug ID is D2093420213.

It still takes around 3 minutes after stopping to press Ctrl+Page Down to load the header of the Item Pane, with one item selected in the Items Tree. That means 8 minutes after actually starting Zotero. But this time can be increased to any value you want, as continuously switching tabs will prevent Zotero from loading as long as you keep pressing it. That seems to be similar to the loading time observed with BBT enabled. But I don't know if there are still operations still running in the background after that.

I can provide more testing to the devs if they think it is useful.

To see the influence of the automatic sync during loading, I just performed the "Normal" procedure: I just restart without doing anything else.

• Automatic sync disabled: 7HZEZQYK-euc/6.7.203.2887.6392-7
• Automatic sync enabled: FLI3WPRD-euc/6.7.203.2887.6392-7

[retorquere]

Here is a debug output obtained: The Debug ID is D2093420213.

I have no access to those, but if you have the debug log plugin (which does nothing except add a menu entry) you can submit a log to file.io, which I can access.

It still takes around 3 minutes after stopping to press Ctrl+Page Down to load the header of the Item Pane, with one item selected in the Items Tree.

That's strictly a Zotero problem then.

But I don't know if there are still operations still running in the background after that.

There are, but they take seconds at most.

Automatic sync disabled: 7HZEZQYK

BBT startup took 00:00:07.163 after waiting 00:00:17.911 for Zotero

Automatic sync enabled: FLI3WPRD

BBT startup took 00:00:10.721 after waiting 00:00:19.585 for Zotero

so the sync is not the issue then (assuming something was actually syncing). The tab-switching wedges something in Zotero, and since BBT waits for that to clear, it will start up very late. I've not heard back from the devs, so if you could post this disabled-plugins scenario on their forums, that would be really appreciated.

[mjthoraval]

Here it is with more details: https://forums.zotero.org/discussion/114993/zotero-7-beta-switching-tabs-delays-the-loading-of-zotero

The crazy RAM ramp up for more than 10 minutes after releasing the shortcut is what I meant by "operations still running in the background after that".

[mjthoraval]

I have tried to produce one for you, but it did not work:

The data submitted to Zotero (to keep a record of it): The Debug ID is D1698125593.

I still get the same error for a normal restart. So the plugin is not working for me.

Debug Log for Zotero version 2.0.17 Zotero 7.0.0-beta.84+71f83c0a3 (64-bit) Windows 10

[retorquere]

Blegh another thing that dropped out of 7 then. That problem is easy to fix though. I'll get a new version out when I'm home.

[retorquere]

Nope, that still works on beta 84. I don't know why FormData is undefined for you. A new build will drop soon that will confirm whether it actually is. Please try a new log from that (either BBT or file.io)

[github-actions[bot]]

:robot: this is your friendly neighborhood build bot announcing test build 6.7.203.2887.6397 ("FormData not defined?")

This update may name other issues, but the build just dropped here is for you; it just means problems already fixed in other issues have been folded into the work we are doing here. Install in Zotero by downloading test build 6.7.203.2887.6397, opening the Zotero "Tools" menu, selecting "Add-ons", open the gear menu in the top right, and select "Install Add-on From File...".

[mjthoraval]

• With only the BBT plugin enabled: 6RBYDU8G-euc/6.7.203.2887.6397-7
• With only the BBT plugin enabled during restart from file.io: RSJ3S4NV-fio-BUvy8aIDIcmv
• With only the Debug Log plugin enabled: FormData error

I had this already before: https://github.com/retorquere/zotero-better-bibtex/issues/2886#issuecomment-2122164430

[mjthoraval]

But I do not understand why a new BBT version would help understanding the problem with the Debug Log plugin?

[retorquere]

They use a common module to put up the file.io menu entry, so it's surprising to me that it works for BBT but not for debug log. It also just works for me, for both BBT and debug log.

[mjthoraval]

I'm also getting a Windows machine later today.

Is it also working for you on Windows?

[retorquere]

I don't know, I haven't installed the system yet.

[despdx]

Sorry I haven't tried your debug pkgs. Zotero/BBT has been working well, in the sense that BBT isn't hanging for me after auto update. That's the issue I noticed, originally.

If I can find some time next week, though, I'll try your debug pkg.

I also want to say that Zotero doesn't take very long to start up for me. I'm surprised by some of the numbers you are reporting here. I would say maybe 30 seconds at most.

[retorquere]

No need to test these packages, the changes have been rolled into the new release. These extreme startup times need further diagnosis by the Zotero team.