brimdata
Need version and "zed serve" startup failures in logs
Repro is with Zui Insiders 0.30.1-196. Before repro I've deleted the folder "$HOME/Library/Application Support/Zui - Insiders" to simulate a user starting fresh at that old release.
In the video below, I start with having launched Zui Insiders 0.30.1-196 and let it hang out long enough to auto-update itself to the latest, which is currently Zui Insiders 1.4.2-0. As you can see, when it comes up it indicates the Zed lake service could not be reached.
https://github.com/brimdata/zui/assets/5934157/380c93f2-2f3b-40ab-9c5e-47b4eb82792c
Our own @nwt happened to bump into this specific problem because he'd not launched Zui Insiders in a while. Indeed, if you look at the release notes for some of the Zui Insiders releases such as 0.30.1-197 we can see this problem was anticipated: We'd made some non-backward-compatible changes to the lake storage format and therefore made some migration tools available and notified users as to their availability. However, that was long enough ago that I'd forgotten to recognize that as a likely cause for the symptom observed, and so I know it's unreasonable to think our users might remember as well. Thankfully it was not difficult to jump on a Zoom and do some "live" debug with @nwt and confirm what was going on. But we don't always have the liberty of doing this with our community users (and it's made more difficult when they're in far-off timezones or in sensitive roles that don't lend themselves to jumping on Zoom sessions and hacking) so my goal here is not to debug that specific issue but rather improve on the ability to debug this kind of problem in the field.
I'll cite two specific things that would have helped here, hence would like to make the case for adding now in hopes they'll be there the next time something like this happens.
-
Put the app version info into the
main.log. Ideally, make it one of the first things logged.
The following is what was in my main.log after the repro steps above. Notice the lack of version info.
[2023-11-14 15:07:23.220] [info] booting main with: {
lakePort: 9988,
lakeRoot: '/Users/phil/Library/Application Support/Zui - Insiders/lake',
lakeLogs: '/Users/phil/Library/Application Support/Zui - Insiders/logs',
lake: true,
devtools: false,
appState: '/Users/phil/Library/Application Support/Zui - Insiders/appState.json',
releaseNotes: true,
autoUpdater: true,
singleInstance: true
}
[2023-11-14 15:07:23.481] [debug] Initializing: auto-update.js
[2023-11-14 15:07:23.513] [debug] Initializing: custom-protocol.js
[2023-11-14 15:07:23.516] [debug] Initializing: log-filters.js
[2023-11-14 15:07:23.517] [debug] Initializing: secure-web-contents.js
[2023-11-14 15:07:23.524] [debug] Initializing: shortcuts.js
[2023-11-14 15:07:23.527] [debug] Initializing: user-tasks.js
[2023-11-14 15:07:23.528] [debug] Initializing: window-events.js
[2023-11-14 15:07:23.529] [info] initializers loaded
[2023-11-14 15:07:23.530] [debug] IPC Listening: windows.autosave
[2023-11-14 15:07:23.530] [debug] IPC Listening: closeWindow
[2023-11-14 15:07:23.533] [debug] IPC Listening: exportQueries
[2023-11-14 15:07:23.533] [debug] IPC Listening: featureFlags
[2023-11-14 15:07:23.534] [debug] IPC Listening: getAppMeta
[2023-11-14 15:07:23.534] [debug] IPC Listening: getGlobalState
[2023-11-14 15:07:23.535] [debug] IPC Listening: getWindowState
[2023-11-14 15:07:23.535] [debug] IPC Listening: dispatchGlobalFromWindow
[2023-11-14 15:07:23.535] [debug] IPC Listening: dispatchFromMain
[2023-11-14 15:07:23.536] [debug] IPC Listening: importQueries
[2023-11-14 15:07:23.537] [debug] IPC Listening: loadStart
[2023-11-14 15:07:23.537] [debug] IPC Listening: loadEnd
[2023-11-14 15:07:23.538] [debug] IPC Listening: mainArgs
[2023-11-14 15:07:23.538] [debug] IPC Listening: moveToCurrentDisplay
[2023-11-14 15:07:23.538] [debug] IPC Listening: openAboutWindow
[2023-11-14 15:07:23.539] [debug] IPC Listening: detailWindow.open
[2023-11-14 15:07:23.539] [debug] IPC Listening: openDirectory
[2023-11-14 15:07:23.540] [debug] IPC Listening: openSearchWindow
[2023-11-14 15:07:23.540] [debug] IPC Listening: resetState
[2023-11-14 15:07:23.540] [debug] IPC Listening: runCommand
[2023-11-14 15:07:23.541] [debug] IPC Listening: setSecretOp
[2023-11-14 15:07:23.541] [debug] IPC Listening: getSecretOp
[2023-11-14 15:07:23.542] [debug] IPC Listening: deleteSecretOp
[2023-11-14 15:07:23.542] [debug] IPC Listening: showPreferencesOp
[2023-11-14 15:07:23.542] [debug] IPC Listening: showReleaseNotes
[2023-11-14 15:07:23.543] [debug] IPC Listening: showSaveDialogOp
[2023-11-14 15:07:23.543] [debug] IPC Listening: updateSearchAppMenu
[2023-11-14 15:07:23.544] [debug] IPC Listening: windowInitialized
[2023-11-14 15:07:25.558] [debug] IPC Handling: getWindowState
[2023-11-14 15:07:25.558] [debug] IPC Handling: getGlobalState
[2023-11-14 15:07:25.664] [debug] IPC Handling: dispatchGlobalFromWindow
[2023-11-14 15:07:25.665] [debug] IPC Handling: dispatchGlobalFromWindow
[2023-11-14 15:07:25.670] [debug] IPC Handling: dispatchGlobalFromWindow
[2023-11-14 15:07:25.670] [debug] IPC Handling: dispatchGlobalFromWindow
[2023-11-14 15:07:25.671] [debug] IPC Handling: dispatchGlobalFromWindow
[2023-11-14 15:07:25.672] [debug] IPC Handling: dispatchGlobalFromWindow
[2023-11-14 15:07:25.672] [debug] IPC Handling: dispatchGlobalFromWindow
[2023-11-14 15:07:25.673] [debug] IPC Handling: dispatchGlobalFromWindow
[2023-11-14 15:07:25.673] [debug] IPC Handling: dispatchGlobalFromWindow
[2023-11-14 15:07:25.674] [debug] IPC Handling: dispatchGlobalFromWindow
[2023-11-14 15:07:25.674] [debug] IPC Handling: dispatchGlobalFromWindow
[2023-11-14 15:07:25.675] [debug] IPC Handling: featureFlags
[2023-11-14 15:07:25.675] [debug] window registered: { id: 'LfAw5YG1ooS5shKJ3d4xm', name: 'search' }
[2023-11-14 15:07:25.697] [debug] IPC Handling: mainArgs
[2023-11-14 15:07:25.699] [debug] IPC Handling: getAppMeta
[2023-11-14 15:07:25.702] [debug] IPC Handling: dispatchGlobalFromWindow
[2023-11-14 15:07:25.703] [debug] IPC Handling: windowInitialized
[2023-11-14 15:07:25.723] [debug] IPC Handling: updateSearchAppMenu
[2023-11-14 15:07:25.872] [debug] IPC Handling: dispatchGlobalFromWindow
[2023-11-14 15:07:25.879] [debug] IPC Handling: windows.autosave
[2023-11-14 15:07:25.880] [debug] Session Autosaved
[2023-11-14 15:07:25.881] [debug] IPC Handling: dispatchGlobalFromWindow
[2023-11-14 15:07:26.601] [debug] IPC Handling: getWindowState
[2023-11-14 15:07:26.601] [debug] IPC Handling: getGlobalState
[2023-11-14 15:07:26.626] [debug] IPC Handling: dispatchGlobalFromWindow
[2023-11-14 15:07:26.631] [debug] IPC Handling: dispatchGlobalFromWindow
[2023-11-14 15:07:26.632] [debug] IPC Handling: dispatchGlobalFromWindow
[2023-11-14 15:07:26.633] [debug] IPC Handling: dispatchGlobalFromWindow
[2023-11-14 15:07:26.634] [debug] IPC Handling: featureFlags
[2023-11-14 15:07:26.634] [debug] window registered: { id: '6L0NgfV2b_V75BLQPGiIr', name: 'hidden' }
[2023-11-14 15:07:26.636] [debug] IPC Handling: mainArgs
[2023-11-14 15:07:26.636] [debug] IPC Handling: getAppMeta
[2023-11-14 15:07:26.639] [debug] IPC Handling: dispatchGlobalFromWindow
[2023-11-14 15:07:26.639] [debug] IPC Handling: windowInitialized
[2023-11-14 15:07:26.872] [debug] IPC Handling: windows.autosave
[2023-11-14 15:07:26.873] [debug] Session Autosaved
[2023-11-14 15:07:31.785] [debug] window registered: { id: 'd_gQOpQjkJuDeU839nL8x', name: 'about' }
[2023-11-14 15:07:57.260] [error] There was a problem updating the application: Error: The command is disabled and cannot be executed
[2023-11-14 15:07:57.261] [error] There was a problem updating the application: Error: The command is disabled and cannot be executed
[2023-11-14 15:07:57.264] [error] Error: The command is disabled and cannot be executed
at MacUpdater.quitAndInstall (/Applications/Zui - Insiders.app/Contents/Resources/app.asar/node_modules/electron-updater/out/MacUpdater.js:203:26)
at /Applications/Zui - Insiders.app/Contents/Resources/app.asar/dist/js/electron/autoUpdater.js:79:74
at process.processTicksAndRejections (node:internal/process/task_queues:96:5)
[2023-11-14 15:08:00.686] [debug] window unregistered: { id: 'd_gQOpQjkJuDeU839nL8x', name: 'about' }
[2023-11-14 15:08:00.700] [debug] IPC Handling: updateSearchAppMenu
[2023-11-14 15:08:00.788] [debug] IPC Handling: windows.autosave
[2023-11-14 15:08:00.788] [debug] IPC Handling: windows.autosave
[2023-11-14 15:08:00.789] [debug] window unregistered: { id: '6L0NgfV2b_V75BLQPGiIr', name: 'hidden' }
[2023-11-14 15:08:00.792] [debug] window unregistered: { id: 'LfAw5YG1ooS5shKJ3d4xm', name: 'search' }
[2023-11-14 15:08:07.700] [debug] migrating directory /Users/phil/Library/Application Support/Zui - Insiders/data/brimcap-root to /Users/phil/Library/Application Support/Zui - Insiders/plugins/brimcap/storage/root
[2023-11-14 15:08:07.705] [debug] migration success
[2023-11-14 15:08:07.706] [debug] migrating directory /Users/phil/Library/Application Support/Zui - Insiders/data/suricata to /Users/phil/Library/Application Support/Zui - Insiders/plugins/brimcap/storage/suricata
[2023-11-14 15:08:07.776] [debug] migration success
[2023-11-14 15:08:07.776] [debug] removing directory /Users/phil/Library/Application Support/Zui - Insiders/data
[2023-11-14 15:08:07.777] [debug] successfully removed empty folder /Users/phil/Library/Application Support/Zui - Insiders/data
[2023-11-14 15:08:07.777] [info] booting main with: {
lakePort: 9988,
lakeRoot: '/Users/phil/Library/Application Support/Zui - Insiders/lake',
lakeLogs: '/Users/phil/Library/Application Support/Zui - Insiders/logs',
lake: true,
devtools: false,
appState: '/Users/phil/Library/Application Support/Zui - Insiders/appState.json',
autosave: true,
releaseNotes: true,
autoUpdater: true,
singleInstance: true,
pluginsPath: '/Applications/Zui - Insiders.app/Contents/plugins'
}
[2023-11-14 15:08:07.989] [info] migrations pending: 3
[2023-11-14 15:08:07.990] [info] migrations started
[2023-11-14 15:08:07.991] [info] migrated to version: 202307141454
[2023-11-14 15:08:08.001] [info] initializers loaded
[2023-11-14 15:08:08.511] [debug] window registered: { id: 'L-zi9tVJAzOeulb7uKpwH', name: 'about' }
[2023-11-14 15:08:08.720] [debug] window registered: { id: 'Cim5rMIYEm0FRlc9_wgId', name: 'search' }
[2023-11-14 15:08:08.999] [debug] window registered: { id: 'K7Tky4lVxalXPLzzAJRLs', name: 'hidden' }
[2023-11-14 15:08:17.085] [debug] Closing suricata updater
When debugging this particular issue, if the user had sent a log and there was some record of them having been previously running a version 0.30.1-196 or older, that would have helped me more quickly repro the problem and refresh myself on the changes we were making around that time.
-
Include failure output in the
zed servelog.
The following is what was in my zlake.log after the repro steps above.
{"level":"info","ts":1700003243.6587572,"msg":"Listening to brim process pipe","fd":"brimfd"}
{"level":"info","ts":1700003243.7522938,"logger":"core","msg":"Started"}
{"level":"info","ts":1700003243.757157,"logger":"httpd","msg":"Listening","addr":"127.0.0.1:9988"}
{"level":"info","ts":1700003245.87922,"logger":"http.access","msg":"Request completed","request_id":"2YBe95VIIjcjuEjmVPiaHbBUbzE","host":"localhost:9988","method":"POST","proto":"HTTP/1.1","remote_addr":"127.0.0.1:51705","request_content_length":23,"url":"/query?ctrl=true","elapsed":0.002558572,"response_content_length":249,"status_code":200}
{"level":"info","ts":1700003280.79154,"logger":"http.access","msg":"Request completed","request_id":"2YBe9FbwHDfLUWRx7au4P2wK4ra","host":"localhost:9988","method":"GET","proto":"HTTP/1.1","remote_addr":"127.0.0.1:51705","request_content_length":0,"url":"/events","elapsed":34.136521864,"response_content_length":0,"status_code":200}
{"level":"info","ts":1700003280.793646,"logger":"httpd","msg":"Shutting down","reason":"context closed"}
{"level":"info","ts":1700003280.793782,"logger":"httpd","msg":"Closed"}
{"level":"info","ts":1700003280.793803,"logger":"core","msg":"Shutdown"}
{"level":"info","ts":1700003288.168622,"msg":"Listening to Zui process pipe","fd":"brimfd"}
If I manually reproduce the zed serve command line equivalent to what Zui attempted, here's what I see at the shell:
$ "/Applications/Zui - Insiders.app/Contents/Resources/app.asar.unpacked/zdeps/zed" serve -l localhost:9988 -lake "/Users/$USER/Library/Application Support/Zui - Insiders/lake" -log.level=info -log.filemode=rotate -log.path "/Users/$USER/Library/Application Support/Zui - Insiders/logs/zlake.log" --cors.origin=*
unsupported lake version: found version 1 while expecting 3
So if everything had been working as I'd hoped, that unsupported lake version would have been the last line of that zlake.log.
Playing around with redirecting output at the shell, I can see that both the "healthy" zed serve log output (like the Started message) and the failure output (like unsupported lake version) go to stderr. However, for some reason the failure one didn't make it into the zlake.log, and alas, that's what would have most helped here. Maybe we're just failing to catch it when zed serve quits with an error?
(Side note: Zed itself has a similar lack of version info in the zed lake log to what's described above for Zui. I've opened a separate issue https://github.com/brimdata/zed/issues/4882 to track improving that.)
