Add viewing of error messages from Keystone upon self-update failure.

chrome/browser/mac/keystone_glue.mm

 // Copyright (c) 2012 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #import "chrome/browser/mac/keystone_glue.h"
 
 #include <sys/mount.h>
 #include <sys/param.h>
 #include <sys/stat.h>
 
@@ skipping 41 matching lines @@
 NSString* kBrandUserFile = @"~/Library/Google/" kBrandFileName;
 NSString* kBrandSystemFile = @"/Library/Google/" kBrandFileName;
 
 NSString* UserBrandFilePath() {
   return [kBrandUserFile stringByStandardizingPath];
 }
 NSString* SystemBrandFilePath() {
   return [kBrandSystemFile stringByStandardizingPath];
 }
 
+// Non-localized error message to return when we can't initiate any actions

[Mark Mentovai, 2016/03/23 15:52:03]

Why is this not localized?

This should be localized. We have a bunch of infrastructure for localizing
strings.

[Boris Vidolov, 2016/03/23 17:17:24]

If I follow the code correctly, this message should never appear. Why do we need
to waste localization resources for this particular message?

[Mark Mentovai, 2016/03/23 17:22:06]

Boris Vidolov wrote:
If it shouldn’t ever happen, then the logic should be a DCHECK(), we shouldn’t
be firing off this message (localized or not).

[Boris Vidolov, 2016/03/23 17:37:29]

Agree.

[Ryan Myers (chromium), 2016/03/23 22:29:38]

OK, removing and going back to DCHECKs.  (TBH, I'm skeptical that we even need
the DCHECKs, on a second review of the code.)  Done.

+// because Keystone isn't present or won't initialize.
+NSString* kNoRegistrationErrorMessage =
+      @"Cannot start automatic updates - KeystoneRegistration not available.";
+
 // Adaptor for scheduling an Objective-C method call on a |WorkerPool|
 // thread.
 class PerformBridge : public base::RefCountedThreadSafe<PerformBridge> {
  public:
 
   // Call |sel| on |target| with |arg| in a WorkerPool thread.
   // |target| and |arg| are retained, |arg| may be |nil|.
   static void PostPerform(id target, SEL sel, id arg) {
     DCHECK(target);
     DCHECK(sel);
@@ skipping 48 matching lines @@
 
 // Set the registration active and pass profile count parameters.
 - (void)setRegistrationActive;
 
 // Called periodically to announce activity by pinging the Keystone server.
 - (void)markActive:(NSTimer*)timer;
 
 // Called when an update check or update installation is complete.  Posts the
 // kAutoupdateStatusNotification notification to the default notification
 // center.
-- (void)updateStatus:(AutoupdateStatus)status version:(NSString*)version;
+- (void)updateStatus:(AutoupdateStatus)status
+             version:(NSString*)version
+               error:(NSString*)error;
 
 // Returns the version of the currently-installed application on disk.
 - (NSString*)currentlyInstalledVersion;
 
 // These three methods are used to determine the version of the application
 // currently installed on disk, compare that to the currently-running version,
 // decide whether any updates have been installed, and call
-// -updateStatus:version:.
+// -updateStatus:version:error:.
 //
 // In order to check the version on disk, the installed application's
 // Info.plist dictionary must be read; in order to see changes as updates are
 // applied, the dictionary must be read each time, bypassing any caches such
 // as the one that NSBundle might be maintaining.  Reading files can be a
 // blocking operation, and blocking operations are to be avoided on the main
 // thread.  I'm not quite sure what jank means, but I bet that a blocked main
 // thread would cause some of it.
 //
 // -determineUpdateStatusAsync is called on the main thread to initiate the
 // operation.  It performs initial set-up work that must be done on the main
 // thread and arranges for -determineUpdateStatus to be called on a work queue
 // thread managed by WorkerPool.
 // -determineUpdateStatus then reads the Info.plist, gets the version from the
 // CFBundleShortVersionString key, and performs
 // -determineUpdateStatusForVersion: on the main thread.
 // -determineUpdateStatusForVersion: does the actual comparison of the version
-// on disk with the running version and calls -updateStatus:version: with the
-// results of its analysis.
+// on disk with the running version and calls -updateStatus:version:error: with
+// the results of its analysis.
 - (void)determineUpdateStatusAsync;
 - (void)determineUpdateStatus;
 - (void)determineUpdateStatusForVersion:(NSString*)version;
 
 // Returns YES if registration_ is definitely on a user ticket.  If definitely
 // on a system ticket, or uncertain of ticket type (due to an older version
 // of Keystone being used), returns NO.
 - (BOOL)isUserTicket;
 
 // Returns YES if Keystone is definitely installed at the system level,
@@ skipping 33 matching lines @@
 // tag key.  If a full installer (as opposed to a binary diff/delta patch) is
 // required, the tag suffix will contain the string "-full". If no special
 // treatment is required, the tag suffix will be an empty string.
 - (NSString*)tagSuffix;
 
 @end  // @interface KeystoneGlue (Private)
 
 NSString* const kAutoupdateStatusNotification = @"AutoupdateStatusNotification";
 NSString* const kAutoupdateStatusStatus = @"status";
 NSString* const kAutoupdateStatusVersion = @"version";
+NSString* const kAutoupdateStatusErrorMessages = @"errormessages";
 
 namespace {
 
 NSString* const kChannelKey = @"KSChannelID";
 NSString* const kBrandKey = @"KSBrandID";
 NSString* const kVersionKey = @"KSVersion";
 
 }  // namespace
 
 @implementation KeystoneGlue
@@ skipping 308 matching lines @@
   NSArray* profileCountsInformation =
       [NSArray arrayWithObjects:numAccountsAttr, numSignedInAccountsAttr, nil];
 
   if (![registration_ setActiveWithReportingAttributes:profileCountsInformation
                                                  error:&reportingError]) {
     VLOG(1) << [reportingError localizedDescription];
   }
 }
 
 - (void)registerWithKeystone {
-  [self updateStatus:kAutoupdateRegistering version:nil];
+  [self updateStatus:kAutoupdateRegistering version:nil error:nil];
+
+  if (!registration_) {

[Mark Mentovai, 2016/03/23 15:52:04]

This can happen before you enter the “registering” state.

[Boris Vidolov, 2016/03/23 17:17:24]

I don't see how this could happen: see +[KeystoneGlue defaultKeystoneGlue] and
loadKeystoneRegistration. If I read it correctly, registration_ is always set or
defaultKeystoneGlue returns nil, so this method won't be called. All usage of
KeystoneGlue is based on the instance returned by defaultKeystoneGlue method.

[Mark Mentovai, 2016/03/23 17:22:06]

Boris Vidolov wrote:
So then what’s the point of this check at all? Why don’t we get rid of it?

[Boris Vidolov, 2016/03/23 17:37:29]

I am fine with DCHECK for "registration_". Then it should be across the whole
file. Ryan's call.

[Ryan Myers (chromium), 2016/03/23 22:29:38]

Done.

+    [self updateStatus:kAutoupdateRegisterFailed
+               version:nil
+                 error:kNoRegistrationErrorMessage];
+    return;
+  }
 
   NSDictionary* parameters = [self keystoneParameters];
   BOOL result = [registration_ registerWithParameters:parameters];
   if (!result) {
-    [self updateStatus:kAutoupdateRegisterFailed version:nil];
+    // TODO: If Keystone ever makes a variant of this API with a withError:
+    // parameter, include the error message here in the call to updateStatus:.
+    [self updateStatus:kAutoupdateRegisterFailed version:nil error:nil];
     return;
   }
 
   // Upon completion, ksr::KSRegistrationDidCompleteNotification will be
   // posted, and -registrationComplete: will be called.
 
   // Set up hourly activity pings.
   timer_ = [NSTimer scheduledTimerWithTimeInterval:60 * 60  // One hour
                                             target:self
                                           selector:@selector(markActive:)
                                           userInfo:nil
                                            repeats:YES];
 }
 
 - (BOOL)isRegisteredAndActive {
   return registrationActive_;
 }
 
 - (void)registrationComplete:(NSNotification*)notification {
   NSDictionary* userInfo = [notification userInfo];
+  NSString* errorMessages =
+      [userInfo objectForKey:ksr::KSRegistrationUpdateCheckRawErrorMessagesKey];

[Mark Mentovai, 2016/03/23 15:52:03]

When you pull things out of a dictionary, use ObjCCast<NSString> to make sure
that you’re really getting an NSString. Otherwise, possible type confusion
looms. ObjCCast will return nil if the thing isn’t an NSString.

You can also use ObjCCastStrict which will CHECK that it’s an NSString or nil,
and abort otherwise.

[Ryan Myers (chromium), 2016/03/23 22:29:38]

Done, both here and elsewhere in the file (i.e. in -brandFilePath where we pull
the bundle plist.)

+
   if ([[userInfo objectForKey:ksr::KSRegistrationStatusKey] boolValue]) {
     if ([self isSystemTicketDoomed]) {
-      [self updateStatus:kAutoupdateNeedsPromotion version:nil];
+      [self updateStatus:kAutoupdateNeedsPromotion
+                 version:nil
+                   error:errorMessages];
     } else {
-      [self updateStatus:kAutoupdateRegistered version:nil];
+      [self updateStatus:kAutoupdateRegistered version:nil error:errorMessages];
     }
   } else {
     // Dump registration_?
-    [self updateStatus:kAutoupdateRegisterFailed version:nil];
+    [self updateStatus:kAutoupdateRegisterFailed
+               version:nil
+                 error:errorMessages];
   }
 }
 
 - (void)stopTimer {
   [timer_ invalidate];
 }
 
 - (void)markActive:(NSTimer*)timer {
   [self setRegistrationActive];
 }
 
 - (void)checkForUpdate {
-  DCHECK(![self asyncOperationPending]);
-
-  if (!registration_) {
-    [self updateStatus:kAutoupdateCheckFailed version:nil];
+  if ([self asyncOperationPending]) {

[Mark Mentovai, 2016/03/23 15:52:04]

This can come after the registration_ check. Same on line 659.

[Ryan Myers (chromium), 2016/03/23 22:29:38]

Done.

+    // Update check already in process; return without doing anything.
+    VLOG(1) << "checkForUpdate ignored; async operation pending";

[Mark Mentovai, 2016/03/23 15:52:03]

I wasn’t a fan of the three VLOGs that this file already grew, and now things
are getting worse. Do we really need these? This is a form of bloat in my
opinion.

[Ryan Myers (chromium), 2016/03/23 22:29:38]

They're nice to have, but not necessary IMO.  At best, if we have a long-running
async operation in progress, this lets you know why other messages aren't having
an effect, without joining the debugger.  I don't feel strongly about it, so
removed.

     return;
   }
 
-  [self updateStatus:kAutoupdateChecking version:nil];
+  if (!registration_) {
+    [self updateStatus:kAutoupdateCheckFailed
+               version:nil
+                 error:kNoRegistrationErrorMessage];
+    return;
+  }
+
+  [self updateStatus:kAutoupdateChecking version:nil error:nil];
 
   // All checks from inside Chrome are considered user-initiated, because they
   // only happen following a user action, such as visiting the about page.
   // Non-user-initiated checks are the periodic checks automatically made by
   // Keystone, which don't come through this code path (or even this process).
   [registration_ checkForUpdateWasUserInitiated:YES];
 
   // Upon completion, ksr::KSRegistrationCheckForUpdateNotification will be
   // posted, and -checkForUpdateComplete: will be called.
 }
 
 - (void)checkForUpdateComplete:(NSNotification*)notification {
   NSDictionary* userInfo = [notification userInfo];
+  NSString* errorMessages =
+      [userInfo objectForKey:ksr::KSRegistrationUpdateCheckRawErrorMessagesKey];
 
   if ([[userInfo objectForKey:ksr::KSRegistrationUpdateCheckErrorKey]
           boolValue]) {
-    [self updateStatus:kAutoupdateCheckFailed version:nil];
+    [self updateStatus:kAutoupdateCheckFailed version:nil error:errorMessages];
   } else if ([[userInfo objectForKey:ksr::KSRegistrationStatusKey] boolValue]) {
     // If an update is known to be available, go straight to
     // -updateStatus:version:.  It doesn't matter what's currently on disk.
     NSString* version = [userInfo objectForKey:ksr::KSRegistrationVersionKey];
-    [self updateStatus:kAutoupdateAvailable version:version];
+    [self updateStatus:kAutoupdateAvailable
+               version:version
+                 error:errorMessages];
   } else {
     // If no updates are available, check what's on disk, because an update
     // may have already been installed.  This check happens on another thread,
     // and -updateStatus:version: will be called on the main thread when done.
     [self determineUpdateStatusAsync];
   }
 }
 
 - (void)installUpdate {
-  DCHECK(![self asyncOperationPending]);
-
-  if (!registration_) {
-    [self updateStatus:kAutoupdateInstallFailed version:nil];
+  if ([self asyncOperationPending]) {
+    // Update check already in process; return without doing anything.
+    VLOG(1) << "installUpdate ignored; async operation pending";
     return;
   }
 
-  [self updateStatus:kAutoupdateInstalling version:nil];
+  if (!registration_) {
+    [self updateStatus:kAutoupdateInstallFailed
+               version:nil
+                 error:kNoRegistrationErrorMessage];
+    return;
+  }
+
+  [self updateStatus:kAutoupdateInstalling version:nil error:nil];
 
   [registration_ startUpdate];
 
   // Upon completion, ksr::KSRegistrationStartUpdateNotification will be
   // posted, and -installUpdateComplete: will be called.
 }
 
 - (void)installUpdateComplete:(NSNotification*)notification {
   NSDictionary* userInfo = [notification userInfo];
+  NSString* errorMsgs =

[Mark Mentovai, 2016/03/23 15:52:03]

Don’t abbreviate. Elsewhere, this was named errorMessages. It can have that name
here too.

[Ryan Myers (chromium), 2016/03/23 22:29:38]

Done.

+      [userInfo objectForKey:ksr::KSRegistrationUpdateCheckRawErrorMessagesKey];
 
   // http://crbug.com/160308 and b/7517358: when using system Keystone and on
   // a user ticket, KSUpdateCheckSuccessfulKey will be NO even when an update
   // was installed correctly, so don't check it. It should be redudnant when
   // KSUpdateCheckSuccessfullyInstalledKey is checked.
   if (![[userInfo objectForKey:ksr::KSUpdateCheckSuccessfullyInstalledKey]
           intValue]) {
-    [self updateStatus:kAutoupdateInstallFailed version:nil];
+    [self updateStatus:kAutoupdateInstallFailed version:nil error:errorMsgs];
   } else {
     updateSuccessfullyInstalled_ = YES;
 
     // Nothing in the notification dictionary reports the version that was
     // installed.  Figure it out based on what's on disk.
     [self determineUpdateStatusAsync];
   }
 }
 
 - (NSString*)currentlyInstalledVersion {
@@ skipping 42 matching lines @@
       status = kAutoupdateCurrent;
     } else {
       // If the version on disk doesn't match what's currently running, an
       // update must have been applied in the background, without this app's
       // direct participation.  Leave updateSuccessfullyInstalled_ alone
       // because there's no direct knowledge of what actually happened.
       status = kAutoupdateInstalled;
     }
   }
 
-  [self updateStatus:status version:version];
+  [self updateStatus:status version:version error:nil];
 }
 
-- (void)updateStatus:(AutoupdateStatus)status version:(NSString*)version {
+- (void)updateStatus:(AutoupdateStatus)status
+             version:(NSString*)version
+               error:(NSString *)error {

[Mark Mentovai, 2016/03/23 15:52:03]

Chromium style is NSString*, no space in there. Compare to the line above.

[Ryan Myers (chromium), 2016/03/23 22:29:38]

Done.

   NSNumber* statusNumber = [NSNumber numberWithInt:status];
   NSMutableDictionary* dictionary =
       [NSMutableDictionary dictionaryWithObject:statusNumber
                                          forKey:kAutoupdateStatusStatus];
   if (version) {
     [dictionary setObject:version forKey:kAutoupdateStatusVersion];
   }
+  if (error) {
+    [dictionary setObject:version forKey:kAutoupdateStatusErrorMessages];
+  }
 
   NSNotification* notification =
       [NSNotification notificationWithName:kAutoupdateStatusNotification
                                     object:self
                                   userInfo:dictionary];
   recentNotification_.reset([notification retain]);
 
   [[NSNotificationCenter defaultCenter] postNotification:notification];
 }
 
@@ skipping 98 matching lines @@
 
   return [appPath_ hasPrefix:@"/Applications/"];
 }
 
 - (void)promoteTicket {
   if ([self asyncOperationPending] || ![self wantsPromotion]) {
     // Because there are multiple ways of reaching promoteTicket that might
     // not lock each other out, it may be possible to arrive here while an
     // asynchronous operation is pending, or even after promotion has already
     // occurred.  Just quietly return without doing anything.
+    VLOG(1) << "promoteTicket ignored; async operation pending";
     return;
   }
 
   NSString* prompt = l10n_util::GetNSStringFWithFixup(
       IDS_PROMOTE_AUTHENTICATION_PROMPT,
       l10n_util::GetStringUTF16(IDS_PRODUCT_NAME));
   base::mac::ScopedAuthorizationRef authorization(
       base::mac::AuthorizationCreateToRunAsRoot(
           base::mac::NSToCFCast(prompt)));
   if (!authorization.get()) {
     return;
   }
 
   [self promoteTicketWithAuthorization:authorization.release() synchronous:NO];
 }
 
 - (void)promoteTicketWithAuthorization:(AuthorizationRef)authorization_arg
                            synchronous:(BOOL)synchronous {
   base::mac::ScopedAuthorizationRef authorization(authorization_arg);
   authorization_arg = NULL;
 
   if ([self asyncOperationPending]) {
     // Starting a synchronous operation while an asynchronous one is pending
     // could be trouble.
+    VLOG(1) << "promoteTicketWithAuth ignored; async operation pending";
     return;
   }
   if (!synchronous && ![self wantsPromotion]) {
     // If operating synchronously, the call came from the installer, which
     // means that a system ticket is required.  Otherwise, only allow
     // promotion if it's wanted.
     return;
   }
 
   synchronousPromotion_ = synchronous;
 
-  [self updateStatus:kAutoupdatePromoting version:nil];
+  [self updateStatus:kAutoupdatePromoting version:nil error:nil];
 
   // TODO(mark): Remove when able!
   //
   // keystone_promote_preflight will copy the current brand information out to
   // the system level so all users can share the data as part of the ticket
   // promotion.
   //
   // It will also ensure that the Keystone system ticket store is in a usable
   // state for all users on the system.  Ideally, Keystone's installer or
   // another part of Keystone would handle this.  The underlying problem is
@@ skipping 28 matching lines @@
   OSStatus status = base::mac::ExecuteWithPrivilegesAndWait(
       authorization,
       preflightPathC,
       kAuthorizationFlagDefaults,
       arguments,
       NULL,  // pipe
       &exit_status);
   if (status != errAuthorizationSuccess) {
     OSSTATUS_LOG(ERROR, status)
         << "AuthorizationExecuteWithPrivileges preflight";
-    [self updateStatus:kAutoupdatePromoteFailed version:nil];
+
+    NSString *errorMessage =
+        [NSString stringWithFormat:@"Pre-flight script failed to launch: %ld",

[Mark Mentovai, 2016/03/23 15:52:03]

This ought to be localized. Line 987 too.

[Ryan Myers (chromium), 2016/03/23 22:29:38]

Done.

+                                   (long)status];
+    [self updateStatus:kAutoupdatePromoteFailed
+               version:nil
+                 error:errorMessage];
     return;
   }
   if (exit_status != 0) {
     LOG(ERROR) << "keystone_promote_preflight status " << exit_status;
-    [self updateStatus:kAutoupdatePromoteFailed version:nil];
+
+    NSString *errorMessage =
+        [NSString stringWithFormat:@"Promotion pre-flight script failed: %d",
+                                     exit_status];
+    [self updateStatus:kAutoupdatePromoteFailed
+               version:nil
+                 error:errorMessage];
     return;
   }
 
   // Hang on to the AuthorizationRef so that it can be used once promotion is
   // complete.  Do this before asking Keystone to promote the ticket, because
   // -promotionComplete: may be called from inside the Keystone promotion
   // call.
   authorization_.swap(authorization);
 
   NSDictionary* parameters = [self keystoneParameters];
 
   // If the brand file is user level, update parameters to point to the new
   // system level file during promotion.
   if (brandFileType_ == kBrandFileTypeUser) {
     NSMutableDictionary* temp_parameters =
         [[parameters mutableCopy] autorelease];
     [temp_parameters setObject:SystemBrandFilePath()
                         forKey:ksr::KSRegistrationBrandPathKey];
     parameters = temp_parameters;
   }
 
   if (![registration_ promoteWithParameters:parameters
                               authorization:authorization_]) {
-    [self updateStatus:kAutoupdatePromoteFailed version:nil];
+    // TODO: If Keystone ever makes a variant of this API with a withError:
+    // parameter, include the error message here in the call to updateStatus:.
+    [self updateStatus:kAutoupdatePromoteFailed version:nil error:nil];
     authorization_.reset();
     return;
   }
 
   // Upon completion, ksr::KSRegistrationPromotionDidCompleteNotification will
   // be posted, and -promotionComplete: will be called.
 
   // If synchronous, see to it that this happens immediately. Give it a
   // 10-second deadline.
   if (synchronous) {
     CFRunLoopRunInMode(kCFRunLoopDefaultMode, 10, false);
   }
 }
 
 - (void)promotionComplete:(NSNotification*)notification {
   NSDictionary* userInfo = [notification userInfo];
   if ([[userInfo objectForKey:ksr::KSRegistrationStatusKey] boolValue]) {
     if (synchronousPromotion_) {
       // Short-circuit: if performing a synchronous promotion, the promotion
       // came from the installer, which already set the permissions properly.
       // Rather than run a duplicate permission-changing operation, jump
       // straight to "done."
       [self changePermissionsForPromotionComplete];
     } else {
       [self changePermissionsForPromotionAsync];
     }
   } else {
     authorization_.reset();
-    [self updateStatus:kAutoupdatePromoteFailed version:nil];
+    [self updateStatus:kAutoupdatePromoteFailed version:nil error:nil];
   }
 
   if (synchronousPromotion_) {
     // The run loop doesn't need to wait for this any longer.
     CFRunLoopRef runLoop = CFRunLoopGetCurrent();
     CFRunLoopStop(runLoop);
     CFRunLoopWakeUp(runLoop);
   }
 }
 
@@ skipping 35 matching lines @@
 
   SEL selector = @selector(changePermissionsForPromotionComplete);
   [self performSelectorOnMainThread:selector
                          withObject:nil
                       waitUntilDone:NO];
 }
 
 - (void)changePermissionsForPromotionComplete {
   authorization_.reset();
 
-  [self updateStatus:kAutoupdatePromoted version:nil];
+  [self updateStatus:kAutoupdatePromoted version:nil error:nil];
 }
 
 - (void)setAppPath:(NSString*)appPath {
   if (appPath != appPath_) {
     [appPath_ release];
     appPath_ = [appPath copy];
   }
 }
 
 - (BOOL)wantsFullInstaller {
@@ skipping 81 matching lines @@
   return [KeystoneGlue defaultKeystoneGlue] != nil;
 }
 
 base::string16 CurrentlyInstalledVersion() {
   KeystoneGlue* keystoneGlue = [KeystoneGlue defaultKeystoneGlue];
   NSString* version = [keystoneGlue currentlyInstalledVersion];
   return base::SysNSStringToUTF16(version);
 }
 
 }  // namespace keystone_glue