__init__.py 30 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454455456457458459460461462463464465466467468469470471472473474475476477478479480481482483484485486487488489490491492493494495496497498499500501502503504505506507508509510511512513514515516517518519520521522523524525526527528529530531532533534535536537538539540541542543544545546547548549550551552553554555556
  1. # This file is part of Radicale - CalDAV and CardDAV server
  2. # Copyright © 2008 Nicolas Kandel
  3. # Copyright © 2008 Pascal Halter
  4. # Copyright © 2008-2017 Guillaume Ayoub
  5. # Copyright © 2017-2019 Unrud <unrud@outlook.com>
  6. # Copyright © 2024-2025 Peter Bieringer <pb@bieringer.de>
  7. #
  8. # This library is free software: you can redistribute it and/or modify
  9. # it under the terms of the GNU General Public License as published by
  10. # the Free Software Foundation, either version 3 of the License, or
  11. # (at your option) any later version.
  12. #
  13. # This library is distributed in the hope that it will be useful,
  14. # but WITHOUT ANY WARRANTY; without even the implied warranty of
  15. # MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
  16. # GNU General Public License for more details.
  17. #
  18. # You should have received a copy of the GNU General Public License
  19. # along with Radicale. If not, see <http://www.gnu.org/licenses/>.
  20. """
  21. Radicale WSGI application.
  22. Can be used with an external WSGI server (see ``radicale.application()``) or
  23. the built-in server (see ``radicale.server`` module).
  24. """
  25. import base64
  26. import cProfile
  27. import datetime
  28. import io
  29. import pprint
  30. import pstats
  31. import random
  32. import time
  33. import zlib
  34. from http import client
  35. from typing import Iterable, List, Mapping, Tuple, Union
  36. from radicale import config, httputils, log, pathutils, types, utils
  37. from radicale.app.base import ApplicationBase
  38. from radicale.app.delete import ApplicationPartDelete
  39. from radicale.app.get import ApplicationPartGet
  40. from radicale.app.head import ApplicationPartHead
  41. from radicale.app.mkcalendar import ApplicationPartMkcalendar
  42. from radicale.app.mkcol import ApplicationPartMkcol
  43. from radicale.app.move import ApplicationPartMove
  44. from radicale.app.options import ApplicationPartOptions
  45. from radicale.app.post import ApplicationPartPost
  46. from radicale.app.propfind import ApplicationPartPropfind
  47. from radicale.app.proppatch import ApplicationPartProppatch
  48. from radicale.app.put import ApplicationPartPut
  49. from radicale.app.report import ApplicationPartReport
  50. from radicale.auth import AuthContext
  51. from radicale.log import logger
  52. # Combination of types.WSGIStartResponse and WSGI application return value
  53. _IntermediateResponse = Tuple[str, List[Tuple[str, str]], Iterable[bytes]]
  54. REQUEST_METHODS = ["DELETE", "GET", "HEAD", "MKCALENDAR", "MKCOL", "MOVE", "OPTIONS", "POST", "PROPFIND", "PROPPATCH", "PUT", "REPORT"]
  55. class Application(ApplicationPartDelete, ApplicationPartHead,
  56. ApplicationPartGet, ApplicationPartMkcalendar,
  57. ApplicationPartMkcol, ApplicationPartMove,
  58. ApplicationPartOptions, ApplicationPartPropfind,
  59. ApplicationPartProppatch, ApplicationPartPost,
  60. ApplicationPartPut, ApplicationPartReport, ApplicationBase):
  61. """WSGI application."""
  62. _mask_passwords: bool
  63. _auth_delay: float
  64. _internal_server: bool
  65. _max_content_length: int
  66. _max_resource_size: int
  67. _auth_realm: str
  68. _auth_type: str
  69. _web_type: str
  70. _script_name: str
  71. _extra_headers: Mapping[str, str]
  72. _profiling_per_request: bool = False
  73. _profiling_per_request_method: bool = False
  74. profiler_per_request_method: dict[str, cProfile.Profile] = {}
  75. profiler_per_request_method_counter: dict[str, int] = {}
  76. profiler_per_request_method_starttime: datetime.datetime
  77. profiler_per_request_method_logtime: datetime.datetime
  78. def __init__(self, configuration: config.Configuration) -> None:
  79. """Initialize Application.
  80. ``configuration`` see ``radicale.config`` module.
  81. The ``configuration`` must not change during the lifetime of
  82. this object, it is kept as an internal reference.
  83. """
  84. super().__init__(configuration)
  85. self._mask_passwords = configuration.get("logging", "mask_passwords")
  86. self._max_content_length = configuration.get("server", "max_content_length")
  87. self._max_resource_size = configuration.get("server", "max_resource_size")
  88. logger.info("max_content_length set to: %d bytes (%sbytes)", self._max_content_length, utils.format_unit(self._max_content_length, binary=True))
  89. if (self._max_resource_size > (self._max_content_length * 0.8)):
  90. max_resource_size_limited = int(self._max_content_length * 0.8)
  91. logger.warning("max_resource_size set to: %d bytes (%sbytes) (capped from %d to 80%% of max_content_length)", max_resource_size_limited, utils.format_unit(max_resource_size_limited, binary=True), self._max_resource_size)
  92. self._max_resource_size = max_resource_size_limited
  93. else:
  94. logger.info("max_resource_size set to: %d bytes (%sbytes)", self._max_resource_size, utils.format_unit(self._max_resource_size, binary=True))
  95. self._bad_put_request_content = configuration.get("logging", "bad_put_request_content")
  96. logger.info("log bad put request content: %s", self._bad_put_request_content)
  97. self._request_header_on_debug = configuration.get("logging", "request_header_on_debug")
  98. self._request_content_on_debug = configuration.get("logging", "request_content_on_debug")
  99. self._response_header_on_debug = configuration.get("logging", "response_header_on_debug")
  100. self._response_content_on_debug = configuration.get("logging", "response_content_on_debug")
  101. logger.debug("log request header on debug: %s", self._request_header_on_debug)
  102. logger.debug("log request content on debug: %s", self._request_content_on_debug)
  103. logger.debug("log response header on debug: %s", self._response_header_on_debug)
  104. logger.debug("log response content on debug: %s", self._response_content_on_debug)
  105. self._auth_delay = configuration.get("auth", "delay")
  106. self._auth_type = configuration.get("auth", "type")
  107. self._web_type = configuration.get("web", "type")
  108. self._internal_server = configuration.get("server", "_internal_server")
  109. self._script_name = configuration.get("server", "script_name")
  110. if self._script_name:
  111. if self._script_name[0] != "/":
  112. logger.error("server.script_name must start with '/': %r", self._script_name)
  113. raise RuntimeError("server.script_name option has to start with '/'")
  114. else:
  115. if self._script_name.endswith("/"):
  116. logger.error("server.script_name must not end with '/': %r", self._script_name)
  117. raise RuntimeError("server.script_name option must not end with '/'")
  118. else:
  119. logger.info("Provided script name to strip from URI if called by reverse proxy: %r", self._script_name)
  120. else:
  121. logger.info("Default script name to strip from URI if called by reverse proxy is taken from HTTP_X_SCRIPT_NAME or SCRIPT_NAME")
  122. self._max_content_length = configuration.get(
  123. "server", "max_content_length")
  124. self._auth_realm = configuration.get("auth", "realm")
  125. self._permit_delete_collection = configuration.get("rights", "permit_delete_collection")
  126. logger.info("permit delete of collection: %s", self._permit_delete_collection)
  127. self._permit_overwrite_collection = configuration.get("rights", "permit_overwrite_collection")
  128. logger.info("permit overwrite of collection: %s", self._permit_overwrite_collection)
  129. self._extra_headers = dict()
  130. for key in self.configuration.options("headers"):
  131. self._extra_headers[key] = configuration.get("headers", key)
  132. self._strict_preconditions = configuration.get("storage", "strict_preconditions")
  133. logger.info("strict preconditions check: %s", self._strict_preconditions)
  134. # Profiling options
  135. self._profiling = configuration.get("logging", "profiling")
  136. self._profiling_per_request_min_duration = configuration.get("logging", "profiling_per_request_min_duration")
  137. self._profiling_per_request_header = configuration.get("logging", "profiling_per_request_header")
  138. self._profiling_per_request_xml = configuration.get("logging", "profiling_per_request_xml")
  139. self._profiling_per_request_method_interval = configuration.get("logging", "profiling_per_request_method_interval")
  140. self._profiling_top_x_functions = configuration.get("logging", "profiling_top_x_functions")
  141. if self._profiling in config.PROFILING:
  142. logger.info("profiling: %r", self._profiling)
  143. if self._profiling == "per_request":
  144. self._profiling_per_request = True
  145. elif self._profiling == "per_request_method":
  146. self._profiling_per_request_method = True
  147. if self._profiling_per_request or self._profiling_per_request_method:
  148. logger.info("profiling top X functions: %d", self._profiling_top_x_functions)
  149. if self._profiling_per_request:
  150. logger.info("profiling per request minimum duration: %d (below are skipped)", self._profiling_per_request_min_duration)
  151. logger.info("profiling per request header: %s", self._profiling_per_request_header)
  152. logger.info("profiling per request xml : %s", self._profiling_per_request_xml)
  153. if self._profiling_per_request_method:
  154. logger.info("profiling per request method interval: %d seconds", self._profiling_per_request_method_interval)
  155. # Profiling per request method initialization
  156. if self._profiling_per_request_method:
  157. for method in REQUEST_METHODS:
  158. self.profiler_per_request_method[method] = cProfile.Profile()
  159. self.profiler_per_request_method_counter[method] = False
  160. self.profiler_per_request_method_starttime = datetime.datetime.now()
  161. self.profiler_per_request_method_logtime = self.profiler_per_request_method_starttime
  162. def __del__(self) -> None:
  163. """Shutdown application."""
  164. if self._profiling_per_request_method:
  165. # Profiling since startup
  166. self._profiler_per_request_method(True)
  167. def _profiler_per_request_method(self, shutdown: bool = False) -> None:
  168. """Display profiler data per method."""
  169. profiler_timedelta_start = (datetime.datetime.now() - self.profiler_per_request_method_starttime).total_seconds()
  170. for method in REQUEST_METHODS:
  171. if self.profiler_per_request_method_counter[method] > 0:
  172. s = io.StringIO()
  173. s.write("**Profiling statistics BEGIN**\n")
  174. stats = pstats.Stats(self.profiler_per_request_method[method], stream=s).sort_stats('cumulative')
  175. stats.print_stats(self._profiling_top_x_functions) # Print top X functions
  176. s.write("**Profiling statistics END**\n")
  177. logger.info("Profiling data per request method %s after %d seconds and %d requests:\n%s", method, profiler_timedelta_start, self.profiler_per_request_method_counter[method], utils.textwrap_str(s.getvalue(), -1))
  178. else:
  179. if shutdown:
  180. logger.info("Profiling data per request method %s after %d seconds: (no request seen so far)", method, profiler_timedelta_start)
  181. else:
  182. logger.debug("Profiling data per request method %s after %d seconds: (no request seen so far)", method, profiler_timedelta_start)
  183. def _scrub_headers(self, environ: types.WSGIEnviron) -> types.WSGIEnviron:
  184. """Mask passwords and cookies."""
  185. headers = dict(environ)
  186. if (self._mask_passwords and
  187. headers.get("HTTP_AUTHORIZATION", "").startswith("Basic")):
  188. headers["HTTP_AUTHORIZATION"] = "Basic **masked**"
  189. if headers.get("HTTP_COOKIE"):
  190. headers["HTTP_COOKIE"] = "**masked**"
  191. return headers
  192. def __call__(self, environ: types.WSGIEnviron, start_response:
  193. types.WSGIStartResponse) -> Iterable[bytes]:
  194. with log.register_stream(environ["wsgi.errors"]):
  195. try:
  196. status_text, headers, answers = self._handle_request(environ)
  197. except Exception as e:
  198. logger.error("An exception occurred during %s request on %r: "
  199. "%s", environ.get("REQUEST_METHOD", "unknown"),
  200. environ.get("PATH_INFO", ""), e, exc_info=True)
  201. # Make minimal response
  202. status, raw_headers, raw_answer, xml_request = (
  203. httputils.INTERNAL_SERVER_ERROR)
  204. assert isinstance(raw_answer, str)
  205. answer = raw_answer.encode("ascii")
  206. status_text = "%d %s" % (
  207. status, client.responses.get(status, "Unknown"))
  208. headers = [*raw_headers, ("Content-Length", str(len(answer)))]
  209. answers = [answer]
  210. start_response(status_text, headers)
  211. if environ.get("REQUEST_METHOD") == "HEAD":
  212. return []
  213. return answers
  214. def _handle_request(self, environ: types.WSGIEnviron
  215. ) -> _IntermediateResponse:
  216. time_begin = datetime.datetime.now()
  217. request_method = environ["REQUEST_METHOD"].upper()
  218. unsafe_path = environ.get("PATH_INFO", "")
  219. https = environ.get("HTTPS", "")
  220. profiler = None
  221. profiler_active = False
  222. xml_request = None
  223. context = AuthContext()
  224. """Manage a request."""
  225. def response(status: int, headers: types.WSGIResponseHeaders,
  226. answer: Union[None, str, bytes],
  227. xml_request: Union[None, str] = None) -> _IntermediateResponse:
  228. """Helper to create response from internal types.WSGIResponse"""
  229. headers = dict(headers)
  230. content_encoding = "plain"
  231. # Set content length
  232. answers = []
  233. if answer is not None:
  234. if isinstance(answer, str):
  235. if self._response_content_on_debug:
  236. logger.debug("Response content (nonXML):\n%s", utils.textwrap_str(answer))
  237. else:
  238. logger.debug("Response content: suppressed by config/option [logging] response_content_on_debug")
  239. headers["Content-Type"] += "; charset=%s" % self._encoding
  240. answer = answer.encode(self._encoding)
  241. accept_encoding = [
  242. encoding.strip() for encoding in
  243. environ.get("HTTP_ACCEPT_ENCODING", "").split(",")
  244. if encoding.strip()]
  245. if "gzip" in accept_encoding:
  246. zcomp = zlib.compressobj(wbits=16 + zlib.MAX_WBITS)
  247. answer = zcomp.compress(answer) + zcomp.flush()
  248. headers["Content-Encoding"] = "gzip"
  249. content_encoding = "gzip"
  250. headers["Content-Length"] = str(len(answer))
  251. answers.append(answer)
  252. # Add extra headers set in configuration
  253. headers.update(self._extra_headers)
  254. if self._response_header_on_debug:
  255. logger.debug("Response header:\n%s", utils.textwrap_str(pprint.pformat(headers)))
  256. else:
  257. logger.debug("Response header: suppressed by config/option [logging] response_header_on_debug")
  258. # Start response
  259. time_end = datetime.datetime.now()
  260. time_delta_seconds = (time_end - time_begin).total_seconds()
  261. status_text = "%d %s" % (
  262. status, client.responses.get(status, "Unknown"))
  263. flags = []
  264. if xml_request is not None:
  265. if "<sync-token />" in xml_request:
  266. flags.append("sync-token")
  267. if "<CS:getctag />" in xml_request:
  268. flags.append("getctag")
  269. if flags:
  270. flags_text = " (" + " ".join(flags) + ")"
  271. else:
  272. flags_text = ""
  273. if answer is not None:
  274. logger.info("%s response status for %r%s in %.3f seconds %s %s bytes%s: %s",
  275. request_method, unsafe_path, depthinfo,
  276. (time_end - time_begin).total_seconds(), content_encoding, str(len(answer)),
  277. flags_text,
  278. status_text)
  279. else:
  280. logger.info("%s response status for %r%s in %.3f seconds: %s",
  281. request_method, unsafe_path, depthinfo,
  282. time_delta_seconds, status_text)
  283. # Profiling end
  284. if self._profiling_per_request:
  285. if profiler_active is True:
  286. if profiler is not None:
  287. # Profiling per request
  288. if time_delta_seconds < self._profiling_per_request_min_duration:
  289. logger.debug("Profiling data per request %s for %r%s: (suppressed because duration below minimum %.3f < %.3f)", request_method, unsafe_path, depthinfo, time_delta_seconds, self._profiling_per_request_min_duration)
  290. else:
  291. s = io.StringIO()
  292. s.write("**Profiling statistics BEGIN**\n")
  293. stats = pstats.Stats(profiler, stream=s).sort_stats('cumulative')
  294. stats.print_stats(self._profiling_top_x_functions) # Print top X functions
  295. s.write("**Profiling statistics END**\n")
  296. if self._profiling_per_request_header:
  297. s.write("**Profiling request header BEGIN**\n")
  298. s.write(pprint.pformat(self._scrub_headers(environ)))
  299. s.write("\n**Profiling request header END**")
  300. if self._profiling_per_request_xml:
  301. if xml_request is not None:
  302. s.write("\n**Profiling request content (XML) BEGIN**\n")
  303. if xml_request is not None:
  304. s.write(xml_request)
  305. s.write("**Profiling request content (XML) END**")
  306. logger.info("Profiling data per request %s for %r%s:\n%s", request_method, unsafe_path, depthinfo, utils.textwrap_str(s.getvalue(), -1))
  307. else:
  308. logger.debug("Profiling data per request %s for %r%s: (suppressed because of no data)", request_method, unsafe_path, depthinfo)
  309. else:
  310. logger.info("Profiling data per request %s for %r%s: (not available because of concurrent running profiling request)", request_method, unsafe_path, depthinfo)
  311. elif self._profiling_per_request_method:
  312. self.profiler_per_request_method[request_method].disable()
  313. self.profiler_per_request_method_counter[request_method] += 1
  314. profiler_timedelta = (datetime.datetime.now() - self.profiler_per_request_method_logtime).total_seconds()
  315. if profiler_timedelta > self._profiling_per_request_method_interval:
  316. self._profiler_per_request_method()
  317. self.profiler_per_request_method_logtime = datetime.datetime.now()
  318. # Return response content
  319. return status_text, list(headers.items()), answers
  320. reverse_proxy = False
  321. remote_host = "unknown"
  322. if environ.get("REMOTE_HOST"):
  323. remote_host = repr(environ["REMOTE_HOST"])
  324. if environ.get("REMOTE_ADDR"):
  325. if remote_host == 'unknown':
  326. remote_host = environ["REMOTE_ADDR"]
  327. context.remote_addr = environ["REMOTE_ADDR"]
  328. if environ.get("HTTP_X_FORWARDED_FOR"):
  329. reverse_proxy = True
  330. remote_host = "%s (forwarded for %r)" % (
  331. remote_host, environ["HTTP_X_FORWARDED_FOR"])
  332. if environ.get("HTTP_X_REMOTE_ADDR"):
  333. context.x_remote_addr = environ["HTTP_X_REMOTE_ADDR"]
  334. if environ.get("HTTP_X_FORWARDED_HOST") or environ.get("HTTP_X_FORWARDED_PROTO") or environ.get("HTTP_X_FORWARDED_SERVER"):
  335. reverse_proxy = True
  336. remote_useragent = ""
  337. if environ.get("HTTP_USER_AGENT"):
  338. remote_useragent = " using %r" % environ["HTTP_USER_AGENT"]
  339. depthinfo = ""
  340. if environ.get("HTTP_DEPTH"):
  341. depthinfo = " with depth %r" % environ["HTTP_DEPTH"]
  342. if https:
  343. https_info = " " + environ.get("SSL_PROTOCOL", "") + " " + environ.get("SSL_CIPHER", "")
  344. else:
  345. https_info = ""
  346. logger.info("%s request for %r%s received from %s%s%s",
  347. request_method, unsafe_path, depthinfo,
  348. remote_host, remote_useragent, https_info)
  349. if self._request_header_on_debug:
  350. logger.debug("Request header:\n%s",
  351. utils.textwrap_str(pprint.pformat(self._scrub_headers(environ))))
  352. else:
  353. logger.debug("Request header: suppressed by config/option [logging] request_header_on_debug")
  354. # SCRIPT_NAME is already removed from PATH_INFO, according to the
  355. # WSGI specification.
  356. # Reverse proxies can overwrite SCRIPT_NAME with X-SCRIPT-NAME header
  357. if self._script_name and (reverse_proxy is True):
  358. base_prefix_src = "config"
  359. base_prefix = self._script_name
  360. else:
  361. base_prefix_src = ("HTTP_X_SCRIPT_NAME" if "HTTP_X_SCRIPT_NAME" in
  362. environ else "SCRIPT_NAME")
  363. base_prefix = environ.get(base_prefix_src, "")
  364. if base_prefix and base_prefix[0] != "/":
  365. logger.error("Base prefix (from %s) must start with '/': %r",
  366. base_prefix_src, base_prefix)
  367. if base_prefix_src == "HTTP_X_SCRIPT_NAME":
  368. return response(*httputils.BAD_REQUEST)
  369. return response(*httputils.INTERNAL_SERVER_ERROR)
  370. if base_prefix.endswith("/"):
  371. logger.warning("Base prefix (from %s) must not end with '/': %r",
  372. base_prefix_src, base_prefix)
  373. base_prefix = base_prefix.rstrip("/")
  374. if base_prefix:
  375. logger.debug("Base prefix (from %s): %r", base_prefix_src, base_prefix)
  376. # Sanitize request URI (a WSGI server indicates with an empty path,
  377. # that the URL targets the application root without a trailing slash)
  378. path = pathutils.sanitize_path(unsafe_path)
  379. logger.debug("Sanitized path: %r", path)
  380. if (reverse_proxy is True) and (len(base_prefix) > 0):
  381. if path.startswith(base_prefix):
  382. path_new = path.removeprefix(base_prefix)
  383. logger.debug("Called by reverse proxy, remove base prefix %r from path: %r => %r", base_prefix, path, path_new)
  384. path = path_new
  385. else:
  386. if self._auth_type in ['remote_user', 'http_remote_user', 'http_x_remote_user'] and self._web_type == 'internal':
  387. logger.warning("Called by reverse proxy, cannot remove base prefix %r from path: %r as not matching (may cause authentication issues using internal WebUI)", base_prefix, path)
  388. else:
  389. logger.debug("Called by reverse proxy, cannot remove base prefix %r from path: %r as not matching", base_prefix, path)
  390. # Get function corresponding to method
  391. function = getattr(self, "do_%s" % request_method, None)
  392. if not function:
  393. return response(*httputils.METHOD_NOT_ALLOWED)
  394. # Redirect all "…/.well-known/{caldav,carddav}" paths to "/".
  395. # This shouldn't be necessary but some clients like TbSync require it.
  396. # Status must be MOVED PERMANENTLY using FOUND causes problems
  397. if (path.rstrip("/").endswith("/.well-known/caldav") or
  398. path.rstrip("/").endswith("/.well-known/carddav")):
  399. return response(*httputils.redirect(
  400. base_prefix + "/", client.MOVED_PERMANENTLY))
  401. # Return NOT FOUND for all other paths containing ".well-known"
  402. if path.endswith("/.well-known") or "/.well-known/" in path:
  403. return response(*httputils.NOT_FOUND)
  404. # Ask authentication backend to check rights
  405. login = password = ""
  406. external_login = self._auth.get_external_login(environ)
  407. authorization = environ.get("HTTP_AUTHORIZATION", "")
  408. if external_login:
  409. login, password = external_login
  410. login, password = login or "", password or ""
  411. elif authorization.startswith("Basic"):
  412. authorization = authorization[len("Basic"):].strip()
  413. login, password = httputils.decode_request(
  414. self.configuration, environ, base64.b64decode(
  415. authorization.encode("ascii"))).split(":", 1)
  416. (user, info) = self._auth.login(login, password, context) or ("", "") if login else ("", "")
  417. if self.configuration.get("auth", "type") == "ldap":
  418. try:
  419. logger.debug("Groups received from LDAP: %r", ",".join(self._auth._ldap_groups))
  420. self._rights._user_groups = self._auth._ldap_groups
  421. except AttributeError:
  422. pass
  423. if user and login == user:
  424. logger.info("Successful login: %r (%s)", user, info)
  425. elif user:
  426. logger.info("Successful login: %r -> %r (%s)", login, user, info)
  427. elif login:
  428. logger.warning("Failed login attempt from %s: %r (%s)",
  429. remote_host, login, info)
  430. # Random delay to avoid timing oracles and bruteforce attacks
  431. if self._auth_delay > 0:
  432. random_delay = self._auth_delay * (0.5 + random.random())
  433. logger.debug("Failed login, sleeping random: %.3f sec", random_delay)
  434. time.sleep(random_delay)
  435. if user and not pathutils.is_safe_path_component(user):
  436. # Prevent usernames like "user/calendar.ics"
  437. logger.info("Refused unsafe username: %r", user)
  438. user = ""
  439. # Create principal collection
  440. if user:
  441. principal_path = "/%s/" % user
  442. with self._storage.acquire_lock("r", user):
  443. principal = next(iter(self._storage.discover(
  444. principal_path, depth="1")), None)
  445. if not principal:
  446. if "W" in self._rights.authorization(user, principal_path):
  447. with self._storage.acquire_lock("w", user):
  448. try:
  449. new_coll, _, _ = self._storage.create_collection(principal_path)
  450. if new_coll:
  451. jsn_coll = self.configuration.get("storage", "predefined_collections")
  452. for (name_coll, props) in jsn_coll.items():
  453. try:
  454. self._storage.create_collection(principal_path + name_coll, props=props)
  455. except ValueError as e:
  456. logger.warning("Failed to create predefined collection %r: %s", name_coll, e)
  457. except ValueError as e:
  458. logger.warning("Failed to create principal "
  459. "collection %r: %s", user, e)
  460. user = ""
  461. else:
  462. logger.warning("Access to principal path %r denied by "
  463. "rights backend", principal_path)
  464. if self._internal_server:
  465. # Verify content length
  466. content_length = int(environ.get("CONTENT_LENGTH") or 0)
  467. if content_length:
  468. if (self._max_content_length > 0 and
  469. content_length > self._max_content_length):
  470. logger.info("Request body too large: %d", content_length)
  471. return response(*httputils.REQUEST_ENTITY_TOO_LARGE)
  472. if not login or user:
  473. # Profiling
  474. if self._profiling_per_request:
  475. profiler = cProfile.Profile()
  476. try:
  477. profiler.enable()
  478. except ValueError:
  479. profiler_active = False
  480. else:
  481. profiler_active = True
  482. elif self._profiling_per_request_method:
  483. try:
  484. self.profiler_per_request_method[request_method].enable()
  485. except ValueError:
  486. profiler_active = False
  487. else:
  488. profiler_active = True
  489. status, headers, answer, xml_request = function(
  490. environ, base_prefix, path, user, remote_host, remote_useragent)
  491. # Profiling
  492. if self._profiling_per_request:
  493. if profiler is not None:
  494. if profiler_active is True:
  495. profiler.disable()
  496. elif self._profiling_per_request_method:
  497. if profiler_active is True:
  498. self.profiler_per_request_method[request_method].disable()
  499. if (status, headers, answer, xml_request) == httputils.NOT_ALLOWED:
  500. logger.info("Access to %r denied for %s", path,
  501. repr(user) if user else "anonymous user")
  502. else:
  503. status, headers, answer, xml_request = httputils.NOT_ALLOWED
  504. if ((status, headers, answer, xml_request) == httputils.NOT_ALLOWED and not user and
  505. not external_login):
  506. # Unknown or unauthorized user
  507. logger.debug("Asking client for authentication")
  508. status = client.UNAUTHORIZED
  509. headers = dict(headers)
  510. headers.update({
  511. "WWW-Authenticate":
  512. "Basic realm=\"%s\"" % self._auth_realm})
  513. return response(status, headers, answer, xml_request)