satosa.exception.SATOSAUnknownError: Unknown error in the log

pettai commented 2 days ago

Code Version

v8.4.0

Expected Behavior

Try to catch this error to avoid all the tracebacks in log, please

Current Behavior

Lots of Tracebacks like this in the logs:

[...]
2024-09-17 11:49:29,655 [981] [DEBUG] read request data: None
2024-09-17 11:49:29,657 [981] [DEBUG] [urn:uuid:ac232a68-38a0-43ca-b165-94708723e5f0] Loaded state {'SESSION_ID': 'urn:uuid:ac232a68-38a0-43ca-b165-94708723e5f0'} from cookie
2024-09-17 11:49:29,658 [981] [DEBUG] [urn:uuid:ac232a68-38a0-43ca-b165-94708723e5f0] Routing path: Saml2SP/sso/redirect
2024-09-17 11:49:29,658 [981] [DEBUG] [urn:uuid:ac232a68-38a0-43ca-b165-94708723e5f0] Found registered endpoint: module name:'Saml2IDP', endpoint: Saml2SP/sso/redirect
2024-09-17 11:49:29,659 [981] [ERROR] [urn:uuid:ac232a68-38a0-43ca-b165-94708723e5f0] Uncaught exception
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/satosa/base.py", line 254, in run
    resp = self._run_bound_endpoint(context, spec)
  File "/usr/local/lib/python3.9/site-packages/satosa/base.py", line 179, in _run_bound_endpoint
    return spec(context)
  File "/usr/local/lib/python3.9/site-packages/satosa/frontends/saml2.py", line 100, in handle_authn_request
    return self._handle_authn_request(context, binding_in, self.idp)
  File "/usr/local/lib/python3.9/site-packages/satosa/frontends/saml2.py", line 193, in _handle_authn_request
    req_info = idp.parse_authn_request(context.request["SAMLRequest"], binding_in)
TypeError: 'NoneType' object is not subscriptable
2024-09-17 11:49:29,659 [981] [ERROR] Unknown error
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/satosa/base.py", line 254, in run
    resp = self._run_bound_endpoint(context, spec)
  File "/usr/local/lib/python3.9/site-packages/satosa/base.py", line 179, in _run_bound_endpoint
    return spec(context)
  File "/usr/local/lib/python3.9/site-packages/satosa/frontends/saml2.py", line 100, in handle_authn_request
    return self._handle_authn_request(context, binding_in, self.idp)
  File "/usr/local/lib/python3.9/site-packages/satosa/frontends/saml2.py", line 193, in _handle_authn_request
    req_info = idp.parse_authn_request(context.request["SAMLRequest"], binding_in)
TypeError: 'NoneType' object is not subscriptable

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/satosa/proxy_server.py", line 147, in __call__
    resp = self.run(context)
  File "/usr/local/lib/python3.9/site-packages/satosa/base.py", line 272, in run
    raise SATOSAUnknownError("Unknown error") from err
satosa.exception.SATOSAUnknownError: Unknown error

Possible Solution

Steps to Reproduce

Let SATOSA run on the Internet
Observe what SATOSA logs

c00kiemon5ter commented 2 days ago

The immediate issue is that context.request does not have a value. This should be happening when the request does not have a body or query params. You can see this early by

read request data: None

In practice, this means that this was caused by a HEAD request.

Either the proxy should check and drop HEAD requests, or you handle this from the Web Server that sits in front of the proxy (HAProxy, nginx, etc).

This is not critical issue, but it is good to add a handler to avoid these exceptions. We need to agree on the behaviour/response and ensure that the response will not affect the follow-up "normal" request.

pettai commented 2 days ago

The example above was perhaps the best, and perhaps incomplete.

Some more logs (but these doesn't seem to cause a exception at least)

[...]
2024-09-17 01:21:24,719 [1140] [DEBUG] read request data: {}
2024-09-17 01:21:24,722 [1140] [DEBUG] [urn:uuid:1beae8ae-6681-4269-9968-f547936076ff] Loaded state {'SESSION_ID': 'urn:uuid:1beae8ae-6681-4269-9968-f547936076ff'} from cookie
2024-09-17 01:21:24,722 [1140] [DEBUG] [urn:uuid:1beae8ae-6681-4269-9968-f547936076ff] Routing path: favicon.ico
2024-09-17 01:21:24,724 [1140] [DEBUG] [urn:uuid:1beae8ae-6681-4269-9968-f547936076ff] Unknown backend favicon.ico

2024-09-17 01:21:25,449 [1140] [DEBUG] read request data: {}
2024-09-17 01:21:25,450 [1140] [DEBUG] [urn:uuid:04d62bd7-bd4f-423d-a987-cc264eea68dd] Loaded state {'SESSION_ID': 'urn:uuid:04d62bd7-bd4f-423d-a987-cc264eea68dd'} from cookie
2024-09-17 01:21:25,451 [1140] [DEBUG] [urn:uuid:04d62bd7-bd4f-423d-a987-cc264eea68dd] Routing path: sitemap.xml
2024-09-17 01:21:25,451 [1140] [DEBUG] [urn:uuid:04d62bd7-bd4f-423d-a987-cc264eea68dd] Unknown backend sitemap.xml
2024-09-17 01:21:25,452 [1140] [DEBUG] [urn:uuid:04d62bd7-bd4f-423d-a987-cc264eea68dd] 'sitemap.xml' not bound to any function
2024-09-17 01:21:25,462 [1031] [DEBUG] read request data: {}
2024-09-17 01:21:25,462 [1031] [DEBUG] [urn:uuid:54172e51-685f-43ff-8948-9896ab7e78bc] Loaded state {'SESSION_ID': 'urn:uuid:54172e51-685f-43ff-8948-9896ab7e78bc'} from cookie
2024-09-17 01:21:25,463 [1031] [DEBUG] [urn:uuid:54172e51-685f-43ff-8948-9896ab7e78bc] Routing path: robots.txt
2024-09-17 01:21:25,463 [1031] [DEBUG] [urn:uuid:54172e51-685f-43ff-8948-9896ab7e78bc] Unknown backend robots.txt
2024-09-17 01:21:25,464 [1031] [DEBUG] [urn:uuid:54172e51-685f-43ff-8948-9896ab7e78bc] 'robots.txt' not bound to any function

etc. etc.

You're probably right, make the handler deal with HEAD request to stop the exceptions filling the log would be a good thing 👍

pettai commented 2 days ago

(btw. some (poor-mans) loadbalancers uses HEAD requests to check that a web-service is up and running)

vladimir-mencl-eresearch commented 1 day ago

I've also seen HEAD requests causing issues with other applications - triggered by Safe Browsing feature in Microsoft (web) Outlook. When clicking on a link in an email, Microsoft first sends a HEAD to the URL to "check it" before actually opening the link in your browser.

Not sure if this is what caused the HEAD requests here ....

IdentityPython / SATOSA