core: Duplicate push notification

The problem

I have a fairly simply automation that sometimes results in a duplicate notification. It’s not the only one that exhibits this behaviour, but for simplicity of debugging the issue I’m focusing on only this one.

- 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

I logged this issue the first time in March on the forum in case it was an issue on my side. After some assistance from @zacwest it seems like I should report this as a bug.

Zac made a few suggestions, among which to include a random number to establish if it is indeed a duplicate notification and not simply a second notification due to some other issue.

I was already sure at the start that there isn’t a duplicate event or state change – at least not what could be seen via the UI tools.

image

image

image

When I first logged this I was on 2022.2.9. I’m now on 2022.5.4. I keep my iOS companion app up to date all the time.

This is what the duplicate notification looks like:

image

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

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
~

This seems to be the key to the issue:

2022-05-20 17:56:01.807 [Info] [main] [PushProvider.swift:163] localPushManager(_:didReceiveRemoteNotification:) > failed: notCommand

It seems like the local push fails and then the notification gets sent externally.

What version of Home Assistant Core has the issue?

core-2022.5.4

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant Core

Integration causing the issue

notify

Link to integration documentation on our website

https://www.home-assistant.io/integrations/notify/

Diagnostics information

I’d be happy to share the ZIP file of the companion app logs, but I don’t know how to easily sanitise it.

Example YAML snippet

No response

Anything in the logs that might be useful for us?

No response

Additional information

No response

About this issue

  • Original URL
  • State: open
  • Created 2 years ago
  • Reactions: 3
  • Comments: 27 (1 by maintainers)

Most upvoted comments

Getting the same issues on Android… I’m creating the notification via call_service over the websocket api to the local instance. So pretty sure it’s not a “broken” automation

Seeing this is the log

10-22 16:57:02.020 20540 21088 W FirebaseMessaging: Unable to log event: analytics library is missing
10-22 16:57:02.020 20540 21088 D FCMService: From: 331041709873
10-22 16:57:02.023 20540 20540 D MessagingService: Creating notification with following data: {webhook_id=xxx, message=hi, server_id=-1}
10-22 16:57:02.028 20540 20540 D MessagingService: Show notification with tag "null" and id "1478140100"
10-22 16:57:03.272 20540 21088 W FirebaseMessaging: Unable to log event: analytics library is missing
10-22 16:57:03.272 20540 21088 D FCMService: From: 331041709873
10-22 16:57:03.274 20540 20540 D MessagingService: Creating notification with following data: {webhook_id=xxx, message=hi, server_id=2}
10-22 16:57:03.279 20540 20540 D MessagingService: Show notification with tag "null" and id "1478141352"

the server_id part caught my eye I do have nabucasa’s HA Cloud connected. A bit naïve… is that the other “server”

Maybe a clue… maybe not

Home Assistant 2023.10.3 Supervisor 2023.10.0 Operating System 11.0 Frontend 20231005.0 - latest

Companion aoo: 2023.10.2-full

+1
AndyPook on Nov 15, 2023

I am having the same issue of duplicate or occasionally quadruple notifications.

My Home Assistant version is 2023.8.4 and the iOS app is on the latest version: 2023.460.

I have followed a few steps that were recommended in the original forum thread as well as some solutions mentioned here on Github- without any success. My attempts to resolve this included:

  1. Checking my automation yaml for duplicate entries.
  2. Companion App: Notifications > Reset ‘Push ID’
  3. Companion App: Debugging > Reset Frontend Cache
  4. Companion App: Debugging > Reset
  5. Ensured automation mode is set to single- added a delay to my automation to avoid it being executed more than once.
  6. Companion App: Server Settings > Disable Local Push

. The following is my automation:

alias: Notification - Entrance Door Sensor - Open
description: ""
trigger:
  - platform: mqtt
    topic: zigbee2mqtt/hallway.doorsensor
    value_template: "{{value_json.contact}}"
    payload: false
condition: []
action:
  - service: notify.mobile_app_11pro
    data:
      title: Home
      message: Door Opened
  - delay:
      hours: 0
      minutes: 1
      seconds: 0
      milliseconds: 0
mode: single

I am also coming across the following message in my HA logs:

Logger: homeassistant.components.websocket_api.http.connection
Source: components/websocket_api/http.py:51
Integration: Home Assistant WebSocket API (documentation, issues)
First occurred: September 1, 2023 at 1:21:01 AM (6 occurrences)
Last logged: 8:18:58 AM

[140667676457280] from 192.168.1.2 (Home Assistant/2023.4 (io.robbie.HomeAssistant; build:2023.460; iOS 17.0.0)): Disconnected: Did not receive auth message within 10 seconds
[140667190099136] from 192.168.1.2 (Home Assistant/2023.4 (io.robbie.HomeAssistant; build:2023.460; iOS 17.0.0)): Disconnected: Did not receive auth message within 10 seconds
[140665198316352] from 192.168.1.2 (Home Assistant/2023.4 (io.robbie.HomeAssistant; build:2023.460; iOS 17.0.0)): Disconnected: Did not receive auth message within 10 seconds
[140666943905344] from 192.168.1.2 (Home Assistant/2023.4 (io.robbie.HomeAssistant; build:2023.460; iOS 17.0.0)): Disconnected: Did not receive auth message within 10 seconds
[140666183875392] from 192.168.1.109 (Home Assistant/2023.4 (io.robbie.HomeAssistant; build:2023.460; iOS 17.0.0)): Disconnected: Did not receive auth message within 10 seconds




Logger: homeassistant.components.websocket_api.http.connection
Source: components/websocket_api/connection.py:175
Integration: Home Assistant WebSocket API (documentation, issues)
First occurred: September 2, 2023 at 2:55:41 PM (3 occurrences)
Last logged: 8:18:49 AM

[140667569995584] Received invalid command: {'access_token': 'xxx_greyedout_a', 'type': 'auth'}
[140667207352640] Received invalid command: {'access_token': 'xxx_greyedout_b', 'type': 'auth'}

To give a bit more context, the issue started happening for me when I duplicated the above existing automation via the iOS app, in order to create a new automation for the door sensor. The new automation does not include sending a notification- it simply plays some media, when the door is opened. I tried disabling this new automation to see if the issue would persist and unfortunately it does. I also double checked the mode of both automations because I wanted to make sure that these are set to “single”.

Finally, an interesting observation: when executing the automation via the app using the “run” function, I only receive a single notification.

In case there is more information required, I’d be happy to provide this.

Thanks for your help!

+1
onestix on Sep 4, 2023

I think the notable error is actually:

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”}}

It seems like the confirmation code response handler is having an issue finding the pending response, but it’s also still doing the 10 second wait and firing through the HTTP call, making me think it’s failing to add the “cancel this retry” value to the dictionary.

+1
zacwest on May 24, 2022
Read more comments on GitHub
← core: Duplicate lights, sensors for single Z-Wave Motion Dimmer (GE/Jasco 26933)
core: Duplicate TP Links devices in Sense app (different MAC addresses) →