jimboca
commented
1 year ago Yes, as I mentioned in the forum post which you posted on, I am trying to debug. It's an issue specific to eisy, and is not just the speak commands, it's all commands like arming/disarming the system. https://forum.universal-devices.com/topic/39690-slow-response-tofrom-elk-ns
Using ELK NS 3.5.7, EISY IoX 5.5.3, M1 version 5.03.00, XEP version 1.03.1C
When I send a command to speak a word to the M1 (e.g. In a program then statement) there is a 10-30 second delay before the Elk responds with the audible command. If I power up my old ISY994i with the Elk Module sending commands to speak are near instentaneous (~1-2 seconds). Also, if I send a dozen speak word commands programmatically (one after another) the length of the delay is much greater, but all the commands get sent at the same time to the Elk and it recites them correctly without any pauses between the words. If I send it an excessive amount of words to speak (20?) then the program hangs and the Elk never responds.
Here are two debug captures from sending a simple speak word (800mhz tone) through the Elk NS:
Example One: (Ten second delay)
2023-01-14 15:21:54,366 MQTT udi_interface.interface DEBUG interface:_message: QUEUING incoming message command 2023-01-14 15:21:54,366 Command udi_interface.interface DEBUG interface:_parseInput: DEQUEING command 2023-01-14 15:21:54,366 Command udi_interface INFO Controller:cmd_speak_word: ELK Controller: 53 2023-01-14 15:21:54,366 Command udi_interface INFO Controller:cmd_speak_word: ELK Controller: word=[800hz_Tone] 2023-01-14 15:21:55,085 MQTT udi_interface.interface DEBUG interface:_message: QUEUING incoming message shortPoll 2023-01-14 15:21:55,085 Command udi_interface.interface DEBUG interface:_parseInput: DEQUEING shortPoll 2023-01-14 15:21:55,085 Thread-976 udi_interface DEBUG Controller:handler_poll: start 2023-01-14 15:21:55,085 Thread-976 udi_interface DEBUG Controller:shortPoll: start 2023-01-14 15:21:55,086 Thread-976 udi_interface DEBUG Area:shortPoll: area_1:Club Poppy House: ready=True poll_voltages=False 2023-01-14 15:21:55,086 Thread-976 udi_interface DEBUG Controller:shortPoll: done 2023-01-14 15:22:04,867 ELK-2760 elkm1_lib.connection DEBUG connection:write_msg: write_data '09sw05300B5' 2023-01-14 15:22:04,867 ELK-2760 elkm1_lib.connection DEBUG connection:_read_stream: got_data '16XK03221571401230100076' 2023-01-14 15:22:04,867 ELK-2760 udi_interface INFO Controller:callback: ELK Controller: cs={'real_time_clock': '0322157140123010'} 2023-01-14 15:22:04,867 ELK-2760 udi_interface INFO Controller:callback: real_time_clock=0322157140123010
Example Two: (26 second delay)
2023-01-14 15:25:08,815 MQTT udi_interface.interface DEBUG interface:_message: QUEUING incoming message command 2023-01-14 15:25:08,815 Command udi_interface.interface DEBUG interface:_parseInput: DEQUEING command 2023-01-14 15:25:08,815 Command udi_interface INFO Controller:cmd_speak_word: ELK Controller: 53 2023-01-14 15:25:08,815 Command udi_interface INFO Controller:cmd_speak_word: ELK Controller: word=[800hz_Tone] 2023-01-14 15:25:25,124 MQTT udi_interface.interface DEBUG interface:_message: QUEUING incoming message shortPoll 2023-01-14 15:25:25,124 Command udi_interface.interface DEBUG interface:_parseInput: DEQUEING shortPoll 2023-01-14 15:25:25,124 Thread-984 udi_interface DEBUG Controller:handler_poll: start 2023-01-14 15:25:25,124 Thread-984 udi_interface DEBUG Controller:shortPoll: start 2023-01-14 15:25:25,124 Thread-984 udi_interface DEBUG Area:shortPoll: area_1:Club Poppy House: ready=True poll_voltages=False 2023-01-14 15:25:25,125 Thread-984 udi_interface DEBUG Controller:shortPoll: done 2023-01-14 15:25:34,959 ELK-2760 elkm1_lib.connection DEBUG connection:write_msg: write_data '09sw05300B5' 2023-01-14 15:25:34,960 ELK-2760 elkm1_lib.connection DEBUG connection:_read_stream: got_data '16XK33251571401230100070' 2023-01-14 15:25:34,960 ELK-2760 udi_interface INFO Controller:callback: ELK Controller: cs={'real_time_clock': '3325157140123010'} 2023-01-14 15:25:34,960 ELK-2760 udi_interface INFO Controller:callback: real_time_clock=3325157140123010