Announcement

Collapse
No announcement yet.

SSL Support for mcsMQTT

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

  • #46

    Comment


    • #47
      Debug was enabled, and the logs are posted above. Nothing was being written while CPU use was high.

      If i do a trace on the process I see this:
      Code:
      clock_gettime(CLOCK_MONOTONIC, {tv_sec=92741, tv_nsec=274027787}) = 0
      clock_gettime(CLOCK_MONOTONIC, {tv_sec=92741, tv_nsec=274181874}) = 0
      clock_gettime(CLOCK_MONOTONIC, {tv_sec=92741, tv_nsec=274320752}) = 0
      clock_gettime(CLOCK_MONOTONIC, {tv_sec=92741, tv_nsec=274458589}) = 0
      futex(0x73f918, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=9862163}) = -1 ETIMEDOUT (Connection timed out)
      clock_gettime(CLOCK_MONOTONIC, {tv_sec=92741, tv_nsec=284757537}) = 0
      futex(0x73f8d4, FUTEX_WAKE_PRIVATE, 1)  = 0
      And that's all. I'd assume there's a bug in the time code causing high cpu utilization?

      As for SSL. I do not have a 'background' persay, just an avid System Administrator. I'll look around the forum, I did not realize the source was available, maybe that will give some clues.

      Comment


      • #48
        For SSL, vasrc looks to have a solution using callback approach to authentication of the certificate. He is now trying to integrate it into the mcsMQTT source.

        Can you provide some insight into the environment you are running mcsMQTT? Based upon your debug it looks like you have nothing selected for publication so no callbacks for device changes from HS and you indicated no connection the broker was setup.

        The main is in a 10 ms loop monitoring the HS connection. This is boilerplate from the HS3 SDK.

        There is a MQTT thread that wakes up on 10 second intervals to assess the broker connection. This does update the Statistics tab so you can see if it is being refreshed with at least elapsed time.

        There are many synchronization wait loops. In each case the reason for waiting is written to the debug log. Since you have none of these in the log we should be able to rule them out.

        There is a thread that wakes up on HS event callbacks. Since you have no callbacks in the log we can rule out this thread.

        There is a thread to run GNUPlot on Linux on chart requests. Since no data exists for charting and I doubt if you tried to generate a chart this one can be ruled out too.

        There is MQTT callback thread from broker message received. No broker connection and nothing in the log so this is not a candidate.

        There is Browser ajax postback at 2 second intervals. In some versions I have this in the debug. I can add it back on the next iteration.

        Give me a little background on your setup and I will put together some debug in the candidate loops. The Statistics tab updating will mean that the ajax postbacks are being processed.

        Comment


        • #49
          Originally posted by Michael McSharry View Post
          Can you provide some insight into the environment you are running mcsMQTT? Based upon your debug it looks like you have nothing selected for publication so no callbacks for device changes from HS and you indicated no connection the broker was setup.

          Give me a little background on your setup and I will put together some debug in the candidate loops. The Statistics tab updating will mean that the ajax postbacks are being processed.
          This seems to be the wrong thread for this, if you'd like this somewhere else, please say so.

          Both of the environments I've installed mcsMQTT in experienced this after installation.

          Currently: Ubuntu 18.04, Mono 5.12, the broker is on the same device (localhost), Broker using TLS 1.2.
          Prevously: Debian 8.10, Mono 5.12, the broker is on the same device (localhost), no TLS.

          Currently: I have nothing selected for publish and the plugin is minimally configured, it has been uninstalled and reinstalled to test. The connection to the broker is configured, but it cannot be reached because the broker is behind TLS1.2 and mcsMQTT cannot talk to it.

          Previously: The plugin ran for a week before over port 1833 with several associations from the broker from other devices. After installation the device started rebooting frequently prompting the move (high CPU load seemed to be the cause). Nothing from HS3 was being published or controlled at that point.

          I've just installed plugin v3.4.0.0, CPU spiked and the trace seems to show the same, although I'm not sure it's really useful:

          Code:
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=341022}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=341243}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=341375}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=341495}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=341648}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=341838}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=341993}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=342145}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=342269}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=342420}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=342578}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=342884}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=343142}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=343260}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=343418}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=343636}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=343755}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=343908}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=344064}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=344189}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=344345}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=344500}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=344659}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=344855}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=344999}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=345220}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=345376}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=345593}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=345735}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=345874}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=346009}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=346166}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=346339}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=346546}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=346790}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=347172}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=347506}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=347882}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=348094}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=348259}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=348477}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=348688}, NULL) = 0
          [pid  3897] <... futex resumed> )       = -1 ETIMEDOUT (Connection timed out)
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=348811}, NULL) = 0
          [pid  3897] clock_gettime(CLOCK_MONOTONIC,  <unfinished ...>
          [pid  3913] gettimeofday( <unfinished ...>
          [pid  3897] <... clock_gettime resumed> {tv_sec=101372, tv_nsec=971166930}) = 0
          [pid  3913] <... gettimeofday resumed> {tv_sec=1526792189, tv_usec=348946}, NULL) = 0
          [pid  3897] futex(0x7718d4, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
          [pid  3913] gettimeofday( <unfinished ...>
          [pid  3897] <... futex resumed> )       = 0
          [pid  3913] <... gettimeofday resumed> {tv_sec=1526792189, tv_usec=349140}, NULL) = 0
          [pid  3897] clock_gettime(CLOCK_MONOTONIC,  <unfinished ...>
          [pid  3913] gettimeofday( <unfinished ...>
          [pid  3897] <... clock_gettime resumed> {tv_sec=101372, tv_nsec=971631108}) = 0
          [pid  3913] <... gettimeofday resumed> {tv_sec=1526792189, tv_usec=349396}, NULL) = 0
          [pid  3897] clock_gettime(CLOCK_MONOTONIC,  <unfinished ...>
          [pid  3913] gettimeofday( <unfinished ...>
          [pid  3897] <... clock_gettime resumed> {tv_sec=101372, tv_nsec=971811779}) = 0
          [pid  3913] <... gettimeofday resumed> {tv_sec=1526792189, tv_usec=349575}, NULL) = 0
          [pid  3897] clock_gettime(CLOCK_MONOTONIC,  <unfinished ...>
          [pid  3913] gettimeofday( <unfinished ...>
          [pid  3897] <... clock_gettime resumed> {tv_sec=101372, tv_nsec=972004534}) = 0
          [pid  3913] <... gettimeofday resumed> {tv_sec=1526792189, tv_usec=349780}, NULL) = 0
          [pid  3897] clock_gettime(CLOCK_MONOTONIC,  <unfinished ...>
          [pid  3913] gettimeofday( <unfinished ...>
          [pid  3897] <... clock_gettime resumed> {tv_sec=101372, tv_nsec=972194455}) = 0
          [pid  3913] <... gettimeofday resumed> {tv_sec=1526792189, tv_usec=350035}, NULL) = 0
          [pid  3897] futex(0x771918, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=9810079} <unfinished ...>
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=350242}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=350402}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=350556}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=350752}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=350989}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=351121}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=351237}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=351385}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=351519}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=351657}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=351783}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=351941}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=352056}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=352327}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=352585}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=352820}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=353186}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=353648}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=353774}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=353922}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=354076}, NULL) = 0
          [pid  3913] gettimeofday({tv_sec=1526792189, tv_usec=354233}, NULL) = 0
          With "Disconnect from broker" checked, I tried to start the plugin like so: " mono --trace HSPI_MCSMQTT.exe" and this is what it was doing over and over (however, this may not be a valid way to start a plugin by hand, so this trace may be useless too):
          Code:
          [0xb6f35010: 50.06988 4] ENTER: HSCF.Communication.ScsServices.Client.ScsServiceClient`1<T_REF>:get_CommunicationState ()() ip: (nil)
          [0xb6f35010: 50.06990 5] ENTER: HSCF.Communication.Scs.Client.ScsClientBase:get_CommunicationState ()() ip: (nil)
          [0xb6f35010: 50.06991 6] ENTER: HSCF.Communication.Scs.Communication.Channels.CommunicationChannelBase:get_CommunicationState ()() ip: (nil)
          [0xb6f35010: 50.06992 6] LEAVE: HSCF.Communication.Scs.Communication.Channels.CommunicationChannelBase:get_CommunicationState ()result=0
          [0xb6f35010: 50.06995 5] LEAVE: HSCF.Communication.Scs.Client.ScsClientBase:get_CommunicationState ()result=0
          [0xb6f35010: 50.06997 4] LEAVE: HSCF.Communication.ScsServices.Client.ScsServiceClient`1<T_REF>:get_CommunicationState ()result=0
          [0xb6f35010: 50.07001 4] ENTER: (wrapper managed-to-native) System.Threading.Thread:SleepInternal (int)() ip: (nil)
          [0xb6f35010: 50.08011 4] LEAVE: (wrapper managed-to-native) System.Threading.Thread:SleepInternal (int)
          [0xb6f35010: 50.08016 4] ENTER: HSCF.Communication.ScsServices.Client.ScsServiceClient`1<T_REF>:get_CommunicationState ()() ip: (nil)
          [0xb6f35010: 50.08018 5] ENTER: HSCF.Communication.Scs.Client.ScsClientBase:get_CommunicationState ()() ip: (nil)
          [0xb6f35010: 50.08019 6] ENTER: HSCF.Communication.Scs.Communication.Channels.CommunicationChannelBase:get_CommunicationState ()() ip: (nil)
          [0xb6f35010: 50.08020 6] LEAVE: HSCF.Communication.Scs.Communication.Channels.CommunicationChannelBase:get_CommunicationState ()result=0
          [0xb6f35010: 50.08025 5] LEAVE: HSCF.Communication.Scs.Client.ScsClientBase:get_CommunicationState ()result=0
          [0xb6f35010: 50.08028 4] LEAVE: HSCF.Communication.ScsServices.Client.ScsServiceClient`1<T_REF>:get_CommunicationState ()result=0
          [0xb6f35010: 50.08030 4] ENTER: (wrapper managed-to-native) System.Threading.Thread:SleepInternal (int)() ip: (nil)
          [0xb6f35010: 50.09041 4] LEAVE: (wrapper managed-to-native) System.Threading.Thread:SleepInternal (int)
          [0xb6f35010: 50.09046 4] ENTER: HSCF.Communication.ScsServices.Client.ScsServiceClient`1<T_REF>:get_CommunicationState ()() ip: (nil)
          [0xb6f35010: 50.09047 5] ENTER: HSCF.Communication.Scs.Client.ScsClientBase:get_CommunicationState ()() ip: (nil)
          [0xb6f35010: 50.09048 6] ENTER: HSCF.Communication.Scs.Communication.Channels.CommunicationChannelBase:get_CommunicationState ()() ip: (nil)
          [0xb6f35010: 50.09050 6] LEAVE: HSCF.Communication.Scs.Communication.Channels.CommunicationChannelBase:get_CommunicationState ()result=0
          [0xb6f35010: 50.09053 5] LEAVE: HSCF.Communication.Scs.Client.ScsClientBase:get_CommunicationState ()result=0
          [0xb6f35010: 50.09055 4] LEAVE: HSCF.Communication.ScsServices.Client.ScsServiceClient`1<T_REF>:get_CommunicationState ()result=0
          [0xb6f35010: 50.09058 4] ENTER: (wrapper managed-to-native) System.Threading.Thread:SleepInternal (int)() ip: (nil)
          [0xb6f35010: 50.10068 4] LEAVE: (wrapper managed-to-native) System.Threading.Thread:SleepInternal (int)
          [0xb6f35010: 50.10073 4] ENTER: HSCF.Communication.ScsServices.Client.ScsServiceClient`1<T_REF>:get_CommunicationState ()() ip: (nil)
          [0xb6f35010: 50.10074 5] ENTER: HSCF.Communication.Scs.Client.ScsClientBase:get_CommunicationState ()() ip: (nil)
          [0xb6f35010: 50.10076 6] ENTER: HSCF.Communication.Scs.Communication.Channels.CommunicationChannelBase:get_CommunicationState ()() ip: (nil)
          [0xb6f35010: 50.10076 6] LEAVE: HSCF.Communication.Scs.Communication.Channels.CommunicationChannelBase:get_CommunicationState ()result=0
          [0xb6f35010: 50.10078 5] LEAVE: HSCF.Communication.Scs.Client.ScsClientBase:get_CommunicationState ()result=0
          [0xb6f35010: 50.10081 4] LEAVE: HSCF.Communication.ScsServices.Client.ScsServiceClient`1<T_REF>:get_CommunicationState ()result=0
          [0xb6f35010: 50.10083 4] ENTER: (wrapper managed-to-native) System.Threading.Thread:SleepInternal (int)() ip: (nil)
          [0xb6f35010: 50.11093 4] LEAVE: (wrapper managed-to-native) System.Threading.Thread:SleepInternal (int)
          [0xb6f35010: 50.11098 4] ENTER: HSCF.Communication.ScsServices.Client.ScsServiceClient`1<T_REF>:get_CommunicationState ()() ip: (nil)
          [0xb6f35010: 50.11099 5] ENTER: HSCF.Communication.Scs.Client.ScsClientBase:get_CommunicationState ()() ip: (nil)
          [0xb6f35010: 50.11100 6] ENTER: HSCF.Communication.Scs.Communication.Channels.CommunicationChannelBase:get_CommunicationState ()() ip: (nil)
          [0xb6f35010: 50.11100 6] LEAVE: HSCF.Communication.Scs.Communication.Channels.CommunicationChannelBase:get_CommunicationState ()result=0
          [0xb6f35010: 50.11103 5] LEAVE: HSCF.Communication.Scs.Client.ScsClientBase:get_CommunicationState ()result=0
          Last edited by Jeeves; May 20th, 2018, 12:22 AM.

          Comment


          • #50
            I moved the thread to https://forums.homeseer.com/showthre...53#post1366753

            The mono trace shows the main thread that is simply maintaining a socket connection with HS.

            The OS level debug does not give me much insight as there are multple layers between the application and the OS. The mcsMQTT_Debug.txt is most helpful for me as we progress in the investigation.

            Comment


            • #51
              Originally posted by Michael McSharry View Post
              For SSL, vasrc looks to have a solution using callback approach to authentication of the certificate. He is now trying to integrate it into the mcsMQTT source.
              CPU debugging issue aside, if I can help with testing this once it's to a point, I'd be happy to.

              Comment


              • #52
                @Michael and Vasrc,

                Should I be posting testing results here for current modified SSL build?
                - Pete

                Auto mator
                Homeseer 3 Pro - 3.0.0.534 (Linux) - Ubuntu 18.04/W7e 64 bit Intel CPU - Mono 5.20
                Homeseer Zee2 (Lite) - 3.0.0.534 (Linux) - Ubuntu 18.04/W7e BeeLink 4Gb BT3 Pro - Mono 5.20

                X10, UPB, Zigbee, ZWave and Wifi MQTT automation.

                Comment


                • #53
                  Just email me with what you find
                  You should download the latest version from Dropbox first there have been several updates

                  Comment


                  • #54
                    Thank you and will do.
                    - Pete

                    Auto mator
                    Homeseer 3 Pro - 3.0.0.534 (Linux) - Ubuntu 18.04/W7e 64 bit Intel CPU - Mono 5.20
                    Homeseer Zee2 (Lite) - 3.0.0.534 (Linux) - Ubuntu 18.04/W7e BeeLink 4Gb BT3 Pro - Mono 5.20

                    X10, UPB, Zigbee, ZWave and Wifi MQTT automation.

                    Comment

                    Working...
                    X