mcsMQTT Triggers

[Michael McSharry]

I added trigger-specific debug in 3.2.1.0. An example is below where I edited two of my receive triggers and the debug shows each procedure call where something was potentially changing.

3/26/2018 4:47:22 PM	1011400	| ReceiveTriggerGeteTrig ID=661, Topic=GarageDoor/#  
3/26/2018 4:47:22 PM	1011433	| ReceiveTriggerTrigFromInfo ID=661, Topic=GarageDoor/#  
3/26/2018 4:47:22 PM	1011436	| ReceiveTriggerGeteTrig ID=661, Topic=GarageDoor/#  
3/26/2018 4:47:32 PM	1021886	| ReceiveTriggerTrigFromInfo ID=661, Topic=GarageDoor/#  
3/26/2018 4:47:32 PM	1021889	| ReceiveTriggerGeteTrig ID=661, Topic=GarageDoor/#  
3/26/2018 4:47:32 PM	1021955	| ReceiveTriggerTrigFromInfo ID=661, Topic=GarageDoor/#  
3/26/2018 4:47:32 PM	1021958	| ReceiveTriggerGeteTrig ID=661, Topic=GarageDoor/#  
3/26/2018 4:47:32 PM	1021961	| ReceiveTriggerBuildUI ID=661, Topic=GarageDoor/#, TrigInfoUID= 661  
3/26/2018 4:47:39 PM	1028565	| ReceiveTriggerTrigFromInfo ID=661, Topic=GarageDoor/#  
3/26/2018 4:47:39 PM	1028567	| ReceiveTriggerGeteTrig ID=661, Topic=GarageDoor/#  
3/26/2018 4:47:39 PM	1028573	| ReceiveTriggerPostUI ID=661, Topic=GarageDoor/#  
3/26/2018 4:47:39 PM	1028575	| ReceiveTriggerAddUpdate ID=661, Topic=GarageDoor/#  
3/26/2018 4:47:39 PM	1028581	| ReceiveTriggerTrigFromInfo ID=661, Topic=GarageDoor/#  
3/26/2018 4:47:39 PM	1028584	| ReceiveTriggerGeteTrig ID=661, Topic=GarageDoor/#  
3/26/2018 4:47:39 PM	1028631	| ReceiveTriggerTrigFromInfo ID=661, Topic=GarageDoor/#  
3/26/2018 4:47:39 PM	1028633	| ReceiveTriggerGeteTrig ID=661, Topic=GarageDoor/#  
3/26/2018 4:47:39 PM	1028634	| ReceiveTriggerBuildUI ID=661, Topic=GarageDoor/#, TrigInfoUID= 661  
3/26/2018 4:47:41 PM	1030786	| ReceiveTriggerTrigFromInfo ID=661, Topic=GarageDoor/#  
3/26/2018 4:47:41 PM	1030789	| ReceiveTriggerGeteTrig ID=661, Topic=GarageDoor/#  
3/26/2018 4:47:41 PM	1030804	| ReceiveTriggerTrigFromInfo ID=661, Topic=GarageDoor/#  
3/26/2018 4:47:41 PM	1030806	| ReceiveTriggerGeteTrig ID=661, Topic=GarageDoor/#  
3/26/2018 4:47:47 PM	1036191	| ReceiveTriggerTrigFromInfo ID=4570, Topic=Sonoff120/cmnd/+  
3/26/2018 4:47:47 PM	1036194	| ReceiveTriggerGeteTrig ID=4570, Topic=Sonoff120/cmnd/+  
3/26/2018 4:47:47 PM	1036209	| ReceiveTriggerTrigFromInfo ID=4570, Topic=Sonoff120/cmnd/+

The Debug flag on the General tab will enable it. Others have been having difficulty in getting the prior version 3.2.0.0 operational with their prior setup. As a safety measure you should backup as a minimum \data\mcsMQTT.db, or more globally the HS folder.

3.2.1.0 is in the updater.

[Guest]

Mar-26 22:58:09 Info Plugin mcsMQTT with instance: has disconnected
Mar-26 22:58:09 Error Initializing plug-in(1): mcsMQTT Instance::InitHW An item with the same key has already been added. Time to load: 112 milliseconds
Mar-26 22:58:09 mcsMQTT InitHW Line 0 An item with the same key has already been added.
Mar-26 22:58:09 mcsMQTT Version 3.2.1.0 Registered with Homeseer
Mar-26 22:58:09 mcsMQTT Add_Update_Trigger An item with the same key has already been added. Line 0 An item with the same key has already been added.



i tried to reinstall, restart computer etc. Nothing works.

[Michael McSharry]

Yours is pseudo good news as the error reflects on the same type of error for which debug was added. I protected the debug collection and updated to V3.2.1.1 that is now in the updater. You should have better success on startup and the info should help understand the trigger duplications.

[Guest]

thank you

[drodegeb]

I'm running the 3.2.1.1 and have the same problem with it disconnecting and reconnecting continuously.

Mar-26 10:54:40 PM Info Plugin mcsMQTT with instance: has disconnected
Mar-26 10:54:31 PM Plug-In Finished initializing plug-in mcsMQTT
Mar-26 10:54:31 PM mcsMQTT MQTT Broker Connection Accepted
Mar-26 10:54:31 PM mcsMQTT Version 3.2.1.1 Registered with Homeseer
Mar-26 10:54:31 PM Info Plugin mcsMQTT has connected. IP:127.0.0.1:52514

[Michael McSharry]

Do you have debug enabled and is there anything in it?

[drodegeb]

I don't think it's enabled. It doesn't stay up long enough to use the gui to check it, but the config looks like it's disabled.

[General]
DebugLog=0

And all that is in the log file is:
3/26/2018 11:08:20 PM 0 | mcsMQTT Running at C:\Program Files (x86)\HomeSeer HS3

[Michael McSharry]

It would also be interesting to know what HS uses to indicate that a program has disconnected. There is Console output in the main program related to the socket connection with HS. If you enable developer mode from Plugin/Interface tab of HS then you will get a window with the console output.

[drodegeb]

Here you go.

Plugin: mcsMQTT Instance: Connecting to server at 127.0.0.1

Unhandled Exception: System.NullReferenceException: Object reference not set to an instance of an object.
at uPLibrary.Networking.M2Mqtt.Messages.MqttMsgSubscribe.GetByt es(Byte protocolVersion)
at uPLibrary.Networking.M2Mqtt.MqttClient.Send(MqttMsgBase msg)
at uPLibrary.Networking.M2Mqtt.MqttClient.ProcessInflightThread ()
at System.Threading.ThreadHelper.ThreadStart_Context(Object state)
at System.Threading.ExecutionContext.RunInternal(ExecutionConte xt executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
at System.Threading.ThreadHelper.ThreadStart()

[Michael McSharry]

This is coming from the dll I use to manage the socket for MQTT traffic. I put error traps around every call I make to it in 3.2.1.2. I also have more debug going to the file related to connection and startup.

The debug I was asking about is the file \data\mcsMQTT_Debug.txt. It helps to have Debug set from General Tab of mcsMQTT setup.

Another change was made in the updater package with this one. It now puts the three supporting dlls in \bin\mcsMQTT rather than \bin. It should make no difference to you, but just letting you know of the change.

[drodegeb]

ok, updated to the latest. It looks like it was already dumping to the debug log with this version. It doesn't stay up long enough to use the gui to enable the debug so I edited the ini file.

The console window isn't hanging around long enough for me to copy the contents on the screen.

Here's what is in the debug log:
3/27/2018 12:04:51 AM 0 | mcsMQTT Running at C:\Program Files (x86)\HomeSeer HS3
3/27/2018 12:04:51 AM 11 | mcsMQTT InitHW ComputerName= DRPC, IOEnabled=False
3/27/2018 12:04:51 AM 87 | mcsMQTT InitHW Database Ready
3/27/2018 12:04:51 AM 89 | mcsMQTT Receive Ready
3/27/2018 12:04:51 AM 90 | mcsMQTT Trigger Ready
3/27/2018 12:04:51 AM 115 | Spawning MQTT Thread
3/27/2018 12:04:51 AM 116 | mcsMQTT MQTT Ready
3/27/2018 12:04:51 AM 116 | HW Init Complete
3/27/2018 12:04:52 AM 117 | Background Init Started
3/27/2018 12:04:52 AM 117 | MQTT Thread Started with broker 192.168.1.95, Shutdown=False, Disconnect=False, Client=False
3/27/2018 12:04:52 AM 117 | Background Init Received
3/27/2018 12:04:52 AM 220 | MQTT Thread Subscribing
3/27/2018 12:04:52 AM 222 | MQTT Subscription Start
3/27/2018 12:04:52 AM 222 | MQTT Subscription Topics being selected
3/27/2018 12:04:52 AM 222 | MQTT Subscription Topics selected
3/27/2018 12:04:52 AM 223 | MQTTSubscribe List / NoDiscovery=True to
3/27/2018 12:04:52 AM 223 |
3/27/2018 12:04:52 AM 225 | Background Send

[Michael McSharry]

In this instance there is only one more step that did not show up in the file and it could be just because it was in the cache and never was written to the disk.

Background Init Complete

Between Background "Send" and "Complete" is the construction of the filters used on the Association tab. Nothing unusual about this area that I would expect issue. The background processing is also not on the main thread that is used to interact with HS so it is unlikely that this background thread is what is causing a problem.

I also noticed that you have no subscriptions. This could be because the .ini file has NoDiscovery set to 1 and not explicit subscriptions setup.

Is this repeatable with the same info in the debug file?

Another debug technique is to remove large sections of the plugin and then incrementally add. If you or others are willing I can support that approach too.

[Michael McSharry]

The following ini settings will bypass much of the mcsMQTT processing to provide a minimum to try to get it running. They can be edited before staring

Disconnect=1
NoEnumeration=1
CreateStatusDevices=0
ShowMQTTSourced=0
ShowHomeserSourced=0
ShowRejected=0
rename \Data\mcsMQTT.db to something else

There will be no connection to the MQTT broker so traffic will not exist, but should be able to bring up the browser page and select between the tabs. The Manual page will accept inputs, but only these should then be visible on the Association page. The general page should reflect the above settings.

The purpose is only to try to reduce the amount of code that is executing to help isolate the source of the disconnect problem.

I made some minor debug updates so the latest is now 3.2.1.3

[drodegeb]

Thank you. I'll give that new version and the settings a try out tonight.

[Michael McSharry]

mwolter did some excellent diagnostics reported in another thread on this forum and it seems the issue is the initial flood of messages from the broker when mcsMQTT connects. I am going to implement some flow management so best to wait until it is ready.