Duplicate iOS companion app notifications

parautenbach · March 28, 2022, 11:11am

I’m receiving duplicate notifications for some of my automations. It used to work fine. I think this started happening in the past month or so, but I don’t have an exact date.

Here is one of the automations:

- alias: "Notify If New Backup Found"
  trigger:
    - platform: state
      entity_id: sensor.last_backup
  mode: single
  condition:
    condition: template
    value_template: >-
      {% set last_backup = states('sensor.last_backup') | as_datetime %}
      {{ ((utcnow() - last_backup).seconds) < 60 }}
  action:
    - service: notify.mobile_app_ceres
      data:
        title: "System"
        message: "A new Home Assistant backup was made."
        data:
          group: "system-backup"
          url: homeassistant://navigate/lovelace/devices

And what I see:

At first, I thought there could be a race condition in the state engine, but I found very little evidence of anything even close to that – and I think the world would’ve been up in arms if that was the case. Regardless, I explicitly added mode: single (even though it’s the default).

My current theory is that it might have something to do with when you can receive push notifications directly (when on your home network). Unfortunately, I’ve been too late to capture the companion app logs (truncated). I need to be quicker to export it when it happens again. Maybe the notification gets sent both internally and externally?

I’m sure the state the automation triggers on only changed once – at that time. The second change seen here was after an HA restart.

Zoomed in to 02:00 until 02:10.

I’m sure the automation only triggered once:

Server version: 2022.2.9 (I’m still planning my upgrade to 2022.3.x)
Companion app (iOS): 2022.3

I couldn’t find any related posts on the forum or on any of the relevant GitHub repos.

zacwest · March 29, 2022, 6:01am

A few debugging things worth investigating:

Include a random identifier: add something like {{ range(1, 1000) | random }} to your message. If it’s the same number, it’s the same send that’s duplicated somehow.
Reset the push token in App Configuration > Notifications. It’s possible Firebase has double-recorded your device for its internal identifier, which could in theory make it fire twice. Hard to debug this one.
Try turning off Local Push in the server’s settings in App Configuration.
Check if there’s any error logs in the event log in App Configuration > Debugging.

parautenbach · March 29, 2022, 9:09am

Thanks, Zac. Good ideas (who would know better than you anyway ).

I’m going to try the first step first.

I’ll report back once I know more.

parautenbach · April 3, 2022, 3:21pm

I’ve added the random string and had a few notifications since. No duplicates!

Since this doesn’t seem to happen every time, I’m thinking I’ll keep running it like this for a little longer. If it doesn’t happen again, I’m going to remove the random string to see if I’m getting duplicates again, and take it from there.

parautenbach · May 14, 2022, 7:03am

At last, it happened again, but I forgot to capture the companion app logs…

zacwest · May 15, 2022, 2:14am

The logs stick around for a few days (3 days for App Store versions, 7 days for TestFlight versions), so it may still be in there. If you export them you can glance in the zip file.

parautenbach · May 15, 2022, 6:31pm

Unfortunately I was too late, so I’ll need to wait for the next round…

Edwin_D · May 15, 2022, 6:36pm

Maybe check your automations yaml to see if there are two instances of the automation sending the message. I’ve had this happen to me. When you save an automation via the gui, the automations.yaml gets reloaded in the background and you manage to save again you end up with duplicates. The bigger automations.yaml, the bigger the chance.

parautenbach · May 15, 2022, 7:58pm

Thanks for the idea, Edwin.

I checked now to be sure and don’t see any duplicates. My issue happens for a number of automations. I’m just sticking to the one here for simplicity.

I’ve implemented the suggestion to add a random number to the message too (in the screenshot), so I think if there was a duplicate those number would differ.

I’ll keep the issue you mention in mind though. I only edit via YAML, but do have unique IDs assigned in order to benefit from the automation debugger.

Edwin_D · May 15, 2022, 8:26pm

If there are no duplicate values from the random number, there must be double execution. If you look at the backup log the backup is mentioned twice too, so double execution is not that strange considering. You’d think it was caused by something changed with the backup process if it weren’t for the fact you see it elsewhere too.

Hiding the effect is easy enough by adding a short delay after the notification (combined with the single execution mode) but I wouldn’t be satisfied until I understand where this comes from. My bet is in the event system or more than in the automation itself, seeing there are double backup finished events. Do you have any automations or scripts that explicitly fire events?

Just noticed: Weird is there are two backup lines about the same backup at completely different times. It almost looks like it is revisiting old events again. That is very strange indeed. Without deeper knowledge of inner workings it is almost impossible to guess how this could happen. Anything happened at the time of the repeated event?

parautenbach · May 16, 2022, 6:14am

Where are you seeing that? On your own system? I should note that I’m not using the new backup mechanism recently introduced. This is still an older shell script being executed. That said, it doesn’t change much and it’s only one of my automations doing this (as you said too).

Yeah, so concurrent executions would be limited. I already have mode: single which I added the first time I saw this and I thought I wouldn’t bother to debug the issue further. Then it kept on happening…

Ditto. Luckily it’s not crazy annoying as it doesn’t always happen, but it seems interestingly enough now to understand this better.

Only a few automations where I trigger on events, none of them related to the automations where I see duplicate notifications. I don’t emit custom events anywhere.

Where are you seeing this? I’ve thought of duplicate events too, and I can probably create a little automation for only the event of this one automation based on an event trigger and not a state trigger. That said, the HA devs have been pretty clear that even if there are multiple events, if they result in the same (current) state, there won’t be a state trigger.

Not that I can think of.

Edwin_D · May 16, 2022, 1:08pm

What caught me is your own logbook screenshot. It mentions twice the last backup changed to March 27, 2:05 AM, the first time at (no surprise) 2:05 AM, but then again at 9:43 PM, but mentioning the same backup date time of 2:05 AM. That seems weird - even if you backup twice a day it should mention a different time, not the earlier one.

parautenbach · May 16, 2022, 1:34pm

Oh, good spot!

The odd times you see are times when I restarted HA. I normally work on it a bit in the evenings when I have time.

I know it was the case here and for the previous screenshot.

It’s probably the state getting restored upon start-up.

I really thought we (you) might be onto something.

parautenbach · May 21, 2022, 1:30pm

@zacwest it happened again – and this time I got the logs too.

Home Assistant.txt:

2022-05-20 17:53:13.339 [Info] [hakit-work-queue] [Environment.swift:71] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 711)
2022-05-20 17:53:13.339 [Info] [hakit-work-queue] [Environment.swift:71] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 711)
2022-05-20 17:53:13.339 [Info] [hakit-work-queue] [Environment.swift:71] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 711)
2022-05-20 17:53:13.340 [Info] [hakit-work-queue] [Environment.swift:71] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 711)
2022-05-20 17:56:13.148 [Verbose] [main] [WebViewController.swift:1014] sendExternalBus(message:) > sending {"type":"command","id":-1,"command":"restart"}
2022-05-20 17:56:13.148 [Info] [hakit-work-queue] [Environment.swift:71] init() > WebSocket: Sending: {"id":712,"type":"ping"}
2022-05-20 17:56:13.154 [Verbose] [main] [NotificationManager.swift:236] userNotificationCenter(_:didReceive:withCompletionHandler:) > User info in incoming not
ification [AnyHashable("webhook_id"): REDACTED, AnyHashable("url"): homeassistant://navigate/lovelace/de
vices, AnyHashable("aps"): {
    alert =     {
        body = "Systems shut down prior to loadshedding. (547)";
        title = System;
    };
    sound = default;
    "thread-id" = "system-general";
}] with response <UNNotificationResponse: 0x2827cc1e0; actionIdentifier: com.apple.UNNotificationDefaultActionIdentifier, notification: <UNNotification: 0x2827d
b540; source: io.robbie.HomeAssistant date: 2022-05-20 15:56:01 +0000, request: <UNNotificationRequest: 0x2827dacd0; identifier: 024FC8AC-8444-4D9B-9506-8C52493
BE92E, content: <UNNotificationContent: 0x2814df900; title: <redacted>, subtitle: (null), body: <redacted>, summaryArgument: , summaryArgumentCount: 0, category
Identifier: , launchImageName: , threadIdentifier: system-general, attachments: (
), badge: (null), sound: <UNNotificationSound: 0x280398850>, realert: 0, interruptionLevel: 1, relevanceScore: 0.00, trigger: (null)>, intents: (
)>>
2022-05-20 17:56:13.154 [Info] [main] [NotificationManager.swift:250] userNotificationCenter(_:didReceive:withCompletionHandler:) > launching URL homeassistant:
//navigate/lovelace/devices
2022-05-20 17:56:13.386 [Error] [main] [Environment.swift:72] init() > WebSocket: Error: Optional(POSIXErrorCode(rawValue: 53): Software caused connection abort
)
2022-05-20 17:56:13.386 [Info] [main] [Environment.swift:71] init() > WebSocket: phase transition to disconnected(error: Optional(POSIXErrorCode(rawValue: 53):
Software caused connection abort), forReset: false)
2022-05-20 17:56:13.386 [Info] [main] [Environment.swift:71] init() > WebSocket: disconnecting; permanently: false, error: Optional(POSIXErrorCode(rawValue: 53)
: Software caused connection abort)
2022-05-20 17:56:13.386 [Info] [main] [Environment.swift:71] init() > WebSocket: phase transition to disconnected(error: nil, forReset: true)
2022-05-20 17:56:13.387 [Info] [main] [WebhookManager.swift:217] sendEphemeral(server:request:) > sending to historic: WebhookRequest(type: "update_registration
", data: ["manufacturer": "Apple", "model": "iPhone13,1", "app_data": ["push_url": "https://mobile-apps.home-assistant.io/api/sendPushNotification", "push_token
": "REDACTED"], "os_version": "15.5", "app_version": "2022.3 (2022.358)", "device_name": "Ceres"], localMetadata: nil)
2022-05-20 17:56:13.388 [Verbose] [main] [WebViewController.swift:835] userContentController(_:didReceive:) > message {     id = "-1";     result = "<null>";
  success = 1;     type = result; }
2022-05-20 17:56:13.388 [Error] [main] [WebViewController.swift:997] handleExternalMessage(_:) > unknown: result
2022-05-20 17:56:13.419 [Info] [main] [Environment.swift:71] init() > WebSocket: connecting using HAConnectionInfo(url: http://homeassistant.local:8123, userAge
nt: Optional("Home Assistant/2022.3 (io.robbie.HomeAssistant; build:2022.358; iOS 15.5.0)"), engine: nil)
2022-05-20 17:56:13.422 [Verbose] [main] [IncomingURLHandler.swift:16] handle(url:) > Received URL: homeassistant://navigate/lovelace/devices
2022-05-20 17:56:13.552 [Info] [main] [Environment.swift:71] init() > WebSocket: Viability changed: true
2022-05-20 17:56:13.559 [Info] [main] [Environment.swift:71] init() > WebSocket: connected with headers: ["Content-Type": "application/octet-stream", "Connectio
n": "upgrade", "Sec-WebSocket-Accept": "Z2OGWnybF3xoqPFrK4t7UDvCHjU=", "Date": "Fri, 20 May 2022 15:56:13 GMT", "Upgrade": "websocket", "Server": "Python/3.9 ai
ohttp/3.8.1", "Sec-WebSocket-Extensions": "permessage-deflate"]
2022-05-20 17:56:13.559 [Info] [main] [Environment.swift:71] init() > WebSocket: phase transition to auth

From the above, this stands out:

2022-05-20 17:56:13.386 [Error] [main] [Environment.swift:72] init() > WebSocket: Error: Optional(POSIXErrorCode(rawValue: 53): Software caused connection abort
)

HomeAssistant-Extensions-PushProvider.txt:

2022-05-20 17:53:28.421 [Info] [main] [Environment.swift:71] init() > WebSocket: Ping
2022-05-20 17:53:43.563 [Info] [hakit-work-queue] [Environment.swift:71] init() > WebSocket: Sending: {"id":2136,"type":"ping"}
2022-05-20 17:53:43.571 [Info] [hakit-work-queue] [Environment.swift:71] init() > WebSocket: Received: result success HARequestIdentifier(rawValue: 2136)
2022-05-20 17:54:39.405 [Info] [main] [Environment.swift:71] init() > WebSocket: Ping
2022-05-20 17:55:16.442 [Info] [hakit-work-queue] [Environment.swift:71] init() > WebSocket: Sending: {"id":2137,"type":"ping"}
2022-05-20 17:55:16.503 [Info] [hakit-work-queue] [Environment.swift:71] init() > WebSocket: Received: result success HARequestIdentifier(rawValue: 2137)
2022-05-20 17:56:01.785 [Info] [hakit-work-queue] [Environment.swift:71] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 2097)
2022-05-20 17:56:01.789 [Debug] [main] [LocalPushManager.swift:161] handle(event:) > handling LocalPushEvent(confirmID: Optional("REDACTED"), identifier: "REDACTED", contentWithoutServer: <UNNotificationContent: 0x13be72620; title: System, subtitle: (null), body: Systems shut down prior to loadshedding. (547), summaryArgument: , summaryArgumentCount: 0, categoryIdentifier: , launchImageName: , threadIdentifier: system-general, attachments: (
), badge: (null), sound: <UNNotificationSound: 0x13be620c0>, realert: 0, interruptionLevel: 1, relevanceScore: 0.00)
2022-05-20 17:56:01.799 [Info] [hakit-work-queue] [Environment.swift:71] init() > WebSocket: Sending: {"confirm_id":"REDACTED","id":2138,"type":"mobile_app\/push_notification_confirm","webhook_id":"REDACTED"}
2022-05-20 17:56:01.807 [Info] [main] [PushProvider.swift:163] localPushManager(_:didReceiveRemoteNotification:) > failed: notCommand
2022-05-20 17:56:01.808 [Info] [hakit-work-queue] [Environment.swift:71] init() > WebSocket: Received: result failure HARequestIdentifier(rawValue: 2138): external(HAKit.HAError.ExternalError(code: "not_found", message: "Push notification channel not found")) via {"id":2138,"type":"result","success":false,"error":{"code":"not_found","message":"Push notification channel not found"}}
2022-05-20 17:56:01.808 [Error] [main] [NotificationAttachmentManager.swift:47] content(from:api:) > failed at getting attachment info: noAttachment
2022-05-20 17:56:01.808 [Info] [main] [NotificationAttachmentManager.swift:74] content(from:api:) > delivering content <UNMutableNotificationContent: 0x13bf60b10; title: <redacted>, subtitle: (null), body: <redacted>, summaryArgument: , summaryArgumentCount: 0, categoryIdentifier: , launchImageName: , threadIdentifier: system-general, attachments: (
), badge: (null), sound: <UNNotificationSound: 0x13be620c0>, realert: 0, interruptionLevel: 1, relevanceScore: 0.00
2022-05-20 17:56:01.817 [Error] [main] [LocalPushManager.swift:172] handle(event:) > failed to confirm local push: external(HAKit.HAError.ExternalError(code: "not_found", message: "Push notification channel not found"))
2022-05-20 17:56:01.837 [Info] [main] [LocalPushManager.swift:188] handle(event:) > added local notification
~

In this one, this stands out:

2022-05-20 17:56:01.808 [Info] [hakit-work-queue] [Environment.swift:71] init() > WebSocket: Received: result failure HARequestIdentifier(rawValue: 2138): external(HAKit.HAError.ExternalError(code: "not_found", message: "Push notification channel not found")) via {"id":2138,"type":"result","success":false,"error":{"code":"not_found","message":"Push notification channel not found"}}

So, should I just reset my push notification ID/token?

zacwest · May 21, 2022, 4:03pm

The connection abort is normal - the app is returning from the background and discovering its WebSocket connection disconnected in the background, so that’s not an indication of a problem.

However, the Push Provider thing is a good clue and is likely the cause, though I don’t know specifically what the issue is. The way Local Push works, to make sure we don’t lose notifications, is that each one requires explicit confirmation from the app or the server re-sends it as a non-local push. So I believe what’s happening is:

The notification is received as a local push
The app attempts to confirm the local push, but it errors with “Push notification channel not found”
The server after 10 seconds notes the local push went unconfirmed and re-sends it as a normal push notification
You receive a 2nd notification

So this pinpoints the problem somewhere in the app<->server side, and not on your automations. I do not believe, however, that resetting your push token will do much for this. I’m not really sure what’s going on, though. Since it seems to happen rarely, my hunch is there’s some kind of race condition in the local push handling in core, but it may require some guess-and-check to get there.

parautenbach · May 21, 2022, 8:32pm

Thanks for that.

I will file a bug report for this tomorrow.

I suppose it is also possible that I have a local networking issue.

parautenbach · May 22, 2022, 7:06pm

Issue reported here.