Announcement

Collapse
No announcement yet.

Failed to get a response from the ISY

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

    Failed to get a response from the ISY

    Bob,

    Again, thanks for your help before.

    Just wondering is there a limit to the number of events that your plugin can handle in any given moment? The reason I ask, is that I'm getting the follow error:

    Code:
    Apr-25 3:27:03 PM	 	ISYInsteon	ProcessCommand : Attempt to send DON to Family Room/Lighting/Family Room Table Light failed. Likely cause is invalid command.
    Apr-25 3:27:03 PM	 	ISYInsteon	SendRequest : -> Using Authorization [Basic XXXXXXXXXXXXXXXXX]
    Apr-25 3:27:03 PM	 	ISYInsteon	SendRequest : -> For command: [DON2553D DF 80 10 ]
    Apr-25 3:27:03 PM	 	ISYInsteon	SendRequest : Failed to get response from ISY (The remote server returned an error: (501) Not Implemented.).
    Apr-25 3:26:58 PM	 	Device Control	Device: Unknown Unknown Downstairs Watch TV to Off (0)
    Apr-25 3:26:58 PM	 	Device Control	Device: Lighting Entry Hall Entry Hall Lights to Off (0)
    Apr-25 3:26:58 PM	 	Device Control	Device: Lighting Foyer Foyer Light to Off (0)
    Apr-25 3:26:58 PM	 	Device Control	Device: Lighting Dining Room Dining Room Light to Off (0)
    Apr-25 3:26:58 PM	 	Device Control	Device: Lighting Family Room Family Room Table Light to On (100)
    Apr-25 3:26:58 PM	 	Device Control	Device: Lighting Kitchen Kitchen Lights to Dim 50% (50)
    Apr-25 3:26:58 PM	 	Device Control	Device: Lighting Kitchen Pantry Light to Off (0)
    Apr-25 3:26:58 PM	 	Device Control	Device: Lighting Kitchen Butlers Pantry to Off (0)
    Apr-25 3:26:58 PM	 	Device Control	Device: Lighting Kitchen Kitchen Island Lights to Off (0)
    Apr-25 3:26:58 PM	 	Device Control	Device: Lighting Kitchen Kitchen Nook Lights to Off (0)
    Apr-25 3:26:58 PM	 	Device Control	Device: Lighting Stairs Stair Lights to Off (0)
    Apr-25 3:26:58 PM	 	Event	Event Trigger "Family Room Downstairs Watch TV"
    Apr-25 3:26:58 PM	 	Event	Event Family Room Downstairs Watch TV triggered by the event page 'Run' button.
    when I attempt to update multiple devices at once thru an event, or using the SceneMaster plugin. In the case of the above error, I'm updating 10 devices thru an HS3 event.

    I noticed this error before when I was creating some VB code, but was able to somewhat prevent it with 200ms sleep calls.

    I know I can do the same thing directly from the ISY, but for simplicity I would like to do it in HS as I will have Insteon and non-Intseon devices participate in the scene. I don't want to have to configure the scene in two distinct places. Plus there are some other advantages of using SceneMaster.

    Thanks

    Richard

    #2
    Hi Richard,

    There's no defined limit in the plug-in, but it does add commands to a queue and sets up events to wait for the response, thus I'm sure there is some type of limit when the system runs out of memory, but that should be well over 10 commands.

    A 501 error from the ISY usually means that something was sent that the ISY doesn't understand. On commands are pretty basic so it doesn't seem like that would be the issue.

    Is it always the same device that has the error? Or does every device after that also fail?

    I assume you're able to control the device that failed if you just try to control that one device. Anything special about that device?
    --
    Bob Paauwe
    ISYInsteon Plug-in
    http://www.bobsplace.com/ISYInsteon/

    Comment


      #3
      Bob,

      Nothing special about any of the devices, just standard 2477D, 2477S, KPL and even an outletlinc. And yes, individually I can control them without an issues.

      In regards to your other questions, it seems like the same device fails, and then every subsequent device fails afterward. But I believe changing up the order of the devices in the HS event, will change up which device begins the failure chain. I'll need to figure out at what specific point it fails, i.e. is it device specific or does it fail at some quantity of devices. I do believe the later is the case.

      Will report back.

      Richard

      Comment


        #4
        Bob,

        Here is what I've figured out so far, but before I do, let me give you a bit of background on my configuration. I make use of a lot of programs that sync devices states. It started as a way to sync a KPL button with the status of a room, and now it has expanded so I can use Alexa and Imperihome to dim lights properly since you can use scene to perform that function. The programs keep the load device synced with 'linked' devices & buttons. The programs are designed to minimize insteon traffic and overall they work just fine.

        Way below is an example of these syncing programs (this one syncs an outletlinc with a kpl button). What I've done is disabled all these programs for the lights that I'm manipulating...but enabled these two below. By just enabling them, I get the a similar error to the one below, disable them again, error disappears:

        Code:
        Apr-25 9:10:18 PM	 	ISYInsteon	ProcessCommand : Attempt to send DOF to Upstairs Hall/Lighting/Left Hall Lights failed. Likely cause is invalid command.
        Apr-25 9:10:18 PM	 	ISYInsteon	SendRequest : -> Using Authorization [Basic XXXXXXXXXXXXXXXXXXXXXXXXXXXXXX]
        Apr-25 9:10:18 PM	 	ISYInsteon	SendRequest : -> For command: [DOF038 91 F 10 ]
        Apr-25 9:10:18 PM	 	ISYInsteon	SendRequest : Failed to get response from ISY (The remote server returned an error: (501) Not Implemented.).
        Apr-25 9:10:08 PM	 	Event	Event Trigger "Family Room Family Room Lights - Insteon Switch - Off"
        Apr-25 9:10:06 PM	 	Device Control	Device: Lighting Upstairs Hall Right Hall Lights to Off (0)
        Apr-25 9:10:06 PM	 	Device Control	Device: Lighting Upstairs Hall Left Hall Lights to Off (0)
        Apr-25 9:10:06 PM	 	Device Control	Device: Lighting Stairs Stair Lights to Off (0)
        Apr-25 9:10:06 PM	 	Device Control	Device: Lighting Powder Room Powder Room Entry Light to Off (0)
        Apr-25 9:10:06 PM	 	Device Control	Device: Lighting Kitchen Pantry Light to Off (0)
        Apr-25 9:10:06 PM	 	Device Control	Device: Lighting Kitchen Kitchen Nook Lights to Off (0)
        Apr-25 9:10:06 PM	 	Device Control	Device: Lighting Kitchen Kitchen Lights to Dim 50% (50)
        Apr-25 9:10:06 PM	 	Device Control	Device: Lighting Kitchen Kitchen Island Lights to Off (0)
        Apr-25 9:10:06 PM	 	Device Control	Device: Lighting Foyer Foyer Light to Off (0)
        Apr-25 9:10:06 PM	 	Device Control	Device: Lighting Entry Hall Entry Hall Table Light to Off (0)
        Apr-25 9:10:06 PM	 	Device Control	Device: Lighting Entry Hall Entry Hall Lights to Off (0)
        Apr-25 9:10:06 PM	 	Device Control	Device: Lighting Downstairs Hall Downstairs Hall Lights to Off (0)
        Apr-25 9:10:06 PM	 	Device Control	Device: Lighting Dining Room Dining Room Light to Off (0)
        Apr-25 9:10:06 PM	 	Device Control	Device: Lighting Kitchen Butlers Pantry to Off (0)
        Apr-25 9:10:06 PM	 	Device Control	Device: ISY Control Family Room *Family Room Lights to Off (0)
        Apr-25 9:10:06 PM	 	Device Control	Device: Unknown Family Room Watch TV Downstairs to Off (0)
        Apr-25 9:10:06 PM	 	Event	Event Trigger "Family Room Watch TV Downstairs 2nd Test"
        Apr-25 9:10:06 PM	 	Event	Event Family Room Watch TV Downstairs 2nd Test triggered by the event page 'Run' button.
        By changing the wait time, it will effect the device that throws an error. It seems consistent in that regard. If I set the wait time to 10 seconds, then no errors appear. I've zipped up the debug version of the log below.

        For the record, I've disabled about 40+ of these syncing programs. There are other similar programs that will also generate the error, but I've also seen that not every one will. Haven't figured out the correlation, but hoping the logs will help figure out what's happening.

        One more thing to mention, at the point of the first error (when I have all these syncing program running) appears, anything after that will not update.
        But if I run the event multiple times, with each iteration turning off an additional device before the error is thrown, I will be eventually able to run the event and it will not generate any errors.

        Update1: Did a bit more testing, and the device that appears in the error message seems somewhat random.

        Update2: If I created an ISY program to set the device states, and then call it from HS. That works just fine. Issue only appears if the change originates from HS.

        Regards

        Richard
        Attached Files
        Last edited by ruderthanyou; April 26, 2017, 01:44 PM.

        Comment


          #5
          I'm not sure I'm clear on everything you have set up and what the relationships are between the ISY programs / scenes / HS triggers / HS actions. The log isn't real helpful because it looks like you have one or more scenes with a large number of devices and most of the log messages are just the plug-in checking if a device state change will cause a scene state change.

          The one thing I do see in the log is that sometime between when the failing command was pulled off the command queue and when it is sent to the ISY, the ISY goes busy. That's possibly why the ISY is failing to accept the command.

          When the ISY reports that it's busy, that means that it may not process requests (device commands). The plug-in is trying to honor this as it essentially does a "wait for not busy then send command" already. But there's no way to guarantee that it doesn't become busy between when I check and when I send the command.

          Historically, when the ISY has returned a 501 error that means that it doesn't like something about the command, thus it didn't make sense to re-try the command. But maybe I need to check and if the ISY is now busy, wait again and retry.

          When the ISY is executing programs, it tends to be busy. It doesn't have a very powerful CPU and thus isn't really able to handle too many things at once. You may just be overloading it with this setup. That may explain why increasing the wait time or disabling the programs helps.
          --
          Bob Paauwe
          ISYInsteon Plug-in
          http://www.bobsplace.com/ISYInsteon/

          Comment


            #6
            Bob,

            Yes, I do have one huge scene for all my lights in the house. Used for alarm purposes, otherwise most of my scene are relatively small. Though I have to admit, reading that log was very interesting, it really put the spotlight regarding all the things your PI is checking/keeping track of.

            Regarding the crux of my issue which is those 501 errors popping up, I definitely thought I could be overloading the ISY, which is why I tried the wait command. It does work, but putting sleep/wait command all over the place is going to make my code pretty complex. Plus I don't really know how long I should wait, 500ms, 2s, 5s since I don't have any way to check to see if the ISY is busy so I would also have to guess on the conservative side making my events run pretty slow.

            Would it be possible for you to add the wait/retry for occurrences of these errors? It looks like 501 errors are not just related to bad commands.

            Regards

            Richard

            Comment


              #7
              Bob,

              I did some more testing this morning and I'm starting to rule out that I'm loading my ISY up too much (And I can be totally wrong here). I did another test this morning and started by disabling every single one of my programs on the ISY. I do still have lots of scenes, but I'm not activating a single one in this test. Then I ran an event in the HS3 that does 3 things:

              1. 'Runthen' a program on the ISY. This program will turn OFF 11 lights (devices) and set the 12th to 50%.
              2. Turns on a light (device) on the ISY to ON.
              3. Turns on a light (device) on the ISY to ON.

              The result is still the: 'Failed to get response from ISY (The remote server returned an error: (501) Not Implemented.). SendRequest' error twice, basically anything command I send after item 1, generates that error and does not run. Every light actuated by the ISY program does get updated.

              For the error log, I disabled reporting on 'CheckForSceneActivated' event to hopefully makes it easier to read otherwise every other item is checked.

              Also, I've been seeing these errors on 5.0.4, 5.0.9 and now 5.0.10. So not sure if this is something introduced with 5.0.x.

              Regards

              Richard
              Attached Files

              Comment


                #8
                Originally posted by ruderthanyou View Post
                Bob,

                I did some more testing this morning and I'm starting to rule out that I'm loading my ISY up too much (And I can be totally wrong here). I did another test this morning and started by disabling every single one of my programs on the ISY. I do still have lots of scenes, but I'm not activating a single one in this test. Then I ran an event in the HS3 that does 3 things:

                1. 'Runthen' a program on the ISY. This program will turn OFF 11 lights (devices) and set the 12th to 50%.
                2. Turns on a light (device) on the ISY to ON.
                3. Turns on a light (device) on the ISY to ON.
                I'm assuming the program run in step 1 is still enabled, right?

                That's what causes the ISY to be busy. If I recall correctly, the ISY gives pretty high priority to running programs and one that is sequentially controlling 12 devices is going to take a while to run.

                I trimmed and annotated your log to just the relevant parts and it still looks like this is just bad timing. Right when the plug-in starts sending each of those commands, the ISY is reporting that it's busy. It's very likely that the ISY goes busy every time it sends commands to a device and may stay that way until it gets a response.

                Code:
                // ISY becomes idle
                4/28/2017 12:27:56 PM	ISY is idle.	
                
                // ISY again reports failure (note that ISY is in busy state at this point)
                4/28/2017 12:27:56 PM	Attempt to send DON to Powder Room/Lighting/Powder Room Light failed. Likely cause is invalid command.	ProcessCommand
                
                // ISY has become busy again
                4/28/2017 12:27:54 PM	ISY is busy.	
                
                // Plug-in check queue, sees command waiting, checks ISY state, starts sending
                // command to ISY
                4/28/2017 12:27:54 PM	Sending DON, 255 to Powder Room/Lighting/Powder Room Light Attempt 0	ProcessCommand
                
                // ISY is now idle
                4/28/2017 12:27:54 PM	ISY is idle.	
                
                // Plug-in adds command to turn on second light to send queue
                4/28/2017 12:27:54 PM	Command for Powder Room/Lighting/Powder Room Light added to queue. Queue size = 1	Add
                
                // ISY reports failure (note that ISY is in busy state at this point)
                4/28/2017 12:27:54 PM	Attempt to send DON to Powder Room/Lighting/Powder Room Vanity Light failed. Likely cause is invalid command.	ProcessCommand
                
                
                // ISY has become busy (This is reported by the ISY to the plug-in)
                4/28/2017 12:27:54 PM	ISY is busy.	
                
                // Plug-in checks queue, sees command waiting, checks ISY status, Starts sending
                // command to ISY
                4/28/2017 12:27:54 PM	Sending DON, 255 to Powder Room/Lighting/Powder Room Vanity Light Attempt 0	ProcessCommand
                
                // HomeSeer process action and calls into plug-in for second device command
                4/28/2017 12:27:54 PM	SetIOMulti set 2363 to value 255	SetIOMulti
                
                // Plug-in adds command to turn on the light to the send queue
                4/28/2017 12:27:54 PM	Command for Powder Room/Lighting/Powder Room Vanity Light added to queue. Queue size = 1	Add
                
                // HomeSeer process action and calls into plug-in for first device command
                4/28/2017 12:27:54 PM	SetIOMulti set 2366 to value 100	SetIOMulti
                The log reads bottom to top. It may be that something has changed in the 5.x series of firmware in the way that it's running the program and processing external commands. But that's not something we have any control over.

                What happens if reverse the steps above? Does it work reliably if you do that?

                As soon as I have time, I'll work on adding a retry to that failure. I'm not sure how much that will help in this case as the computer you're running HS on is probably much faster than the ISY and may be able to send the command multiple times in span of time the ISY running that program.
                --
                Bob Paauwe
                ISYInsteon Plug-in
                http://www.bobsplace.com/ISYInsteon/

                Comment


                  #9
                  Bob,

                  Regarding the program, it was disabled too, I just called it through your plugin. In any case, I reversed the HS event around, I sent the two ON first, and then ran the program. Still got the errors, and it's very consistent, every time I run it, it will generate the follow errors:

                  Code:
                  Apr-28 7:49:11 PM	 	ISYInsteon	Family Room/ISY Programs/+Watch TV Downstairs now at 21
                  Apr-28 7:49:11 PM	 	ISYInsteon	ISY is idle.
                  Apr-28 7:49:11 PM	 	ISYInsteon	Command Queue is now empty.
                  Apr-28 7:49:11 PM	 	ISYInsteon	ProcessCommand : Attempt to send DON to Powder Room/Lighting/Powder Room Light failed. Likely cause is invalid command.
                  Apr-28 7:49:11 PM	 	ISYInsteon	SendRequest : -> Using Authorization [Basic cmljaGFyZDpKZXRTa2kxMA==]
                  Apr-28 7:49:11 PM	 	ISYInsteon	SendRequest : -> For command: [DON2553D EC CF 10 ]
                  Apr-28 7:49:11 PM	 	ISYInsteon	SendRequest : Failed to get response from ISY (The remote server returned an error: (501) Not Implemented.).
                  Apr-28 7:49:10 PM	 	ISYInsteon	ISY is busy.
                  Apr-28 7:49:09 PM	 	ISYInsteon	ISY is idle.
                  Apr-28 7:49:09 PM	 	ISYInsteon	Command Queue is now empty.
                  Apr-28 7:49:09 PM	 	ISYInsteon	ProcessCommand : Attempt to send DON to Powder Room/Lighting/Powder Room Vanity Light failed. Likely cause is invalid command.
                  Apr-28 7:49:09 PM	 	ISYInsteon	SendRequest : -> Using Authorization [Basic **********************==]
                  Apr-28 7:49:09 PM	 	ISYInsteon	SendRequest : -> For command: [DON2553C E1 2C 10 ]
                  Apr-28 7:49:09 PM	 	ISYInsteon	SendRequest : Failed to get response from ISY (The remote server returned an error: (501) Not Implemented.).
                  Apr-28 7:49:09 PM	 	ISYInsteon	ISY is busy.
                  Apr-28 7:49:08 PM	 	ISYInsteon	ISY is idle.
                  Apr-28 7:49:08 PM	 	ISYInsteon	Family Room/ISY Programs/+Watch TV Downstairs now at 22
                  Apr-28 7:49:08 PM	 	ISYInsteon	ISY is busy.
                  Apr-28 7:49:08 PM	 	ISYInsteon	Command Queue is now empty.
                  Apr-28 7:49:08 PM	 	Device Control	Device: Lighting Powder Room Powder Room Light to On (255)
                  Apr-28 7:49:08 PM	 	Device Control	Device: Lighting Powder Room Powder Room Vanity Light to On (100)
                  I honestly thought that would have worked. Now I a bit more worried about how to construct events in HS3 because, at least for me, it would be pretty easy to busy out the pipe, considering in this scenario I've disabled all my programs.

                  By the way, can you reproduce this on your end? I'm wondering if there might be an issue with something in my environment that could be causing this.

                  Thank you

                  Richard

                  Comment


                    #10
                    Originally posted by ruderthanyou View Post
                    Bob,

                    Regarding the program, it was disabled too, I just called it through your plugin. In any case, I reversed the HS event around, I sent the two ON first, and then ran the program. Still got the errors, and it's very consistent, every time I run it, it will generate the follow errors:
                    Well, base on the log, changing the order in the action list didn't actually change the order they were executed. It looks like, that because the device control route through HS first, they still end up getting sent to the ISY after the program command. That's interesting and certainly unexpected. I have two suggestions.

                    1) Add a pause/wait after sending the two device commands.

                    2) Change the device control commands from HS commands to use the ISY Device Commands instead.

                    I haven't had time to look closely at reproducing this but I think I now have a better understanding of what's happening, I'll make some time.
                    --
                    Bob Paauwe
                    ISYInsteon Plug-in
                    http://www.bobsplace.com/ISYInsteon/

                    Comment


                      #11
                      I had some time to look at this issue in depth. I am able to reproduce.

                      The root of the problem is the that the ISY is returning failure on commands sent while it's busy running a program. I'm surprised that this hasn't been reported before as it seems to be pretty easy to trigger the problem. So maybe it is more likely to happen with the 5.x firmware.

                      I tried adding some additional checks for busy but still have the problem where the ISY turns busy between when I check and when I send the command. It seems like the ISY is toggling between busy/idle multiple times while a program is running.

                      The best solution I've come up with so far is to actually wait for the program to stop running before sending any other commands. This slows things down quite a bit as it can take a couple of seconds for the program to run.

                      There are programs that once started, run in a loop and never stop. In that case I have to timeout which I have set to about 5 seconds right now.

                      I'm still testing and have to finalize the changes, but it's looking pretty good.
                      --
                      Bob Paauwe
                      ISYInsteon Plug-in
                      http://www.bobsplace.com/ISYInsteon/

                      Comment


                        #12
                        I just uploaded a new version. Please give this a try and let me know if it solves the problem.
                        --
                        Bob Paauwe
                        ISYInsteon Plug-in
                        http://www.bobsplace.com/ISYInsteon/

                        Comment


                          #13
                          Bob,

                          Sorry about the long delay in responding. And thanks for working with me on this issue & the update. Unfortunately I'm still getting the errors using .41. There does seem to be less of them, case in point:

                          The last scenario that failed (the one I discussed on April 28th below), where I turned on two lights, and then ran the program, now works very consistently. I can actually actuate 3 devices and the program without an error.

                          Once I get to four device (regardless of the program) there is a very good chance to get an error. It starts erroring pretty consistently at 4 devices in a row, but I've had successful runs up to 5 devices being updated sequentially.

                          I'm also seeing more devices successfully updating after the error occurs. I have a HS3 test event for this issue, where I update 15 devices. I see about 3-4 of these errors when running this event. But I also see devices being updated successfully that are between the devices that error out.

                          I'm going to do some more testing to see if I can work out a theme, but .41 is definitely an improvement.

                          Regards

                          Richard

                          Comment


                            #14
                            Originally posted by ruderthanyou View Post
                            Bob,

                            Once I get to four device (regardless of the program) there is a very good chance to get an error. It starts erroring pretty consistently at 4 devices in a row, but I've had successful runs up to 5 devices being updated sequentially.
                            This is still with all programs disabled, correct?

                            If that's true then either I've got something messed up or the ISY firmware may have a problem.

                            I'll do some experiments too, but the plug-in is supposed to wait for each command to complete before sending the next so it should not be possible to overload the ISY this way. I'll have to review the plug-in's code and make sure I didn't miss something here that's preventing it from waiting after each command.

                            If it's not the plug-in, I'll try to come up with a simple way to reproduce this and file a bug report with UDI.

                            I think there's still another case that might cause problems. Right now I have the plug-in block after it sends a command that starts a program running, but I don't do any checks to see if a program is already running before sending commands. I believe the busy checks that I do are supposed to cover this case, but I'll need to do some experiments for this too.
                            --
                            Bob Paauwe
                            ISYInsteon Plug-in
                            http://www.bobsplace.com/ISYInsteon/

                            Comment


                              #15
                              Bob,

                              Originally posted by bpwwer View Post
                              This is still with all programs disabled, correct?
                              No, I had programs running. I thought if the plugin was waiting on busy time then I could have programs executing too. Sorry my bad.

                              I will do it again tonight when I get home and disable everything again.

                              I do though need to be able to have programs doing their normal things though. Programs not running makes the WAF factor significantly drop. Do you think there would be a point in time where programs can run and I won't get the error.

                              Regards

                              Comment

                              Working...
                              X