dsf-python-3.5.1rc1 problems with http endpoint not working

[achrn]

@Falcounet thanks for dsf-python-3.5.1rc1. I've used object model subscription functions (both getting full model and getting patches) and also simple command connection and they all work fine (on a bookworm DuetPi with 3.5.1 firmware running on Raspberry Pi 4 and a Duet MB6HC).

However, I'm having problems with http endpoints - they look like they are working, but no content is passed. This is the case even if I use the example in the source with no changes.

I'm running the example custom_http_endpoint.py as user 'ian', but once the script is running doing a chmod a+w on /run/dsf/custom/getIt-GET.sock so any (every) process should have full access. In the command prompt running the script, everything looks good, there's nothing untoward showing up in journal logging, the routine accessing the endpoint reports a 200 result code, but there's no actual data.

I've run out of things to try / test, so would welcome some suggestions.

The example script gives me happy-looking output:

ian@delta:~/dsf-python-3.5.1rc1/examples $ ./custom_http_endpoint.py
send: {"mode":"Command","version":12}
recv: {"success":true}
send: {"command":"AddHttpEndpoint","EndpointType":"GET","Namespace":"custom","Path":"getIt","IsUploadRequest":false}
recv: {"result":"/run/dsf/custom/getIt-GET.sock","success":true}
Try accessing http://duet3.local/machine/custom/getIt in your browser...
recv: {"sessionId":-1,"queries":{},"headers":{"accept":"*/*","connection":"keep-alive","host":"localhost","user-Agent":"Wget/1.21.3","accept-Encoding":"identity"},"contentType":null,"body":""}
send: {"StatusCode": 200, "Response": "so happy you asked for it!", "ResponseType": "StatusCode"}

so it thinks it has sent a response and status code 200. (I'm not accessing duet3.local - that machine name doesn't exist, I get the same behaviour whether I access by machine name or IP address.)

In this case I was actually using wget from the same machine, to hopefully bypass any network issues (firewalls etc). Wget apparently had a satisfactory transaction, and reports status 200, but the response it got is empty (zero bytes):

ian@delta:~ $ wget -S http://localhost/machine/custom/getIt
--2024-05-12 12:19:24--  http://localhost/machine/custom/getIt
Resolving localhost (localhost)... ::1, 127.0.0.1
Connecting to localhost (localhost)|::1|:80... connected.
HTTP request sent, awaiting response...
  HTTP/1.1 200 OK
  Content-Length: 0
  Date: Sun, 12 May 2024 11:19:24 GMT
  Server: Kestrel
Length: 0
Saving to: ‘getIt’

getIt                                  [ <=>                                                             ]       0  --.-KB/s    in 0s

2024-05-12 12:19:24 (0.00 B/s) - ‘getIt’ saved [0/0]

As noted, the socket has lax permissions:

ian@delta:/run/dsf/custom $ ls -l
total 0
srwxrwxrwx 1 ian dsf 0 May 12 12:18 getIt-GET.sock

Also journal log looks OK (this from journalctl -f, ie no filtering, so I don't think I'm missing anything there):

May 12 12:19:24 delta.lan.smithnet DuetWebServer[764]: Microsoft.AspNetCore.Hosting.Diagnostics[1] Request starting HTTP/1.1 GET http://localhost/machine/custom/getIt - -
May 12 12:19:24 delta.lan.smithnet DuetWebServer[764]: DuetWebServer.Singletons.SessionStorage[0] Session af57b5fc46e241e2838aff23d84c2d9c added (readWrite)
May 12 12:19:24 delta.lan.smithnet DuetWebServer[764]: Microsoft.AspNetCore.Hosting.Diagnostics[2] Request finished HTTP/1.1 GET http://localhost/machine/custom/getIt - - - 200 0 - 28.3188ms
May 12 12:19:32 delta.lan.smithnet DuetWebServer[764]: DuetWebServer.Singletons.SessionStorage[0] Session af57b5fc46e241e2838aff23d84c2d9c expired

I can't find anything untoward in any other logs I've looked in.

If I try from Edge on a PC on the LAN it's all very similar - script output looks OK:

recv: {"sessionId":-1,"queries":{},"headers":{"accept":"text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.7","connection":"keep-alive","host":"delta.lan.smithnet","user-Agent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/124.0.0.0 Safari/537.36 Edg/124.0.0.0","accept-Encoding":"gzip, deflate","accept-Language":"en-GB,en;q=0.9,en-US;q=0.8","cache-Control":"max-age=0","upgrade-Insecure-Requests":"1"},"contentType":null,"body":""}
send: {"StatusCode": 200, "Response": "so happy you asked for it!", "ResponseType": "StatusCode"}

nothing untoward in journal log:

May 12 11:56:48 delta.lan.smithnet DuetWebServer[764]: Microsoft.AspNetCore.Hosting.Diagnostics[1] Request starting HTTP/1.1 GET http://delta.lan.smithnet/machine/custom/getIt - -
May 12 11:56:48 delta.lan.smithnet DuetWebServer[764]: DuetWebServer.Singletons.SessionStorage[0] Session 6c608d29a6e94d22bdad493356b5f630 added (readWrite)
May 12 11:56:48 delta.lan.smithnet DuetWebServer[764]: Microsoft.AspNetCore.Hosting.Diagnostics[2] Request finished HTTP/1.1 GET http://delta.lan.smithnet/machine/custom/getIt - - - 200 0 - 15.2017ms
May 12 11:56:56 delta.lan.smithnet DuetWebServer[764]: DuetWebServer.Singletons.SessionStorage[0] Session 6c608d29a6e94d22bdad493356b5f630 expired

Browser is apparently happy (200) but only 92 bytes received on the network and no actual content - the page in the browser is empty. The headers wget reported are 90 bytes (if 2-byte line ending) so no space for any content. It remains as 92 bytes even if I change the response the endpoint is supposed to be sending.

[Falcounet]

@achrn Is your user running the script in the dsf group ?

[achrn]

@Falcounet said in dsf-python-3.5.1rc1 problems with http endpoint not working:

@achrn Is your user running the script in the dsf group ?

Yes.

I've also tried converting the example into a plugin and having it run as dsf but that behaved similarly.
Process is running as dsf:

dsf        35101  0.6  0.5 106340 22272 ?        Sl   13:44   0:00 python3 /opt/dsf/plugins/GetIt/dsf/custom_http_endpoint.py

wget status 200 but zero bytes:

--2024-05-12 13:44:15--  http://localhost/machine/custom/getIt
Resolving localhost (localhost)... ::1, 127.0.0.1
Connecting to localhost (localhost)|::1|:80... connected.
HTTP request sent, awaiting response...
  HTTP/1.1 200 OK
  Content-Length: 0
  Date: Sun, 12 May 2024 12:44:15 GMT
  Server: Kestrel
Length: 0
Saving to: ‘wget.result’

wget.result                            [ <=>                                                           ]       0  --.-KB/s    in 0s

2024-05-12 13:44:15 (0.00 B/s) - ‘wget.result’ saved [0/0]

journal log apparently mostly happy. This is the full install, start, then access the endpoint entries. I note there are a number of lines about CORS policy failed - I don't know what that means. However, it gets to receiving requests. Does the 0 after the 200 in the Request finished line indicate it knows it's sending zero bytes?

May 12 13:44:04 delta.lan.smithnet DuetWebServer[764]: Microsoft.AspNetCore.Hosting.Diagnostics[1] Request starting HTTP/1.1 PUT http://delta.lan.smithnet/machine/plugin application/x-zip-compressed 2544
May 12 13:44:04 delta.lan.smithnet DuetWebServer[764]: Microsoft.AspNetCore.Cors.Infrastructure.CorsService[5] CORS policy execution failed.
May 12 13:44:04 delta.lan.smithnet DuetWebServer[764]: Microsoft.AspNetCore.Cors.Infrastructure.CorsService[6] Request origin http://delta.lan.smithnet does not have permission to access the resource.
May 12 13:44:04 delta.lan.smithnet DuetWebServer[764]: Microsoft.AspNetCore.Routing.EndpointMiddleware[0] Executing endpoint 'DuetWebServer.Controllers.MachineController.InstallPlugin (DuetWebServer)'
May 12 13:44:04 delta.lan.smithnet DuetWebServer[764]: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[3] Route matched with {action = "InstallPlugin", controller = "Machine"}. Executing controller action with signature System.Threading.Tasks.Task`1[Microsoft.AspNetCore.Mvc.IActionResult] InstallPlugin(DuetWebServer.Singletons.ISessionStorage) on controller DuetWebServer.Controllers.MachineController (DuetWebServer).
May 12 13:44:04 delta.lan.smithnet DuetWebServer[764]: DuetWebServer.Singletons.SessionStorage[0] Session 7915ccc3209e4ac2b64bd7e4154e2c40 started a long-running request
May 12 13:44:04 delta.lan.smithnet DuetPluginService[34803]: [info] Plugin GetIt: Installing files
May 12 13:44:04 delta.lan.smithnet DuetPluginService[34803]: [warn] Plugin GetIt: Skipping installation of file LICENSE
May 12 13:44:04 delta.lan.smithnet DuetPluginService[34803]: [warn] Plugin GetIt: Skipping installation of file README.txt
May 12 13:44:04 delta.lan.smithnet DuetPluginService[34803]: [info] Plugin GetIt: File installation complete
May 12 13:44:05 delta.lan.smithnet audit[35098]: AVC apparmor="STATUS" operation="profile_load" profile="unconfined" name="/opt/dsf/plugins/GetIt/**" pid=35098 comm="apparmor_parser"
May 12 13:44:05 delta.lan.smithnet DuetPluginService[34802]: [info] Plugin GetIt: Security profile installed
May 12 13:44:05 delta.lan.smithnet kernel: audit: type=1400 audit(1715517845.132:20): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/opt/dsf/plugins/GetIt/**" pid=35098 comm="apparmor_parser"
May 12 13:44:05 delta.lan.smithnet DuetWebServer[764]: DuetWebServer.Singletons.SessionStorage[0] Session 7915ccc3209e4ac2b64bd7e4154e2c40 finished a long-running request
May 12 13:44:05 delta.lan.smithnet DuetWebServer[764]: Microsoft.AspNetCore.Mvc.StatusCodeResult[1] Executing StatusCodeResult, setting HTTP status code 204
May 12 13:44:05 delta.lan.smithnet DuetWebServer[764]: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[2] Executed action DuetWebServer.Controllers.MachineController.InstallPlugin (DuetWebServer) in 235.1672ms
May 12 13:44:05 delta.lan.smithnet DuetWebServer[764]: Microsoft.AspNetCore.Routing.EndpointMiddleware[1] Executed endpoint 'DuetWebServer.Controllers.MachineController.InstallPlugin (DuetWebServer)'
May 12 13:44:05 delta.lan.smithnet DuetWebServer[764]: Microsoft.AspNetCore.Hosting.Diagnostics[2] Request finished HTTP/1.1 PUT http://delta.lan.smithnet/machine/plugin application/x-zip-compressed 2544 - 204 - - 236.3794ms
May 12 13:44:09 delta.lan.smithnet DuetWebServer[764]: Microsoft.AspNetCore.Hosting.Diagnostics[1] Request starting HTTP/1.1 POST http://delta.lan.smithnet/machine/startPlugin text/plain;charset=UTF-8 5
May 12 13:44:09 delta.lan.smithnet DuetWebServer[764]: Microsoft.AspNetCore.Cors.Infrastructure.CorsService[5] CORS policy execution failed.
May 12 13:44:09 delta.lan.smithnet DuetWebServer[764]: Microsoft.AspNetCore.Cors.Infrastructure.CorsService[6] Request origin http://delta.lan.smithnet does not have permission to access the resource.
May 12 13:44:09 delta.lan.smithnet DuetWebServer[764]: Microsoft.AspNetCore.Routing.EndpointMiddleware[0] Executing endpoint 'DuetWebServer.Controllers.MachineController.StartPlugin (DuetWebServer)'
May 12 13:44:09 delta.lan.smithnet DuetWebServer[764]: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[3] Route matched with {action = "StartPlugin", controller = "Machine"}. Executing controller action with signature System.Threading.Tasks.Task`1[Microsoft.AspNetCore.Mvc.IActionResult] StartPlugin() on controller DuetWebServer.Controllers.MachineController (DuetWebServer).
May 12 13:44:09 delta.lan.smithnet DuetPluginService[34803]: [info] Plugin GetIt: Process has been started (pid 35101)
May 12 13:44:09 delta.lan.smithnet DuetWebServer[764]: Microsoft.AspNetCore.Mvc.StatusCodeResult[1] Executing StatusCodeResult, setting HTTP status code 204
May 12 13:44:09 delta.lan.smithnet DuetWebServer[764]: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[2] Executed action DuetWebServer.Controllers.MachineController.StartPlugin (DuetWebServer) in 24.2977ms
May 12 13:44:09 delta.lan.smithnet DuetWebServer[764]: Microsoft.AspNetCore.Routing.EndpointMiddleware[1] Executed endpoint 'DuetWebServer.Controllers.MachineController.StartPlugin (DuetWebServer)'
May 12 13:44:09 delta.lan.smithnet DuetWebServer[764]: Microsoft.AspNetCore.Hosting.Diagnostics[2] Request finished HTTP/1.1 POST http://delta.lan.smithnet/machine/startPlugin text/plain;charset=UTF-8 5 - 204 - - 25.5820ms
May 12 13:44:15 delta.lan.smithnet DuetWebServer[764]: Microsoft.AspNetCore.Hosting.Diagnostics[1] Request starting HTTP/1.1 GET http://localhost/machine/custom/getIt - -
May 12 13:44:15 delta.lan.smithnet DuetWebServer[764]: DuetWebServer.Singletons.SessionStorage[0] Session 91ff25abfd93499e9aa1031eb2cf0415 added (readWrite)
May 12 13:44:15 delta.lan.smithnet DuetWebServer[764]: Microsoft.AspNetCore.Hosting.Diagnostics[2] Request finished HTTP/1.1 GET http://localhost/machine/custom/getIt - - - 200 0 - 17.6863ms
May 12 13:44:23 delta.lan.smithnet DuetWebServer[764]: DuetWebServer.Singletons.SessionStorage[0] Session 91ff25abfd93499e9aa1031eb2cf0415 expired

[Falcounet]

I do confirm the permission on the socket file being incorrect as there is no write permission for the group :

$ ls -al /run/dsf/custom/getIt-GET.sock
srwxr-xr-x+ 1 loic dsf 0 May 12 13:46 /run/dsf/custom/getIt-GET.sock

I think this is related to the Bookworm image.
However, granting the write permission for dsf group makes the request to return HTTP 200 code and I confirm I doesn't get the "so happy you asked for it!" response neither.

This response is being sent to DSF as we can see it in the dsf-python debug lines : send: {"StatusCode": 200, "Response": "so happy you asked for it!", "ResponseType": "StatusCode"}

It is probably one for @chrishamm to look at.