Closed MrSerth closed 2 months ago
2.0.19 of debug-log is up.
Do you have any idea what could be going so bad with my Zotero installation?
I don't yet. The cache is being used before it is opened, and it is being closed before shutdown, the rest appears to be knock-on damage from that. I'm trying to find out what part of the code does the use-before-open and the early-close.
:robot: this is your friendly neighborhood build bot announcing test build 6.7.226.6877 ("make cache fetch optional for error report")
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.226.6877, opening the Zotero "Tools" menu, selecting "Add-ons", open the gear menu in the top right, and select "Install Add-on From File...".
I think 6877 will enable the regular debug log for you.
Thanks for the two new builds and your time. I installed them early this morning and observed the situation throughout the day. Today, it was quite tough to get the actual error, but I managed to get three reports I can share with you:
6CL8HS8B-fio-ocQVkMuWoRgX
: Another startup-related error occurred:
4MYXZN4H-euc/6.7.226.6877-7
: Intermediate report before exporting, everything here should be included in the next one, too. I already got the feeling something would be off.
4D7RYU74-euc/6.7.226.6877-7
: BBT stopped working, exporting didn't work any longer, and we see a log entry related to a transaction started on a closed database.
Would it be OK for me to get a copy of your zotero folder? I really have no idea what I'm chasing here but if I can reproduce it locally it will give me a much better shot at finding what causes it.
Sure, I can look into exporting the library (just need to remove the syncing, I guess). However, I don't have very clear reproduction steps yet. Rather, it looks like some race condition is happening from time to time.
In a preparation to reproduce the issue again and sharing the library, I created a new Zotero profile as described in the Zotero docs:
/Applications/Zotero.app/Contents/MacOS/zotero -P
Even with this clean and shiny new profile not containing any library items (but just your two plugins), I (finally) managed to reproduce the issue and send a debug log: 57FRNVHJ-fio-xVUPSUeHdpfN
.
The error message I've seen was, once again: UnknownError: The operation failed for reasons unrelated to the database itself and not covered by any other error code.
My best approach to trigger the issue currently is to open and close Zotero (with different timings having it open and in the foreground, move the window to the background, close it without quitting, waiting a varying amount of time, reopening it, etc.). To me, it seems like that the "Zotero is running but no window is open" state possible with macOS is causing one of the issues. When trying with Windows (couldn't test Linux), I did not get that state: Closing Zotero (ctrl+W) quit Zotero too, with no trace in Task Manager. On macOS, however, there is a difference between Closing (cmd+W) and quitting (cmd+Q), where closing keeps the program run in the background (shown in Activity Monitor and indicated in macOS Dock).
Sure, I can look into exporting the library (just need to remove the syncing, I guess).
Not an export, a real copy. Cmd-Q zotero, zip up ~/Zotero. Sync info, settings and whatnot is not included in that, that is in your profile. I don't (think I) need that.
Even with this clean and shiny new profile not containing any library items (but just your two plugins), I (finally) managed to reproduce the issue and send a debug log: 57FRNVHJ-fio-xVUPSUeHdpfN.
wait what?!
~That's not the same error though, nothing about the cache or sqlite database connections. I'll try to get the mainwindowload issue sorted, I thought that was separate, but maybe it has an influence.~ strike that, I had missed the cache message.
:robot: this is your friendly neighborhood build bot announcing test build 6.7.226.6906 ("empty error?!")
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.226.6906, opening the Zotero "Tools" menu, selecting "Add-ons", open the gear menu in the top right, and select "Install Add-on From File...".
Thanks for the new build. I tested that again using the empty profile (called Zotero BBT-BugReport-2948
) and reproduced the cache-related issue. The log is uploaded with 35LDZSI3-fio-K6tjARZJnb7C
.
Furthermore, I zipped my personal Zotero folder and the empty one, encrypted that archive with your GPG key D4A1A6BE8F8B32B1E0B7B988EC2B9137E228EB86
, and uploaded it to our Nextcloud: https://nextcloud.hpi.de/s/NzkcPJMFCPsxCiq, Password zCsrznYjgd
I hope you find it useful, thanks again!
how do I decrypt this zip?
:robot: this is your friendly neighborhood build bot announcing test build 6.7.226.6922 ("Merge branch 'master' into gh-2948")
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.226.6922, opening the Zotero "Tools" menu, selecting "Add-ons", open the gear menu in the top right, and select "Install Add-on From File...".
how do I decrypt this zip?
With GPG being installed and your GPG key with fingerprint D4A1A6BE8F8B32B1E0B7B988EC2B9137E228EB86
being available, you simply run:
gpg --output "2024-08-31 Zotero Data Dir MrSerth.zip" --decrypt "2024-08-31 Zotero Data Dir MrSerth.zip.gpg"
Alternatively, I can share the file unencrypted with you, e.g., through a share link via email. I just don't want to make it publicly accessible.
I don't know what "your GPG key with fingerprint D4A1A6BE8F8B32B1E0B7B988EC2B9137E228EB86 being available" means. I am shamefully ignorant of encryption tools. I have received the other.
Here is a debug log with the empty profile and the newest plugin version: EDWEXBSI-fio-Vcc4IcFusPdw
Have you copied your profile to another place at some point? There is the strangest error in the log which a google search seems to indicate is related to a metadata file pointing to the old location of the profile.
This is super roundabout, but can you:
and tell me what the resulting page says
Have you copied your profile to another place at some point? There is the strangest error in the log which a google search seems to indicate is related to a metadata file pointing to the old location of the profile.
No. The profile that is located at ~/Library/Application Support/Zotero/Profiles/protcja8.default
has been created by Zotero 7.0.0 (release version) on August 10, 2024 at 3:06 pm CEST. It has never been moved from that directory.
For the data directory at ~/Zotero
, the case is different: I am using this data directly since years (since February 2019, to be specific) and have used it on other systems, too (before switching to my current machine). There, it has been located at the same place (macOS; same username and same path to the home directory).
Can you tell me what the resulting page says
For both profiles (my regular one and the empty one) it seems to pass, I'd say.
**Regular Profile:**
```
Overview:
Storage is working. This is your first visit or all storage was automatically cleared.
Specific Subsystem Statuses:
LocalStorage
Good: Totally Working. (fullyOperational)
QuotaManager
Good: Totally Working. (fullyOperational)
IndexedDB
Good: Totally Working. (fullyOperational)
Cache API
Good: Totally Working. (fullyOperational)
Debug Info:
{
"v": 1,
"curVersion": 115,
"prevVersion": 0,
"ls": {},
"qm": {
"lastWorkedIn": 115
},
"idb": {
"persistentCreatedIn": 115,
"persistentLastOpenedIn": 115,
"clearDetectedIn": 0
},
"cache": {
"firstCacheCreatedIn": 115,
"unpaddedOpaqueCreatedIn": 0,
"paddedOpaqueCreatedIn": 115
}
}
```
```
Overview:
Storage is working. This is your first visit or all storage was automatically cleared.
Specific Subsystem Statuses:
LocalStorage
Good: Totally Working. (fullyOperational)
QuotaManager
Good: Totally Working. (fullyOperational)
IndexedDB
Good: Totally Working. (fullyOperational)
Cache API
Good: Totally Working. (fullyOperational)
Debug Info:
{
"v": 1,
"curVersion": 115,
"prevVersion": 0,
"ls": {},
"qm": {
"lastWorkedIn": 115
},
"idb": {
"persistentCreatedIn": 115,
"persistentLastOpenedIn": 115,
"clearDetectedIn": 0
},
"cache": {
"firstCacheCreatedIn": 115,
"unpaddedOpaqueCreatedIn": 0,
"paddedOpaqueCreatedIn": 115
}
}
```
Debug Info as Text
Debug Info as Text
For the data directory at ~/Zotero, the case is different
This isn't the problem it turns out. It's having trouble initializing the IndexedDB cache, that's separate from the storage directory. The error of interest is
UnknownError: The operation failed for reasons unrelated to the database itself and not covered by any other error code
but if you have started Zotero with a new profile, all the relevant files would have been recreated, so it can't really be that these are corrupted (which is what what little info I could find on this seems to indicate as the cause of this error).
The empty profile doesn't have any sync info or other privacy-related info? If so, I'd love to have a copy. I need to be able to replicate this locally.
The empty profile doesn't have any sync info or other privacy-related info? If so, I'd love to have a copy. I need to be able to replicate this locally.
Sure, I just shared a copy with you. The archive contains two directories:
Data Directory
: The folder present is stored in my home directory located at ~
.Profile
: The folder present is stored at ~/Library/Application Support
. I zipped everything except my default profile at ~/Library/Application Support/Profiles/protcja8.default
:robot: this is your friendly neighborhood build bot announcing test build 6.7.227.6945 ("Merge branch 'master' into gh-2948")
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.227.6945, opening the Zotero "Tools" menu, selecting "Add-ons", open the gear menu in the top right, and select "Install Add-on From File...".
Can you get me a new log from the empty profile?
Here's another log with the empty profile: VFJBJ9SZ-euc/6.7.227.6945-7
. This time, the native BBT error reporting still worked and I didn't had to use the file.io alternative.
I still don't have clear reproduction steps but rather click around, close and re-open Zotero, ...
New build incoming, same with the empty profile again please, but what error are you experiencing in VFJBJ9SZ-euc/6.7.227.6945-7
? As far as I can tell the cache was opened normally, the only problem I can see is that the error report can't fetch the cache.
:robot: this is your friendly neighborhood build bot announcing test build 6.7.227.6951 ("log on all disabled activity")
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.227.6951, opening the Zotero "Tools" menu, selecting "Add-ons", open the gear menu in the top right, and select "Install Add-on From File...".
Here's a new log: WYHCNWPD-euc/6.7.227.6951-7
without any item in the library.
New build incoming, same with the empty profile again please, but what error are you experiencing in
VFJBJ9SZ-euc/6.7.227.6945-7
? As far as I can tell the cache was opened normally, the only problem I can see is that the error report can't fetch the cache.
With the empty library, it is difficult to perform an export. Hence, I am relying on the debug output to identify errors as an indication:
For testing (and after sending WYHCNWPD-euc/6.7.227.6951-7
), I've added one of my last publications to the empty profile through the "magic wand" by copying 10.1145/3657604.3662037
. Then, I performed a right click and chose to export the item, which failed with a hang:
This issue, like a hang in exporting items, is one of the consequences when BBT has "crashed". Here is a second debug log of that state with additional errors: 9RCUKS37-euc/6.7.227.6951-7
. Regardless of how long I'll wait, I won't get the export and can only force quit Zotero.
:robot: this is your friendly neighborhood build bot announcing test build 6.7.229.6974 ("more logging")
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.229.6974, opening the Zotero "Tools" menu, selecting "Add-ons", open the gear menu in the top right, and select "Install Add-on From File...".
I got new logs, both with new error messages:
2INLQ5MD-euc/6.7.229.6974-7
: The first error occurred during startup:
9YQEKAK9-euc/6.7.229.6974-7
: After the first error occurred, I tried exporting the only item available: Error: An error has occurred while trying to export the selected file.
Despite the new message, the situation improved: Zotero didn't show a full overlay and I could still quit normally. However, the export didn't work since the file created was empty.
Once the first error occurs, the rest is knock-on damage. I'm just trying to figure out why you can't open the indexeddb database. New build incoming.
:robot: this is your friendly neighborhood build bot announcing test build 6.7.229.6977 ("rename cache")
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.229.6977, opening the Zotero "Tools" menu, selecting "Add-ons", open the gear menu in the top right, and select "Install Add-on From File...".
Here's the next log: 66C9VVQT-euc/6.7.229.6977-7
. Error message seen was TypeError: this.db is null
.
Ignore 6979 -- new build incoming.
:robot: this is your friendly neighborhood build bot announcing test build 6.7.229.6980 ("manual open")
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.229.6980, opening the Zotero "Tools" menu, selecting "Add-ons", open the gear menu in the top right, and select "Install Add-on From File...".
Here's the new log with build 6980: Q25CVGLZ-euc/6.7.229.6980-7
.
:robot: this is your friendly neighborhood build bot announcing test build 6.7.229.6982 ("add glitch probe")
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.229.6982, opening the Zotero "Tools" menu, selecting "Add-ons", open the gear menu in the top right, and select "Install Add-on From File...".
I got another TypeError: this.db is null
: V9JXRDC3-euc/6.7.229.6982-7
.
Since you've integrated the glitch test (and it seems damaged), I repeated the test with the Translator Editor:
Then, I've quit Zotero completely and tried a second time. This time, I didn't get any error message, but exporting didn't work either: YYDPDBY6-euc/6.7.229.6982-7
. Regarding the manual glitch test, I got the exact same result.
Do you think this is still BBT-related or rather a (general) Zotero bug I am observing? Or is it related to some initialization / termination order (since I am mostly experiencing these issues on opening / closing Zotero) and the manual glitch test seem to be fine?
Once again: Thank you for all the time and effort you put into this issue -- I really appreciate it! 💐
I have an idea where this may be coming from. It may just involve replacing a library I use.
I have an idea where this may be coming from. It may just involve replacing a library I use.
Or a total rewrite of it. Build incoming.
:robot: this is your friendly neighborhood build bot announcing test build 6.7.230.6993 ("merge latest changes from master")
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.230.6993, opening the Zotero "Tools" menu, selecting "Add-ons", open the gear menu in the top right, and select "Install Add-on From File...".
If this solves the problem I really want to roll it out in a new release.
Awesome, thank you! We are getting close, the new plugin version seems much more robust! 💪
While testing, I experienced one remaining issue during startup: TypeError: window is null
, logged in: B5IG4VNI-euc/6.7.230.6993-7
. However -- and that's great news -- exporting an item still worked correctly afterwards 🥳
When playing around with the plugin version, I also captured other errors in the error console (without any visible error alert popping up): AAIIJEXH-euc/6.7.230.6993-7
. In this case, similarly, exporting still worked 🥳
With this experience, I would attest your recent changes a positive impact, mostly addressing the issue.
window is null
will be addressed as part of #2965; for the Transaction is already committing
I have a build incoming. Looks like I have a new library to my name -- none of the existing indexedDB libraries seem to address this. Not that I could blame them, necessarily; the people who specced indexedDB have made some really strange choices (edit: stuff like this. The transaction semantics of indexedDB are nuts).
No idea why your system so consistently triggered these problems but very happy to have them addressed.
:robot: this is your friendly neighborhood build bot announcing test build 6.7.230.6996 ("sync promises for indexeddb")
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.230.6996, opening the Zotero "Tools" menu, selecting "Add-ons", open the gear menu in the top right, and select "Install Add-on From File...".
Thanks for pointing out the issues with IndexedDB; I haven't used them myself yet, but it really sounds painful. I am glad you took the challenge to implement the necessary changes there, making BBT more robust and fault-tolerant.
I think that this new version is fine, and I haven't found a remaining issues with the transaction handling (just window is null
, being handled in the other issue). Just to be sure, here's another debug log: It still contains some errors, but I would assume those are rather Zotero related? 2HQVQ4BB-euc/6.7.230.6996-7
Well that is annoying. The indexedDB issue still exists for the cache dump. That's not critical but it is very useful to have it for debug logs. I'll look into that later.
I use indexedDB because I need to share data between Zotero and the background thread I use for exports, and there are only a few mechanisms that allow that without also using a lot of memory. IndexedDB, as broken as it is, is the best option.
The other issues are general Zotero issues, yes.
:robot: this is your friendly neighborhood build bot announcing test build 6.7.230.7000 ("separate transactions for dump -- indexedDB is so b0rked")
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.230.7000, opening the Zotero "Tools" menu, selecting "Add-ons", open the gear menu in the top right, and select "Install Add-on From File...".
Thanks for looking into the remaining minor issue. Here is another debug log (potentially still showing an issue, I assume?): 4Z9P8T3S-euc/6.7.230.7000-7
:robot: this is your friendly neighborhood build bot announcing test build 6.7.231.7003 ("Merge branch 'master' into gh-2948")
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.231.7003, opening the Zotero "Tools" menu, selecting "Add-ons", open the gear menu in the top right, and select "Install Add-on From File...".
Debug log ID
N/A, since BBT wasn't loaded any longer After a restart:
X9SLMXCX-fio-24vflMf76l5q
What happened?
This issue is probably a follow-up to #2892.
Zotero just crashed during the update from 7.0.0 to 7.0.1. After I started it again, it first worked fine. As soon as I closed Zotero, I saw two errors
directly followed by:
In the development console, another error is shown (that I reported earlier as #2892 already):
Development Console
![Bildschirmfoto 2024-08-15 um 11 44 56](https://github.com/user-attachments/assets/fad0fbb4-98b8-49e0-a30c-6ec22021db03)
Further, I saw two other warnings when looking into the logs:
Development Console as text
``` DEPRECATION WARNING: Calling FileUtils.getDir(..., ..., true) causes main thread I/O and should be avoided especially during startup/shutdown You may find more details about this deprecation at: https://bugzilla.mozilla.org/show_bug.cgi?id=921157 resource://gre/modules/FileUtils.sys.mjs 62 FileUtils_getDir resource://gre/modules/UpdateService.sys.mjs 1057 getUpdateDirCreate resource://gre/modules/UpdateService.sys.mjs 1160 getReadyUpdateDir resource://gre/modules/UpdateService.sys.mjs 1332 cleanUpReadyUpdateDir resource://gre/modules/UpdateService.sys.mjs 1442 cleanupReadyUpdate resource://gre/modules/UpdateService.sys.mjs 3116 AUS__postUpdateProcessing resource://gre/modules/UpdateService.sys.mjs 2715 AUS_observe resource://gre/modules/UpdateServiceStub.sys.mjs 109 UpdateServiceStub [Deprecated.sys.mjs:79:13](resource://gre/modules/Deprecated.sys.mjs) warning resource://gre/modules/Deprecated.sys.mjs:79 FileUtils_getDir resource://gre/modules/FileUtils.sys.mjs:62 getUpdateDirCreate resource://gre/modules/UpdateService.sys.mjs:1057 getReadyUpdateDir resource://gre/modules/UpdateService.sys.mjs:1160 cleanUpReadyUpdateDir resource://gre/modules/UpdateService.sys.mjs:1332 cleanupReadyUpdate resource://gre/modules/UpdateService.sys.mjs:1442 AUS__postUpdateProcessing resource://gre/modules/UpdateService.sys.mjs:3116 AUS_observe resource://gre/modules/UpdateService.sys.mjs:2715 UpdateServiceStub resource://gre/modules/UpdateServiceStub.sys.mjs:109 Error: Addon must include an id, version, and type 2 [XPIProvider.jsm:1723:13](resource://gre/modules/addons/XPIProvider.jsm) unreachable code after return statement [util.js:205:4](resource://zotero/bluebird/util.js) Missing resource in locale de: better-bibtex.ftl Plugin better-bibtex@iris-advies.com is missing bootstrap method 'onMainWindowUnload' Zotero.getMainWindow() is null [better-bibtex.js:8695](jar:file://~/Library/Application%20Support/Zotero/Profiles/protcja8.default/extensions/better-bibtex@iris-advies.com.xpi!/content/better-bibtex.js) 1723714458819 addons.xpi-utils WARN Add-on better-bibtex@iris-advies.com is not compatible with application version. 3 Missing resource in locale de: toolkit/global/commonDialog.ftl 2 InstallTrigger is deprecated and will be removed in the future. 4 [reader.js:20134:16](resource://zotero/reader/reader.js) Missing resource in locale de: better-bibtex.ftl DOMException: Could not get children of file(~/Library/Application Support/Zotero/Crash Reports/events) because it does not exist [CrashManager.sys.mjs:663:17](resource://gre/modules/CrashManager.sys.mjs) _getUnprocessedEventsFiles resource://gre/modules/CrashManager.sys.mjs:663 Missing resource in locale de: toolkit/about/aboutAddons.ftl Missing resource in locale de: toolkit/about/abuseReports.ftl Missing resource in locale de: browser/components/mozSupportLink.ftl 2 Missing resource in locale de: toolkit/global/extensions.ftl This page is in Quirks Mode. Page layout may be impacted. For Standards Mode use “”. ```
Zotero Debug output
``` 1723714426727 addons.xpi WARN Checking /Applications/Zotero.app/Contents/Resources/distribution/extensions for addons 1723714426847 addons.xpi-utils WARN addMetadata: Add-on undefined is invalid: Error: Invalid addon ID: expected addon ID undefined, found undefined in manifest(resource://gre/modules/addons/XPIDatabase.jsm:3108:15) JS Stack trace: addMetadata@XPIDatabase.jsm:3108:15 processFileChanges@XPIDatabase.jsm:3569:26 checkForChanges@XPIProvider.jsm:3121:60 startup@XPIProvider.jsm:2532:12 callProvider@AddonManager.sys.mjs:228:31 _startProvider@AddonManager.sys.mjs:536:17 startup@AddonManager.sys.mjs:742:14 startup@AddonManager.sys.mjs:3666:26 observe@amManager.sys.mjs:73:29 [JavaScript Error: "Error: Addon must include an id, version, and type" {file: "resource://gre/modules/addons/XPIProvider.jsm" line: 1723}] [JavaScript Error: "Error: Addon must include an id, version, and type" {file: "resource://gre/modules/addons/XPIProvider.jsm" line: 1723}] [JavaScript Error: "Zotero.getMainWindow() is null" {file: "jar:file://~/Library/Application%20Support/Zotero/Profiles/protcja8.default/extensions/better-bibtex@iris-advies.com.xpi!/content/better-bibtex.js" line: 8695}] 1723714458819 addons.xpi-utils WARN Add-on better-bibtex@iris-advies.com is not compatible with application version. 1723714458819 addons.xpi-utils WARN Add-on better-bibtex@iris-advies.com is not compatible with application version. 1723714458819 addons.xpi-utils WARN Add-on better-bibtex@iris-advies.com is not compatible with application version. appName => Zotero, version => 7.0.1 (ARM64), os => macOS 14.6.1, locale => de, extensions => Better BibTex for Zotero (6.7.221, extension) ```
Please let me know if you need further details or assistance with the localization for German. Thanks for the great plugin.