known bug in selector switches? Topic is solved

[lost]

Hello,

Is there a known bug for 2023.2 (i'm on last beta before OZW removal, soon after stable, 15462) for selector switches not triggering intended action?

My issue is with a virtual selector switch that sends this kind of commands (with N=0..4 as I have 5 timer plans)
/json.htm?type=command&param=setactivetimerplan&ActiveTimerPlan=N

But looking at what's active (same from UI but easier to refresh from API) using:
/json.htm?type=command&param=gettimerplans

That's clearly not the command intended for the selector level that is sent.
Not a JSON API issue, as using commands from a browser does intended timer plan activation. But the same commands in the virtual selector levels does not do the intended action.

When switch is done correctly, logs shows 2 lines:

Code: Select all

2023-09-28 17:51:46.264 Status: User: XXX (IP: 192.168.1.25) initiated a switch command (318/Planning actif/Set Level)
2023-09-28 17:51:46.497 Status: Scheduler Timerplan changed (1 - Holiday) 

But clearly the timer plan is not the intended one (like 1 - Holiday here) for level 3 for instance:

Code: Select all

023-09-28 17:53:38.092 Status: User: domo (IP: 192.168.1.25) initiated a switch command (318/Planning actif/Set Level)
2023-09-28 17:53:38.308 Status: Scheduler Timerplan changed (0 - default) 

Here, believe me, timer plan 3 was intended but got 0!

Quite bad as I need this for my winter planing management & still OZW...

[waltervl]

Are the action command values exactly the same except for N?
Is it randomly going wrong or only for a specific level?
Do you have other scripts looking at this selector switch or setting the timer plan that can interfere in the behavior?

[lost]

Are the action command values exactly the same except for N?
Is it randomly going wrong or only for a specific level?
Do you have other scripts looking at this selector switch or setting the timer plan that can interfere in the behavior?

I would say anything over 2 fails, as if a modulo 2 on N was done in fact. No other script taking this virtual over... Level 0/off was hidden, tried to reverse this but no difference.

I'll try to rebuild another same switch from scratch to see if this makes a difference. Mostly use Default/vacations (id 0/1) plannings so don't know when this may have stopped working.

As I added another new planning (for high electricity prices days, as I changed my contract a few months ago), I re-tested & saw this problem... Unfortunately, logs for selectors does not show level. This would make issue more obvious with a switch configuration screenshot to compare with planning id that is triggered.

[waltervl]

You can switch on debugging, see the wiki page troubleshooting.

[lost]

You can switch on debugging, see the wiki page troubleshooting.

Hello, I think I got it:

Code: Select all

2023-09-30 07:41:24.559  [7f98d6ff80] Status: User: domo (IP: 192.168.1.100) initiated a switch command (318/Planning actif/Set Level)
2023-09-30 07:41:24.560  [7f98d6ff80] Debug: MAIN SwitchLight idx:318 cmd:Set Level lvl:30 
2023-09-30 07:41:24.561  [7f98d6ff80] Debug: MAIN SwitchLightInt : switchcmd:Set Level level:30 HWid:23  sd:23 00000000 1 244 62 18
2023-09-30 07:41:24.565  [7f927fbf80] Debug: SQLH HandleOnOffAction: OnAction:http://127.0.0.1:8080/json.htm?type=command&param=setactivetimerplan&activeTimerPlan=2
2023-09-30 07:41:24.566  [7f927fbf80] Debug: SQLH AddTask: Request to add task: idx=0, DelayTime=0.200000, Command='', Level=0, Color='{INVALID}', RelatedEvent=''
2023-09-30 07:41:24.567  [7f927fbf80] Debug: SQLH UpdateValueInt Planning actif HwID:23  DevID:00000000 Type:244  sType:62 nValue:2 sValue:30 
2023-09-30 07:41:24.577  [7f927fbf80] Planning Select: Light/Switch (Planning actif)
2023-09-30 07:41:24.577  [7f927fbf80] Debug: CWebServer::GetJSonPage :getdevices :/json.htm?type=command&param=getdevices&rid=318 
2023-09-30 07:41:24.587  [7f98d6ff80] Debug: Web ACLF: 192.168.1.100 - - [30/Sep/2023:07:41:24.556 +0200] "GET /json.htm?type=command&param=switchlight&idx=318&switchcmd=Set%20Level&level=30&passcode= HTTP/1.1" 200 47 "http://192.168.1.31:8080/" "Mozilla/5.0 (X11; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/115.0"
2023-09-30 07:41:24.778  [7f9a572f80] Debug: SQLH: Do Task ItemType:6 Cmd: Value:http://127.0.0.1:8080/json.htm?type=command&param=setactivetimerplan&activeTimerPlan=2 
2023-09-30 07:41:24.781  [7f98d6ff80] Debug: [web:8080] Host:127.0.0.1 Uri:/json.htm?type=command&param=setactivetimerplan&activeTimerPlan=2
2023-09-30 07:41:24.781  [7f98d6ff80] Debug: [web:8080] Request Headers:
Host: 127.0.0.1:8080
User-Agent: Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/602.36 (KHTML, like Gecko) Chrome/53.0.38679.0 Safari/602.37
Accept: */*
Accept-Encoding: deflate, gzip, br

2023-09-30 07:41:24.783  [7f98d6ff80] Debug: [web:8080] IP (127.0.0.1) is within Trusted network range!
2023-09-30 07:41:24.783  [7f98d6ff80] Debug: [web:8080] isPage 1 isAction 0 isUpgrade 0 needsAuthentication 1 isAuthenticated 1 (domo)
2023-09-30 07:41:24.784  [7f98d6ff80] Debug: CWebServer::GetJSonPage :setactivetimerplan :/json.htm?type=command&param=setactivetimerplan&activeTimerPlan=2 
2023-09-30 07:41:24.785  [7f98d6ff80] Status: Scheduler Timerplan changed (0 - default)
2023-09-30 07:41:24.794  [7f98d6ff80] Debug: Web ACLF: 127.0.0.1 - - [30/Sep/2023:07:41:24.781 +0200] "GET /json.htm?type=command&param=setactivetimerplan&activeTimerPlan=2 HTTP/1.1" 200 54 - "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/602.36 (KHTML, like Gecko) Chrome/53.0.38679.0 Safari/602.37"

At 2023-09-30 07:41:24.561 you see requested change for level 30 (with action : http://127.0.0.1:8080/json.htm?type=com ... imerPlan=2), right on this side (matching virtual selector button I pressed).

At 2023-09-30 07:41:24.781 / 2023-09-30 07:41:24.784 command passed match hereupper action.

2023-09-30 07:41:24.785 message says it changed... for level 0 (default), not 2 (the requested one).

If I select level 20 / planning idx 1 with selection done correctly, I have:

Code: Select all

2023-09-30 07:53:50.941  [7f98d6ff80] Status: User: domo (IP: 192.168.1.100) initiated a switch command (318/Planning actif/Set Level)
2023-09-30 07:53:50.941  [7f98d6ff80] Debug: MAIN SwitchLight idx:318 cmd:Set Level lvl:20 
2023-09-30 07:53:50.942  [7f98d6ff80] Debug: MAIN SwitchLightInt : switchcmd:Set Level level:20 HWid:23  sd:23 00000000 1 244 62 18
2023-09-30 07:53:50.944  [7f927fbf80] Debug: SQLH HandleOnOffAction: OnAction:http://127.0.0.1:8080/json.htm?type=command&param=setactivetimerplan&ActiveTimerPlan=1
2023-09-30 07:53:50.944  [7f927fbf80] Debug: SQLH AddTask: Request to add task: idx=0, DelayTime=0.200000, Command='', Level=0, Color='{INVALID}', RelatedEvent=''
2023-09-30 07:53:50.945  [7f927fbf80] Debug: SQLH UpdateValueInt Planning actif HwID:23  DevID:00000000 Type:244  sType:62 nValue:2 sValue:20 
2023-09-30 07:53:50.949  [7f927fbf80] Planning Select: Light/Switch (Planning actif)
2023-09-30 07:53:50.949  [7f927fbf80] Debug: CWebServer::GetJSonPage :getdevices :/json.htm?type=command&param=getdevices&rid=318 
2023-09-30 07:53:50.955  [7f98d6ff80] Debug: Web ACLF: 192.168.1.100 - - [30/Sep/2023:07:53:50.940 +0200] "GET /json.htm?type=command&param=switchlight&idx=318&switchcmd=Set%20Level&level=20&passcode= HTTP/1.1" 200 47 "http://192.168.1.31:8080/" "Mozilla/5.0 (X11; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/115.0"
2023-09-30 07:53:51.168  [7f9a572f80] Debug: SQLH: Do Task ItemType:6 Cmd: Value:http://127.0.0.1:8080/json.htm?type=command&param=setactivetimerplan&ActiveTimerPlan=1 
2023-09-30 07:53:51.170  [7f98d6ff80] Debug: [web:8080] Host:127.0.0.1 Uri:/json.htm?type=command&param=setactivetimerplan&ActiveTimerPlan=1
2023-09-30 07:53:51.170  [7f98d6ff80] Debug: [web:8080] Request Headers:
Host: 127.0.0.1:8080
User-Agent: Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/602.36 (KHTML, like Gecko) Chrome/53.0.38679.0 Safari/602.37
Accept: */*
Accept-Encoding: deflate, gzip, br

2023-09-30 07:53:51.170  [7f98d6ff80] Debug: [web:8080] IP (127.0.0.1) is within Trusted network range!
2023-09-30 07:53:51.171  [7f98d6ff80] Debug: [web:8080] isPage 1 isAction 0 isUpgrade 0 needsAuthentication 1 isAuthenticated 1 (domo)
2023-09-30 07:53:51.171  [7f98d6ff80] Debug: CWebServer::GetJSonPage :setactivetimerplan :/json.htm?type=command&param=setactivetimerplan&ActiveTimerPlan=1 
2023-09-30 07:53:51.171  [7f98d6ff80] Status: Scheduler Timerplan changed (1 - Holiday)
2023-09-30 07:53:51.178  [7f98d6ff80] Debug: Web ACLF: 127.0.0.1 - - [30/Sep/2023:07:53:51.170 +0200] "GET /json.htm?type=command&param=setactivetimerplan&ActiveTimerPlan=1 HTTP/1.1" 200 54 - "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/602.36 (KHTML, like Gecko) Chrome/53.0.38679.0 Safari/602.37"

At 2023-09-30 07:53:50.941 button for level 20 is pressed
At 2023-09-30 07:53:51.171 the intended action is done (level 20 action is http://127.0.0.1:8080/json.htm?type=com ... imerPlan=1) and planning 1 is stelected.

For reference, the plannings I have setup with their idx (back to normal one selection, here, that also works from selector):

Code: Select all

$ curl 'http://127.0.1.1:8080/json.htm?type=command&param=gettimerplans'
{
	"result" : 
	[
		{
			"Active" : false,
			"Name" : "AtHome",
			"idx" : 2
		},
		{
			"Active" : true,
			"Name" : "default",
			"idx" : 0
		},
		{
			"Active" : false,
			"Name" : "Empty",
			"idx" : 3
		},
		{
			"Active" : false,
			"Name" : "Holiday",
			"idx" : 1
		},
		{
			"Active" : false,
			"Name" : "tempoR",
			"idx" : 4
		}
	],
	"status" : "OK",
	"title" : "GetTimerPlans"
}

+ as already mentioned, direct API selection (for instance: curl 'http://127.0.1.1:8080/json.htm?type=com ... imerPlan=2') works for all levels. Only selector switch selection with actions cause issues for levels != 0 or 1.

I'll shut debug now as very verbose but keep whole file if needed.

[boum]

can you quick check if that's some case sensitivity issue? activeTimerPlan (not working) vs. ActiveTimerPlan (working)

[lost]

Hello,

Issue should be quite clear from logs, seeing both OK/KO cases

KO: Request to switch to timer plan 2... But 0 being activated.

Code: Select all

2023-09-30 07:41:24.784  [7f98d6ff80] Debug: CWebServer::GetJSonPage :setactivetimerplan :/json.htm?type=command&param=setactivetimerplan&activeTimerPlan=2 
2023-09-30 07:41:24.785  [7f98d6ff80] Status: Scheduler Timerplan changed (0 - default)

OK:Request to switch to timer plan 1, being correctly activated.

Code: Select all

2023-09-30 07:53:51.171  [7f98d6ff80] Debug: CWebServer::GetJSonPage :setactivetimerplan :/json.htm?type=command&param=setactivetimerplan&ActiveTimerPlan=1 
2023-09-30 07:53:51.171  [7f98d6ff80] Status: Scheduler Timerplan changed (1 - Holiday)

If there is more info to provide, please let me know...

[boum]

i don't see both cases from the logs you provided, it's always the same two requests
OK -> uppercase A ActiveTimerPlan=1
KO -> lowercase a activeTimerPlan=2
anyway it might not be the issue at all

[lost]

i don't see both cases from the logs you provided, it's always the same two requests
OK -> uppercase A ActiveTimerPlan=1
KO -> lowercase a activeTimerPlan=2
anyway it might not be the issue at all

Did not saw your message when I answered: You're right, this was just this case issue I didn't noticed. I changed this & that's now working as intended

Strange this does not trigger any error message for a malformed command, even with full debug. In fact, this even silently trigger default/0: A bit disturbing!

Anyway, most important is that's working! Thanks.

[boum]

no problem & good for you
yes that's a bug, and the http request should return an error and not change to the default timer plan. filed issue https://github.com/domoticz/domoticz/issues/5827

[kiddigital]

Latest beta should prevent this issue. If wrong info provided, the resulting JSON should state ERR and the old value should remain.

[lost]

Thanks for the change!

[boum]

yes, thank you for the swiftness
and also in the github ticket explaining HTTP return code was not to be trusted yet
i fell on that image and had to share (here rather than on the github issue)

error code meme

server 200 json 400.jpg (34.25 KiB) Viewed 1485 times

[Patricen]

Hello,

It's spring time and I tried to change timer plan, but got stuck.
I'm using the latest stable version and it looks like
http://192.168.1.121/json.htm?type=comm ... imerPlan=1

does not work anymore.

Is there a fix?
Thanks

Edit:
Returned error is : 2024-04-11 21:10:05.404 Error: Error opening url: http://192.168.1.121/json.htm?type=comm ... imerPlan=1

Edit2:
Solved, Domoticz' IP was not within the trusted network list... adding it solved the issue