Multiple PushProviders Instantiated at one time

I have an issue that causes multiple instances of the push provider to be initialized. And I'd like to ask you what could trigger the instantiation NEAppPushProvider subclass. It seems like it's being triggered excessively. If there's documentation that I have overlooked then just show it to me and I'll be on my way.

Here's the details. But really all I want to know is why is my subclass for NEAppPushProvider keeps getting initialized. If you can answer me that than maybe all these details don't really matter but here they are.

Here's why I believe there's multiple push provider. I see logs for my push provider initializing but I don't see it de-initializing. I also see redundant logs showing multiple instances trying to log into my server. Each time it initializes, an additional log is added for trying to log into my server.

In the app, the system saves it's configuration shortly after initialization, after saving and loading the push configuration, the app doesn't touch config.

Meanwhile in the extension, after 8 or so hours, the extension starts creating a new instance of the push provider. Then a few hours later it does it again. And again. Until the watch dog kills us for wasting too much CPU.

Normally on a fresh install, I'll observe turning off the wifi to call stop on the push provider and later have the push provider de-initialize.

The extension maintains a socket connection to the server, the server can send it messages to display push notifications. The software runs on hospital networks, which will not have access to the internet. It seems like the connection to the server is stable from the logs. I don't detect any disconnections. I'll check with the server to confirm.

In the app I call removeFromPreferences to clear out any extensions before logging in/saving push configurations. And I call saveToPreferences on the NEAppPushManager. I do this to make sure I don't have more than one push configuration saved at one time. I also have many logs looking out for this. I used the sample code from apple as the basis of the my own Push Manager. I can post code if you deem it necessary.

Hope to here from you soon. Thank you.

I’m not super familiar with app push providers, but there’s one thing I want to check up front. You wrote:

Written by dtanmasimo in 773468021
I see logs for my push provider initializing but I don't see it de-initializing.

Are you sure they’re all from the same process? I’ve hit situations like this — with other NE provider types, mind you — where the process died and was restarted, but the logging didn’t make that obvious.

I generally do all my logging with the system log (see Your Friend the System Log) which records the pid with each log entry. So, all I need to do to rule this out is to show that column in Console.

Share and Enjoy

Quinn “The Eskimo!” @ Developer Technical Support @ Apple
let myEmail = "eskimo" + "1" + "@" + "apple.com"

I'll keep that in mind, but for my situation it takes approximately 4-8 hours for the issue to occur and I'm not sure if system log will go back that far.

But let me give you an example of what I'm seeing. When I first init you'll see this

 > 🗒️ Connection status: Optional(AuthenticationStatus.connecting)
 > 🗒️ Connection status: Optional(AuthenticationStatus.authenticating) 
 > 🗒️⚡️ didLogIn

Later I see it init

🗒️🪬🪬🗒️ MyPushProvider Init D6E50D82-3671-4ED9-BBA4-411F8FB854C4

Then I see the following

 > 🗒️ Connection status: Optional(ReplicaShared.AuthenticationStatus.connecting)
 > 🗒️ Connection status: Optional(ReplicaShared.AuthenticationStatus.connecting)
 > 🗒️ Connection status: Optional(ReplicaShared.AuthenticationStatus.authenticating)
 > 🗒️ Connection status: Optional(ReplicaShared.AuthenticationStatus.authenticating)
 > 🗒️⚡️ didLogIn

With ever init log, I'll see an additional print for the connection status.

So after the 3rd MyPushProvider Init I'll see a third log, and so on. So it seems likely, at least from what I see, that there are multiple Push Providers in existence at once. I'm adding additional logs to keep track of which instances are giving out their status as well as what their provider info, such as provider configuration info.

From the app, I only saved one configuration and it tracks to a minute or less before the first log where this push provider is initialized. Other than that there are no other saves to the push configuration manager. I feel pretty stuck because it doesn't seem like I control what calls MyPushProvider()

You say you don't have specific experience with the NEAppPushProvider, is there a way to get into someone else who does?

I'm pretty stuck, and if you can unstuck me then I'll be super grateful. Thanks.

Are you sure they’re all from the same process? I’ve hit situations like this — with other NE provider types, mind you — where the process died and was restarted, but the logging didn’t make that obvious.

As a general note on this, if you're doing your own logging I recommend including the pid in every log message. It takes up minimal space and I've seen way to many cases where it was the one detail that suddenly made everything clear.

I'll keep that in mind, but for my situation it takes approximately 4-8 hours for the issue to occur and I'm not sure if system log will go back that far.

The exact behavior depend on the device state, but if the device has plenty of empty space and hasn't been rebooted, then the sysdiagnose will often to back 24+ hours. The one thing to be aware of is that the system does start purging data (particularly when space is constrained) and this purging is by system/subsystem, not just time. In concrete terms, many logs often go back a very long time but on closer inspection you'll find that there are significant process (like, "the kernel") missing from those older log messages. Regardless, the next step here is to pull the log data and see what you find.

In terms of the log message here:

 > 🗒️ Connection status: Optional(ReplicaShared.AuthenticationStatus.connecting)
 > 🗒️ Connection status: Optional(ReplicaShared.AuthenticationStatus.connecting)
 > 🗒️ Connection status: Optional(ReplicaShared.AuthenticationStatus.authenticating)
 > 🗒️ Connection status: Optional(ReplicaShared.AuthenticationStatus.authenticating)
 > 🗒️⚡️ didLogIn

...the critical information that's missing here is the PID and timestamps. If this is all happening in the same process, then that's an app logic issue that you'd need to investigate. If they're different processes, then my guess is that what actually happened is something like this:

pid 10-> 🗒️ Connection status: Optional(ReplicaShared.AuthenticationStatus.connecting)
pid 20-> 🗒️ Connection status: Optional(ReplicaShared.AuthenticationStatus.connecting)
pid 10-> 🗒️ Connection status: Optional(ReplicaShared.AuthenticationStatus.authenticating)
pid 20-> 🗒️ Connection status: Optional(ReplicaShared.AuthenticationStatus.authenticating)
pid 20-> 🗒️⚡️ didLogIn

...over a relatively short period of time.

What can cause this is that the device lost and regained WiFi over a very short period of time temporarily causing two extensions to be running at the same time.

__
Kevin Elliott
DTS Engineer, CoreOS/Hardware

As a general note on this, if you're doing your own logging I recommend including the pid in every log message. It takes up minimal space and I've seen way to many cases where it was the one detail that suddenly made everything clear.

Will do, need to check my assumptions and include the PID.

The exact behavior depend on the device state, but if the device has plenty of empty space and hasn't been rebooted, then the sysdiagnose will often to back 24+ hours. The one thing to be aware of is that the system does start purging data (particularly when space is constrained) and this purging is by system/subsystem, not just time. In concrete terms, many logs often go back a very long time but on closer inspection you'll find that there are significant process (like, "the kernel") missing from those older log messages. Regardless, the next step here is to pull the log data and see what you find.

I read your posts on using the system log and I'm going to include them next since they'll be good to have in our release build. Right now in our debug builds we log to file in the documents directory. As a fast fix I added the PID to existing logs.

Gotcha I'll be sure to get the critical information, PIDs and timestamps. They'll be in the next long term test in QA. I'll report back when I get something. Thank you.

I'm back with new logs. Just as a reminder, there's a 1-1 correspondence with the PushProvider subclass instantiated and the ExtensionConnectionInteractor. The interactor is only instantiated in the init of the PushProvider subclass.

Below is how the log starts out. The last 5 characters, after connection success, are from a UUID to identify the instance of the interactor. As requested the PID was added to the log.

2025-02-06 15:17:11.241 [Debug] [ExtensionClient.swift:453] setAndBroadcastAuthenticationState(_:error:) > 🗒️🗒️🗒️ state: authenticated
2025-02-06 15:17:11.241 [Debug] [ExtensionConnectionInteractor.swift:150] start(providerConfiguration:) > PID: 65933 | 🗒️✅ Connection success 0D170
2025-02-06 15:17:11.242 [Debug] [AuthenticationViewModel.swift:89] updateAuthenticationStatus(_:) > PID: 65933 | success...

Here's the system in the process of reconnection before it crashes. Note the date, it took about 3 days to get here. Note the same PID but separate instances of the interactor. This seems to imply multiple calls to instantiate the PushProvider subclass.

** many lines were removed due to character limit. But the lines are all calls from additional interactors trying to reconnect **
2025-02-10 07:02:01.751 [Debug] [ExtensionConnectionInteractor.swift:153] start(providerConfiguration:) > PID: 65933 | 🗒️ Connection status: Optional(ReplicaShared.AuthenticationStatus.authenticating) 9C171
2025-02-10 07:02:01.751 [Debug] [AuthenticationViewModel.swift:93] updateAuthenticationStatus(_:) > PID: 65933 | authenticating
2025-02-10 07:02:01.751 [Debug] [Authenticatable.swift:101] setupAuthenticationFlow(lifetime:) > PID: 65933 | 🔑 didConnect --> Registering Device
2025-02-10 07:02:01.752 [Debug] [ExtensionConnectionInteractor.swift:153] start(providerConfiguration:) > PID: 65933 | 🗒️ Connection status: Optional(ReplicaShared.AuthenticationStatus.authenticating) FD88C
2025-02-10 07:02:01.752 [Debug] [AuthenticationViewModel.swift:93] updateAuthenticationStatus(_:) > PID: 65933 | authenticating
2025-02-10 07:02:01.752 [Debug] [Authenticatable.swift:101] setupAuthenticationFlow(lifetime:) > PID: 65933 | 🔑 didConnect --> Registering Device
2025-02-10 07:02:01.752 [Debug] [ExtensionConnectionInteractor.swift:153] start(providerConfiguration:) > PID: 65933 | 🗒️ Connection status: Optional(ReplicaShared.AuthenticationStatus.authenticating) B5416
2025-02-10 07:02:01.753 [Debug] [AuthenticationViewModel.swift:93] updateAuthenticationStatus(_:) > PID: 65933 | authenticating
2025-02-10 07:02:01.753 [Debug] [Authenticatable.swift:101] setupAuthenticationFlow(lifetime:) > PID: 65933 | 🔑 didConnect --> Registering Device
2025-02-10 07:02:01.754 [Debug] [ExtensionConnectionInteractor.swift:153] start(providerConfiguration:) > PID: 65933 | 🗒️ Connection status: Optional(ReplicaShared.AuthenticationStatus.authenticating) 6C848
2025-02-10 07:02:01.754 [Debug] [AuthenticationViewModel.swift:93] updateAuthenticationStatus(_:) > PID: 65933 | authenticating
2025-02-10 07:02:01.754 [Debug] [Authenticatable.swift:101] setupAuthenticationFlow(lifetime:) > PID: 65933 | 🔑 didConnect --> Registering Device
2025-02-10 07:02:01.754 [Debug] [ExtensionConnectionInteractor.swift:153] start(providerConfiguration:) > PID: 65933 | 🗒️ Connection status: Optional(ReplicaShared.AuthenticationStatus.authenticating) 31276
2025-02-10 07:02:01.755 [Debug] [AuthenticationViewModel.swift:93] updateAuthenticationStatus(_:) > PID: 65933 | authenticating
2025-02-10 07:02:01.755 [Debug] [Authenticatable.swift:101] setupAuthenticationFlow(lifetime:) > PID: 65933 | 🔑 didConnect --> Registering Device
2025-02-10 07:02:01.755 [Debug] [ExtensionConnectionInteractor.swift:153] start(providerConfiguration:) > PID: 65933 | 🗒️ Connection status: Optional(ReplicaShared.AuthenticationStatus.authenticating) 51463
2025-02-10 07:02:01.755 [Debug] [AuthenticationViewModel.swift:93] updateAuthenticationStatus(_:) > PID: 65933 | authenticating
2025-02-10 07:02:01.756 [Debug] [Authenticatable.swift:101] setupAuthenticationFlow(lifetime:) > PID: 65933 | 🔑 didConnect --> Registering Device
2025-02-10 07:02:01.756 [Debug] [ExtensionConnectionInteractor.swift:153] start(providerConfiguration:) > PID: 65933 | 🗒️ Connection status: Optional(ReplicaShared.AuthenticationStatus.authenticating) CD715
2025-02-10 07:02:01.756 [Debug] [AuthenticationViewModel.swift:93] updateAuthenticationStatus(_:) > PID: 65933 | authenticating
2025-02-10 07:02:01.757 [Debug] [Authenticatable.swift:101] setupAuthenticationFlow(lifetime:) > PID: 65933 | 🔑 didConnect --> Registering Device
2025-02-10 07:02:01.757 [Debug] [ExtensionConnectionInteractor.swift:153] start(providerConfiguration:) > PID: 65933 | 🗒️ Connection status: Optional(ReplicaShared.AuthenticationStatus.authenticating) 21B76
2025-02-10 07:02:01.757 [Debug] [AuthenticationViewModel.swift:93] updateAuthenticationStatus(_:) > PID: 65933 | authenticating
2025-02-10 07:02:01.758 [Debug] [Authenticatable.swift:101] setupAuthenticationFlow(lifetime:) > PID: 65933 | 🔑 didConnect --> Registering Device
2025-02-10 07:02:01.758 [Debug] [ExtensionConnectionInteractor.swift:153] start(providerConfiguration:) > PID: 65933 | 🗒️ Connection status: Optional(ReplicaShared.AuthenticationStatus.authenticating) B46CF
2025-02-10 07:02:01.758 [Debug] [AuthenticationViewModel.swift:93] updateAuthenticationStatus(_:) > PID: 65933 | authenticating
2025-02-10 07:02:01.758 [Debug] [Authenticatable.swift:101] setupAuthenticationFlow(lifetime:) > PID: 65933 | 🔑 didConnect --> Registering Device
2025-02-10 07:02:01.759 [Debug] [ExtensionConnectionInteractor.swift:153] start(providerConfiguration:) > PID: 65933 | 🗒️ Connection status: Optional(ReplicaShared.AuthenticationStatus.authenticating) 4F224
2025-02-10 07:02:01.759 [Debug] [AuthenticationViewModel.swift:93] updateAuthenticationStatus(_:) > PID: 65933 | authenticating
2025-02-10 07:02:01.759 [Debug] [Authenticatable.swift:101] setupAuthenticationFlow(lifetime:) > PID: 65933 | 🔑 didConnect --> Registering Device
2025-02-10 07:02:01.759 [Debug] [ExtensionConnectionInteractor.swift:153] start(providerConfiguration:) > PID: 65933 | 🗒️ Connection status: Optional(ReplicaShared.AuthenticationStatus.authenticating) EDC79
2025-02-10 07:02:01.760 [Debug] [AuthenticationViewModel.swift:93] updateAuthenticationStatus(_:) > PID: 65933 | authenticating
2025-02-10 07:02:01.760 [Debug] [Authenticatable.swift:101] setupAuthenticationFlow(lifetime:) > PID: 65933 | 🔑 didConnect --> Registering Device
2025-02-10 07:02:01.760 [Debug] [ExtensionConnectionInteractor.swift:153] start(providerConfiguration:) > PID: 65933 | 🗒️ Connection status: Optional(ReplicaShared.AuthenticationStatus.authenticating) D2257
2025-02-10 07:02:01.760 [Debug] [AuthenticationViewModel.swift:93] updateAuthenticationStatus(_:) > PID: 65933 | authenticating

Here's a log that comes after the crash. Note the new PID.

2025-02-10 07:02:11.657 [Debug] [ExtensionConnectionInteractor.swift:150] start(providerConfiguration:) > PID: 71304 | 🗒️✅ Connection success 9FE76
2025-02-10 07:02:11.658 [Debug] [AuthenticationViewModel.swift:89] updateAuthenticationStatus(_:) > PID: 71304 | success...
2025-02-10 07:02:11.659 [Debug] [Authenticatable.swift:145] setupAuthenticationFlow(lifetime:) > PID: 71304 | 🔑 didLogIn --> Completed

And then in an hour before it crashes we see this. It seems that more push providers are being created still.

** many redundant lines were removed due to character limit **
start(providerConfiguration:) > PID: 71304 | 🗒️✅ Connection success B9979
2025-02-10 08:34:49.671 [Debug] [AuthenticationViewModel.swift:89] updateAuthenticationStatus(_:) > PID: 71304 | success...
2025-02-10 08:34:49.671 [Debug] [Authenticatable.swift:145] setupAuthenticationFlow(lifetime:) > PID: 71304 | 🔑 didLogIn --> Completed
2025-02-10 08:34:49.672 [Debug] [ExtensionConnectionInteractor.swift:150] start(providerConfiguration:) > PID: 71304 | 🗒️✅ Connection success A6665
2025-02-10 08:34:49.672 [Debug] [AuthenticationViewModel.swift:89] updateAuthenticationStatus(_:) > PID: 71304 | success...
2025-02-10 08:34:49.672 [Debug] [Authenticatable.swift:145] setupAuthenticationFlow(lifetime:) > PID: 71304 | 🔑 didLogIn --> Completed
2025-02-10 08:34:49.672 [Debug] [ExtensionConnectionInteractor.swift:150] start(providerConfiguration:) > PID: 71304 | 🗒️✅ Connection success 2BD1F
2025-02-10 08:34:49.672 [Debug] [AuthenticationViewModel.swift:89] updateAuthenticationStatus(_:) > PID: 71304 | success...
2025-02-10 08:34:49.672 [Debug] [Authenticatable.swift:145] setupAuthenticationFlow(lifetime:) > PID: 71304 | 🔑 didLogIn --> Completed
2025-02-10 08:34:49.673 [Debug] [ExtensionConnectionInteractor.swift:150] start(providerConfiguration:) > PID: 71304 | 🗒️✅ Connection success 3F205
2025-02-10 08:34:49.673 [Debug] [AuthenticationViewModel.swift:89] updateAuthenticationStatus(_:) > PID: 71304 | success...
2025-02-10 08:34:49.673 [Debug] [Authenticatable.swift:145] setupAuthenticationFlow(lifetime:) > PID: 71304 | 🔑 didLogIn --> Completed
2025-02-10 08:34:49.673 [Debug] [ExtensionConnectionInteractor.swift:150] start(providerConfiguration:) > PID: 71304 | 🗒️✅ Connection success 6BA62
2025-02-10 08:34:49.674 [Debug] [AuthenticationViewModel.swift:89] updateAuthenticationStatus(_:) > PID: 71304 | success...
2025-02-10 08:34:49.674 [Debug] [Authenticatable.swift:145] setupAuthenticationFlow(lifetime:) > PID: 71304 | 🔑 didLogIn --> Completed
2025-02-10 08:34:49.675 [Debug] [ExtensionConnectionInteractor.swift:150] start(providerConfiguration:) > PID: 71304 | 🗒️✅ Connection success 3D807
2025-02-10 08:34:49.675 [Debug] [AuthenticationViewModel.swift:89] updateAuthenticationStatus(_:) > PID: 71304 | success...
2025-02-10 08:34:49.675 [Debug] [Authenticatable.swift:145] setupAuthenticationFlow(lifetime:) > PID: 71304 | 🔑 didLogIn --> Completed
2025-02-10 08:34:49.676 [Debug] [ExtensionConnectionInteractor.swift:150] start(providerConfiguration:) > PID: 71304 | 🗒️✅ Connection success 7C9B0
2025-02-10 08:34:49.676 [Debug] [AuthenticationViewModel.swift:89] updateAuthenticationStatus(_:) > PID: 71304 | success...
2025-02-10 08:34:49.676 [Debug] [Authenticatable.swift:145] setupAuthenticationFlow(lifetime:) > PID: 71304 | 🔑 didLogIn --> Completed
2025-02-10 08:34:49.676 [Debug] [ExtensionConnectionInteractor.swift:150] start(providerConfiguration:) > PID: 71304 | 🗒️✅ Connection success E408B
2025-02-10 08:34:49.676 [Debug] [AuthenticationViewModel.swift:89] updateAuthenticationStatus(_:) > PID: 71304 | success...
2025-02-10 08:34:49.676 [Debug] [Authenticatable.swift:145] setupAuthenticationFlow(lifetime:) > PID: 71304 | 🔑 didLogIn --> Completed
2025-02-10 08:34:49.677 [Debug] [ExtensionConnectionInteractor.swift:150] start(providerConfiguration:) > PID: 71304 | 🗒️✅ Connection success C21C1
2025-02-10 08:34:49.677 [Debug] [AuthenticationViewModel.swift:89] updateAuthenticationStatus(_:) > PID: 71304 | success...
2025-02-10 08:34:49.677 [Debug] [Authenticatable.swift:145] setupAuthenticationFlow(lifetime:) > PID: 71304 | 🔑 didLogIn --> Completed
2025-02-10 08:34:49.678 [Debug] [ExtensionConnectionInteractor.swift:150] start(providerConfiguration:) > PID: 71304 | 🗒️✅ Connection success 57EFC
2025-02-10 08:34:49.678 [Debug] [AuthenticationViewModel.swift:89] updateAuthenticationStatus(_:) > PID: 71304 | success...
2025-02-10 08:34:49.678 [Debug] [Authenticatable.swift:145] setupAuthenticationFlow(lifetime:) > PID: 71304 | 🔑 didLogIn --> Completed
2025-02-10 08:34:49.679 [Debug] [ExtensionConnectionInteractor.swift:150] start(providerConfiguration:) > PID: 71304 | 🗒️✅ Connection success CF0A5
2025-02-10 08:34:49.679 [Debug] [AuthenticationViewModel.swift:89] updateAuthenticationStatus(_:) > PID: 71304 | success...
2025-02-10 08:34:49.679 [Debug] [Authenticatable.swift:145] setupAuthenticationFlow(lifetime:) > PID: 71304 | 🔑 didLogIn --> Completed
2025-02-10 08:34:49.679 [Debug] [ExtensionConnectionInteractor.swift:150] start(providerConfiguration:) > PID: 71304 | 🗒️✅ Connection success 85337
2025-02-10 08:34:49.679 [Debug] [AuthenticationViewModel.swift:89] updateAuthenticationStatus(_:) > PID: 71304 | success...
2025-02-10 08:34:49.680 [Debug] [Authenticatable.swift:145] setupAuthenticationFlow(lifetime:) > PID: 71304 | 🔑 didLogIn --> Completed
2025-02-10 08:34:49.680 [Debug] [ExtensionConnectionInteractor.swift:150] start(providerConfiguration:) > PID: 71304 | 🗒️✅ Connection success 5D0E3
2025-02-10 08:34:49.680 [Debug] [AuthenticationViewModel.swift:89] updateAuthenticationStatus(_:) > PID: 71304 | success...
2025-02-10 08:34:49.680 [Debug] [Authenticatable.swift:145] setupAuthenticationFlow(lifetime:) > PID: 71304 | 🔑 didLogIn --> Completed

Though I didn't change over to system logs, I've did add the inclusion of the PID.

I think with this new bit of info we can say that there are multiple instances of the PushProvider being made on the same PID.

Could you provide me with more info as to why the system is doing this?

I'll add the system log and see what else could be discovered.

Though I didn't change over to system logs, I've did add the inclusion of the PID. I think with this new bit of info we can say that there are multiple instances of the PushProvider being made on the same PID.

Could you provide me with more info as to why the system is doing this?

I cannot. Please file a bug on this and post the bug number back here.

__
Kevin Elliott
DTS Engineer, CoreOS/Hardware

Multiple PushProviders Instantiated at one time
 
 
Q