Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

fix: add logger to electron-updater #2552

Merged
merged 6 commits into from Jul 12, 2023
Merged

fix: add logger to electron-updater #2552

merged 6 commits into from Jul 12, 2023

Conversation

SgtPooki
Copy link
Member

I looked into reproducing #2551 multiple times, multiple ways, and I cannot reproduce it.

Users do have a workaround by manually installing new versions. Though it's not ideal, it means auto-update failures aren't a complete blocker.

For now, the best I can figure to do is add more logging information so we are better equipped to help those who do run into these errors.

fixes #2551

@SgtPooki SgtPooki requested review from a team and whizzzkid as code owners July 11, 2023 17:17
Comment on lines +92 to +105
let progressPercentTimeout = null
autoUpdater.on('download-progress', ({ percent, bytesPerSecond }) => {
const logDownloadProgress = () => {
logger.info(`[updater] download progress is ${percent.toFixed(2)}% at ${bytesPerSecond} bps.`)
}
// log the percent, but not too often to avoid spamming the logs, but we should
// be sure we're logging at what percent any hiccup is occurring.
clearTimeout(progressPercentTimeout)
if (percent === 100) {
logDownloadProgress()
return
}
progressPercentTimeout = setTimeout(logDownloadProgress, 2000)
})
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I would not base it on time, because it's likely that you'll only see three types log messages.

  • one at 100%
  • other at 2secs after the download-progress stops publishing messages.
  • occasionally when the progress is reported between 2secs, YMMV.

What if the log messages are based on percent rather than time?

Suggested change
let progressPercentTimeout = null
autoUpdater.on('download-progress', ({ percent, bytesPerSecond }) => {
const logDownloadProgress = () => {
logger.info(`[updater] download progress is ${percent.toFixed(2)}% at ${bytesPerSecond} bps.`)
}
// log the percent, but not too often to avoid spamming the logs, but we should
// be sure we're logging at what percent any hiccup is occurring.
clearTimeout(progressPercentTimeout)
if (percent === 100) {
logDownloadProgress()
return
}
progressPercentTimeout = setTimeout(logDownloadProgress, 2000)
})
let lastUpdatedPercent = 0
autoUpdater.on('download-progress', ({ percent, bytesPerSecond }) => {
const MIN_PERCENT_DIFF = 5
if (percent - lastUpdatedPercent > MIN_PERCENT_DIFF || percent === 100) {
logger.info(`[updater] download progress is ${percent.toFixed(2)}% at ${bytesPerSecond} bps.`)
lastUpdatedPercent = percent
}
})

The benefits are two fold:

  • don't see frequent messages.
  • don't rely on time and timeouts (which are always finicky in js)

unless the goal is to capture stalled downloads, is it?

Copy link
Member Author

@SgtPooki SgtPooki Jul 11, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

unless the goal is to capture stalled downloads, is it?

Yes, that's part of it. But also to see download speeds of users so we can infer "oh, slow network.. something happened, and it failed" or "oh, something happened and bps reduced significantly, then they got an error"

don't rely on time and timeouts (which are always finicky in js)

I disagree with this.

I think we still need the timeout. Basically, if we do not get another download-progress event, we need to have the last one logged, no matter what, or else we won't know at what percentage the download failed.


A few requirements I think we should have for this log:

  1. Do not spam the log (logging every 5 % is too much.. maybe every 25% is ideal)
  2. If download % is 100, we should log immediately
  3. If download fails at any point, the last download-progress event should be logged, no matter the value.

The 3rd criteria here is missing from your changes, and part of why I did the setTimeout. No matter what, the last event will be logged when setTimeout resolves. Criteria#3 is also challenging because a signal for "this is the last download-progress event" is missing from electron.

In a perfect world, electron would emit an actual 'updateFailed' event, and we could store the last percent received and output at that point, but electron only emits an 'error' event, which is also emitted for non-fatal errors (wth?)

One failure with my 2-second timeout is that Criteria#1 is invalidated for slow networks.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In a perfect world, electron would emit an actual 'updateFailed' event, and we could store the last percent received and output at that point, but electron only emits an 'error' event, which is also emitted for non-fatal errors (wth?)

I was expecting this to happen, nvm.

Copy link
Contributor

@whizzzkid whizzzkid left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

thanks

Comment on lines +92 to +105
let progressPercentTimeout = null
autoUpdater.on('download-progress', ({ percent, bytesPerSecond }) => {
const logDownloadProgress = () => {
logger.info(`[updater] download progress is ${percent.toFixed(2)}% at ${bytesPerSecond} bps.`)
}
// log the percent, but not too often to avoid spamming the logs, but we should
// be sure we're logging at what percent any hiccup is occurring.
clearTimeout(progressPercentTimeout)
if (percent === 100) {
logDownloadProgress()
return
}
progressPercentTimeout = setTimeout(logDownloadProgress, 2000)
})
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In a perfect world, electron would emit an actual 'updateFailed' event, and we could store the last percent received and output at that point, but electron only emits an 'error' event, which is also emitted for non-fatal errors (wth?)

I was expecting this to happen, nvm.

@SgtPooki SgtPooki merged commit 316ec42 into main Jul 12, 2023
7 checks passed
@SgtPooki SgtPooki deleted the fix/auto-updater branch July 12, 2023 19:23
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

[gui error report] Error: Command failed: powershell.exe -NoProfile -NonInteractive -InputF
2 participants