search

jsiegenthaler / homebridge-eosstb

A homebridge plugin for the EOS set-top box as used by Sunrise, Telenet, Ziggo, Virgin Media and maybe more in various countries on the Horizon Go (HGO) platform
https://github.com/jsiegenthaler/homebridge-eosstb
32 stars 4 forks source link

Authorization error #60

Closed pietje63 closed 2 years ago

pietje63 commented 2 years ago

After using the plugin some time I get these repeating messages in the Homebridge log every second.

[31/01/2022, 08:45:40] [Ziggo next] mqttClient: Connection closed [31/01/2022, 08:45:41] [Ziggo next] mqttClient: Reconnect started [31/01/2022, 08:45:41] [Ziggo next] mqttClient: Error: Error: Connection refused: Not authorized at MqttClient._handleConnack (/usr/local/lib/node_modules/homebridge-eosstb/node_modules/mqtt/lib/client.js:1386:17) at MqttClient._handlePacket (/usr/local/lib/node_modules/homebridge-eosstb/node_modules/mqtt/lib/client.js:547:12) at work (/usr/local/lib/node_modules/homebridge-eosstb/node_modules/mqtt/lib/client.js:436:12) at Writable.writable._write (/usr/local/lib/node_modules/homebridge-eosstb/node_modules/mqtt/lib/client.js:450:5) at doWrite (/usr/local/lib/node_modules/homebridge-eosstb/node_modules/readable-stream/lib/_stream_writable.js:409:139) at writeOrBuffer (/usr/local/lib/node_modules/homebridge-eosstb/node_modules/readable-stream/lib/_stream_writable.js:398:5) at Writable.write (/usr/local/lib/node_modules/homebridge-eosstb/node_modules/readable-stream/lib/_stream_writable.js:307:11) at Duplex.ondata (node:internal/streams/readable:754:22) at Duplex.emit (node:events:390:28) at addChunk (node:internal/streams/readable:315:12) { code: 5 }

The error appears clear (Connection refused, Not authorized), though it does not really make sense as (i) the authorization details are correct, and (ii) a reboot of the (child) bidge fixes the issue. The log after rebooting just seems fine

[31/01/2022, 08:45:56] [Ziggo next] Child bridge process ended [31/01/2022, 08:45:56] [Ziggo next] Process Ended. Code: 143, Signal: null [31/01/2022, 08:45:58] [Homebridge UI] Changes to config.json saved. [31/01/2022, 08:46:00] [Homebridge UI] Starting terminal session [31/01/2022, 08:46:03] [Ziggo next] Restarting Process... [31/01/2022, 08:46:12] [Homebridge UI] Terminal session ended. [31/01/2022, 08:46:13] [Ziggo next] Launched child bridge with PID 7862 [31/01/2022, 08:46:16] Registering platform 'homebridge-eosstb.eosstb' [31/01/2022, 08:46:17] [Ziggo next] Loaded homebridge-eosstb v1.2.2 child bridge successfully [31/01/2022, 08:46:17] Loaded 0 cached accessories from cachedAccessories.0E8F9A5D40AF. [31/01/2022, 08:46:17] [Ziggo next] homebridge-eosstb v1.2.2 [31/01/2022, 08:46:17] Homebridge v1.4.0 (HAP v0.10.0) (Ziggo next) is running on port 39912. [31/01/2022, 08:46:20] [Homebridge UI] Starting terminal session [31/01/2022, 08:46:32] [Ziggo next] Session is not connected, starting session reconnect... [31/01/2022, 08:46:32] [Ziggo next] Creating eosstb session... [31/01/2022, 08:46:32] [Ziggo next] Step 1 of 1: logging in with username [[username]] [31/01/2022, 08:46:35] [Ziggo next] Step 1 of 1: response: 200 OK [31/01/2022, 08:46:35] [Ziggo next] Session created [31/01/2022, 08:47:02] [Ziggo next] Discovering platform and devices... [31/01/2022, 08:47:02] [Ziggo next] Found customer data: [[ID and name]] [31/01/2022, 08:47:02] [Ziggo next] Loading master channel list and personalization data [31/01/2022, 08:47:02] [Ziggo next] Refreshing personalization data for profiles [31/01/2022, 08:47:02] [Ziggo next] Refreshing personalization data for devices [31/01/2022, 08:47:07] [Ziggo next] Found 1 device [31/01/2022, 08:47:07] [Ziggo next] Discovery completed [31/01/2022, 08:47:07] [Ziggo next] Finding devices in cache... [31/01/2022, 08:47:07] [Ziggo next] Device 1: Mediabox [[boxID]] [31/01/2022, 08:47:07] [Ziggo next] Device not found in cache, creating new accessory for [[boxID]] [31/01/2022, 08:47:07] [Ziggo next] Setting up device 1 of 1: Mediabox [31/01/2022, 08:47:07] [Ziggo next] Mediabox: Refreshing channel list... [31/01/2022, 08:47:08] [Ziggo next] Mediabox: No valid profile found in config. Selecting best-fitting profile [31/01/2022, 08:47:08] [Ziggo next] Mediabox: Using profile 0 'Shared Profile' [31/01/2022, 08:47:08] [Ziggo next] Mediabox: Profile 'Shared Profile' contains 96 channels [31/01/2022, 08:47:08] [Ziggo next] Mediabox: Refreshing channels 1 to 20 [31/01/2022, 08:47:08] [Ziggo next] Mediabox: Channel list refreshed from profile 'Shared Profile' with 20 channels [31/01/2022, 08:47:11] [Ziggo next] Mediabox: Initializing accessory... [31/01/2022, 08:47:11] [Ziggo next] Mediabox: Set Manufacturer to ARRIS [EOS] [31/01/2022, 08:47:11] [Ziggo next] Mediabox: Set Model to DCX960 [] [31/01/2022, 08:47:11] [Ziggo next] Mediabox: Set Serial Number to [[boxID]] [31/01/2022, 08:47:11] [Ziggo next] Mediabox: Set Firmware to 1.2.2 [31/01/2022, 08:47:14] [Ziggo next] Mediabox: Initialization completed [31/01/2022, 08:47:15] Mediabox 15B2 is running on port 41521. [31/01/2022, 08:47:15] Please add [Mediabox 15B2] manually in Home app. Setup Code: 549-50-313 [31/01/2022, 08:47:17] [Ziggo next] mqttClient: Connected: true [31/01/2022, 08:47:17] [Ziggo next] Refreshing recording state

Any idea what is happening?

Using a Pi Zero, 1.4.0 Homebridge, Node 16.13.2, plugin 1.2.2

jsiegenthaler commented 2 years ago

Hi. I'm aware of this, the same thing happens to me. It is the mqtt server killing the session for some unknown reason. I have a fix in beta-test and am fine tuning it. A slow process for each test I have to wait a day or so.

jsiegenthaler commented 2 years ago

I have published 1.3.0-beta.2 tonight. Try it out and report back

pietje63 commented 2 years ago

Thanks, installing the beta right now. Will let you know the status in a day or two

pietje63 commented 2 years ago

So far so good.

Only thing I noticed is some additional logs regarding status

[01/02/2022, 11:06:00] [Ziggo next] Mediabox: Status Active changed from 0 [NOT_ACTIVE] to 1 [ACTIVE] [01/02/2022, 11:06:00] [Ziggo next] Mediabox: Power changed from 0 [OFF] to 1 [ON] [01/02/2022, 11:06:00] [Ziggo next] Mediabox: In Use changed from 0 [NOT_IN_USE] to 1 [IN_USE] [01/02/2022, 11:43:11] [Ziggo next] Mediabox: Power changed from 1 [ON] to 0 [OFF] [01/02/2022, 11:43:11] [Ziggo next] Mediabox: In Use changed from 1 [IN_USE] to 0 [NOT_IN_USE] [01/02/2022, 11:48:18] [Ziggo next] Mediabox: Status Active changed from 1 [ACTIVE] to 0 [NOT_ACTIVE]

Though assume this is just part of the beta setup. Last night - while everyone in home was at sleep - also had some logging regarding "Status Active" change

[02/02/2022, 02:36:15] [Ziggo next] Mediabox: Status Active changed from 0 [NOT_ACTIVE] to 1 [ACTIVE] [02/02/2022, 03:36:19] [Ziggo next] Mediabox: Status Active changed from 1 [ACTIVE] to 0 [NOT_ACTIVE]

No log regarding "Power" or "In Use" change during the night. Not sure where it comes from; may also be a hickup at Ziggo's data?

jsiegenthaler commented 2 years ago

Excellent. Those extra log entries are the extra characteristics that I have added in this beta. See the Wiki for full details of how to use them. As for Active and NotActive, here's what I documented in the Wiki: ACTIVE when box is connected to the network and is reachable, or NOT_ACTIVE if the box is not reachable. Useful to indicate if the box is physically powered on and the network is working. If the box is reachable on the network, it should be 1 Active. Any periods where it is 0 NotActive is normally an internet connectivity issue. Keep an eye on it.

jsiegenthaler commented 2 years ago

Closing ticket, issue addressed in 1.3.0-beta.2