Delay in luup requests
-
@elcid said in Delay in luup requests:
OK the issue is the POST request, it does not like it, if i make it GET everything is smooth.
OK. Our messages crossed, but that's a good start.
What is generating the request? Are you sure it's valid?
-
A get request
2020-11-17 15:45:24.304 luup.variable_set:: 10186.urn:micasaverde-com:serviceId:SecuritySensor1.Tripped was: 0 now: 1 #hooks:1 2020-11-17 15:45:24.305 luup.watch_callback:: 10186.urn:micasaverde-com:serviceId:SecuritySensor1.Tripped called [10]reactorWatch() function: 0xf0d38d0 2020-11-17 15:45:24.321 luup.variable_set:: 14.urn:toggledbits-com:serviceId:ReactorSensor.cstate was: {"condpxw4kq6":{"evaledge":{"t":1605296162,"f":1605296163},"stateedge":{"t":1605296162,"f":1605296163},"id":"condpx... now: {"condpxw4kq6":{"evaledge":{"t":1605296162,"f":1605296163},"stateedge":{"t":1605296162,"f":1605296163},"id":"condpx... #hooks:0 2020-11-17 15:45:24.324 luup.variable_set:: 14.urn:toggledbits-com:serviceId:ReactorSensor.lastacc was: 1605627873 now: 1605627924 #hooks:0 2020-11-17 15:45:24.325 luup.variable_set:: 14.urn:toggledbits-com:serviceId:ReactorSensor.Message was: Not tripped now: Not tripped #hooks:0 2020-11-17 15:45:25.310 openLuup.server:: GET /data_request?id=lu_status2&output_format=json&DataVersion=296260928&Timeout=60&MinimumDelay=1500&_=1605627659979 HTTP/1.1 tcp{client}: 0xf3e3758 2020-11-17 15:45:25.427 openLuup.server:: request completed (40635 bytes, 3 chunks, 116 ms) tcp{client}: 0xf3e3758 2020-11-17 15:45:26.315 openLuup.server:: GET /data_request?id=lu_status2&output_format=json&DataVersion=296260933&Timeout=60&MinimumDelay=1500&_=1605627659980 HTTP/1.1 tcp{client}: 0xf3e3758 2020-11-17 15:45:28.614 luup.variable_set:: 10090.urn:micasaverde-com:serviceId:EnergyMetering1.KWHReading was: 1605627908 now: 1605627928 #hooks:0 2020-11-17 15:45:29.028 openLuup.server:: request completed (17279 bytes, 2 chunks, 2711 ms) tcp{client}: 0xf3e3758 2020-11-17 15:45:30.058 openLuup.server:: GET /data_request?id=lu_status2&output_format=json&DataVersion=296260935&Timeout=60&MinimumDelay=1500&_=1605627659981 HTTP/1.1 tcp{client}: 0xf3e3758 2020-11-17 15:45:38.635 openLuup.io.server:: HTTP:3480 connection from 192.168.1.10 tcp{client}: 0xff28f20 2020-11-17 15:45:38.638 openLuup.server:: GET /data_request?id=action&DeviceNum=11&serviceId=urn:toggledbits-com:serviceId:ReactorSensor&action=SetVariable&VariableName=A_home&NewValue=0 HTTP/1.1 tcp{client}: 0xff28f20 2020-11-17 15:45:38.639 luup.call_action:: 11.urn:toggledbits-com:serviceId:ReactorSensor.SetVariable 2020-11-17 15:45:38.640 luup.call_action:: action will be handled by parent: 10 2020-11-17 15:45:38.652 luup.variable_set:: 11.urn:toggledbits-com:serviceId:ReactorSensor.cstate was: {"grpsplfxbw":{"evaledge":{"f":1605524998,"t":1605524998},"stateedge":{"f":1605524998,"t":1605524998},"id":"grpsplf... now: {"grpsplfxbw":{"evaledge":{"f":1605524998,"t":1605524998},"stateedge":{"f":1605524998,"t":1605524998},"id":"grpsplf... #hooks:0 2020-11-17 15:45:38.657 openLuup.server:: request completed (137 bytes, 1 chunks, 18 ms) tcp{client}: 0xff28f20 2020-11-17 15:45:38.659 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0xff28f20 2020-11-17 15:45:38.775 openLuup.server:: request completed (43132 bytes, 3 chunks, 8716 ms) tcp{client}: 0xf3e3758 2020-11-17 15:45:39.715 luup.variable_set:: 11.urn:toggledbits-com:serviceId:ReactorSensor.cstate was: {"grpsplfxbw":{"evaledge":{"f":1605524998,"t":1605524998},"stateedge":{"f":1605524998,"t":1605524998},"id":"grpsplf... now: {"grpsplfxbw":{"evaledge":{"f":1605524998,"t":1605524998},"stateedge":{"f":1605524998,"t":1605524998},"id":"grpsplf... #hooks:0 2020-11-17 15:45:39.719 luup.variable_set:: 11.urn:toggledbits-com:serviceId:ReactorSensor.lastacc was: 1605627571 now: 1605627939 #hooks:0 2020-11-17 15:45:39.722 luup.variable_set:: 10.urn:toggledbits-com:serviceId:Reactor.runscene was: {} now: {} #hooks:0 2020-11-17 15:45:39.724 luup.variable_set:: 10.urn:toggledbits-com:serviceId:Reactor.runscene was: {} now: {"ctx11.scgrpv8xitp8.true":{"starttime":1605627939,"context":11,"scene":"grpv8xitp8.true","taskid":"ctx11.scgrpv8xi... #hooks:0 2020-11-17 15:45:39.727 luup_log:10: Reactor: "Reactor Sensor 1" (#11) Performing "Device Action" ("grpv8xitp8.true" group 1 step 1) 2020-11-17 15:45:39.729 luup.call_action:: 10165.urn:upnp-org:serviceId:SwitchPower1.SetTarget 2020-11-17 15:45:39.731 luup.call_action:: action will be handled by parent: 5 2020-11-17 15:45:39.732 luup.variable_set:: 10.urn:toggledbits-com:serviceId:Reactor.runscene was: {"ctx11.scgrpv8xitp8.true":{"starttime":1605627939,"context":11,"scene":"grpv8xitp8.true","taskid":"ctx11.scgrpv8xi... now: {"ctx11.scgrpv8xitp8.true":{"starttime":1605627939,"context":11,"scene":"grpv8xitp8.true","taskid":"ctx11.scgrpv8xi... #hooks:0 2020-11-17 15:45:39.735 luup.variable_set:: 10.urn:toggledbits-com:serviceId:Reactor.runscene was: {"ctx11.scgrpv8xitp8.true":{"starttime":1605627939,"context":11,"scene":"grpv8xitp8.true","taskid":"ctx11.scgrpv8xi... now: {} #hooks:0 2020-11-17 15:45:39.736 luup.variable_set:: 11.urn:toggledbits-com:serviceId:ReactorGroup.GroupStatus_grpv8xitp8 was: 0 now: 1 #hooks:0 2020-11-17 15:45:39.738 luup.variable_set:: 11.urn:toggledbits-com:se
a post request
:10.738 openLuup.server:: GET /data_request?id=lu_status2&output_format=json&DataVersion=296261179&Timeout=60&MinimumDelay=1500&_=1605627660009 HTTP/1.1 tcp{client}: 0xf5f46e0 2020-11-17 15:48:28.610 luup.variable_set:: 11.urn:toggledbits-com:serviceId:ReactorSensor.cstate was: {"grpsplfxbw":{"statestamp":1605524998,"stateedge":{"f":1605524998,"t":1605524998},"id":"grpsplfxbw","evalstamp":16... now: {"grpsplfxbw":{"statestamp":1605524998,"stateedge":{"f":1605524998,"t":1605524998},"id":"grpsplfxbw","evalstamp":16... #hooks:0 2020-11-17 15:48:28.614 luup.variable_set:: 11.urn:toggledbits-com:serviceId:ReactorSensor.lastacc was: 1605628086 now: 1605628108 #hooks:0 2020-11-17 15:48:28.615 luup.variable_set:: 11.urn:toggledbits-com:serviceId:ReactorSensor.Message was: Not tripped now: Not tripped #hooks:0 2020-11-17 15:48:28.644 luup.variable_set:: 10090.urn:micasaverde-com:serviceId:EnergyMetering1.KWHReading was: 1605628088 now: 1605628108 #hooks:0 2020-11-17 15:48:29.084 openLuup.server:: request completed (69817 bytes, 5 chunks, 18345 ms) tcp{client}: 0xf5f46e0 2020-11-17 15:48:30.151 openLuup.server:: GET /data_request?id=lu_status2&output_format=json&DataVersion=296261184&Timeout=60&MinimumDelay=1500&_=1605627660010 HTTP/1.1 tcp{client}: 0xf5f46e0 2020-11-17 15:48:48.627 luup.variable_set:: 10090.urn:micasaverde-com:serviceId:EnergyMetering1.KWHReading was: 1605628108 now: 1605628128 #hooks:0 2020-11-17 15:48:48.745 openLuup.server:: request completed (33122 bytes, 3 chunks, 18590 ms) tcp{client}: 0xf5f46e0 2020-11-17 15:48:49.782 openLuup.server:: GET /data_request?id=lu_status2&output_format=json&DataVersion=296261186&Timeout=60&MinimumDelay=1500&_=1605627660011 HTTP/1.1 tcp{client}: 0xf5f46e0 2020-11-17 15:48:55.201 openLuup.io.server:: HTTP:3480 connection from 192.168.1.10 tcp{client}: 0xf8bd6d8 2020-11-17 15:48:55.202 openLuup.server:: POST /data_request?id=action&DeviceNum=11&serviceId=urn:toggledbits-com:serviceId:ReactorSensor&action=SetVariable&VariableName=A_home&NewValue=0 HTTP/1.1 tcp{client}: 0xf8bd6d8 2020-11-17 15:49:00.203 luup.call_action:: 11.urn:toggledbits-com:serviceId:ReactorSensor.SetVariable 2020-11-17 15:49:00.204 luup.call_action:: action will be handled by parent: 10 2020-11-17 15:49:00.217 luup.variable_set:: 11.urn:toggledbits-com:serviceId:ReactorSensor.cstate was: {"grpsplfxbw":{"statestamp":1605524998,"stateedge":{"f":1605524998,"t":1605524998},"id":"grpsplfxbw","evalstamp":16... now: {"grpsplfxbw":{"statestamp":1605524998,"stateedge":{"f":1605524998,"t":1605524998},"id":"grpsplfxbw","evalstamp":16... #hooks:0 2020-11-17 15:49:00.222 openLuup.server:: error 'closed' sending 4 bytes to tcp{client}: 0xf8bd6d8 2020-11-17 15:49:00.223 openLuup.server:: ...only 0 bytes sent 2020-11-17 15:49:00.224 openLuup.server:: error 'closed' sending 137 bytes to tcp{client}: 0xf8bd6d8 2020-11-17 15:49:00.224 openLuup.server:: ...only 0 bytes sent 2020-11-17 15:49:00.225 openLuup.server:: error 'closed' sending 2 bytes to tcp{client}: 0xf8bd6d8 2020-11-17 15:49:00.225 openLuup.server:: ...only 0 bytes sent 2020-11-17 15:49:00.226 openLuup.server:: error 'closed' sending 5 bytes to tcp{client}: 0xf8bd6d8 2020-11-17 15:49:00.226 openLuup.server:: ...only 0 bytes sent 2020-11-17 15:49:00.227 openLuup.server:: request completed (137 bytes, 1 chunks, 23 ms) tcp{client}: 0xf8bd6d8 2020-11-17 15:49:00.228 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0xf8bd6d8 2020-11-17 15:49:00.753 openLuup.server:: request completed (58975 bytes, 4 chunks, 10970 ms) tcp{client}: 0xf5f46e0 2020-11-17 15:49:01.682 luup.variable_set:: 11.urn:toggledbits-com:serviceId:ReactorSensor.cstate was: {"grpsplfxbw":{"statestamp":1605524998,"stateedge":{"f":1605524998,"t":1605524998},"id":"grpsplfxbw","evalstamp":16... now: {"grpsplfxbw":{"statestamp":1605524998,"stateedge":{"f":1605524998,"t":1605524998},"id":"grpsplfxbw","evalstamp":16... #hooks:0 2020-11-17 15:49:01.687 luup.variable_set:: 11.urn:toggledbits-com:serviceId:ReactorSensor.lastacc was: 1605628108 now: 1605628141 #hooks:0 2020-11-17 15:49:01.688 luup.variable_set:: 10.urn:toggledbits-com:serviceId:Reactor.runscene was: {} now: {} #hooks:0 2020-11-17 15:49:01.689 luup.variable_set:: 10.urn:toggledbits-com:serviceId:Reactor.runscene was: {} now: {"ctx11.scgrpv8xitp8.true":{"starttime":1605628141,"context":11,"scene":"grpv8xitp8.true","taskid":"ctx11.scgrpv8xi... #hooks:0 2020-11-17 15:49:01.691 luup_log:10: Reactor: "Reactor Sensor 1" (#11) Performing "Device Action" ("grpv8xitp8.true" group 1 step 1) 2020-11-17 15:49:01.691 luup.call_action:: 10165.urn:upnp-org:serviceId:SwitchPower1.SetTa
the server page is code 200 for all items wxcept favicon which is 404.
/cgi-bin/cmh/sysinfo.sh 3 200 /openLuup 63 200 D_ALTUI.xml 7 200 D_AltAppStore.xml 7 200 D_BinaryLight1.xml 8 200 D_BluetoothNetwork.xml 6 200 D_BroadLink_Mk2_1.xml 6 200 D_DimmableLight1.xml 6 200 D_DimmableRGBLight1.xml 6 200 D_DoorSensor1.xml 6 200 D_EzloBridge.xml 6 200 D_GenericSensor1.xml 6 200 D_LightSensor1.xml 6 200 D_MotionSensor1.xml 6 200 D_PowerMeter1.xml 9 200 D_Reactor.xml 6 200 D_ReactorDeviceInfo.json 5 200 D_ReactorSensor.xml 6 200 D_SceneController1.xml 9 200 D_SiteSensor1.xml 6 200 D_SmartHomeHelper.xml 6 200 D_Switchboard1.xml 6 200 D_TemperatureSensor1.xml 6 200 D_VeraAlexa1.xml 6 200 D_VeraBridge.xml 6 200 D_WindowCovering1.xml 6 200 D_ZWaveNetwork.xml 6 200 D_ZigbeeNetwork.xml 6 200 D_openLuup.xml 10 200 J_ALTUI_api.js 12 200 J_ALTUI_iphone.js 12 200 J_ALTUI_jquery.ui.touch-punch.min.js 12 200 J_ALTUI_multibox.js 12 200 J_ALTUI_plugins.js 12 200 J_ALTUI_uimgr.js 12 200 J_ALTUI_upnp.js 12 200 J_ALTUI_utils.js 12 200 J_ALTUI_verabox.js 12 200 J_ReactorSensor_ALTUI.js 12 200 J_ReactorSensor_UI7.js 3 200 J_Reactor_ALTUI.js 12 200 J_SiteSensor1_ALTUI.js 12 200 S_HaDevice1.xml 1 200 S_ReactorSensor.xml 1 200 S_SecuritySensor1.xml 1 200 S_SwitchPower1.xml 1 200 favicon.ico 5 404 icons/AltAppStore.svg 7 200 icons/VeraBridge.svg 5 200 icons/dimmable_light_10.png 3 200 icons/dimmable_light_100.png 1 200 icons/dimmable_light_20.png 1 200 icons/dimmable_light_50.png 1 200 icons/dimmable_light_off.png 17 200 icons/door_window_untripped.png 15 200 icons/light_sensor_default.png 13 200 icons/meter_default.png 16 200 icons/motion_sensor_tripped.png 11 200 icons/motion_sensor_untripped.png 13 200 icons/openLuup.svg 66 200 icons/switch_off.png 14 200 icons/switch_on.png 13 200 icons/temperature_sensor_default.png 15 200 icons/window_covering_10.png 13 200 icons/zwave_default.png 15 200 id=action 807 200 id=actions 15 200 id=lr_ALTUI_Handler 36 200 id=lr_ALTUI_LuaRunHandler 154 200 id=lr_HTTP_VeraBridgeMirror_192.168.1.11 0 id=lr_Reactor 24 200 id=lr_SiteSensor 0 id=lr_Switchboard 0 id=lu_action 2 200 id=lu_status2 2158 200 id=scene 1 200 id=sdata 9 200 id=status 3 200 id=user_data 13 200 id=variableget 16 200 id=variableset 12 200 w3.css 60 200
having troble with this forum, not allowing image upload.
-
@elcid said in Delay in luup requests:
having troble with this forum, not allowing image upload.
...need to flag this to @DesT
-
Automate is generating the requests when phone leaves home wifi.
-
...so it looks like Automate doesn't like chunked responses to the POST request.
The logs are a bit misleading, because action requests are processed asynchronously as jobs, so things don't always appear in the order that you might expect.. The timeouts should precede the action execution, and they are, almost definitely, what is delaying it.
-
Ok i will have to edit my automate http request forwarder so i can specify request type in the payload. i.e post,get,put,etc
-
@akbooer said in Delay in luup requests:
@elcid said in Delay in luup requests:
having troble with this forum, not allowing image upload.
...need to flag this to @DesT
Are you still having an issue ?
-
@DesT
ye.
seems certain buttons are working.
none of the buttons/icons on reply page.
the 4 black icons to left of reply, above quick reply input.
Also the context menu chevron on the reply button/icon.
i can not edit or delete a post either. -
Dark mode has disappeared and there is no longer an icon in the title bar.
15/15