Announcement

Collapse
No announcement yet.

Fails to install?

Collapse
X
 
  • Filter
  • Time
  • Show
Clear All
new posts

  • Michael McSharry
    replied
    With success "MQTT Thread Client Created" is in the mcsMQTT debug log. If an error is thrown then a line with "StartMQTTThread" and the actual error message will be in the HS log. If neither of the two then it is stuck in the bowels of M2MQTT.Net.dll.

    Leave a comment:


  • gizmos
    replied
    Originally posted by Michael McSharry View Post
    since "MQTT Thread Client Created" was not in your debug log
    Actually it is -

    5/19/2019 8:06:10 PM 2471 | Calling MQTTclient
    5/19/2019 8:06:10 PM 2474 | MQTT Thread Client Created
    5/19/2019 8:06:10 PM 2474 | MQTT Thread Client ID=HS3MQTT
    5/19/2019 8:06:10 PM 2475 | Calling MQTT Connect


    What happens after "Calling MQTT Connect" ?

    Leave a comment:


  • Michael McSharry
    replied
    The applicable code sequence is below. Your debug shows it gets to this point, but does not return normally from creating the client object since "MQTT Thread Client Created" was not in your debug log. The exception trap looks to send the message to the HS log with "StartMQTTThread" as part of the message. Do you see anything in the HS log?

    The client is established with M2MMqtt.Net.dll which should be in HS subfolder /bin/mcsMQTT. The one I have has a file date of May 27, 2018. The pointer to get to this file is contained in HSPI_MCSMQTT.exe.config which will be in the same folder as HS. The pointer in the file will contain <probing privatePath="bin\mcsMQTT;bin/mcsMQTT;html\bin;html/bin;bin"/>
    Code:
                           hsWriteLog(PLUGIN_DEBUG, "Calling MQTTclient")
                            Try
                                oMQTTClient = New MqttClient(gMQTTBroker,
                                gMQTTBrokerPort,
                                bSecure,
                                caCert,
                                clientCert,
                                sslProtocol,
                                New Security.RemoteCertificateValidationCallback(AddressOf ValidateBrokerCertificate))
                                'New Security.LocalCertificateSelectionCallback(AddressOf SelectClientCertificate))
                            Catch ex As Exception
                                hsWriteLog(PLUGIN_NAME, "StartMQTT Client attempt Failed to Broker" & gMQTTBroker & ex.Message & ":" & ex.InnerException.Message)
                            End Try
    
                            bSubscribed = False
                            If bFirstPass Then
                                hsWriteLog(PLUGIN_DEBUG, "MQTT Thread Client Created")
                            End If
    :
    :
    
            Catch ex As Exception
                hsWritelogEx(PLUGIN_NAME, "StartMQTTThread", ex.Message)
            End Try

    Leave a comment:


  • gizmos
    replied
    Originally posted by Michael McSharry View Post
    Take a look at the debug file that we started with to help understand.
    Sorry - there's nothing here that looks like an error to me. I've deleted some of the lines about database updates for brevity, but I can post the entire thing if it will help. You can see where it says "Thread Started with broker 172.16.1.2, ..." but that's it.

    BTW, the "garbage" chronologically out of order extra lines at the end are real. It's not an artifact of something I did (or at least I don't think so!).
    5/19/2019 8:06:07 PM 18 | mcsMQTT Version 3.6.1.3 running at /usr/local/HomeSeer, HS is at /usr/local/HomeSeer
    5/19/2019 8:06:07 PM 36 | mcsMQTT InitHW ComputerName= ziti, IOEnabled=False
    5/19/2019 8:06:08 PM 475 | mcsMQTT Debug InitHW Database Ready
    5/19/2019 8:06:08 PM 494 | PopulateReceiveDict environment/temperature/outside_1, PluginDevice=1, Ref=137
    5/19/2019 8:06:08 PM 544 | PopulateReceiveDict environment/barometer, PluginDevice=1, Ref=138
    5/19/2019 8:06:08 PM 549 | PopulateReceiveDict environment/solar, PluginDevice=1, Ref=139
    5/19/2019 8:06:08 PM 554 | mcsMQTT Debug Receive Ready
    5/19/2019 8:06:08 PM 560 | mcsMQTT Debug Trigger Ready
    5/19/2019 8:06:08 PM 750 | HW Init Complete
    5/19/2019 8:06:08 PM 754 | Background Init Started
    5/19/2019 8:06:08 PM 755 | PopulateReceiveDict , PluginDevice=0, Ref=10
    5/19/2019 8:06:08 PM 756 | PopulateReceiveDict , PluginDevice=0, Ref=100
    5/19/2019 8:06:08 PM 756 | PopulateReceiveDict , PluginDevice=0, Ref=101
    ......
    5/19/2019 8:06:08 PM 791 | PopulateReceiveDict , PluginDevice=0, Ref=98
    5/19/2019 8:06:08 PM 792 | PopulateReceiveDict , PluginDevice=0, Ref=99
    5/19/2019 8:06:08 PM 793 | PopulateReceiveDict environment/temperature/outside_1, PluginDevice=1, Ref=137
    5/19/2019 8:06:08 PM 795 | PopulateReceiveDict environment/barometer, PluginDevice=1, Ref=138
    5/19/2019 8:06:08 PM 795 | PopulateReceiveDict environment/solar, PluginDevice=1, Ref=139
    5/19/2019 8:06:08 PM 795 | Background Init Received
    5/19/2019 8:06:09 PM 1426 | AddToMQTTSend1 10, PayloadTemplate=
    5/19/2019 8:06:09 PM 1429 | AddToMQTTSend1 100, PayloadTemplate=
    5/19/2019 8:06:09 PM 1433 | AddToMQTTSend1 101, PayloadTemplate=
    ......
    5/19/2019 8:06:09 PM 1733 | AddToMQTTSend1 98, PayloadTemplate=
    5/19/2019 8:06:09 PM 1735 | AddToMQTTSend1 99, PayloadTemplate=
    5/19/2019 8:06:09 PM 1737 | Background Send
    5/19/2019 8:06:10 PM 2432 | Background Init Filters - Background Complete
    5/19/2019 8:06:10 PM 2434 | Spawning MQTT Threads
    5/19/2019 8:06:10 PM 2448 | mcsMQTT Debug MQTT Ready
    5/19/2019 8:06:10 PM 2465 | MQTT Thread Started with broker 172.16.1.2, Shutdown=False, Disconnect=False, Client=False, Connected=False
    5/19/2019 8:06:10 PM 2471 | MQTT Thread Not Connected Yet
    5/19/2019 8:06:10 PM 2471 | Calling MQTTclient
    5/19/2019 8:06:10 PM 2474 | MQTT Thread Client Created
    5/19/2019 8:06:10 PM 2474 | MQTT Thread Client ID=HS3MQTT
    5/19/2019 8:06:10 PM 2475 | Calling MQTT Connect
    5/19/2019 8:06:20 PM 12818 | Page Timing Start
    5/19/2019 8:06:20 PM 12940 | Sort > 0
    5/19/2019 8:06:21 PM 13496 | Page Timing End
    5/19/2019 8:16:18 PM 610986 | HSEvent VALUE_CHANGE| 1024| F2| 100| 0| 58
    5/19/2019 8:17:03 PM 655380 | HSEvent VALUE_CHANGE| 1024| 0184F557-014-Q26| 255| 0| 111
    5/19/2019 8:17:03 PM 655689 | HSEvent VALUE_CHANGE| 1024| 0184F557-014-Q25| 8| 0| 110
    5/19/2019 8:17:08 PM 660453 | HSEvent VALUE_CHANGE| 1024| 0184F557-009-Q12| 22| 21| 36
    ......
    5/20/2019 6:04:19 AM 35891301 | HSEvent VALUE_CHANGE| 1024| S6| 1| 2| 7
    5/20/2019 6:04:19 AM 35891348 | HSEvent VALUE_CHANGE| 1024| F15| 100| 0| 18
    5/20/2019 6:04:54 AM 35926677 | HSEvent VALUE_CHANGE| 1024| S6| 2| 1| 7
    5/20/2019 6:04:54 AM 35926729 | HSEvent VALUE_CHANGE| 1024| F15| 0| 100| 18
    39 PM 615268 | MessageRefExists SELECT count(Ref) as extant FROM MQTT_MESSAGE WHERE (Ref=119)=15/19/2019 8:05:39 PM 615291 | UpdateRecord UPDATE MQTT_MESSAGE SET Source='',Topic='',Payload='',Template='',Pattern='',Replace ='',Match='0',LastDate='2019-05-14 08:44:09',Reject=0,Express=0,Accept=0,RetainFlag=0,PluginDev ice=0,Subscribe=0,Chart=0,History=0,Ref=119,ChangeType=1,Mis c=262160,QOS=0,StatusType=0 WHERE (Ref=119), result=1, Key=Ref
    5/19/2019 8:05:39 PM 615291 | MessageRefExists SELECT count(Ref) as extant FROM MQTT_MESSAGE WHERE (Ref=12)=1
    5/19/2019 8:05:39 PM 615317 | UpdateRecord UPDATE MQTT_MESSAGE SET Source='',Topic='',Payload='',Template='',Pattern='',Replace ='',Match='0',LastDate='2019-05-14 08:44:09',Reject=0,Express=0,Accept=0,RetainFlag=0,PluginDev ice=0,Subscribe=0,Chart=0,History=0,Ref=12,ChangeType=1,Misc =262160,QOS=0,StatusType=0 WHERE (Ref=12), result=1, Key=Ref
    5/19/2019 8:05:39 PM 615318 | MessageRefExists SELECT count(Ref) as extant FROM MQTT_MESSAGE WHERE (Ref=120)=1
    5/19/2019 8:05:39 PM 615343 | UpdateRecord UPDATE MQTT_MESSAGE SET Source='',Topic='',Payload='',Template='',Pattern='',Replace ='',Match='0'

    Leave a comment:


  • Michael McSharry
    replied
    Take a look at the debug file that we started with to help understand.

    Leave a comment:


  • gizmos
    replied
    Originally posted by Michael McSharry View Post
    Be explicit on the port. My setup is attached. You may also want the explicit IP rather than the pseudo localhost.
    Sorry - I misspoke. I didn't leave the port blank; it's filled in with 1883 by default and I just left it. ANyway I took your suggestion and filled it in explicitly. I also set the IP explicitly. Here's my actual Config file -
    bob@ziti:/usr/local/HomeSeer/Config$ more mcsMQTT.ini
    [General]
    DebugLog=1
    Version=3.6.1.3
    LASTTRIGGERS=""
    MQTTBroker="172.16.1.2"
    RetainPublishHistory="1"
    RetainAcceptedSubscribeHistory="1"
    RetainSubscribeHistory="0"
    RetainCheckedHistory="1"
    MQTTCLIENTID="HS3-mcsMQTT"
    BackupDatabase="0"
    MQTTBrokerPort="1883"

    No change, I'm afraid. The status still says "Last Online @ Never". Just for fun I manually set up a couple of associations using the Edit/Add tab for topics that I know are regularly published. I can see them on the Associations tab, but the LastDate and Payload show that it's never received any of them.

    Leave a comment:


  • Michael McSharry
    replied
    Be explicit on the port. My setup is attached. You may also want the explicit IP rather than the pseudo localhost. Click image for larger version

Name:	Capture.PNG
Views:	34
Size:	28.3 KB
ID:	1306057

    Leave a comment:


  • gizmos
    replied
    Well, some progress has been made. The initial problem turns out to be the version of mono that I was using. The Linux/Ubuntu I'm using is 14.04 (because it's an older server and later kernels have some compatibility issues with some of the hardware) and the mono version was 2.10.5. Upgrading the mono version to 3.2.8 made mcsMQTT happier. The plugin now starts up and stays running, and I can access all the configuration pages. Yay!

    BUT I cannot for the life of me figure out how to get it to connect to my MQTT server. The MQTT broker is Mosquitto and is running on the same machine as HS3. I know the broker works and that data is being published because I can access it with mosquitto_sub. But in mcsMQTT Setup I go to the General page, and enter 127.0.0.1 as the "broker name or IP". I'm using the standard 1883 port so I leave that blank. The broker has no security, so select "None". It doesn't seem to connect. I don't see any published topics and the Statistics page says "Last Online @ Never".

    Frustratingly, again the HS log and the mcsMQTT Debug files don't show any errors.

    Oh, and I did remember to remove the "Disconnect=1" from my config file! And also I put back the original HSPI_MCSMQTT.exe file.

    Any suggestions?

    Thanks again,

    Leave a comment:


  • Michael McSharry
    replied
    You are correct about the disconnect has no meaning since you were never able to setup a broker connection.
    Do you have Visual Studio? If so it would be easier to debug using the source that I can provide.
    In your original post the log showed that initialization completed fine, but two seconds later a disconnect occurred. The cycle repeating means HS is trying to establish an new connection. What I did with the second test is to ignore the shutdown request from HS. This means that you will need to use top/htop or other process management means to stop the plugin. This one is at at http://mcsSprinklers.com/HSPI_MCSMQTT_Test2.zip It would be easier if we had visibility into what criteria HS uses to manage the connection. I submitted a request previously for this info but it never was received. It is also odd that this problem occurs with your system while with so many users it has not shown up elsewhere.

    Leave a comment:


  • gizmos
    replied
    Originally posted by Michael McSharry View Post

    This one starts up and doesn't die.


    Leave a comment:


  • Michael McSharry
    replied
    At http://mcsSprinklers.com/HSPI_MCSMQTT_Test1.zip is a plugin that bypasses almost all of its initialization. Replace the file in your HS folder. Let us see if the issue is associated with the startup or something else. Dont expect it to do anthing useful. It is just for testing this.

    Leave a comment:


  • gizmos
    replied
    Originally posted by Michael McSharry View Post
    In your most recent log it seems odd that the "Shutdown IO" timestamp is 5 minutes before everything else in the log, but it shows last in the log. If you deleted the .txt file before starting then there should not have been anything remaining in the file from the prior run.
    What appears to be happening is that 1) HS starts the plug-in; 2) a few seconds later, for whatever reason, HS says "CRITICAL: plug-in has disconnected"; then 3) HS says "INFO: plug in start is pending", and then the whole cycle repeats about once every minute.

    Every time mcsMQTT restarts, it seems to rewrite the mcsMQTT\ Debug.txt file. The contents are identical every time, and only the date/time stamps seem to change. I don't know how (what mode) mcsMQTT uses to write this file, but it's almost as if it's just overwriting the previous file in place - i.e. it opens the file, seeks to the start, doesn't truncate it and starts writing. I say this because every so often there'll be a line from the PREVIOUS invocation left over at the end. Seems very odd, but maybe it's supposed to be that way.

    Only one instance of HS is running - of that I'm pretty confident.

    I tried the Disconnect=1 thing in mcsMQTT.ini, but it made no apparent difference. Dumb question - you said this leaves the MQTT broker disconnectedd during startup, but I haven't done anything yet to configure ANY broker. I thought you did that thru the plugin's web interface once the plugin is running, and I can't get that far. Is there some manual configuration I'm supposed to be doing before starting the plugin?

    Thanks again!

    Leave a comment:


  • Michael McSharry
    replied
    Sorry, I forgot about this. The thread that had a similar discussion is a bit long at https://forums.homeseer.com/forum/li...ics?q=shutdown. There were three things in that thread. One was that a prior version of Mono errored when trying to handle the SortDictionary when passes as an object rather than explicitly typed. Source was changed to work around that specific problem. Other versions of Mono may have different issues. There was also discussion on QOS setting, but I think that also got resolved in source update. The third is that two instances of HS were running and calling home.

    HS has commanded the plugin to shutdown. This is the "Shutdown IO" in the debug file. The question is why does HS do this? The startup time for the plugin was 3 seconds per the debug log, This should not be considered excessive. There actually should be a message in the HS log indicating how long the startup was for the plugin. An example from mine running on a slow Windows laptop is below where it shows initialization to be about 1 second. The plugin ran for 10 minutes before being intentionally shutdown in this log sequence. Your original post showed that HS tagged mcsMQTT startup time at 1164 milliseconds which is very similar to my 966 milliseconds.
    May-12 2:15:49 PM Info Plugin mcsMQTT with instance: has disconnected
    May-12 2:04:59 PM mcsMQTT MQTTClient is Connected
    May-12 2:04:49 PM Starting Plug-In Plugin mcsMQTT started successfully in 966 milliseconds
    May-12 2:04:48 PM mcsMQTT Version 3.7.0.0 Registered with Homeseer
    May-12 2:04:48 PM Starting Plug-In Initializing plugin mcsMQTT ...
    May-12 2:04:47 PM Info Plugin mcsMQTT has connected. IP:192.168.0.17:53779
    In your most recent log it seems odd that the "Shutdown IO" timestamp is 5 minutes before everything else in the log, but it shows last in the log. If you deleted the .txt file before starting then there should not have been anything remaining in the file from the prior run.

    During the debug process in the thread referenced here one technique to isolate was to keep the MQTT broker disconnected during startup. Let us try this in your case. In /config/mcsMQTT.ini add a line "Disconnect=1" without the quotes. There are also some console messages that mcsMQTT produces that can be seen when running HS plugins in developer mode. I suspect, however, that the console will be closed down at time of plugin shutdown so you will be able to recognize what was produced.

    Leave a comment:


  • gizmos
    replied
    Any suggestions as to how to debug this problem? I'm kind of at a loss as to how to proceed - there don't appear to be any errors in the log that I can trace down. ANy ideas why the plug-in would just decide to quit?

    FWIW, I updated to the latest HS3 release, 3.0.0.531 and did a clean re-install of mcsMQTT. Same result.

    Leave a comment:


  • gizmos
    replied
    I guess the 3AM stuff at the end was left over from the first run. I tried deleting the debug .TXT file and running it again. This is what I get

    bob@ziti:/usr/local/HomeSeer/Data/mcsMQTT$ more mcsMQTT\ Debug.txt
    5/13/2019 8:26:29 AM 13 | mcsMQTT Version 3.6.1.3 running at /usr/local/HomeSeer, HS is at /usr/local/HomeSeer
    5/13/2019 8:26:29 AM 34 | mcsMQTT InitHW ComputerName= ziti, IOEnabled=False
    5/13/2019 8:26:30 AM 544 | mcsMQTT Debug InitHW Database Ready
    5/13/2019 8:26:30 AM 553 | mcsMQTT Debug Receive Ready
    5/13/2019 8:26:30 AM 559 | mcsMQTT Debug Trigger Ready
    5/13/2019 8:26:30 AM 825 | HW Init Complete
    5/13/2019 8:26:30 AM 831 | Background Init Started
    5/13/2019 8:26:30 AM 887 | Background Init Received
    5/13/2019 8:26:31 AM 1887 | Background Send
    5/13/2019 8:26:32 AM 2438 | Background Init Filters - Background Complete
    5/13/2019 8:26:32 AM 2441 | Spawning MQTT Threads
    5/13/2019 8:26:32 AM 2443 | mcsMQTT Debug MQTT Ready
    5/13/2019 8:21:49 AM 2449 | Shutdown IO

    Leave a comment:

Working...
X