iOS icon indicating copy to clipboard operation
iOS copied to clipboard

Published 20 hours ago • verified publisher icon home-assistant

Webhooks sometimes not firing — "Webhook failed with status code 503"

Open jamieshaw opened this issue 4 years ago • 3 comments
trafficstars

iOS device model, version and app version Model Name: iPhone 13 Pro Max Software Version: iOS 15. App version: 2021.10 (2021.247)

Home Assistant Core Version 2021.10.6

Describe the bug Webhooks triggered from Notification Actions or Shortcut "fire_event" actions sometimes fail to register correctly with my Home Assistant instance.

To Reproduce Haven't found reproducible behaviour.

Expected behavior Less errors, and correct webhook calls.

Screenshots N/A

Additional context Setup: HA Core on Ubuntu 18.06 VM under ESXi 6.7 Server domain passes through two Apache servers as reverse proxy:

  • Home gateway web server, ports 80 & 443 exposed publicly. Routes traffic to devices/VMs on internal network.
  • Home Assistant server. Routes traffic to various applications on same VM via subdomain e.g. hass.host.domain.tld.

Exported logs at same time of "Webhook failed with status code 503" message:


2021-11-01 1:29:06.650 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Sending: {"id":72,"type":"ping"}
2021-11-01 1:29:06.879 pm [Error] [main] [Environment.swift:54] init() > WebSocket: Error: Optional(POSIXErrorCode: Software caused connection abort)
2021-11-01 1:29:06.879 pm [Info] [main] [Environment.swift:53] init() > WebSocket: phase transition to disconnected(error: Optional(POSIXErrorCode: Software caused connection abort), forReset: false)
2021-11-01 1:29:06.879 pm [Info] [main] [Environment.swift:53] init() > WebSocket: disconnecting; permanently: false, error: Optional(POSIXErrorCode: Software caused connection abort)
2021-11-01 1:29:06.879 pm [Info] [main] [Environment.swift:53] init() > WebSocket: phase transition to disconnected(error: nil, forReset: true)
2021-11-01 1:29:06.879 pm [Info] [main] [WebhookManager.swift:212] sendEphemeral(request:) > sending: WebhookRequest(type: "update_registration", data: ["device_name": "Jamie iPhone", "os_version": "15.1", "model": "iPhone14,3", "app_version": "2021.10 (2021.247)", "app_data": ["push_token": "<<removed>>", "push_url": "<<removed>>"], "manufacturer": "Apple"], localMetadata: nil)
2021-11-01 1:29:06.884 pm [Info] [main] [Environment.swift:53] init() > WebSocket: connecting using HAConnectionInfo(url: https://<<removed>>, userAgent: Optional("Home Assistant/2021.10 (io.robbie.HomeAssistant; build:2021.247; iOS 15.1.0)"), engine: nil)
2021-11-01 1:29:06.914 pm [Info] [main] [Environment.swift:53] init() > WebSocket: Viability changed: true
2021-11-01 1:29:06.921 pm [Verbose] [main] [WebViewController.swift:698] userContentController(_:didReceive:) > getExternalAuth called, forced: false
2021-11-01 1:29:06.921 pm [Info] [main] [TokenManager.swift:93] authDictionaryForWebView(forceRefresh:) > using existing token
2021-11-01 1:29:06.987 pm [Verbose] [main] [WebViewController.swift:714] userContentController(_:didReceive:) > Success on getExternalAuth callback: nil
2021-11-01 1:29:07.185 pm [Info] [main] [Environment.swift:53] init() > WebSocket: connected with headers: ["Content-Type": "application/octet-stream", "Upgrade": "websocket", "Date": "Mon, 01 Nov 2021 13:29:03 GMT", "Server": "Python/3.8 aiohttp/3.7.4.post0", "Connection": "upgrade", "Sec-WebSocket-Accept": "lPLZiZIbS2abKgEtSSU5akXPL0o="]
2021-11-01 1:29:07.185 pm [Info] [main] [Environment.swift:53] init() > WebSocket: phase transition to auth
2021-11-01 1:29:07.185 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Sending: (auth)
2021-11-01 1:29:07.186 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: auth: required
2021-11-01 1:29:07.192 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: auth: ok(version: "2021.10.6")
2021-11-01 1:29:07.192 pm [Info] [main] [Environment.swift:53] init() > WebSocket: phase transition to command(version: "2021.10.6")
2021-11-01 1:29:07.192 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Sending: {"id":73,"type":"ping"}
2021-11-01 1:29:07.192 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Sending: {"id":74,"type":"auth\/current_user"}
2021-11-01 1:29:07.192 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Sending: {"id":75,"type":"get_panels"}
2021-11-01 1:29:07.192 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Sending: {"id":76,"type":"get_states"}
2021-11-01 1:29:07.192 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Sending: {"event_type":"core_config_updated","id":77,"type":"subscribe_events"}
2021-11-01 1:29:07.192 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Sending: {"event_type":"component_loaded","id":78,"type":"subscribe_events"}
2021-11-01 1:29:07.294 pm [Info] [main] [WebhookManager.swift:212] sendEphemeral(request:) > sending: WebhookRequest(type: "fire_event", data: ["event_data": ["sourceDeviceName": "Jamie iPhone", "sourceDeviceID": "jamie_shaws_iphone", "sourceDevicePermanentID": "<<removed>>"], "event_type": "ios.became_active"], localMetadata: nil)
2021-11-01 1:29:07.294 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: result success HARequestIdentifier(rawValue: 73)
2021-11-01 1:29:07.410 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: result success HARequestIdentifier(rawValue: 75)
2021-11-01 1:29:07.411 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Sending: {"event_type":"panels_updated","id":79,"type":"subscribe_events"}
2021-11-01 1:29:07.420 pm [Info] [main] [WidgetOpenPageIntent+Observation.swift:36] handle(panels:) > updated timeline and cache
2021-11-01 1:29:07.440 pm [Info] [main] [ClientEventStore.swift:8] ClientEventStore > networkRequest: Webhook failed with status code 503 [:]
2021-11-01 1:29:07.442 pm [Error] [main] [WebhookManager.swift:236] sendEphemeral(request:) > got failure for update_registration: unacceptableStatusCode(503)
2021-11-01 1:29:07.442 pm [Info] [main] [HAAPI.swift:190] Connect(reason:) > not re-registering, but failed to update registration: unacceptableStatusCode(503)
2021-11-01 1:29:07.442 pm [Error] [main] [LifecycleManager.swift:186] connectAPI(reason:) > Couldn't connect for reason warm: unacceptableStatusCode(503)
2021-11-01 1:29:07.455 pm [Info] [main] [ClientEventStore.swift:8] ClientEventStore > networkRequest: Webhook failed with status code 503 [:]
2021-11-01 1:29:07.456 pm [Error] [main] [WebhookManager.swift:236] sendEphemeral(request:) > got failure for fire_event: unacceptableStatusCode(503)
2021-11-01 1:29:07.456 pm [Info] [main] [Environment.swift:36] init() > PromiseKit:cauterized-error: unacceptableStatusCode(503)
2021-11-01 1:29:07.488 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: result success HARequestIdentifier(rawValue: 76)
2021-11-01 1:29:07.489 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: result success HARequestIdentifier(rawValue: 77)
2021-11-01 1:29:07.489 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: result success HARequestIdentifier(rawValue: 78)
2021-11-01 1:29:07.489 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: result success HARequestIdentifier(rawValue: 74)
2021-11-01 1:29:07.489 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: result success HARequestIdentifier(rawValue: 79)
2021-11-01 1:29:07.686 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Sending: {"event_type":"state_changed","id":80,"type":"subscribe_events"}
2021-11-01 1:29:07.686 pm [Verbose] [main] [AccountRow.swift:150] fetchAvatar() > got user from user HAResponseCurrentUser(id: "<<removed>>", name: Optional("Jamie Shaw"), isOwner: true, isAdmin: true, credentials: [HAKit.HAResponseCurrentUser.Credential(type: "trusted_networks", id: nil), HAKit.HAResponseCurrentUser.Credential(type: "command_line", id: nil)], mfaModules: [HAKit.HAResponseCurrentUser.MFAModule(id: "totp", name: "Authenticator app", isEnabled: true)])
2021-11-01 1:29:07.690 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: result success HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:07.693 pm [Verbose] [main] [AccountRow.swift:197] fetchAvatar() > got image (500.0, 500.0)
2021-11-01 1:29:08.488 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:08.560 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:09.612 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:09.686 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:10.720 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:10.798 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:11.259 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:11.289 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:12.328 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:12.400 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:12.763 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:12.764 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:13.485 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:13.512 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:14.024 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:14.550 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:14.622 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:15.770 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:15.770 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:15.827 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:15.828 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:15.828 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:16.003 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:16.842 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:16.904 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:16.975 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:18.017 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:18.037 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:19.041 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:19.068 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:20.168 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:20.185 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:21.294 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:21.295 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:22.422 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:22.423 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:23.549 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:23.549 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:23.549 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:23.734 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:23.876 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:24.674 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:24.776 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:24.816 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:25.698 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:25.902 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:26.778 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:26.926 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:27.952 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:27.963 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:29.081 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:29.081 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:30.204 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:30.205 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:31.331 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:31.331 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:31.843 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:31.843 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:32.457 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:32.458 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:33.480 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:33.528 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:33.587 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:34.094 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:34.299 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:34.607 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:34.641 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:34.699 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:35.016 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:35.224 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:35.426 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:35.733 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:35.733 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)
2021-11-01 1:29:35.789 pm [Info] [hakit-work-queue] [Environment.swift:53] init() > WebSocket: Received: event: for HARequestIdentifier(rawValue: 80)

jamieshaw avatar Nov 01 '21 13:11 jamieshaw

Checking the access.log and error.log files on the Home Assistant VM…

I can see successful (200) network requests during the above timespan received from my the app on my iPhone (based off User Agent), but there seems no similar logging in error.log. (For the record, it is outputting logs, as I can see WebSocket errors during downtime whilst the HA instance is rebooting during YAML development.)

jamieshaw avatar Nov 01 '21 13:11 jamieshaw

It's also worth noting that I often see webhooks for the six devices we use (2 users; iPhone, iPad and Mac each) expire with "deleted webhook" showing in the Cloud configuration panel. These seem to rapidly increase, I can easily amass 10 deleted webhooks in the space of a week, for whatever reason, and I periodically remove them from .storage/mobile_app.

NOTE: I don't use Nabu Casa Remote Access, due to the reverse proxy on the same machine and trusting 127.0.0.1 as a proxy.

jamieshaw avatar Nov 01 '21 13:11 jamieshaw

Is this still an issue with latest versions of app and core? Feel free to reopen if needed

bgoncal avatar Mar 26 '24 12:03 bgoncal