ACDR / homebridge-yamaha-avr

homebridge-plugin for Yamaha AVR. Audio Receiver Accessory with Power, Input, Volume & Remote Control
Apache License 2.0
45 stars 6 forks source link

Error in Logfile: "Warning from the characteristic Active Identifier" #51

Closed jack-blackson closed 2 years ago

jack-blackson commented 3 years ago

Since updating to the current Homebridge version (1.3.4), I receive this error message:

[2021-4-18 10:05:25] [homebridge-yamaha-avr] This plugin generated a warning from the characteristic 'Active Identifier': characteristic was supplied illegal value: number -1 exceeded minimum of 0. See https://git.io/JtMGR for more info. [2021-4-18 10:05:27] [homebridge-yamaha-avr] This plugin slows down Homebridge. The read handler for the characteristic 'Active Identifier' didn't respond at all!. Please check that you properly call the callback! See https://git.io/JtMGR for more info.

Plugin Version is 2.0.4

adrianopery commented 3 years ago

I'm receiving a similar error message.

20/06/2021 11:46:51 [Yamaha AVR 59F3@Active Identifier] The read handler for the characteristic 'Active Identifier' on the accessory 'Yamaha AVR 59F3' was slow to respond! 20/06/2021 11:46:55 [Yamaha AVR 59F3@@Active Identifier] characteristic was supplied illegal value: number -1 exceeded minimum of 0 20/06/2021 11:46:56 [Yamaha AVR 59F3@@Active Identifier] The read handler for the characteristic 'Active Identifier' didn't respond at all!. Please check that you properly call the callback! 20/06/2021 11:46:57 [Yamaha AVR 59F3@Active Identifier] The read handler for the characteristic 'Active Identifier' on the accessory 'Yamaha AVR 59F3' didn't respond at all!. Please check that you properly call the callback! 20/06/2021 11:47:00 [Yamaha AVR 59F3@@Active Identifier] characteristic was supplied illegal value: number -1 exceeded minimum of 0 20/06/2021 11:47:05 [Yamaha AVR 59F3@@Active Identifier] characteristic was supplied illegal value: number -1 exceeded minimum of 0 20/06/2021 11:47:10 [Yamaha AVR 59F3@@Active Identifier] characteristic was supplied illegal value: number -1 exceeded minimum of 0 20/06/2021 11:47:15 [Yamaha AVR 59F3@@Active Identifier] characteristic was supplied illegal value: number -1 exceeded minimum of 0 20/06/2021 11:47:20 [Yamaha AVR 59F3@@Active Identifier] characteristic was supplied illegal value: number -1 exceeded minimum of 0 20/06/2021 11:47:25 [Yamaha AVR 59F3@@Active Identifier] characteristic was supplied illegal value: number -1 exceeded minimum of 0 20/06/2021 11:47:30 [Yamaha AVR 59F3@@Active Identifier] characteristic was supplied illegal value: number -1 exceeded minimum of 0

AndrewReaganM commented 3 years ago

I'm also getting the same error.

[7/29/2021, 10:23:33 AM] [homebridge-yamaha-avr] This plugin slows down Homebridge. The read handler for the characteristic 'Active Identifier' on the accessory 'Yamaha AVR 894F' didn't respond at all!. Please check that you properly call the callback! See https://git.io/JtMGR for more info.
[7/29/2021, 10:23:33 AM] [homebridge-yamaha-avr] Error: 
    at Accessory.sendCharacteristicWarning (/usr/lib/node_modules/homebridge/node_modules/hap-nodejs/src/lib/Accessory.ts:1874:14)
    at Timeout._onTimeout (/usr/lib/node_modules/homebridge/node_modules/hap-nodejs/src/lib/Accessory.ts:1431:16)
    at listOnTimeout (internal/timers.js:557:17)
    at processTimers (internal/timers.js:500:7)

Any ideas on how to go about fixing this?

brystmar commented 2 years ago

Same here:

Unhandled rejection Error: connect EHOSTUNREACH 192.168.xxx.yyy:80
    at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1161:16)
[11/23/2021, 11:21:51 AM] [homebridge-yamaha-avr] This plugin slows down Homebridge. The read handler for the characteristic 'Active Identifier' didn't respond at all!. Please check that you properly call the callback! See https://git.io/JtMGR for more info.
Unhandled rejection Error: connect EHOSTUNREACH 192.168.xxx.yyy:80
    at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1161:16)
[11/23/2021, 11:40:30 AM] [homebridge-yamaha-avr] This plugin slows down Homebridge. The read handler for the characteristic 'Active Identifier' didn't respond at all!. Please check that you properly call the callback! See https://git.io/JtMGR for more info.
[11/23/2021, 11:40:48 AM] [Yamaha AVR] Communication with Yamaha AVR at 192.168.xxx.yyy restored

The plugin is also regularly posting to the logs (and possibly getting frequent status updates?), even when the AVR is on standby (not powered on):

[11/22/2021, 2:56:44 PM] [Yamaha AVR] Current input: Apple TV (HDMI1)
[11/22/2021, 3:01:08 PM] [Yamaha AVR] Current input: Apple TV (HDMI1)
[11/22/2021, 3:31:45 PM] [Yamaha AVR] Current input: Apple TV (HDMI1)
[11/22/2021, 3:34:27 PM] [Yamaha AVR] Current input: Apple TV (HDMI1)
[11/22/2021, 3:40:45 PM] [Yamaha AVR] Current input: Apple TV (HDMI1)
[11/22/2021, 4:06:50 PM] [Yamaha AVR] Current input: Apple TV (HDMI1)
[11/22/2021, 4:11:41 PM] [Yamaha AVR] Current input: Apple TV (HDMI1)
[11/22/2021, 4:21:35 PM] [Yamaha AVR] Current input: Apple TV (HDMI1)
[11/22/2021, 4:43:50 PM] [Yamaha AVR] Current input: Apple TV (HDMI1)
[11/22/2021, 5:56:07 PM] [Yamaha AVR] Current input: Apple TV (HDMI1)
[11/22/2021, 7:10:14 PM] [Yamaha AVR] Current input: Apple TV (HDMI1)
[11/22/2021, 7:10:59 PM] [Yamaha AVR] Current input: Apple TV (HDMI1)
[11/22/2021, 7:42:59 PM] [Yamaha AVR] Current input: Apple TV (HDMI1)
[11/22/2021, 7:42:59 PM] [Yamaha AVR] Current input: Apple TV (HDMI1)
[11/22/2021, 8:41:30 PM] [Yamaha AVR] Current input: Apple TV (HDMI1)
[11/22/2021, 8:44:55 PM] [Yamaha AVR] Current input: Apple TV (HDMI1)
[11/22/2021, 8:54:31 PM] [Yamaha AVR] Current input: Apple TV (HDMI1)
[11/22/2021, 9:39:04 PM] [Yamaha AVR] Current input: Apple TV (HDMI1)
[11/22/2021, 10:00:35 PM] [Yamaha AVR] Current input: Apple TV (HDMI1)
[11/22/2021, 10:01:32 PM] [Yamaha AVR] Current input: Apple TV (HDMI1)
[11/22/2021, 10:36:02 PM] [Yamaha AVR] Current input: Apple TV (HDMI1)
[11/22/2021, 10:48:06 PM] [Yamaha AVR] Current input: Apple TV (HDMI1)
[11/22/2021, 11:25:18 PM] [Yamaha AVR] Current input: Apple TV (HDMI1)
iSteve-O commented 2 years ago

I think this error This plugin generated a warning from the characteristic 'Active Identifier': characteristic was supplied illegal value: number -1 exceeded minimum of 0 is because of the AVR being set to an input that isn't being cached by the plugin for some reason.

I only get this error when my receiver is set to "TV" input & the HomeKit tile errors out not displaying the input (just on) & the input switcher is blank until I change the receiver manually to another input that is has cached. "TV" appears to be the only one not cached.

I hope this helps to fix the plugin because otherwise it works well.

calvarez commented 2 years ago

It appears this project is no longer being watched or updated by the dev. I'm getting constant warnings now about this plugin slowing down all of Homebridge.

iSteve-O commented 2 years ago

It appears this project is no longer being watched or updated by the dev. I'm getting constant warnings now about this plugin slowing down all of Homebridge.

I agree. It's a shame development has ceased.

I seem to have fixed this issue in my home by moving the Yamaha plug-in/receiver to its own child bridge. This has the added benefit of being able to be restarted without restarting the entire Homebridge (many restarts were required for me to get all inputs cached properly).

Once the plug-in properly cached all of the inputs these errors stopped appearing. I had to "initialize" the receiver a couple times, but everything seems to be working fine now, wo even the message about it slowing down Homebridge.

You need to make sure that the receiver has properly named all of the inputs before starting the plug-in and then it should get rid of this error.

I am almost 100% certain this error is from the receiver being set to an input the plug-in hasn't cached & therefore can't recognize.

Maybe someone will fork this great start into another project to iron out some of these kinks. I've tried the other Yamaha plugins and they just don't work as well as this one.

Good luck!

ACDR commented 2 years ago

Apologies, I've had quite a bit going on lately and haven't had an opportunity to look into this.

I will investigate & update with a fix as soon as I can.

I appreciate the patience!

ACDR commented 2 years ago

Beta release with reworked caching & input handling: https://github.com/ACDR/homebridge-yamaha-avr/releases/tag/v2.1.0-beta.3

Will need somebody to test & report back on whether this release resolves the issues described here as I haven't been able to replicate them myself to confirm.

iSteve-O commented 2 years ago

I've been using Yamaha-zone. I'm sorry I haven't responded. Maybe I will give this plug-in a whirl to see if it works better for me now than the zone one, since I only use the 1 (main) zone.

Thank you for your hard work on this, I still appreciate it.

jack-blackson commented 2 years ago

@ACDR i just updated to homebridge-yamaha-avr v2.1.0-beta.3 , and restarted homebrigde, but unfortunately still receiving these errors:

grafik
ACDR commented 2 years ago

@jack-blackson - thanks, have now managed to replicate it, your screenshot implied the error is happening when we ping for the updated AVR state, seems to be a mismatch with some input IDs and the AVR.

If you could try again with 2.1.0-beta.6 that would be much appreciated. This version should catch this scenario and log a more detailed error with details on the AVR input causing this error & the inputs the plugin expects.

jack-blackson commented 2 years ago

@ACDR I ran the update, and set it to debug mode: [28.8.2022, 18:11:24] [homebridge-yamaha-avr] This plugin generated a warning from the characteristic 'Active Identifier': characteristic was supplied illegal value: number -1 exceeded minimum of 0. See https://homebridge.io/w/JtMGR for more info. [28.8.2022, 18:11:24] [homebridge-yamaha-avr] Error: at ActiveIdentifier.Characteristic.characteristicWarning (/usr/lib/node_modules/homebridge/node_modules/hap-nodejs/src/lib/Characteristic.ts:2142:105) at ActiveIdentifier.Characteristic.validateUserInput (/usr/lib/node_modules/homebridge/node_modules/hap-nodejs/src/lib/Characteristic.ts:2045:14) at ActiveIdentifier.Characteristic.updateValue (/usr/lib/node_modules/homebridge/node_modules/hap-nodejs/src/lib/Characteristic.ts:1457:20) at Television.Service.updateCharacteristic (/usr/lib/node_modules/homebridge/node_modules/hap-nodejs/src/lib/Service.ts:481:35) at /usr/lib/node_modules/homebridge-yamaha-avr/src/accessory.ts:442:22

jack-blackson commented 2 years ago

I just recognized this new error:

[28.8.2022, 18:13:33] [Yamaha RX-V473] Unexpected input: "TUNER" [ { id: 'SERVER', name: 'SERVER', index: 0 }, { id: 'NET RADIO', name: 'NET RADIO', index: 1 }, { id: 'AirPlay', name: 'AirPlay', index: 2 }, { id: 'HDMI1', name: ' HDMI1 ', index: 3 }, { id: 'HDMI2', name: ' HDMI2 ', index: 4 }, { id: 'HDMI3', name: ' HDMI3 ', index: 5 }, { id: 'HDMI4', name: ' HDMI4 ', index: 6 }, { id: 'AV1', name: ' AV1 ', index: 7 }, { id: 'AV2', name: ' AV2 ', index: 8 }, { id: 'AV3', name: ' AV3 ', index: 9 }, { id: 'AV4', name: ' AV4 ', index: 10 }, { id: 'AV5', name: ' AV5 ', index: 11 }, { id: 'AV6', name: ' AV6 ', index: 12 }, { id: 'VAUX', name: ' V-AUX ', index: 13 }, { id: 'USB', name: ' USB ', index: 14 } ]

Error ends when I change from radio (tuner) to something else, and comes back when I switch to tuner

iSteve-O commented 2 years ago

Seems like it's trying to cache input -1 "TUNER" but the plug-in is expecting only positive values or zero. Also I don't see "TV" listed in there and that was the issue I had when I had this plug-in installed. I got the exact same messages only about the "TV" input.

Good luck resolving, as I hope this narrows it down.

ACDR commented 2 years ago

Seems like it's trying to cache input -1 "TUNER" but the plug-in is expecting only positive values or zero.

It's happening when we ping the AVR for the current input state. This is for scenarios where the input of the AVR changes without using HomeKit (eg. using the remote) so that the plug-in device input updates to reflect the change.

When we set up the device, we create services for each of the inputs fetched from the AVR. Somehow when we do that we are missing the input that is then sent from the AVR on the device state ping, in this case "TUNER" and "TV".

When the plug-in looks for the input service to match that to and we don't find it, it was setting the active input identifier to "-1", which is not a valid value for the active input.

Next step is to figure out why we're missing those inputs when we set up the input services.

Thanks both, this has been very helpful in narrowing down the cause.

iSteve-O commented 2 years ago

I love the progress toward a solution.

I don't know if this will help any, but I was having a similar issue with the Bravia plug-in that the developer was able to fix.

What was happening in the Bravia case was when the plug-in initially contacted the TV to get the list of inputs and apps it was caching some inputs as apps and therefore would throw similar errors if you specified one in the config that it had cached improperly. I had to really examine the input cache to figure this out.

That's probably not helpful but I thought I'd mention it since it seems like some are not being cached (is it possible they are being cached but are just not being cached properly?).

Maybe check out how the Yamaha-zone plug-in does it because it seems to get them all well.

Good luck and I appreciate your effort!

ACDR commented 2 years ago

Looks like there may be some AVRs that have different outputs for AVR features & "available inputs". These are combined to generate a list of usable inputs in the plug-in. However, I was filtering out some known duplicates from the feature data that should already be in the "available inputs" data (and is with my AVR) - e.g. "Tuner" & "USB".

It seems, specifically in the case of the Tuner input on the RX-V473 that this isn't the case.

I've published another version (2.1.0-beta.8) that should hopefully resolve this.

@iSteve-O - The feature filtering issue doesn't explain the "TV" input in your case though. I've added some extra debug logging of feature/input data from the AVR, I'd be curious to see what your receiver is outputting if you have some time to test & report that back. If beta.8 doesn't already fix that too that is.

jack-blackson commented 2 years ago

@ACDR I've loaded the update, restarted homebridge, but the error unfortunately stayed the same :( Thanks already for your time spending on fixing the problem!!

ACDR commented 2 years ago

@ACDR I've loaded the update, restarted homebridge, but the error unfortunately stayed the same :( Thanks already for your time spending on fixing the problem!!

@jack-blackson Can you please post the additional input/feature debug log output from your device? There should be three arrays logged. The "features", "availableInputs" & the mapped/combined "inputs". e.g:

[8/29/2022, 12:28:46 PM] [Yamaha RX-V685] features [
  'Tuner',     'Spotify',
  'Qobuz',     'TIDAL',
  'Deezer',    'Amazon_Music',
  'Alexa',     'AirPlay',
  'SERVER',    'NET_RADIO',
  'Bluetooth', 'USB'
]
[8/29/2022, 12:28:46 PM] [Yamaha RX-V685] availableInputs [
  {
    TUNER: [ 'TUNER' ],
    PHONO: [ 'PHONO' ],
    HDMI_1: [ 'SHIELD' ],
    HDMI_2: [ 'Lounge' ],
    HDMI_3: [ 'HDMI3' ],
    HDMI_4: [ 'PlayStation 5' ],
    HDMI_5: [ 'Xbox' ],
    AV_1: [ 'AV1' ],
    AV_2: [ 'AV2' ],
    AUX: [ 'AUX' ],
    AUDIO_1: [ 'AUDIO1' ],
    AUDIO_2: [ 'AUDIO2' ],
    AUDIO_3: [ 'AUDIO3' ],
    AUDIO_4: [ 'AUDIO4' ],
    AUDIO_5: [ 'AUDIO5' ],
    MusicCast_Link: [ 'MusicCast Link' ],
    SERVER: [ 'SERVER' ],
    NET_RADIO: [ 'NET RADIO' ],
    Bluetooth: [ 'Bluetooth' ],
    USB: [ 'USB' ]
  }
]
[8/29/2022, 12:28:46 PM] [Yamaha RX-V685] inputs [
  { id: 'Tuner', name: 'Tuner' },
  { id: 'Spotify', name: 'Spotify' },
  { id: 'Qobuz', name: 'Qobuz' },
  { id: 'TIDAL', name: 'TIDAL' },
  { id: 'Deezer', name: 'Deezer' },
  { id: 'AmazonMusic', name: 'Amazon Music' },
  { id: 'Alexa', name: 'Alexa' },
  { id: 'AirPlay', name: 'AirPlay' },
  { id: 'SERVER', name: 'SERVER' },
  { id: 'NETRADIO', name: 'NET RADIO' },
  { id: 'Bluetooth', name: 'Bluetooth' },
  { id: 'USB', name: 'USB' },
  { id: 'PHONO', name: 'PHONO' },
  { id: 'HDMI1', name: 'SHIELD' },
  { id: 'HDMI2', name: 'Lounge' },
  { id: 'HDMI3', name: 'HDMI3' },
  { id: 'HDMI4', name: 'PlayStation 5' },
  { id: 'HDMI5', name: 'Xbox' },
  { id: 'AV1', name: 'AV1' },
  { id: 'AV2', name: 'AV2' },
  { id: 'AUX', name: 'AUX' },
  { id: 'AUDIO1', name: 'AUDIO1' },
  { id: 'AUDIO2', name: 'AUDIO2' },
  { id: 'AUDIO3', name: 'AUDIO3' },
  { id: 'AUDIO4', name: 'AUDIO4' },
  { id: 'AUDIO5', name: 'AUDIO5' },
  { id: 'MusicCastLink', name: 'MusicCast Link' }
]
iSteve-O commented 2 years ago

I just installed it and wanted to get you this info. I know how frustrating waiting can be. I haven't added it to home to really test it yet but this is what the HB log says...

[28/08/2022, 21:43:25] [Yamaha AVR2] features [

 'Tuner',        'Napster',

  'SiriusXM',     'Pandora',

  'Spotify',      'Qobuz',

  'TIDAL',        'Deezer',

  'Amazon_Music', 'Alexa',

  'AirPlay',      'SERVER',

  'NET_RADIO',    'Bluetooth',

  'USB'

]

[28/08/2022, 21:43:25] [Yamaha AVR2] availableInputs [

  {

    TUNER: [ 'TUNER' ],

    PHONO: [ 'PHONO' ],

    HDMI_1: [ 'Xfinity X1' ],

    HDMI_2: [ 'Apple TV 4K' ],

    HDMI_3: [ 'PlayStation 4' ],

    HDMI_4: [ 'HDMI4' ],

    HDMI_5: [ 'HDMI5' ],

    HDMI_6: [ 'HDMI6' ],

    HDMI_7: [ 'HDMI7' ],

    AUDIO_1: [ 'AUDIO1' ],

    AUDIO_2: [ 'AUDIO2' ],

    AUDIO_3: [ 'AUDIO3' ],

    AUDIO_4: [ 'AUDIO4' ],

    AUDIO_5: [ 'AUDIO5' ],

    TV: [ 'TV' ],

    MusicCast_Link: [ 'MusicCast Link' ],

    SERVER: [ 'SERVER' ],

    NET_RADIO: [ 'NET RADIO' ],

    Bluetooth: [ 'Bluetooth' ],

    USB: [ 'USB' ]

  }

]

[28/08/2022, 21:43:25] [Yamaha AVR2] inputs [

  { id: 'Tuner', name: 'Tuner' },

  { id: 'Napster', name: 'Napster' },

  { id: 'SiriusXM', name: 'SiriusXM' },

  { id: 'Pandora', name: 'Pandora' },

  { id: 'Spotify', name: 'Spotify' },

  { id: 'Qobuz', name: 'Qobuz' },

  { id: 'TIDAL', name: 'TIDAL' },

  { id: 'Deezer', name: 'Deezer' },

  { id: 'AmazonMusic', name: 'Amazon Music' },

  { id: 'Alexa', name: 'Alexa' },

  { id: 'AirPlay', name: 'AirPlay' },

  { id: 'SERVER', name: 'SERVER' },

  { id: 'NETRADIO', name: 'NET RADIO' },

  { id: 'Bluetooth', name: 'Bluetooth' },

  { id: 'USB', name: 'USB' },

  { id: 'PHONO', name: 'PHONO' },

  { id: 'HDMI1', name: 'Xfinity X1' },

  { id: 'HDMI2', name: 'Apple TV 4K' },

  { id: 'HDMI3', name: 'PlayStation 4' },

  { id: 'HDMI4', name: 'HDMI4' },

  { id: 'HDMI5', name: 'HDMI5' },

  { id: 'HDMI6', name: 'HDMI6' },

  { id: 'HDMI7', name: 'HDMI7' },

  { id: 'AUDIO1', name: 'AUDIO1' },

  { id: 'AUDIO2', name: 'AUDIO2' },

  { id: 'AUDIO3', name: 'AUDIO3' },

  { id: 'AUDIO4', name: 'AUDIO4' },

  { id: 'AUDIO5', name: 'AUDIO5' },

  { id: 'TV', name: 'TV' },

  { id: 'MusicCastLink', name: 'MusicCast Link' }

]

Let me know if you need any more info and I'll get it to you as quickly as possible. I will update if any errors.

Edit: I must add it does keep printing this above over and over again... I'm gathering this is the input polling and expected...

Congratulations! you appear to have fixed TSR-700 support! I can now switch to the TV input without error.

GREAT WORK!

ACDR commented 2 years ago

Thanks @iSteve-O - it looks like all of your device's features & inputs have been mapped correctly - I don't see anything missing from either features or inputs.

I must add it does keep printing this above over and over again

It will log repeatedly as the inputs are checked every few seconds to remain in sync with the device. 😄

ACDR commented 2 years ago

Congratulations! you appear to have fixed TSR-700 support! I can now switch to the TV input without error.

Ah, fantastic! 🎉

iSteve-O commented 2 years ago

Thanks @iSteve-O - it looks like all of your device's features & inputs have been mapped correctly - I don't see anything missing from either features or inputs.

I must add it does keep printing this above over and over again

It will log repeatedly as the inputs are checked every few seconds to remain in sync with the device. 😄

Yeah, I gathered that LOL it's just the first time I'm running in debug, so first time I've seen it. I may remove Yamaha-zone now and use this because it has a lot of stuff I don't need and this has just what I need. As long as stable now I think I'll switch. Thanks again!

jack-blackson commented 2 years ago

@ACDR I am sorry but I can test next time on Wednesday as I am not at home at the moment

ACDR commented 2 years ago

@jack-blackson - I'm going to close this issue, please feel free to open a new one if you still have issues with your "TUNER" input in the latest v2.1.0 release.