MH Scene - suggestions + issue with Message sending

[stepir]

Hi

I'm currently using Message sending for firing MyHome scene with messages like

  message: '*15*07*01##'

To do so I've configured HA scripts. The problem is that 'sometimes', let's say daily, but I was not able to understand why/when - the script is not actually sending any message on the bus (checked with web net client).

ATM I'm just awaiting and manually running it again but: 1) can anyone suggest how to investigate further on the reasons why? 2) is what I'm doing the right approach? or should I do something different? 3) I tried changing the script to await 30 sec and sending again the same command - although it would be not ideal as there's steps in such scene that should not be done twice - it's also not working always!!

Thanks for your suggestions

[anotherjulien]

Can you provide debug logs from the integration when your attempt fails?

[stepir]

hi @anotherjulien thanks for answering!

here is the log - when the integration is not sending the message :

2021-11-11 16:37:42 INFO (MainThread) [homeassistant.components.script.mh_giorno] MH-Giorno: Running script sequence
2021-11-11 16:37:42 INFO (MainThread) [homeassistant.components.script.mh_giorno] MH-Giorno: Executing step call service
2021-11-11 16:37:43 INFO (MainThread) [custom_components.myhome] Gateway device type is: F454.
2021-11-11 16:37:47 INFO (MainThread) [custom_components.myhome] Gateway device type is: F454.
2021-11-11 16:38:02 INFO (MainThread) [pyhap.hap_protocol] ('192.168.2.38', 57230): Connection made to Home Assistant Bridge
2021-11-11 16:38:06 WARNING (MainThread) [custom_components.myhome] Unknown device: WHO=4 WHERE=0
2021-11-11 16:38:08 INFO (MainThread) [custom_components.myhome] Zone 14's fan is off.
2021-11-11 16:38:08 INFO (MainThread) [custom_components.myhome] Gateway device type is: F454.
2021-11-11 16:38:08 INFO (MainThread) [custom_components.myhome] Zone 14's fan is off.
2021-11-11 16:38:12 INFO (MainThread) [custom_components.myhome] Gateway device type is: F454.

here is the same log when integration is sending the message:

2021-11-11 16:41:28 INFO (MainThread) [custom_components.myhome] Gateway device type is: F454.
2021-11-11 16:41:32 INFO (MainThread) [homeassistant.components.script.mh_giorno] MH-Giorno: Running script sequence
2021-11-11 16:41:32 INFO (MainThread) [homeassistant.components.script.mh_giorno] MH-Giorno: Executing step call service
2021-11-11 16:41:32 INFO (MainThread) [custom_components.myhome] Button 7 of CEN object 01 has been pressed.
2021-11-11 16:41:32 INFO (MainThread) [custom_components.myhome] Message *15*07*01## was successfully sent.
2021-11-11 16:41:32 INFO (MainThread) [custom_components.myhome] Gateway device type is: F454.
2021-11-11 16:41:32 INFO (MainThread) [custom_components.myhome] Light 54 is switched off.
2021-11-11 16:41:32 INFO (MainThread) [custom_components.myhome] Light 55 is switched off.
2021-11-11 16:41:32 INFO (MainThread) [custom_components.myhome] Light 17 is switched on.
2021-11-11 16:41:32 INFO (MainThread) [custom_components.myhome] Light 54 is switched off.
2021-11-11 16:41:33 INFO (MainThread) [custom_components.myhome] Light 55 is switched off.
2021-11-11 16:41:33 INFO (MainThread) [custom_components.myhome] Zone 14's main sensor is reporting a temperature of 21.1°C.
2021-11-11 16:41:33 INFO (MainThread) [custom_components.myhome] Zone 14's mode is set to 'heat'.
2021-11-11 16:41:34 INFO (MainThread) [custom_components.myhome] Cover 91 stopped.
2021-11-11 16:41:34 INFO (MainThread) [custom_components.myhome] Cover 92 stopped.
2021-11-11 16:41:34 INFO (MainThread) [custom_components.myhome] Cover 93 stopped.
2021-11-11 16:41:34 INFO (MainThread) [custom_components.myhome] Cover 94 stopped.
2021-11-11 16:41:34 INFO (MainThread) [custom_components.myhome] Cover 95 stopped.
2021-11-11 16:41:34 INFO (MainThread) [custom_components.myhome] Light 0513 is switched off.
2021-11-11 16:41:34 INFO (MainThread) [custom_components.myhome] Cover 91 is opening.
2021-11-11 16:41:34 INFO (MainThread) [custom_components.myhome] Cover 92 is opening.
2021-11-11 16:41:34 INFO (MainThread) [custom_components.myhome] Cover 93 is opening.
2021-11-11 16:41:34 INFO (MainThread) [custom_components.myhome] Cover 94 is opening.
2021-11-11 16:41:34 INFO (MainThread) [custom_components.myhome] Cover 95 is opening.
2021-11-11 16:41:34 WARNING (MainThread) [custom_components.myhome] Unknown device: WHO=1 WHERE=89
2021-11-11 16:41:34 INFO (MainThread) [custom_components.myhome] Zone 11's actuator 1 is off.
2021-11-11 16:41:34 INFO (MainThread) [custom_components.myhome] Light 0515 is switched off.
2021-11-11 16:41:35 INFO (MainThread) [custom_components.myhome] Button 9 of CEN+ object 1 is being held pressed

mh_giorno is the script calling the message:

alias: MH-Giorno
sequence:
  - service: myhome.send_message
    data:
      message: '*15*07*01##'
mode: single

in the first case nothing is coming on the bus - in the second case everything work and the integration is also catching the events resulting the activation of the scene (producing effect like opening blinds, changing temp etc etc)

[stepir]

hey @anotherjulien any ideas?

[anotherjulien]

I can see only info and warning logs in what you provided, did you turn on debug before capturing them?

[stepir]

my bad I did enabled logging with

homeassistant.components.myhome: debug

instead of

custom_components.myhome: debug Will reproduce and get back

tnx

[stepir]

this is what is logged when nothing happen

2021-11-28 11:18:55 DEBUG (MainThread) [custom_components.myhome] message to be sent: *15*07*01##
2021-11-28 11:18:55 DEBUG (MainThread) [custom_components.myhome] OWN Message: *15*07*01##
2021-11-28 11:18:55 DEBUG (MainThread) [custom_components.myhome] message valid
2021-11-28 11:18:55 DEBUG (MainThread) [custom_components.myhome] Message *15*07*01## was successfully queued.
2021-11-28 11:18:55 DEBUG (MainThread) [custom_components.myhome] Message *15*07*01## was successfully unqueued by worker 0.
2021-11-28 11:18:55 DEBUG (MainThread) [custom_components.myhome] Message *15*07*01## received response *#4*11*0*0222##.
2021-11-28 11:19:03 DEBUG (MainThread) [custom_components.myhome] Received: *2*0*51##

[stepir]

what *#4*11*0*0222## mean? seems like it's the gateway not executing the commands?

[stepir]

@anotherjulien wanted to mention this happen particularly after some time not sending any command to the gateway. Once the first is accepted all the following get accepted. To reproduce I need to await 1hr or so and then the following message is ignored.

Sorry for multiple response/messages in short time here

[anotherjulien]

*#4*11*0*0222## is a message related to the heating system (zone 11 reporting a temperature of 22.2°) If it's been received as a 'response' to your message it's most likely because there were many messages sent on the command session at that time. A collision of sorts, if you want.

How many workers are configured in the integration? Only 1?

[stepir]

have to admit I have no clue of what you are talking :-) yes would guess 1 at this point and could not find any documentation related to the matter - however the integration is not sending only the message *15*07*01## ? and the rest is a consequence of the gateway (F454 in my case) executing what is configured inside the MH200?

[stepir]

ok, this?

That… is a lot of retries!
Did you try to reboot the gateway itself?
Alternatively, can you try going in the __init__.py file on line 84 and reduce the number of concurrent workers from 5 down to maybe even just 1?

/edit

ahhhhhhhhhh

tried increasing it to 2

[stepir]

no joy so far - increased 1 by 1 workers till 8 and stil experiencing the same. Moved back to 2, debug mode on and trying now using my MH200 as gateway instead of the F454.

[stepir]

@anotherjulien look at this:

2021-11-30 18:27:20 INFO (MainThread) [custom_components.myhome] Gateway's internal datetime is: 2021-11-30 18:27:02+01:00.
2021-11-30 18:27:40 DEBUG (MainThread) [custom_components.myhome] message to be sent: *15*07*01##
2021-11-30 18:27:40 DEBUG (MainThread) [custom_components.myhome] OWN Message: *15*07*01##
2021-11-30 18:27:40 DEBUG (MainThread) [custom_components.myhome] message valid
2021-11-30 18:27:40 DEBUG (MainThread) [custom_components.myhome] Message *15*07*01## was successfully queued.
2021-11-30 18:27:40 DEBUG (MainThread) [custom_components.myhome] Message *15*07*01## was successfully unqueued by worker 0.
2021-11-30 18:27:40 DEBUG (MainThread) [custom_components.myhome] Message *15*07*01## received response *1*0*75##.
2021-11-30 18:27:40 ERROR (MainThread) [custom_components.myhome] Could not send message *15*07*01##.
2021-11-30 18:27:50 DEBUG (MainThread) [custom_components.myhome] Received: *#13**22*18*27*32*001*02*30*11*2021##
2021-11-30 18:27:50 INFO (MainThread) [custom_components.myhome] Gateway's internal datetime is: 2021-11-30 18:27:32+01:00.

[stepir]

and here is another sequence:

2021-11-30 18:35:35 DEBUG (MainThread) [custom_components.myhome] message to be sent: *15*07*01##
2021-11-30 18:35:35 DEBUG (MainThread) [custom_components.myhome] OWN Message: *15*07*01##
2021-11-30 18:35:35 DEBUG (MainThread) [custom_components.myhome] message valid
2021-11-30 18:35:35 DEBUG (MainThread) [custom_components.myhome] Message *15*07*01## was successfully queued.
2021-11-30 18:35:35 DEBUG (MainThread) [custom_components.myhome] Message *15*07*01## was successfully unqueued by worker 0.
2021-11-30 18:35:35 DEBUG (MainThread) [custom_components.myhome] Message *15*07*01## received response *4*1*11##.
2021-11-30 18:35:46 DEBUG (MainThread) [custom_components.myhome] message to be sent: *15*07*01##
2021-11-30 18:35:46 DEBUG (MainThread) [custom_components.myhome] OWN Message: *15*07*01##
2021-11-30 18:35:46 DEBUG (MainThread) [custom_components.myhome] message valid
2021-11-30 18:35:46 DEBUG (MainThread) [custom_components.myhome] Message *15*07*01## was successfully queued.
2021-11-30 18:35:46 DEBUG (MainThread) [custom_components.myhome] Message *15*07*01## was successfully unqueued by worker 1.
2021-11-30 18:35:46 DEBUG (MainThread) [custom_components.myhome] Command session connection reset, retrying...
2021-11-30 18:35:46 DEBUG (MainThread) [custom_components.myhome] Opening command session.
2021-11-30 18:35:46 DEBUG (MainThread) [custom_components.myhome] Negotiating command session.
2021-11-30 18:35:46 DEBUG (MainThread) [custom_components.myhome] Reply: *#*1##
2021-11-30 18:35:46 DEBUG (MainThread) [custom_components.myhome] Received nonce: *#74338507##
2021-11-30 18:35:46 DEBUG (MainThread) [custom_components.myhome] Sending command session password.
2021-11-30 18:35:46 DEBUG (MainThread) [custom_components.myhome] Reply: *#*1##
2021-11-30 18:35:46 DEBUG (MainThread) [custom_components.myhome] Command session established.
2021-11-30 18:35:46 INFO (MainThread) [custom_components.myhome] Message *15*07*01## was successfully sent.
2021-11-30 18:35:46 DEBUG (MainThread) [custom_components.myhome] Received: *15*07*01##
2021-11-30 18:35:46 INFO (MainThread) [custom_components.myhome] Button 7 of CEN object 01 has been pressed.
2021-11-30 18:35:46 DEBUG (MainThread) [custom_components.myhome] Received: *17*1*11##
2021-11-30 18:35:46 INFO (MainThread) [custom_components.myhome] Unsupported message type: *17*1*11##
2021-11-30 18:35:47 DEBUG (MainThread) [custom_components.myhome] Received: *1*0*54##
2021-11-30 18:35:47 INFO (MainThread) [custom_components.myhome] Light 54 is switched off.
2021-11-30 18:35:47 DEBUG (MainThread) [custom_components.myhome] Received: *1*1000#1*44##
2021-11-30 18:35:47 DEBUG (MainThread) [custom_components.myhome] Ignoring translation message *1*1000#1*44##
2021-11-30 18:35:47 DEBUG (MainThread) [custom_components.myhome] Received: *1*0*55##
2021-11-30 18:35:47 INFO (MainThread) [custom_components.myhome] Light 55 is switched off.
2021-11-30 18:35:47 DEBUG (MainThread) [custom_components.myhome] Received: *1*1*44##
2021-11-30 18:35:47 INFO (MainThread) [custom_components.myhome] Light 44 is switched on.
2021-11-30 18:35:47 DEBUG (MainThread) [custom_components.myhome] Received: *1*1*17##
2021-11-30 18:35:47 INFO (MainThread) [custom_components.myhome] Light 17 is switched on.
2021-11-30 18:35:47 DEBUG (MainThread) [custom_components.myhome] Received: *1*0*#8##
2021-11-30 18:35:47 DEBUG (MainThread) [custom_components.myhome] Received: *1*0*54##
2021-11-30 18:35:47 INFO (MainThread) [custom_components.myhome] Light 54 is switched off.

the first attempt did not produced anything, no errors no reactions from the system - the second worked immediately as shown in the logs

[stepir]

ok so when the thing don't work what I noticed is that the message is queued and then immediately unqued:

2021-11-30 22:05:13 DEBUG (MainThread) [custom_components.myhome] message to be sent: *15*07*01##
2021-11-30 22:05:13 DEBUG (MainThread) [custom_components.myhome] OWN Message: *15*07*01##
2021-11-30 22:05:13 DEBUG (MainThread) [custom_components.myhome] message valid
2021-11-30 22:05:13 DEBUG (MainThread) [custom_components.myhome] Message *15*07*01## was successfully queued.
2021-11-30 22:05:13 DEBUG (MainThread) [custom_components.myhome] Message *15*07*01## was successfully unqueued by worker 1.

@anotherjulien what could be the reason why the worker enqueue the message?

[anotherjulien]

It's normal for messages to be unqueued quickly, if there was any delay at this stage, you'd notice that delay between sending an action in HA and it happening in the real world. I'm unclear on why the gateway does not acknowledge the message the first time it is sent, and moreover, why the command session is reset when you retry!

From going over the OpenWebNet docs, I understand that what you're trying to do is what they call "virtual pressure"; aren't you supposed to follow that with at least a "virtual release after short pressure" *15*07#01*01##?

[stepir]

this is the way it's configured the scene in my mh200 and it's just activated with a virtual pressure start of button 7:

I'm happy to test a virtual release but i'm unsure how to implement it?