Announcement

Collapse
No announcement yet.

Fails to install?

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

    Fails to install?

    I'm using HS3 standard, 3.0.0.435, ON LINUX and I wanted to try out the mcsMQTT plugin. I just went to the plug in manager in HS3, selected mcsMQTT, and installed it from there. When I enable the plug in, HS says "plug in start pending" and then after a few seconds "plug in has disconnected". The HS log is not very informative -
    May-13 07:30:05 Info Plugin mcsMQTT with instance: has disconnected
    May-13 07:30:03 Starting Plug-In Plugin mcsMQTT started successfully in 1164 milliseconds
    May-13 07:30:02 Z-Wave Device: Z-Wave Living Temperature Set to 70.88 (F)
    May-13 07:30:02 mcsMQTT Version 3.6.1.3 Registered with Homeseer
    May-13 07:30:02 Starting Plug-In Initializing plugin mcsMQTT ...
    May-13 07:30:02 Info Plugin mcsMQTT has connected. IP:127.0.0.1:33034
    I read the mcsMQTT manual, but its only installation instructions are to download a ZIP and manually install all the files. Is this necessary? Is it not possible to install from the plug in manager? Or what am I doing wrong?

    THanks!

    #2
    You can install from the Updater as you did. Look in HS subfolder /data/mcsMQTT for a .txt file. It should have some startup info that you can post.

    Comment


      #3
      Thanks, Michael. Here you go, but I don't see anything in here that looks like an error -


      bob@ziti:/usr/local/HomeSeer/Data/mcsMQTT$ more mcsMQTT\ Debug.txt
      5/13/2019 7:47:18 AM 14 | mcsMQTT Version 3.6.1.3 running at /usr/local/HomeSeer, HS is at /usr/local/HomeSeer
      5/13/2019 7:47:18 AM 36 | mcsMQTT InitHW ComputerName= ziti, IOEnabled=False
      5/13/2019 7:47:18 AM 531 | mcsMQTT Debug InitHW Database Ready
      5/13/2019 7:47:18 AM 539 | mcsMQTT Debug Receive Ready
      5/13/2019 7:47:18 AM 546 | mcsMQTT Debug Trigger Ready
      5/13/2019 7:47:18 AM 822 | HW Init Complete
      5/13/2019 7:47:18 AM 828 | Background Init Started
      5/13/2019 7:47:19 AM 881 | Background Init Received
      5/13/2019 7:47:20 AM 1876 | Background Send
      5/13/2019 7:47:20 AM 2446 | Background Init Filters - Background Complete
      5/13/2019 7:47:20 AM 2448 | Spawning MQTT Threads
      5/13/2019 7:47:20 AM 2455 | mcsMQTT Debug MQTT Ready
      3/2019 3:00:19 AM 230 | MakeTable CREATE TABLE MQTT_VGP ( Source VARCHAR (255) NULL , Item VARCHAR (255) NULL , Value INT NULL )

      5/13/2019 3:00:19 AM 254 | MakeTable CREATE TABLE tblTransform ( Source VARCHAR (255) NULL , RateDevice INT NULL , RateSensitivity
      VARCHAR (255) NULL , RateInterval INT NULL , AccumDevice INT NULL , AccumReset INT NULL , AccumMidnight VARCHAR (255) NULL , Expression
      VARCHAR (255) NULL , FilterSensitivity VARCHAR (255) NULL )
      5/13/2019 3:00:19 AM 280 | MakeTable CREATE TABLE MQTT_HISTORY ( Sequence INT NULL , Publish INT NULL , LastDate TEXT NULL , Topic
      VARCHAR (255) NULL , Payload VARCHAR (255) NULL )
      5/13/2019 3:00:19 AM 308 | MakeTable CREATE TABLE tblRef ( LastDate TEXT NULL , Ref INT NULL , Value VARCHAR (255) NULL )
      5/13/2019 3:00:19 AM 343 | mcsMQTT Debug InitHW Database Ready
      5/13/2019 3:00:19 AM 353 | mcsMQTT Debug Receive Ready
      5/13/2019 3:00:19 AM 359 | mcsMQTT Debug Trigger Ready
      5/13/2019 3:00:19 AM 662 | HW Init Complete
      5/13/2019 3:00:19 AM 669 | Background Init Started
      5/13/2019 3:00:19 AM 670 | Background Init Received
      5/13/2019 3:00:23 AM 4201 | Background Send
      5/13/2019 3:00:23 AM 4777 | Background Init Filters - Background Complete
      5/13/2019 3:00:23 AM 4780 | Spawning MQTT Threads
      5/13/2019 3:00:23 AM 4790 | mcsMQTT Debug MQTT Ready
      5/13/2019 3:00:23 AM 4815 | Shutdown IO


      Comment


        #4
        P.S. Hmm - right after the "5/13/2019 7:47:20 AM 2455 | mcsMQTT Debug MQTT Ready" line about halfway thru, the time seems to glitch. What's up with that? That's not a mistake in my copy and paste - that's the way the file appears. Don't know if it means anything..

        Comment


          #5
          The same file space is used for each start so the tail of the file is from a prior start. Nothing unusual. It also looks like a clean startup sequence.

          HS did provide the Shutdown IO command to tell the plugin to exit at an earlier 3 AM run. I think it is part of the HS management of a plugin that it does not think is responding. I saw something like this in the early days of mcsMQTT but don't remember the resolution. Will need to review the early threads on this forum.

          Comment


            #6
            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

            Comment


              #7
              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.

              Comment


                #8
                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.

                Comment


                  #9
                  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!

                  Comment


                    #10
                    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.

                    Comment


                      #11
                      Originally posted by Michael McSharry View Post

                      This one starts up and doesn't die.


                      Comment


                        #12
                        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.

                        Comment


                          #13
                          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,

                          Comment


                            #14
                            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:	117
Size:	28.3 KB
ID:	1306057

                            Comment


                              #15
                              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.

                              Comment

                              Working...
                              X