"Logs not found; cannot show summary!"
bowernite opened this issue · 35 comments
Getting this error in the macOS notification when rebooting and autoupdate is running.
Anything I can do to fix this? Or some trace/logs I can look at to look into it?
I'm seeing the same message.
The error seems to stem from here.
Looking at the single log file found by that pattern, there are no lines with "taps" in them in the last ten lines of the file, I need to set -n1000 to see "Updated 3 taps (homebrew/core, homebrew/cask and dart-lang/dart).".
Perhaps that line could be rewritten like this to search for a line with "taps" in it from the end of the file?
tail -r ~/Library/Logs/com.github.domt4.homebrew-autoupdate/*.out | grep -m1 tapsThanks for submitting this issue! I'd noticed this on my own machine and was hoping someone else would confirm. The issue as @antonagestam touches on is that the command used to read the logs trips over once the log has multiple successful executions to read from. A fix for this should be coming very soon.
Is the new style of notification behaving as expected for you both beside the misreading of the logs? Appearing in the notification centre, executing a little submarine alert noise when it runs, no other issues? I'm looking at rolling it out by default to everyone but trying to baby-step it to make sure all is working okay first.
Yeah, all of those behaviors with regards to notifications have been working fine for me 🙂
Should be fixed now. The output needs some fine-tuning at some point but the new notification is still an active work-in-progress.
Thanks both of you for the report and feedback. Let me know if you have any further issues.
Great, thanks for your work and help! 😀
@DomT4 ok... so after the most recent fix for this issue, I don't get any notification at all 😞
I've confirmed that:
- I'm running the latest release
- Tried stopping and restarting the service
- Waited for it to give a notification for a few days
The only thing I can think of is that there were no updates to be made? Not sure if there's a notification to be expected at that point (would make sense for there not to be). But I've had cask apps specifically ask if I want to upgrade over the past few weeks, even though that should ostensibly never happen if brew-autoupdate is working properly (though maybe that's just the nature of casks, where the homebrew registry is always going to be a bit behind on new releases).
@babramczyk Are you still having the issue? I removed the RunAtLoad key from the plist because Apple basically tells you not to use it anymore for a couple of sensible-enough reasons, so now the first execution of the command won't happen until 24 hours (Assuming you didn't change the default value) after you've executed the --start command. You can force the old behaviour to return by adding --debug to the command execution, which restores the RunAtLoad key, mostly so I can test things locally without having to wait 24 hours to see whether it works or not.
The other issue that might be clogging up the pipeline here is that for some reason using an AppleScript applet to send the notifications seems to require on a degree of accessibility privileges being granted to the app. I'm not sure if those are actually needed or if I can refine the permissions to a degree or whether it's simply something Apple has decided might be needed with every AppleScript and so folds them in by default. I'll try and look into that more.
There is a known issue with Casks increasingly needing sudo and there being no Homebrew-supported way to handle that non-interactively, which is proving a real sticky issue to think about and handle. The most useful idea I've had so far is to probe the output of brew outdated, see which of those Casks need sudo usage and then exclude those from an automated upgrade command but that's... a lot of work, and quite delicate, so I'm still sort of thinking over how viable that is.
@DomT4 I'm pretty sure I'm still having the issue. I haven't seen a notification from the app in weeks. And there are still times where an app prompts me to install an update when ostensibly autoupdate should have already handled that (though again, can't really be sure here)
Regardless, I'm not seeing any notifications (either on boot or every 24 hours)
FWIW, just did brew upgrade spotify -- did not require sudo, and I was 4 releases behind the latest release.
Looking into it a bit now. Will hopefully have some progress/information for you later tonight 😬.
Some discovered issues:
- For some reason the tap updated output is being redirected to the error logfile instead of the output logfile now. I assume that's a change on Homebrew's end but I'm not 100% sure. My loose thinking is to simply merge the output & error logfiles, since there's no huge need to actually have them separate. This seems to be the reason the notification isn't working currently.
- If looks like now if you pass
brew upgrade --caskit treats that as a user only intending to upgrade Casks and nothing else. I would guess the path forwards here is either dropping the explicitbrew upgrade --cask -vline and simply reverting to a universalbrew upgrade -vcommand or issuing two upgrade commands, one for formulae first and then one for casks. The latter might be the route I go down, simply because there are existing issues with Casks that require sudo and I don't want the wholeupgradecommand to get bogged down in those circumstances.
Made some changes locally, which I need to test before pushing remotely, and then update the notification app again & push a new codesigned version. Hopefully tomorrow evening sometime. Changes below, if you want to test them out yourself or suggest anything.
diff --git a/lib/autoupdate.rb b/lib/autoupdate.rb
index 6bac077..9222ad2 100644
--- a/lib/autoupdate.rb
+++ b/lib/autoupdate.rb
@@ -1,3 +1,4 @@
+require "date"
require "fileutils"
require "pathname"
require "autoupdate/core"
diff --git a/lib/autoupdate/start.rb b/lib/autoupdate/start.rb
index 3ef1a94..80e3f04 100644
--- a/lib/autoupdate/start.rb
+++ b/lib/autoupdate/start.rb
@@ -15,7 +15,7 @@ module Autoupdate
auto_args = "update"
# Spacing at start of lines is deliberate. Don't undo.
if ARGV.include? "--upgrade"
- auto_args << " && #{Autoupdate::Core.brew} upgrade -v"
+ auto_args << " && #{Autoupdate::Core.brew} upgrade --formula -v"
auto_args << " && #{Autoupdate::Core.brew} upgrade --cask -v" if (HOMEBREW_PREFIX/"Caskroom").exist?
auto_args << " && #{Autoupdate::Core.brew} cleanup" if ARGV.include? "--cleanup"
end
@@ -56,11 +56,9 @@ module Autoupdate
# we can't write to later, so need to ensure a future `start` command
# doesn't silently fail.
if File.writable?(Autoupdate::Core.logs)
- log_err = "#{Autoupdate::Core.logs}/#{Autoupdate::Core.name}.err"
- log_std = "#{Autoupdate::Core.logs}/#{Autoupdate::Core.name}.out"
+ log_out = "#{Autoupdate::Core.logs}/#{Autoupdate::Core.name}.out"
elsif File.writable?(Autoupdate::Core.fallback_logs)
- log_err = "#{Autoupdate::Core.fallback_logs}/#{Autoupdate::Core.name}.err"
- log_std = "#{Autoupdate::Core.fallback_logs}/#{Autoupdate::Core.name}.out"
+ log_out = "#{Autoupdate::Core.fallback_logs}/#{Autoupdate::Core.name}.out"
else
puts <<~EOS
#{Autoupdate::Core.logs} does not seem to be writable.
@@ -121,9 +119,9 @@ module Autoupdate
</array>
#{debug}
<key>StandardErrorPath</key>
- <string>#{log_err}</string>
+ <string>#{log_out}</string>
<key>StandardOutPath</key>
- <string>#{log_std}</string>
+ <string>#{log_out}</string>
<key>StartInterval</key>
<integer>#{interval}</integer>
<key>LowPriorityBackgroundIO</key>
diff --git a/lib/autoupdate/status.rb b/lib/autoupdate/status.rb
index bff4cd5..e6ed109 100644
--- a/lib/autoupdate/status.rb
+++ b/lib/autoupdate/status.rb
@@ -15,11 +15,42 @@ module Autoupdate
!File.exist?(Autoupdate::Core.plist)
end
+ def date_of_last_modification
+ if File.exist?(Autoupdate::Core.location/"brew_autoupdate")
+ birth = File.birthtime(Autoupdate::Core.location/"brew_autoupdate").to_s
+ date = DateTime.parse(birth)
+ formatted_string = date.strftime("%D")
+ else
+ formatted_string = "Unable to determine date of command invocation. Please report this."
+ end
+ formatted_string
+ end
+
def status
if autoupdate_running?
- puts "Autoupdate is installed and running."
+ puts <<~EOS
+ Autoupdate is installed and running.
+
+ Autoupdate was initialised on #{date_of_last_modification}.
+ EOS
elsif autoupdate_installed_but_stopped?
- puts "Autoupdate is installed but stopped."
+ puts <<~EOS
+ Autoupdate is installed but stopped.
+
+ Autoupdate was initialised on #{date_of_last_modification}.
+ EOS
elsif autoupdate_not_configured?
puts "Autoupdate is not configured. Use `brew autoupdate --start` to begin."
elseDoes this change just affect notifications? Or does it try to address some apps not updating at all? (like what happened for Spotify for me above)
Does this change just affect notifications? Or does it try to address some apps not updating at all? (like what happened for Spotify for me above)
No, it has the potential to cause issues with app updates. Do you know if Spotify was the only Cask update or did you have multiple updates pending?
Not sure if there were other updates pending, just tested Spotify as an example.
I have a pending flux update right now, if you'd like me to do anything specific with regards to testing it
Mind running brew update and then brew autoupdate --delete && brew autoupdate --start --upgrade and then giving it 24 hours from that command to see if it kicks in successfully? I need to iron out some notification issues around reading the log file more accurately but with the recent commits 4eddb6f & d69aeb2 locally I can get things to update/upgrade as planned.
If you don't see anything within 24hours (ish) try the same set of commands but with --debug attached to the brew autoupdate --start --upgrade command.
FYI, running brew autoupdate —start —upgrade —debug seemed to work for me (flux was autoupdated).
Going to run it with —enable-notification and see if it still works
As a side note, I’ve been running into something where when I initially —start the service, the casks I’m upgrading quit, and opening them (i.e. from Spotlight) doesn’t work properly.
Not sure if this happens always, or just when starting the service, but I can keep an eye on it.
Hey @babramczyk, how are things going your end? I changed my interval locally to hourly to keep an eye on things and it's been pretty smooth sailing for me since the last set of changes. Anything different for you?
I don't think the Cask thing is related to this tool; I can't think of any reason this tool would cause that to happen, it doesn't really interact with the upgrade process directly enough to cause that sort of issue 🤔.
Hey! 👋
Pretty smooth sailing here as well.
- The notifications never show for me, though I know for a fact that formulae/casks have been upgrading in the background.
- I still get the macOS modal for
x is an app downloaded from the internet, are you sure you want to open it?+ it removes the app from my dock and I have to reorder it again. But I have an unconfirmed hunch that this only happens the first timeautoupdatedownloads a cask, and it won’t happen again. But still don’t know for sure.
Glad to hear things have been smooth on your side for a while @babramczyk!
Can I double check WRT the notification that you're on Big Sur? Do you run any sort of program that restricts what can run/execute AppleScripts/etc? Things like FS Protection for Mac with its included "DeepGuard" feature can silently block the notification sometimes.
Not that I know of, no.
FWIW, I run plenty of other apps that I assume are triggering notifications and running AppleScript (Alfred, other cli tools). Not sure if that’s applicable or not.
And yes, I’m on Big Sur.
What happens if you execute open -a brew-autoupdate in your shell?
Can’t find a way to see the full error message though.
Interesting. Looks like it has gotten stuck somewhere in the past, potentially. Can you execute the following for me please:
cat ~/Library/Logs/com.github.domt4.homebrew-autoupdate/com.github.domt4.homebrew-autoupdate.out
cat ~/Library/Logs/com.github.domt4.homebrew-autoupdate/com.github.domt4.homebrew-autoupdate.err
If the latter doesn't exist that's fine, I merged the logs into one a while back so depends how recently you invoked the command afresh.
Here’s the out file: https://gist.github.com/babramczyk/83108ba0ce0d5c0e29b6224b24a7f1fb.
No .err file.
I noticed in that logfile that the Bartender app is quitting a lot, and it seems like autoupdate is the reason. Lines up with the behavior from other apps, where every time autoupdate upgrades them they move to the end of my dock and macos asks me “X is an app downloaded by homebrew-cask, are you sure you want to open it?”
Hmmm… maybe this just isn’t suited for cask auto-updates. It’s a bummer though, since I’d love to take the friction out of the status quo of upgrading apps where you get disrupted by some modal asking you to upgrade (when you’re already busy doing something else).
It looks like a lot of the errors you're hitting are related to sudo usage, which is part of what I'm having some internal struggles around about supporting Cask upgrades (#40). It looks like Dropbox/Microsoft Autoupdate/Microsoft Edge/Docker/Bartender/Zoom are all demanding sudo, not being granted that access and then failing (often uncleanly) but obviously the next time the autoupdate command runs it's trying to do that all over again.
If you're willing to try I'd definitely be interested in seeing what happens if you set up SUDO_ASKPASS locally and then delete/debug start the command again.
Got it. Just set SUDO_ASKPASS (and tested it with a sudo command locally to make sure I did it right) — so I’ll let you know what happens in the next few days here 👍
@DomT4 here’s the results so far from SUDO_ASKPASS: https://gist.github.com/babramczyk/32a1444b57f377b8304c6426728fdb7b
Looks like things are working!
I’m still getting confirmation dialogs for some apps after updating, but I’m still not sure if it happens after autoupdate installs a new version for the first time (I’m going to start keeping a list, and I’ll let you know if it happens multiple times for the same app). If it does, it might be a dealbreaker for using autoupdate for casks, but it also might be unavoidable from a technical perspective.
But very happy with the askpass solution!! 😀
I'm feeling lucky, so I set interval to 1 hour. I see this message after each run. E.g. last run was ~20 minutes ago, I see output for recent run in log, and its modification time matches. Recent runs have this line at the end:
The application cannot be opened for an unexpected reason, error=Error Domain=NSOSStatusErrorDomain Code=-600 "procNotFound: no eligible process with specified descriptor" UserInfo={_LSLine=379, _LSFunction=_LSAnnotateAndSendAppleEventWithOptions}
It seems that after reboot, the previous notification now states the same useless no logs message even for previous runs before that error message started to appear.
Clicking on any old notification that came before reboot produces the same notification:
And there is a loop, i.e. clicked notification is still there, but they produce these extra ones, that in turn produce their clones again on click.
Notification that came after reboot didn't have this clone bomb, it was successfully removed from NC. And IIRC there was some useful message, but I'm unsure. So my NC now looks like this:
Those with svn word are clones, older ones without svn have fire time before reboot.
Correction: I see from logs that error started to appear with run ended at 9:44. The system was rebooted around 14:50 with very small downtime. So these two events somehow correlate. Latest run from 16:24:27 has same message with svn. Clicking on notifications before 9:44 has same cloning effect with not removing notification from NC.
My current time is 16:37.
Oh, I have terminal-notifier, so I see two notifications every time.
According to logs last started at 16:24, my interval is 1 hr (3600), but now, at 16:47 I see this messages with no records in log:
I finally figured out why this was happening in my notifications! The AppleScript at /usr/local/Homebrew/Library/Taps/homebrew/homebrew-autoupdate/notifier/brew-autoupdate.app/Contents/Resources/Scripts/main.scpt is calling tail -r. I've installed coreutils so I'm running GNU tail (at /usr/local/opt/coreutils/libexec/gnubin/tail), which doesn't support the -r flag.
This can be fixed by using the default /usr/bin/tail, instead of tail from the user's PATH.
$ tail -r ~/Library/Logs/com.github.domt4.homebrew-autoupdate/*.out | grep -E -m1 'taps|date'
tail: invalid option -- 'r'
Try 'tail --help' for more information.
$ /usr/bin/tail -r ~/Library/Logs/com.github.domt4.homebrew-autoupdate/*.out | grep -E -m1 'taps|date'
Already up-to-date.
Also I figured out that I can run it immediately with launchctl start com.github.domt4.homebrew-autoupdate, instead of needing to wait for the scheduled time