(Last Updated: November 21, 2020)
For those who registered but didn't received the confirmation email, please send an email to support@smarthome.community with the email you used

  • Hi,

    I have a couple of luup request, one is a request to VeraAlexa pluging to make alexa speak, the other updating a variable in reactor. They all seem to have a 10-20 second delay
    example request
    http://192.168.1.134:3480/data_request?id=action&DeviceNum=44&serviceId=urn:toggledbits-com:serviceId:ReactorSensor&action=SetVariable&VariableName=A_home&NewValue=1

    I can not figure out what is causing the delay, does anyone have any ideas?


  • What does the log show?


  • 26.399   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}: 0xfc90558
    2020-11-17 14:53:31.400   luup.call_action:: 11.urn:toggledbits-com:serviceId:ReactorSensor.SetVariable 
    2020-11-17 14:53:31.401   luup.call_action:: action will be handled by parent: 10
    2020-11-17 14:53:31.414   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 14:53:31.419   openLuup.server:: error 'closed' sending 4 bytes to tcp{client}: 0xfc90558
    2020-11-17 14:53:31.420   openLuup.server:: ...only 0 bytes sent
    2020-11-17 14:53:31.420   openLuup.server:: error 'closed' sending 137 bytes to tcp{client}: 0xfc90558
    2020-11-17 14:53:31.421   openLuup.server:: ...only 0 bytes sent
    2020-11-17 14:53:31.421   openLuup.server:: error 'closed' sending 2 bytes to tcp{client}: 0xfc90558
    2020-11-17 14:53:31.422   openLuup.server:: ...only 0 bytes sent
    2020-11-17 14:53:31.422   openLuup.server:: error 'closed' sending 5 bytes to tcp{client}: 0xfc90558
    2020-11-17 14:53:31.423   openLuup.server:: ...only 0 bytes sent
    2020-11-17 14:53:31.423   openLuup.server:: request completed (137 bytes, 1 chunks, 23 ms) tcp{client}: 0xfc9055
    

  • OK the issue is the POST request, it does not like it, if i make it GET everything is smooth.


  • No idea.

    • I would like to see earlier in the log where there should be an initial connection message from the server module.
    • also would like to see the HTTP Server page at http://openLuupIP:3480/openLuup?page=http
    • the exact 5 second delay between the first and second lines would indicate a timeout...
    • ... but a valid request appears to be received and acted upon (very quickly)

    No indication of 10-20 second delays in this case.

    Do you always get those errors?


  • @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.


  • Still not working for me @DesT