Why macOS anti-malware scans can behave oddly

macOS Catalina and later include an anti-malware scanning service, XProtect Remediator (XPR), that periodically checks your Mac for known malware. If it detects anything untoward, it tries to remove it in a process Apple terms remediation. Because this is all performed as a background service, XPR doesn’t inform you when it scans, or when it detects and remediates malware. Instead it records those events in the log, and in Ventura and later makes them available to third-party software through Endpoint Security events.

To help you keep track of this, three of my utilities report on XPR: SilentKnight runs a quick check on the last 24 hours, as can Mints, and XProCheck provides detailed reports for periods of up to 30 days.

xprocheck155

Every few weeks I get a flurry of comments here, and emails, when those using XProCheck, or browsing the log, notice warnings and strange behaviour by XPR. This article explains what’s happening, and why it’s perfectly healthy.

Background scans

XPR runs its scans according to the frequencies set for the service; although they ran more frequently a year ago, when it had just been introduced and threat was different, currently its scans are run once a day as the user, and once a day as root. Look in Activity Monitor and you’ll see not two XProtect services, but a total of seven: XProtectBehaviorService is a new behavioural protection system still being introduced, but it’s the two XProtectPluginService processes that are responsible for arranging XPR’s periodic anti-malware scans, one run as user, the other as root.

This is scheduled and dispatched through the DAS-CTS system so that scans are performed when your Mac is awake but not doing much. Each XProtectPluginService is fired up and runs through its cycle of scans performed by plugins contained within the XPR bundle, with names like XProtectRemediatorMRTv3, which performs most if not all of the checks that used to be performed by the macOS Malware Removal Tool, MRT. XProCheck looks through the log for reports from each of those scanning modules, and informs you of what they contain, for example
2023-08-11 08:12:15.260 FloppyFlipper NoThreatDetected status_code 20 time 0.0000510
which is a normal report for a scan to detect malware Apple calls FloppyFlipper.

Infrequent scans

Sometimes XPR doesn’t report any scans in 24 hours, usually because there hasn’t been a convenient time when that Mac has been awake and relatively inactive. The DAS-CTS system will then automatically increase the priority of those scans until they’re completed. You can help that by leaving your Mac running, awake and unused for an hour or so, which should enable the scans to be run.

Bad signatures

Depending on how you use it and when you shut down or restart your Mac, every few weeks you may notice some odd behaviour in these reports, shortly after I announce here that Apple has released an update to XPR. What happens then might appear concerning, as each copy of XPR’s background service reports a signature error and immediately aborts a set of scans, as if something has gone wrong with the update and the new copy of XPR. This might be reported in XProCheck as
2023-08-10 08:46:10.545 Eicar BadPluginServiceSignature status_code 31 (normal if XPR has recently been updated)

When your Mac installs an update to XPR, it replaces the whole of its bundle, including all the scanner modules and XProtectPluginService. The latter process communicates with individual scanner modules using XPC, and that’s made secure by checking the signatures of those modules. When an update has just been installed, macOS is left still running the previous version of XProtectPluginService, but all the modules are now from the new version.

When DAS-CTS dispatches the new XPR scans, XProtectPluginService tries to run the first of the new modules, but discovers that its signature doesn’t match that expected. It reports that in the log, and macOS then quits and restarts the XProtectPluginService. As the version that now starts up is the new one, when DAS-CTS next dispatches XPR scans, the signatures now match, and the scans complete as expected.

Full log entries

If, instead of looking at the log summary reports in XProCheck, you were to browse the whole log using Ulbow, you’d see this all spelled out. After seeing DAS-CTS dispatch the scans, you’d see the following.

19.143590 com.apple.XProtectFramework.Plugin XProtectRemediatorMRTv3 PluginService has an invalid code signature, terminating
resulting in the log entry you see in XProCheck:
19.144380 com.apple.XProtectFramework.PluginAPI XProtectRemediatorMRTv3 {"caused_by":[],"status_message":"Unknown","status_code":31,"execution_duration":0.00016105175018310547}

Next, the offending scanner module inside XPR was exited, and its XPC communications with other processes, in particular XProtectPluginService, were cancelled.
19.144390 XProtectRemediatorMRTv3 CoreAnalytics Entering exit handler.
19.144416 XProtectRemediatorMRTv3 CoreAnalytics Cancelling XPC connection. Any further reply handler invocations will not retry messages
19.144446 XProtectRemediatorMRTv3 CoreAnalytics XPC connection invalidated (daemon unloaded/disabled)
19.274219+0000 Error XProtectPluginService com.apple.XProtectFramework.plugins.MRTv3 @ file:///Library/Apple/System/Library/CoreServices/XProtect.app/Contents/MacOS/XProtectRemediatorMRTv3 - BB9B968A-D632-49BC-9CC4-2F1A2363DB47 exited with .badPluginServiceSignature - exiting

This was propagated to XProtectPluginService, which runs these scans.
19.274224 XProtectPluginService CoreAnalytics Entering exit handler.
19.274267 XProtectPluginService CoreAnalytics Cancelling XPC connection. Any further reply handler invocations will not retry messages
19.274305 XProtectPluginService CoreAnalytics XPC connection invalidated (daemon unloaded/disabled)
19.274346 Error [XPC Server] managed connection recieved connection invalidated: Connection invalid
19.274523 Fault com.apple.XProtectFramework XProtect XPC connection interrupted
19.275667 system/com.apple.XprotectFramework.PluginService [1946] launchd launchd exited due to exit(0)
19.275694 system/com.apple.XprotectFramework.PluginService [1946] launchd launchd service state: not running
19.275699 pid/1946 [XProtectPluginS] launchd launchd shutting down
19.275708 launchd removing child: pid/1946

In the last two of those entries, that process ID (PID) is that of XProtectPluginService.

Then the underlying cause is revealed, and that attempt at a scan abandoned as complete.
19.278403 Fault XProtectPluginService connection error: Couldn’t communicate with a helper application.
19.278445 com.apple.XProtectFramework XProtect Finished system scan, ran as 0
19.278491 Fault com.apple.XProtectFramework XProtect XPC connection invalidated
19.278543 Completed XPC Activity: com.apple.XProtect.PluginService.daemon.scan (0x7fd016514e60)

As this is a periodic task, its next set of scans was then set up with Duet Activity Scheduler (DAS), to run in 24 hours time.
19.282677 com.apple.duetactivityscheduler Submitted Activity: 0:com.apple.XProtect.PluginService.daemon.scan:15EF08 at priority 30 with interval 86400 (Fri Feb 3 23:54:02 2023 - Sat Feb 4 23:54:02 2023)

This occurred twice: once for the scan run as root (above), and once for that run as the current user, which generates a second warning message.

Summary

  • XProtect Remediator (XPR) normally scans when your Mac is running, awake, and not doing much else.
  • If you don’t see XPR scans in the last 24 hours, leave your Mac awake and inactive for an hour or so for scans to be run.
  • After installing an XPR update it’s normal to see a BadPluginServiceSignature status_code 31 scan report, and that set of scans aborted.
  • You don’t need to take any action as a result of those reports, as XPR will restart itself and run the next sets of scans normally.
  • If you shut your Mac down, or restart it, shortly after installing an XPR update, you’re not likely to see these reports, as the next scans will be run using the new version of XPR.