Device with unexpected physical address came online on logical address about iobroker.cec2

[Garfonso]

Is there more logging in between? Like for example a response to a name poll or something? Or does the second report happen right after the first one?

[Garfonso]

Hm... maybe can you send me a complete debug log of your startup procedure? From what I see it is correct, that the logical address is not updated in iobroker, this is a bug. But internally the communication should work and a REPORT_POWER_STATUS should be assigned to the right device and the right objects updated in ioBroker.

Another question would be, if you see an unknown device being created with the name of 2000 or something like that.

[boriswerner]

@Garfonso thanks for the reply. I will prepare a full log in the upcoming days. I meanwhile "fixed" this temporary by preventing the removal of the logical address for my device combination but this is really quick and dirty.
Instead of
if (device.active)
I changed the check to:
if (device.active && device.logicalAddressHex != '5' && device.physicalAddress != '2.0.0.0')
There is no unknown device created that I can see in the object tree.

Btw: for my purpose I also had to change setStateChangedAsync at some place to setStateAsync as after polling the status the state isnt getting updated if it stays the same. (I also did that quickndirty as I don't know whether for other things the Changed-method might be more benefitial, but for my requirements it is working)
My process is the following:
If the TV is switched on, after 20 seconds I poll the status of the AVR, if it is (still) off (listens to changes to the power state), turn it on via Broadlink IR.
By using the setStateChangedAsync, the state is not getting an update and thus the listener is not activated, so I changed it. Just for consideration...

[Garfonso]

Ok, thanks. You might want to try an updated version I'll publish later (hopefully today). It might already fix your issue, if it is what I think it is.

Regarding your process: If you want to check after 20 seconds if the AVR is on, why not do that by setTimeout (if you are using a script for that)? You could still use the listener and if it gets online before, you can cancel the timeout, like so:

let timeoutId = 0;
on({id: 'cec2.0.TV.state', val: true, ack: true}, () => { //TV went on and reported power state to bus. For me this does not always happen, so I did remove the 'ack: true' part for me here.
    if (timeoutId) {
       clearTimeout(timeoutId);
    }
    timeoutId = setTimeout(() => { 
        const avrStatus = getState('cec2.0.AV_Receiver.state').val;
        if (!avrStatus) {
             //switch on AVR with set State here:
             setState('cev2.0.AV_Receiver.state', true); //this would switch it on via CEC, but you can replace ID with Broadlink of course
        }
    }, 20000);
});

on({id: 'cec2.0.AV_Receiver.state', val: true, ack: true}, () => {
    if (timeoutId) {
       clearTimeout(timeoutId); //AV Reciever already went on, so we cancel the timeout and won't switch anything.
    }
});

(untested but if no typos are in there, it should work and do what you want)

I'm not so sure if I want to change to setStateAsync there. I'll think about it.

[boriswerner]

Thanks, I also already thought about something like this but it also has some flaws. When the AVR is turning on, I have to poll the status actively, as it seems to not correctly report the state (that might also relate to the logical/physical address update). That is why I would like to listen to the answer of the poll (if it is actively reporting "on" or "off", when I understand the state and ack logic in iobroker correctly, this would also be the "correct" behaviour I guess).

With the normal setStateAsync, the normal on({id: "cec2.1.AV_Receiver.state"} is not triggered, but on({id: "cec2.1.AV_Receiver.state", change: "any"} is triggered. With setStateChangedAsync none of them work although the poll is receiving a correct answer.

I will check out the new version and provide a full log. But most probably I can only do it only on the weekend.

Btw. my AVR is reporting cecVersion VERSION_1_3A. Maybe this has a different behaviour than VERSION_1_4. Sorry for not mentioning this earlier.

[Garfonso]

OK, that's a fair point, with polling it should always report.
Ack = true means report from device, ack = false means command to device

I don't think the version is that important. Cec implementations differ a lot anyways.

[boriswerner]

So, I did some more tests with the v0.0.6 today and saved the logs and descriptions:
https://github.com/boriswerner/ioBroker.cec2/tree/master/test/cec_test_20210102

The version fixed: the physical adress is updated back to 2.0.0.0 after the message "Device with unexpected physical address came online on logical address 5" had updated it to 0.0.0.0 but it still behaves not correct, as the state is not updated, I guess because it is temporarily set to 0.0.0.0 and it tries to create another audio device, but somehow this is not really working it seems. Can you get something from the logs?

The update of the state after polling is also fixed.

1. I recognized two other things: my systemAudio isnt set at all and stays blank all the time, although there are some messages in the log regarding the audio status.

2. when using the POWER button from the TVs iobroker adapter instead of the Power button of the remote, the TV state is updated correctly because it seems to take another standby sequence (see word and additional log-file).

So I guess it already is better than before and I could work with this. But maybe you see something, that I don't, especially regarding the systemAudio and the update of the AVR state.

If I can supply anything else to help, let me know.

[Garfonso]

Hm... this is quite strange... I see some reports of audio status (5F:72:01 and 5F:72:00), but they do not get processed...

The 0.0.0.0 incident can not really be the issue here, because they should get processed (============================ Processing Event: output) in any case. I fear that a feature of the library I sometimes use is blocking the processing, which waits for answers from a device and produces these errors after a timeout:

2021-01-02 13:26:37.950 - �[34mdebug�[39m: cec2.1 (3920) DEBUG: [ 318577] command 'give device power status' timeout 2021-01-02 13:26:39.927 - �[34mdebug�[39m: cec2.1 (3920) TV did not answer to powerRequest: Error: CEC monitor hasn't gotten response in some time (3000 ms) from 0 - Error: CEC monitor hasn't gotten response in some time (3000 ms) from 0 at Timeout._onTimeout (/opt/iobroker/node_modules/@senzil/cec-monitor/lib/cec-monitor.js:447:21) at listOnTimeout (internal/timers.js:554:17) at processTimers (internal/timers.js:497:7)

I'll have a look into that...

[Garfonso]

can you try 0.0.8 if this is now fixed or still broken?

[boriswerner]

Just to give you a short update: I had some issues with my iobroker slave where the cec is running on. But now I have 0.0.10 running and it is at least working as before with my script. I will do the checks of the issues in debug probably on the weekend.

[boriswerner]

Following results:

1. the global systemAudio is now correctly set and the mute, volumeUp and volumeDown buttons are working. the volume level is not set (the poll is not returning a result message so I guess it is because of the AVR not replying).
2. The AVR state is still not updated when turned on. There is still this address change (Device with unexpected physical address came online on logical address 5). After the second REPORT_PHYSICAL_ADDRESS message the address is set correctly again but the power state is not updated. Only if I poll it. When it comes online there is also no REPORT_POWER_STATUS message from the AVR if I dont actively poll it. Although there is a message Audio (5): power status changed from 'standby' to 'on' appearing in the log automatically.
3. The TV reports its state only if turned on with the usual remote control. If I use the normal remote to turn it off, it stays on true. Then it still shows the error:

cec2.1	2021-02-27 14:08:15.443	debug	(12687) state cec2.1.TV.poll.state changed: true (ack = false)

cec2.1	2021-02-27 14:07:54.790	debug	at Timer.processTimers (timers.js:223:10)

cec2.1	2021-02-27 14:07:54.790	debug	at listOnTimeout (timers.js:263:5)

cec2.1	2021-02-27 14:07:54.790	debug	at tryOnTimeout (timers.js:300:5)

cec2.1	2021-02-27 14:07:54.790	debug	at ontimeout (timers.js:436:11)

cec2.1	2021-02-27 14:07:54.790	debug	at Timeout.setTimeout [as _onTimeout] (/opt/iobroker/node_modules/iobroker.cec2/lib/cec-monitor.js:446:24)

cec2.1	2021-02-27 14:07:54.790	debug	(12687) TV did not answer to powerRequest: Error: CEC monitor hasn't gotten response in some time (3000 ms) from 0 - Error: CEC monitor hasn't gotten response in some time (3000 ms) from 0

cec2.1	2021-02-27 14:07:51.820	debug	(12687) TRAFFIC: [ 35169] << 10:8f

So still not fully funtional, but I can really live with this. I watch the state of the TV with the panasonic adapter, if it comes online I let the script poll the AVR state and if the AVR state gets updated I do my magic. Works now for quite a while and also works with the current version.
Thanks for your efforts on this adapter. It really helps a lot :-)
If you dont see a need or dont want to do any more fixes you can close the issue. If I can be of any more help let me know.

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs within the next 7 days. Please check if the issue is still relevant in the most current version of the adapter and tell us. Also check that all relevant details, logs and reproduction steps are included and update them if needed. Thank you for your contributions. Dieses Problem wurde automatisch als veraltet markiert, da es in letzter Zeit keine Aktivitäten gab. Es wird geschlossen, wenn nicht innerhalb der nächsten 7 Tage weitere Aktivitäten stattfinden. Bitte überprüft, ob das Problem auch in der aktuellsten Version des Adapters noch relevant ist, und teilt uns dies mit. Überprüft auch, ob alle relevanten Details, Logs und Reproduktionsschritte enthalten sind bzw. aktualisiert diese. Vielen Dank für Eure Unterstützung.

[stale]

This issue has been automatically closed because of inactivity. Please open a new issue if still relevant and make sure to include all relevant details, logs and reproduction steps. Thank you for your contributions. Dieses Problem wurde aufgrund von Inaktivität automatisch geschlossen. Bitte öffnet ein neues Issue, falls dies noch relevant ist und stellt sicher das alle relevanten Details, Logs und Reproduktionsschritte enthalten sind. Vielen Dank für Eure Unterstützung.