NE SystemExtension upgrade deadlock (OSSystemExtensionErrorDomain 1)

We have had many devices install our SystemExtension based Network Extension via Developer ID, and all of that works fine.

However, when upgrading, some devices end up in a strange state where the SystemExtension is "stuck" between versions.

See the systemextensionsctl list results below:
Code Block language
--- com.apple.system_extension.network_extension
enabled	active	teamID	bundleID (version)	name	[state]
		LLW79T3K9U	app.company.ne (0.5.5/5)	app.company.ne	[terminating for uninstall]
		LLW79T3K9U	app.company.ne (0.3.4/4)	app.company.ne	[terminated waiting to uninstall on reboot]
		LLW79T3K9U	app.company.ne (0.5.6/6)	app.company.ne	[activated waiting to upgrade]

We've noticed that the[terminated waiting to uninstall on reboot] happens on all machines, but appears to be benign.

However, the [terminating for uninstall] 0.5.5 version seems to be blocking 0.5.6 with the[activated waiting to upgrade] state. In this state our 0.5.5 version is not working, throwing immediate errors when trying to start the VPN.

Specifically, we see the below in our logging:

Code Block language
2020-08-05 12:13:21.618+02:00 [Info][AppStateService]: Tunnel activation started.
2020-08-05 12:13:21.619+02:00 [Info][AppStateService]: System extension activation started.
2020-08-05 12:13:21.622+02:00 [Info][SystemExtensionService]: System extension (app.company.ne) request started.
2020-08-05 12:13:21.626+02:00 [Info][AppStateService]: Application state changed - enabling
2020-08-05 12:13:21.627+02:00 [Info][AppStateService]: Application state changed - enabling
2020-08-05 12:13:21.628+02:00 [Info][StatusItemPopoverViewModel]: Reload popover state - enabling
2020-08-05 12:13:26.710+02:00 [Error][SystemExtensionService]: System extension request failed - The operation couldn’t be completed. (OSSystemExtensionErrorDomain error 1.)
2020-08-05 12:13:26.711+02:00 [Error][AppStateService]: System extension activation failed - The operation couldn’t be completed. (OSSystemExtensionErrorDomain error 1.)
2020-08-05 12:13:26.711+02:00 [Error][AppStateService]: Tunnel activation failed - The operation couldn’t be completed. (OSSystemExtensionErrorDomain error 1.)
2020-08-05 12:13:26.752+02:00 [Error][StatusItemPopoverViewModel]: Show error - The operation couldn’t be completed. (OSSystemExtensionErrorDomain error 1.)


Thoughts? Anyone else ever see this?
Up vote post of mattv1234 Down vote post of mattv1234
2.2k views
Posted by
mattv1234
Reply
Add a Comment

Replies

I have not seen this specific error, but are you passing through actionForReplacingExtension in your OSSystemExtensionRequestDelegate ?

Code Block swift
extension MyClass: OSSystemExtensionRequestDelegate {
		func request(_ request: OSSystemExtensionRequest, actionForReplacingExtension existing: OSSystemExtensionProperties, withExtension replacement: OSSystemExtensionProperties) -> OSSystemExtensionRequest.ReplacementAction {
				/* Replacement functionality here */
				return .replace
		}
}


Matt Eaton
DTS Engineering, CoreOS
meaton3@apple.com
Posted by
meaton
Up vote reply of meaton Down vote reply of meaton
Add a Comment
Yes, we are doing exactly that (always returning replace) with only a single line of additional code for logging.

We captured a sysdiagnose on the device and the above system extension state is shown in the systemextensionsctl_list.txt file, but there isn't anything really apparent in the big systems_logs file.

Anything else to check?
Posted by
mattv1234
Up vote reply of mattv1234 Down vote reply of mattv1234
Add a Comment
Ahh, actually, looking at the system logs when the user is trying to upgrade the app, it looks like sysextd is crashing...

Logs filtered by sysextd during an installation:
Code Block language
2291	default	2020-08-10 09:09:50.760221 +0100	sysextd	Restoring state from extensions DB
Previous boot UUID: 4585FFFD-6D28-42A4-B7F4-4CD7F09253BD, current boot UUID: 4585FFFD-6D28-42A4-B7F4-4CD7F09253BD; rebooted = false
2291	default	2020-08-10 09:09:50.761023 +0100	sysextd	Extension com.company.NE/teamID("<redacted>") version 6 is in state activated_waiting_to_upgrade
2291	default	2020-08-10 09:09:50.761116 +0100	sysextd	Extension com.company.NE/teamID("<redacted>") version 6 now in state activated_waiting_to_upgrade
2291	default	2020-08-10 09:09:50.761137 +0100	sysextd	Extension com.company.NE/teamID("<redacted>") version 7 is in state terminating_for_uninstall
2291	default	2020-08-10 09:09:50.761157 +0100	sysextd	Extension com.company.NE/teamID("<redacted>") version 7 now in state terminating_for_uninstall
2291	default	2020-08-10 09:09:50.761161 +0100	sysextd	State restoration from extensions DB completed
2291	default	2020-08-10 09:09:50.783536 +0100	sysextd	attempting to realize extension with identifier com.company.NE
2291	default	2020-08-10 09:09:50.790281 +0100	sysextd	Realizing target path: <private>
2291	default	2020-08-10 09:09:50.790872 +0100	sysextd	Bundle class: UncachedBundle
2291	default	2020-08-10 09:09:50.814968 +0100	sysextd	Fatal error: Activate found 2 extensions in active state, ID: com.company.NE,	teamID("<redacted>"): file /AppleInternal/BuildRoot/Library/Caches/com.apple.xbs/Sources/SystemExtensions_executables/SystemExtensions-35.140.3/core/extension_manager.swift, line 1324
335	default	2020-08-10 09:09:50.838167 +0100	ReportCrash	Parsing corpse data for process sysextd [pid 2291]
335	default	2020-08-10 09:09:52.797288 +0100	ReportCrash	Sending event: com.apple.stability.crash {"appVersion":"???","exceptionType":2,"process":"sysextd","responsibleApp":"sysextd"}
335	default	2020-08-10 09:09:52.824914 +0100	ReportCrash	Saved crash report for sysextd[2291] version 35.140.3 to sysextd_2020-08-10-090952_<redacted>.crash


This looks to explain why the extensions are stuck in their state: sysextd crashes before it can put them into a healthy state.

Time to submit a feedback ticket?
Posted by
mattv1234
Up vote reply of mattv1234 Down vote reply of mattv1234
Add a Comment

Time to submit a feedback ticket?

Definitely! sysextd shouldn’t crash no matter what you throw at it.

Share and Enjoy
—
Quinn “The Eskimo!” @ Developer Technical Support @ Apple
let myEmail = "eskimo" + "1" + "@apple.com"
Posted by
eskimo
Up vote reply of eskimo Down vote reply of eskimo
Add a Comment
Submitted! FB8401363

Will update this thread with any relevant updates towards resolution or workarounds we may find.
Posted by
mattv1234
Up vote reply of mattv1234 Down vote reply of mattv1234
Add a Comment
Has anyone found a solution to this issue? I am facing the same issue.

sysextd keeps on crashing when I try to uninstall it with the following command.
sysextd crash



/usr/bin/systemextensionsctl uninstall ID "systemextension"
Posted by
dankira
Up vote reply of dankira Down vote reply of dankira
Add a Comment
I've found myself in this same situation.

I've tried uninstalling with SIP turned off. I've also tried deactivationRequestForExtension

The logs I'm getting for systextd (xxxx is placeholder for my real extension) are

Code Block language
request contains  authorizationref
extension xxxx advancing from activated_waiting_to_upgrade->terminating_for_uninstall
state transition not allowed, crashing...
sysextd restarted


At this point I don't know what to do? I can't activate or deactivate my extension...
Posted by
cpayn
Up vote reply of cpayn Down vote reply of cpayn
Add a Comment
If you do find yourself in a situation like this where you are experiencing issues, a crash, or the System Extension is not deactivating properly, AND you have SIP enabled, then you should open a bug report.

I encourage you to always test this with SIP enabled so that you are not masking potential issues in Development that you may uncover in QA testing.


Matt Eaton
DTS Engineering, CoreOS
meaton3@apple.com
Posted by
meaton
Up vote reply of meaton Down vote reply of meaton
Add a Comment