QA just stops - Githubissues

MomosX commented 3 years ago

Hi,

I see in the logs :

[20.09.2021] [18:05:11] [DEBUG] [QUICKAPP1508]: HC3-to-MQTT bridge shutdown sequence complete [20.09.2021] [18:07:24] [DEBUG] [QUICKAPP1508]: Disconnected from HC3 (got flagged to stop reading HC3 events)

And QA stops.

Any idea what is flagging it please ?

alexander-vitishchenko commented 3 years ago

It may happen in a few cases:

when you turn off the bridge, like you can turn off any other switch at Fibaro HC3, either manually or by the automation
QA may shutdown itself when it sees any issues with MQTT or Fibaro credentials… I need to see the logs prior to “HC3-to-MQTT bridge shutdown sequence complete”

MomosX commented 3 years ago

here they are. the bridge was not shut down from the interface or by any scene. Device 1282 is FGS223

``

[20.09.2021] [14:30:07] [DEBUG] [QUICKAPP1508]: Device discovery has been complete

[20.09.2021] [14:30:07] [DEBUG] [QUICKAPP1508]: Started monitoring events from Fibaro Home Center 3

[20.09.2021] [16:52:58] [DEBUG] [QUICKAPP1508]: Turn ON for device #1282 [20.09.2021] [16:53:09] [DEBUG] [QUICKAPP1508]: Turn ON for device #1282 [20.09.2021] [16:53:47] [DEBUG] [QUICKAPP1508]: Turn ON for device #1282 [20.09.2021] [16:54:57] [DEBUG] [QUICKAPP1508]: Turn ON for device #1282 [20.09.2021] [16:55:02] [DEBUG] [QUICKAPP1508]: Turn ON for device #1282 [20.09.2021] [16:55:15] [DEBUG] [QUICKAPP1508]: Turn ON for device #1282 [20.09.2021] [18:05:11] [DEBUG] [QUICKAPP1508]: HC3-to-MQTT bridge shutdown sequence complete [20.09.2021] [18:07:24] [DEBUG] [QUICKAPP1508]: Disconnected from HC3 (got flagged to stop reading HC3 events) ``

Thank you

alexander-vitishchenko commented 3 years ago

Interesting, can you share anonymised Quick App variables with me?

I’ll explore several scenarios what could cause such a behaviour with the Quick App shutdown sequence and then come back to you with hopefully a solution, or with more questions :-)

MomosX commented 3 years ago

Capture

This started yesterday, after i updated the QA by copy/paste the contents of all the files

alexander-vitishchenko commented 3 years ago

Let me check it out and explore potential reasons for such a behaviour, as I cannot reproduce it easily with my setup

alexander-vitishchenko commented 3 years ago

Hi @MomosX,

From what I see, "HC3-to-MQTT bridge shutdown sequence complete" log message is only possible to occur when Quick App gets a "turnOff" call, i.e. when somebody turns it off, or when automation does it.

I would normally suggest you check if other people misuse your Smart Home switches, and recheck all the automations that may turnOff switches accidentally... because this kind of issue is exactly what happened to me once, see illustration below ;-)

I've heard you and and you told it shouln't be your case. So, I'm about to enable extra logging for the Quick App, then we get more information on what happens with your setup and hopefully resolve it quickly. Hope to do it during weekend as I have a lot on my plate during the workweek.

Cheers, Alexander

MomosX commented 3 years ago

no worries Alex:) no rush. It might be the case as it sometimes happens in HC3 that some switch gets triggered for no reason, but so far i have only seen that in z-wave devices, not QA's.

I'm keeping an eye on it and wil let you know :) Thank you

MomosX commented 3 years ago

So it happened again:

[21.09.2021] [22:51:35] [DEBUG] [QUICKAPP1508]: HC3-to-MQTT bridge shutdown sequence complete [21.09.2021] [22:51:35] [DEBUG] [QUICKAPP1508]: Disconnected from HC3 (got flagged to stop reading HC3 events)

Pretty sure no scene turned it off and no person as i was the only one still awake:)

This started today after i updated the QA by copy/paste all the contents of the 4 files into my existing QA. I also commented out the line 492 in main file as it was filling the log: -- self:debug("Unsupported event type received \"" .. tostring(event.type) .. "\". All is good - feel free contact this QuickApp developer to get it supported")

Plus i tried to manually turn it off to see the log and there is one extra line in the log when turned off manually: [22.09.2021] [00:53:32] [DEBUG] [QUICKAPP1508]: Disconnected from MQTT [22.09.2021] [00:53:32] [DEBUG] [QUICKAPP1508]: HC3-to-MQTT bridge shutdown sequence complete

The "Disconnected from MQTT" line does not show up when it bugs out.

Also when turning it off manually, the Green button does not turn red and it shows On status. There is no way to manually turn it On again.

Cheers.

MomosX commented 3 years ago

So as an update. It is still crashing. Randomly, once or twice per day. Old version (the one that filled the log with debug messages was working). Where can i download the old version please as this one is not usable now :(

MomosX commented 3 years ago

Any chance to get some help please ?

alexander-vitishchenko commented 3 years ago

Yes, sir! :)

I'm working on a newer QuickApp version right now:

adjusting codebase where it may potentially cause symptoms that you observe
enabling extra logging, so even we are not able to fix the issue now => we have more information to find the root cause nd fix it with the next iteration

MomosX commented 3 years ago

ok ! cheers

alexander-vitishchenko commented 3 years ago

@MomosX I've just uploaded a quick workaround that may help you. Can you please test it and share results with me?

MomosX commented 3 years ago

I have changed the files and will let you know :) if it doesn't crash in 24h means it is working

MomosX commented 3 years ago

One other issue i just noticed now. From HC3 i calibrated a roller shutter. At that point the QA just crashed.

`[18.10.2021] [20:54:58] [DEBUG] [QUICKAPP1508]: Unsupported event type received "PluginChangedViewEvent". All is good - feel free contact this QuickApp developer to get it supported [18.10.2021] [20:54:59] [DEBUG] [QUICKAPP1508]: Device modified 98 [18.10.2021] [20:54:59] [DEBUG] [QUICKAPP1508]: Device removed 98 [18.10.2021] [20:55:00] [DEBUG] [QUICKAPP1508]: Device created {"configXml":false,"properties":{"categories":["blinds"],"pollingTimeSec":0,"emailNotificationID":0,"favoritePosition":50,"showEnergy":true,"localProtectionSupport":5,"smsNotificationType":0,"parametersTemplate":"249","energy":3.24,"manufacturer":"","logTemp":"TxtGreen","emailNotificationType":0,"log":"transfer OK","zwaveInfo":"3,3,52","value":98,"value2":0,"protectionTimeout":0,"userDescription":"","firmwareUpdate":{"updateVersion":"22.22","info":"","status":"UpToDate","progress":0},"useTemplate":true,"protectionExclusiveControlSupport":false,"updateVersion":"","nodeId":32,"parameters":[{"lastReportedValue":0,"lastSetValue":0,"value":0,"size":1,"id":3},{"lastReportedValue":1,"lastSetValue":1,"value":1,"size":1,"id":10},{"lastReportedValue":150,"lastSetValue":150,"value":150,"size":2,"id":12},{"lastReportedValue":1,"lastSetValue":1,"value":1,"size":1,"id":13},{"lastReportedValue":0,"lastSetValue":0,"value":0,"size":1,"id":14},{"lastReportedValue":10,"lastSetValue":10,"value":10,"size":1,"id":17},{"lastReportedValue":10,"lastSetValue":10,"value":10,"size":1,"id":18},{"lastReportedValue":240,"lastSetValue":240,"value":240,"size":2,"id":22},{"lastReportedValue":0,"lastSetValue":0,"value":0,"size":1,"id":29},{"lastReportedValue":0,"lastSetValue":0,"value":0,"size":1,"id":30},{"lastReportedValue":0,"lastSetValue":0,"value":0,"size":1,"id":31},{"lastReportedValue":0,"lastSetValue":0,"value":0,"size":1,"id":32},{"lastReportedValue":0,"lastSetValue":0,"value":0,"size":1,"id":33},{"lastReportedValue":1,"lastSetValue":1,"value":1,"size":1,"id":35},{"lastReportedValue":0,"lastSetValue":0,"value":0,"size":1,"id":40},{"lastReportedValue":0,"lastSetValue":0,"value":0,"size":2,"id":42},{"lastReportedValue":0,"lastSetValue":0,"value":0,"size":1,"id":43},{"lastReportedValue":0,"lastSetValue":0,"value":0,"size":1,"id":44},{"lastReportedValue":0,"lastSetValue":0,"value":0,"size":1,"id":50}],"pushNotificationType":0,"protectionState":0,"RFProtectionState":0,"smsNotificationID":0,"localProtectionState":0,"deviceControlType":54,"markAsDead":true,"productInfo":"1,15,3,1,16,1,22,22","serialNumber":"","endPointId":0,"protectionTimeoutSupport":false,"saveToEnergyPanel":true,"saveLogs":true,"state":"Unknown","deviceIcon":87,"pushNotificationID":0,"sceneActivation":0,"RFProtectionSupport":3,"protectionExclusiveControl":0,"zwaveVersion":"22.22","power":0.0,"zwaveCompany":"Fibargroup","dead":false,"deadReason":"","model":"","configured":true},"actions":{"retryUpdate":1,"startLevelIncrease":0,"setValue2":1,"getParameter":1,"stopLevelChange":0,"sceneActivationSet":0,"abortUpdate":1,"setParameter":2,"open":0,"updateFirmware":1,"close":0,"reconfigure":0,"startUpdate":1,"startLevelDecrease":0,"reset":0,"setValue":1,"stop":0,"setFavoritePosition":0},"visible":true,"enabled":true,"id":98,"roomID":225,"name":"RulouSudVestLiving","isPlugin":false,"baseType":"com.fibaro.FGR","type":"com.fibaro.FGRM222","sortOrder":62,"parentId":97,"modified":1634577413,"created":1634577413,"interfaces":["energy","fibaroFirmwareUpdate","levelChange","power","zwave","zwaveConfiguration","zwaveProtection","zwaveSceneActivation"],"viewXml":false,"view":[{"name":"com.fibaro.rollerShutter","translatesPath":"\/dynamic-plugins\/com.fibaro.rollerShutter\/i18n","type":"ts","jsPath":"\/dynamic-plugins\/com.fibaro.rollerShutter","assetsPath":"\/dynamic-plugins\/com.fibaro.rollerShutter\/assets"},{"name":"energy","translatesPath":"\/dynamic-plugins\/energy\/i18n","type":"ts","jsPath":"\/dynamic-plugins\/energy","assetsPath":"\/dynamic-plugins\/energy\/assets"},{"name":"level-change","translatesPath":"\/dynamic-plugins\/level-change\/i18n","type":"ts","jsPath":"\/dynamic-plugins\/level-change","assetsPath":"\/assets\/icon"},{"name":"power","translatesPath":"\/dynamic-plugins\/power\/i18n","type":"ts","jsPath":"\/dynamic-plugins\/power","assetsPath":"\/dynamic-plugins\/power\/assets"}]} [18.10.2021] [20:55:00] [ERROR] [QUICKAPP1508]: QuickApp crashed [18.10.2021] [20:55:00] [ERROR] [QUICKAPP1508]: mqtt_convention_api.lua:99: attempt to index a nil value (local 'device')

alexander-vitishchenko commented 3 years ago

I'm looking into it right now

Let me track this new issues as #12

alexander-vitishchenko commented 3 years ago

Implemented and tested the fix for #12. Feel free to verify it from your end

MomosX commented 3 years ago

So far so good. QA did not stop anymore. what was the possible issue ?

alexander-vitishchenko commented 3 years ago

I've made QA more tolerant to faulty/unexpected responses from Fibaro HC3, when QA may continue its operation.

It is a bit surprising that it helped you, because if it was the real issue then your logs would clearly indicate an error message, but it didn't. There are a few explanations why (a) you couldn't provide full logs by accident (b) the real issue is still there and it doesn't hit you for some other reason in your environment.

I'd suggest to close this issue, assuming scenario (a) is correct. You can reopen the ticket if the issue appears again and I'd be happy to get my hands on it.

Please let me know if there is anything else I can help you with!

MomosX commented 3 years ago

well its been 2 days and it didnt crash yet. The only thing that changed is that i have upgraded the HC3 to the latest FW. Let close it and i'll reopen if it comes back .

Thank you :)

alexander-vitishchenko / hc3-to-mqtt

QA just stops #10