Draft: Batch up reconciler pushes

server/datastore/mysql/mdm_test.go

@@ -8997,7 +8997,7 @@ func testDeleteMDMProfilesCancelsInstalls(t *testing.T, ds *Datastore) {
 	forceSetAppleHostProfileStatus(t, ds, host2.UUID, test.ToMDMAppleConfigProfile(profNameToProf["A2"]), fleet.MDMOperationTypeInstall, fleet.MDMDeliveryVerifying)
 	// enqueue the corresponding command for the installed profile
 	cmdUUID := uuid.New().String()
-	err = commander.InstallProfile(ctx, []string{host2.UUID}, appleProfs[1].Mobileconfig, cmdUUID)
+	err = commander.InstallProfile(ctx, []string{host2.UUID}, appleProfs[1].Mobileconfig, cmdUUID, true)
 	require.NoError(t, err)
 	ExecAdhocSQL(t, ds, func(q sqlx.ExtContext) error {
 		_, err := q.ExecContext(ctx, `UPDATE host_mdm_apple_profiles SET command_uuid = ? WHERE host_uuid = ? AND profile_uuid = ?`, cmdUUID, host2.UUID, profNameToProf["A2"].ProfileUUID)
@@ -9028,7 +9028,7 @@ func testDeleteMDMProfilesCancelsInstalls(t *testing.T, ds *Datastore) {
 	forceSetAppleHostProfileStatus(t, ds, host1.UUID, test.ToMDMAppleConfigProfile(profNameToProf["A3"]), fleet.MDMOperationTypeInstall, fleet.MDMDeliveryPending)
 	// enqueue the corresponding command for the installed profile
 	cmdUUID = uuid.New().String()
-	err = commander.InstallProfile(ctx, []string{host1.UUID}, appleProfs[2].Mobileconfig, cmdUUID)
+	err = commander.InstallProfile(ctx, []string{host1.UUID}, appleProfs[2].Mobileconfig, cmdUUID, true)
 	require.NoError(t, err)
 	ExecAdhocSQL(t, ds, func(q sqlx.ExtContext) error {
 		_, err := q.ExecContext(ctx, `UPDATE host_mdm_apple_profiles SET command_uuid = ? WHERE host_uuid = ? AND profile_uuid = ?`, cmdUUID, host1.UUID, profNameToProf["A3"].ProfileUUID)

server/fleet/apple_mdm.go

@@ -19,8 +19,8 @@ import (
 )
 
 type MDMAppleCommandIssuer interface {
-	InstallProfile(ctx context.Context, hostUUIDs []string, profile mobileconfig.Mobileconfig, uuid string) error
-	RemoveProfile(ctx context.Context, hostUUIDs []string, identifier string, uuid string) error
+	InstallProfile(ctx context.Context, hostUUIDs []string, profile mobileconfig.Mobileconfig, uuid string, notify bool) error
+	RemoveProfile(ctx context.Context, hostUUIDs []string, identifier string, uuid string, notify bool) error
 	DeviceLock(ctx context.Context, host *Host, uuid string) (unlockPIN string, err error)
 	EnableLostMode(ctx context.Context, host *Host, commandUUID string, orgName string) error
 	DisableLostMode(ctx context.Context, host *Host, commandUUID string) error

server/mdm/apple/commander.go

@@ -45,12 +45,16 @@ func NewMDMAppleCommander(mdmStorage fleet.MDMAppleStore, mdmPushService nanomdm
 
 // InstallProfile sends the homonymous MDM command to the given hosts, it also
 // takes care of the base64 encoding of the provided profile bytes.
-func (svc *MDMAppleCommander) InstallProfile(ctx context.Context, hostUUIDs []string, profile mobileconfig.Mobileconfig, uuid string) error {
+func (svc *MDMAppleCommander) InstallProfile(ctx context.Context, hostUUIDs []string, profile mobileconfig.Mobileconfig, uuid string, notify bool) error {
 	raw, err := svc.SignAndEncodeInstallProfile(ctx, profile, uuid)
 	if err != nil {
 		return err
 	}
-	err = svc.EnqueueCommand(ctx, hostUUIDs, raw)
+	if notify {
+		err = svc.EnqueueCommand(ctx, hostUUIDs, raw)
+	} else {
+		err = svc.EnqueueCommandWithoutNotification(ctx, hostUUIDs, raw)
+	}
 	return ctxerr.Wrap(ctx, err, "commander install profile")
 }
 
@@ -80,7 +84,7 @@ func (svc *MDMAppleCommander) SignAndEncodeInstallProfile(ctx context.Context, p
 }
 
 // RemoveProfile sends the homonymous MDM command to the given hosts.
-func (svc *MDMAppleCommander) RemoveProfile(ctx context.Context, hostUUIDs []string, profileIdentifier string, uuid string) error {
+func (svc *MDMAppleCommander) RemoveProfile(ctx context.Context, hostUUIDs []string, profileIdentifier string, uuid string, notify bool) error {
 	raw := fmt.Sprintf(`<?xml version="1.0" encoding="UTF-8"?>
 <!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
 <plist version="1.0">
@@ -96,7 +100,12 @@ func (svc *MDMAppleCommander) RemoveProfile(ctx context.Context, hostUUIDs []str
 	</dict>
 </dict>
 </plist>`, uuid, profileIdentifier)
-	err := svc.EnqueueCommand(ctx, hostUUIDs, raw)
+	var err error
+	if notify {
+		err = svc.EnqueueCommand(ctx, hostUUIDs, raw)
+	} else {
+		err = svc.EnqueueCommandWithoutNotification(ctx, hostUUIDs, raw)
+	}
 	return ctxerr.Wrap(ctx, err, "commander remove profile")
 }
 
@@ -507,6 +516,26 @@ func (svc *MDMAppleCommander) EnqueueCommand(ctx context.Context, hostUUIDs []st
 	return svc.enqueueAndNotify(ctx, hostUUIDs, cmd, mdm.CommandSubtypeNone)
 }
 
+func (svc *MDMAppleCommander) EnqueueCommandWithoutNotification(ctx context.Context, hostUUIDs []string, rawCommand string) error {
+	cmd, err := mdm.DecodeCommand([]byte(rawCommand))
+	if err != nil {
+		return ctxerr.Wrap(ctx, err, "decoding command")
+	}
+
+	return svc.enqueue(ctx, hostUUIDs, cmd, mdm.CommandSubtypeNone)
+}
+
+func (svc *MDMAppleCommander) enqueue(ctx context.Context, hostUUIDs []string, cmd *mdm.Command,
+	subtype mdm.CommandSubtype,
+) error {
+	if _, err := svc.storage.EnqueueCommand(ctx, hostUUIDs,
+		&mdm.CommandWithSubtype{Command: *cmd, Subtype: subtype}); err != nil {
+		return ctxerr.Wrap(ctx, err, "enqueuing command")
+	}
+
+	return nil
+}
+
 func (svc *MDMAppleCommander) enqueueAndNotify(ctx context.Context, hostUUIDs []string, cmd *mdm.Command,
 	subtype mdm.CommandSubtype,
 ) error {
@@ -524,15 +553,19 @@ func (svc *MDMAppleCommander) enqueueAndNotify(ctx context.Context, hostUUIDs []
 // EnqueueCommandInstallProfileWithSecrets is a special case of EnqueueCommand that does not expand secret variables.
 // Secret variables are expanded when the command is sent to the device, and secrets are never stored in the database unencrypted.
 func (svc *MDMAppleCommander) EnqueueCommandInstallProfileWithSecrets(ctx context.Context, hostUUIDs []string,
-	rawCommand mobileconfig.Mobileconfig, commandUUID string,
+	rawCommand mobileconfig.Mobileconfig, commandUUID string, notify bool,
 ) error {
 	cmd := &mdm.Command{
 		CommandUUID: commandUUID,
 		Raw:         []byte(rawCommand),
 	}
 	cmd.Command.RequestType = "InstallProfile"
 
-	return svc.enqueueAndNotify(ctx, hostUUIDs, cmd, mdm.CommandSubtypeProfileWithSecrets)
+	if notify {
+		return svc.enqueueAndNotify(ctx, hostUUIDs, cmd, mdm.CommandSubtypeProfileWithSecrets)
+	}
+
+	return svc.enqueue(ctx, hostUUIDs, cmd, mdm.CommandSubtypeProfileWithSecrets)
 }
 
 func (svc *MDMAppleCommander) SendNotifications(ctx context.Context, hostUUIDs []string) error {

server/mdm/apple/commander_test.go

@@ -104,7 +104,7 @@ func TestMDMAppleCommander(t *testing.T) {
 	}
 
 	cmdUUID := uuid.New().String()
-	err := cmdr.InstallProfile(ctx, hostUUIDs, mc, cmdUUID)
+	err := cmdr.InstallProfile(ctx, hostUUIDs, mc, cmdUUID, true)
 	require.NoError(t, err)
 	require.True(t, mdmStorage.EnqueueCommandFuncInvoked)
 	mdmStorage.EnqueueCommandFuncInvoked = false
@@ -118,7 +118,7 @@ func TestMDMAppleCommander(t *testing.T) {
 		return nil, nil
 	}
 	cmdUUID = uuid.New().String()
-	err = cmdr.RemoveProfile(ctx, hostUUIDs, payloadIdentifier, cmdUUID)
+	err = cmdr.RemoveProfile(ctx, hostUUIDs, payloadIdentifier, cmdUUID, true)
 	require.True(t, mdmStorage.EnqueueCommandFuncInvoked)
 	mdmStorage.EnqueueCommandFuncInvoked = false
 	require.True(t, mdmStorage.RetrievePushInfoFuncInvoked)

server/service/apple_mdm.go

@@ -12,6 +12,7 @@ import (
 	"errors"
 	"fmt"
 	"io"
+	"maps"
 	"mime/multipart"
 	"net/http"
 	"net/url"
@@ -2217,7 +2218,7 @@ func (svc *Service) enqueueMDMAppleCommandRemoveEnrollmentProfile(ctx context.Co
 	}
 
 	cmdUUID := uuid.New().String()
-	err = svc.mdmAppleCommander.RemoveProfile(ctx, []string{nanoEnroll.ID}, apple_mdm.FleetPayloadIdentifier, cmdUUID)
+	err = svc.mdmAppleCommander.RemoveProfile(ctx, []string{nanoEnroll.ID}, apple_mdm.FleetPayloadIdentifier, cmdUUID, true)
 	if err != nil {
 		return ctxerr.Wrap(ctx, err, "enqueuing mdm apple remove profile command")
 	}
@@ -4841,6 +4842,7 @@ func ReconcileAppleDeclarations(
 	commander *apple_mdm.MDMAppleCommander,
 	logger kitlog.Logger,
 ) error {
+	level.Info(logger).Log("msg", "ReconcileAppleDeclarations starting")
 	appConfig, err := ds.AppConfig(ctx)
 	if err != nil {
 		return fmt.Errorf("reading app config: %w", err)
@@ -4855,12 +4857,15 @@ func ReconcileAppleDeclarations(
 		return ctxerr.Wrap(ctx, err, "updating host declaration state")
 	}
 
+	level.Info(logger).Log("msg", "ReconcileAppleDeclarations fetched changed hosts")
+
 	// Find any hosts that requested a resync. This is used to cover special cases where we're not
 	// 100% certain of the declarations on the device.
 	resyncHosts, err := ds.MDMAppleHostDeclarationsGetAndClearResync(ctx)
 	if err != nil {
 		return ctxerr.Wrap(ctx, err, "getting and clearing resync hosts")
 	}
+	level.Info(logger).Log("msg", "ReconcileAppleDeclarations fetched resync hosts", "resync_host_count", len(resyncHosts))
 	if len(resyncHosts) > 0 {
 		changedHosts = append(changedHosts, resyncHosts...)
 		// Deduplicate changedHosts
@@ -4911,6 +4916,7 @@ func ReconcileAppleProfiles(
 	commander *apple_mdm.MDMAppleCommander,
 	logger kitlog.Logger,
 ) error {
+	level.Info(logger).Log("msg", "ReconcileAppleProfiles starting")
 	appConfig, err := ds.AppConfig(ctx)
 	if err != nil {
 		return fmt.Errorf("reading app config: %w", err)
@@ -4934,16 +4940,20 @@ func ReconcileAppleProfiles(
 	if block == nil || block.Type != "CERTIFICATE" {
 		return ctxerr.Wrap(ctx, err, "failed to decode PEM block from SCEP certificate")
 	}
+	level.Info(logger).Log("msg", "ReconcileAppleProfiles loaded assets")
 
 	if err := ensureFleetProfiles(ctx, ds, logger, block.Bytes); err != nil {
 		logger.Log("err", "unable to ensure a fleetd configuration profiles are in place", "details", err)
 	}
 
+	level.Info(logger).Log("msg", "ReconcileAppleProfiles ensured fleet profiles exist for all teams")
+
 	// retrieve the profiles to install/remove.
 	toInstall, toRemove, err := ds.ListMDMAppleProfilesToInstallAndRemove(ctx)
 	if err != nil {
 		return ctxerr.Wrap(ctx, err, "getting profiles to install and remove")
 	}
+	level.Info(logger).Log("msg", "ReconcileAppleProfiles retrieved profiles to install and remove", "to_install_count", len(toInstall), "to_remove_count", len(toRemove))
 
 	// Exclude macOS only profiles from iPhones/iPads.
 	toInstall = fleet.FilterMacOSOnlyProfilesFromIOSIPadOS(toInstall)
@@ -5130,6 +5140,8 @@ func ReconcileAppleProfiles(
 		hostProfilesToInstallMap[hostProfileUUID{HostUUID: p.HostUUID, ProfileUUID: p.ProfileUUID}] = hostProfile
 	}
 
+	level.Info(logger).Log("msg", "ReconcileAppleProfiles processed install targets")
+
 	for _, p := range toRemove {
 		// Exclude profiles that are also marked for installation.
 		if _, ok := profileIntersection.GetMatchingProfileInDesiredState(p); ok {
@@ -5192,6 +5204,8 @@ func ReconcileAppleProfiles(
 		})
 	}
 
+	level.Info(logger).Log("msg", "ReconcileAppleProfiles processed remove targets")
+
 	// delete all profiles that have a matching identifier to be installed.
 	// This is to prevent sending both a `RemoveProfile` and an
 	// `InstallProfile` for the same identifier, which can cause race
@@ -5208,6 +5222,7 @@ func ReconcileAppleProfiles(
 	}
 	// We need to delete commands from the nano queue so they don't get sent to device.
 	if len(commandUUIDToHostIDsCleanupMap) > 0 {
+		level.Info(logger).Log("msg", "ReconcileAppleProfiles cleaning up nano commands without results", "count", len(commandUUIDToHostIDsCleanupMap))
 		if err := commander.BulkDeleteHostUserCommandsWithoutResults(ctx, commandUUIDToHostIDsCleanupMap); err != nil {
 			return ctxerr.Wrap(ctx, err, "deleting nano commands without results")
 		}
@@ -5216,6 +5231,8 @@ func ReconcileAppleProfiles(
 		return ctxerr.Wrap(ctx, err, "deleting profiles that didn't change")
 	}
 
+	level.Info(logger).Log("msg", "ReconcileAppleProfiles cleaned up profiles")
+
 	// FIXME: How does this impact variable profiles? This happens before pre-processing, doesn't
 	// this potentially race with the command uuid and variable substitution?
 	//
@@ -5229,13 +5246,17 @@ func ReconcileAppleProfiles(
 		return ctxerr.Wrap(ctx, err, "updating host profiles")
 	}
 
+	level.Info(logger).Log("msg", "ReconcileAppleProfiles upserted host profiles")
+
 	// Grab the contents of all the profiles we need to install
 	profileUUIDs := make([]string, 0, len(toGetContents))
 	for pUUID := range toGetContents {
 		profileUUIDs = append(profileUUIDs, pUUID)
 	}
 	profileContents, err := ds.GetMDMAppleProfilesContents(ctx, profileUUIDs)
 	if err != nil {
+		level.Error(logger).Log("err", "ReconcileAppleProfiles error fetching profile contents", "details", err)
+
 		return ctxerr.Wrap(ctx, err, "get profile contents")
 	}
 
@@ -5244,6 +5265,8 @@ func ReconcileAppleProfiles(
 		return ctxerr.Wrap(ctx, err, "getting grouped certificate authorities")
 	}
 
+	level.Info(logger).Log("msg", "ReconcileAppleProfiles fetched profile contents and grouped CAs")
+
 	// Insert variables into profile contents of install targets. Variables may be host-specific.
 	err = preprocessProfileContents(ctx, appConfig, ds,
 		eeservice.NewSCEPConfigService(logger, nil),
@@ -5253,11 +5276,14 @@ func ReconcileAppleProfiles(
 		return err
 	}
 
+	level.Info(logger).Log("msg", "ReconcileAppleProfiles preprocessed profile contents")
+
 	// Find the profiles containing secret variables.
 	profilesWithSecrets, err := findProfilesWithSecrets(logger, installTargets, profileContents)
 	if err != nil {
 		return err
 	}
+	level.Info(logger).Log("msg", "ReconcileAppleProfiles found profiles with secrets", "count", len(profilesWithSecrets))
 
 	type remoteResult struct {
 		Err     error
@@ -5270,17 +5296,18 @@ func ReconcileAppleProfiles(
 
 	execCmd := func(profUUID string, target *cmdTarget, op fleet.MDMOperationType) {
 		defer wgProd.Done()
+		level.Info(logger).Log("msg", "ReconcileAppleProfiles execcmd starting", "operation", op, "profile_uuid", profUUID, "command_uuid", target.cmdUUID, "enrollment_id_count", len(target.enrollmentIDs))
 
 		var err error
 		switch op {
 		case fleet.MDMOperationTypeInstall:
 			if _, ok := profilesWithSecrets[profUUID]; ok {
-				err = commander.EnqueueCommandInstallProfileWithSecrets(ctx, target.enrollmentIDs, profileContents[profUUID], target.cmdUUID)
+				err = commander.EnqueueCommandInstallProfileWithSecrets(ctx, target.enrollmentIDs, profileContents[profUUID], target.cmdUUID, false)
 			} else {
-				err = commander.InstallProfile(ctx, target.enrollmentIDs, profileContents[profUUID], target.cmdUUID)
+				err = commander.InstallProfile(ctx, target.enrollmentIDs, profileContents[profUUID], target.cmdUUID, false)
 			}
 		case fleet.MDMOperationTypeRemove:
-			err = commander.RemoveProfile(ctx, target.enrollmentIDs, target.profIdent, target.cmdUUID)
+			err = commander.RemoveProfile(ctx, target.enrollmentIDs, target.profIdent, target.cmdUUID, false)
 		}
 
 		var e *apple_mdm.APNSDeliveryError
@@ -5291,15 +5318,25 @@ func ReconcileAppleProfiles(
 			level.Error(logger).Log("err", fmt.Sprintf("enqueue command to %s profiles", op), "details", err)
 			ch <- remoteResult{err, target.cmdUUID}
 		}
+		level.Info(logger).Log("msg", "ReconcileAppleProfiles execcmd completing", "profile_uuid", profUUID, "command_uuid", target.cmdUUID, "enrollment_id_count", len(target.enrollmentIDs))
 	}
+	level.Info(logger).Log("msg", "ReconcileAppleProfiles launching goroutines to send commands", "install_target_count", len(installTargets), "remove_target_count", len(removeTargets))
+	enrollmentIDsForNotifications := make(map[string]bool)
 	for profUUID, target := range installTargets {
 		wgProd.Add(1)
+		for _, enrollmentID := range target.enrollmentIDs {
+			enrollmentIDsForNotifications[enrollmentID] = true
+		}
 		go execCmd(profUUID, target, fleet.MDMOperationTypeInstall)
 	}
 	for profUUID, target := range removeTargets {
 		wgProd.Add(1)
+		for _, enrollmentID := range target.enrollmentIDs {
+			enrollmentIDsForNotifications[enrollmentID] = true
+		}
 		go execCmd(profUUID, target, fleet.MDMOperationTypeRemove)
 	}
+	level.Info(logger).Log("msg", "ReconcileAppleProfiles launched goroutines to send commands", "install_target_count", len(installTargets), "remove_target_count", len(removeTargets))
 
 	// index the host profiles by cmdUUID, for ease of error processing in the
 	// consumer goroutine below.
@@ -5331,14 +5368,29 @@ func ReconcileAppleProfiles(
 		}
 	}()
 
+	level.Info(logger).Log("msg", "ReconcileAppleProfiles launched consumer goroutine")
 	wgProd.Wait()
+	level.Info(logger).Log("msg", "ReconcileAppleProfiles all producer goroutines finished")
 	close(ch) // done sending at this point, this triggers end of for loop in consumer
 	wgCons.Wait()
+	level.Info(logger).Log("msg", "ReconcileAppleProfiles consumer goroutine finished")
 
 	if err := ds.BulkUpsertMDMAppleHostProfiles(ctx, failed); err != nil {
 		return ctxerr.Wrap(ctx, err, "reverting status of failed profiles")
 	}
 
+	enrollmentIDs := slices.Collect(maps.Keys(enrollmentIDsForNotifications))
+
+	level.Info(logger).Log("msg", "ReconcileAppleProfiles sending notifications", "enrollment_id_count", len(enrollmentIDs))
+	if len(enrollmentIDs) > 0 {
+		err = commander.SendNotifications(ctx, enrollmentIDs)
+		if err != nil {
+			level.Info(logger).Log("msg", "failed to send APNs notification to some hosts after reconciling profiles, but commands were enqueued successfully", "error", err)
+		}
+	}
+
+	level.Info(logger).Log("msg", "ReconcileAppleProfiles reverted status of failed profiles", "failed_count", len(failed))
+
 	return nil
 }
 
@@ -6321,7 +6373,7 @@ func renewSCEPWithProfile(
 		uuids = append(uuids, assoc.HostUUID)
 	}
 
-	if err := commander.InstallProfile(ctx, uuids, profile, cmdUUID); err != nil {
+	if err := commander.InstallProfile(ctx, uuids, profile, cmdUUID, true); err != nil {
 		return ctxerr.Wrapf(ctx, err, "sending InstallProfile command for hosts %s", uuids)
 	}