def _fail(self, value, contextinfo=None, srcexception=None, errcondition=None):
"""Wrapper to raise (and log) DAVError."""
e = DAVError(value, contextinfo, srcexception, errcondition)
if self.verbose >= 4:
_logger.warn("Raising DAVError {}".format(
safe_re_encode(e.get_user_info(), sys.stdout.encoding)))
raise e
def _fail(self, value, context_info=None, src_exception=None, err_condition=None):
"""Wrapper to raise (and log) DAVError."""
e = DAVError(value, context_info, src_exception, err_condition)
if self.verbose >= 4:
_logger.warning(
"Raising DAVError {}".format(
safe_re_encode(e.get_user_info(), sys.stdout.encoding)
)
)
raise e
def get_domain_realm(self, inputURL, environ):
"""Resolve a relative url to the appropriate realm name."""
# we don't get the realm here, its already been resolved in
# request_resolver
davProvider = environ["wsgidav.provider"]
if not davProvider:
if environ["wsgidav.verbose"] >= 2:
_logger.debug("get_domain_realm({}): '{}'".format(
util.safe_re_encode(inputURL, sys.stdout.encoding), None))
return None
realm = davProvider.sharePath
if realm == "":
realm = "/"
return realm
def _calc_realm_from_path_provider(self, path_info, environ):
"""Internal helper for derived classes to implement get_domain_realm()."""
if environ:
# Called while in a request:
# We don't get the share from the path_info here: it was already
# resolved and stripped by the request_resolver
dav_provider = environ["wsgidav.provider"]
else:
# Called on start-up with the share root URL
_share, dav_provider = self.wsgidav_app.resolve_provider(path_info)
if not dav_provider:
logger.warn("_calc_realm_from_path_provider('{}'): '{}'".format(
util.safe_re_encode(path_info, sys.stdout.encoding), None))
return None
realm = dav_provider.share_path
if realm == "":
realm = "/"
return realm
def _calc_realm_from_path_provider(self, path_info, environ):
"""Internal helper for derived classes to implement get_domain_realm()."""
if environ:
# Called while in a request:
# We don't get the share from the path_info here: it was already
# resolved and stripped by the request_resolver
dav_provider = environ["wsgidav.provider"]
else:
# Called on start-up with the share root URL
_share, dav_provider = self.wsgidav_app.resolve_provider(path_info)
if not dav_provider:
logger.warn(
"_calc_realm_from_path_provider('{}'): '{}'".format(
util.safe_re_encode(path_info, sys.stdout.encoding), None
)
)
return None
realm = dav_provider.share_path
if realm == "":
realm = "/"
return realm
def _start_response_wrapper(status, response_headers, exc_info=None):
# Postprocess response headers
headerDict = {}
for header, value in response_headers:
if header.lower() in headerDict:
_logger.error("Duplicate header in response: {}".format(header))
headerDict[header.lower()] = value
# Check if we should close the connection after this request.
# http://www.w3.org/Protocols/rfc2616/rfc2616-sec4.html#sec4.4
forceCloseConnection = False
currentContentLength = headerDict.get("content-length")
statusCode = int(status.split(" ", 1)[0])
contentLengthRequired = (
environ["REQUEST_METHOD"] != "HEAD"
and statusCode >= 200
and statusCode not in (204, 304)
)
# _logger.info(environ["REQUEST_METHOD"], statusCode, contentLengthRequired)
if contentLengthRequired and currentContentLength in (None, ""):
# A typical case: a GET request on a virtual resource, for which
# the provider doesn't know the length
_logger.error(
"Missing required Content-Length header in {}-response: closing connection".format(
statusCode
)
)
forceCloseConnection = True
elif not type(currentContentLength) is str:
_logger.error(
"Invalid Content-Length header in response ({!r}): closing connection".format(
headerDict.get("content-length")
)
)
forceCloseConnection = True
# HOTFIX for Vista and Windows 7 (GC issue 13, issue 23)
# It seems that we must read *all* of the request body, otherwise
# clients may miss the response.
# For example Vista MiniRedir didn't understand a 401 response,
# when trying an anonymous PUT of big files. As a consequence, it
# doesn't retry with credentials and the file copy fails.
# (XP is fine however).
util.read_and_discard_input(environ)
# Make sure the socket is not reused, unless we are 100% sure all
# current input was consumed
if util.get_content_length(environ) != 0 and not environ.get(
"wsgidav.all_input_read"
):
_logger.warn("Input stream not completely consumed: closing connection")
forceCloseConnection = True
if forceCloseConnection and headerDict.get("connection") != "close":
_logger.warn("Adding 'Connection: close' header")
response_headers.append(("Connection", "close"))
# Log request
if self.verbose >= 3:
userInfo = environ.get("http_authenticator.username")
if not userInfo:
userInfo = "(anonymous)"
extra = []
if "HTTP_DESTINATION" in environ:
extra.append('dest="{}"'.format(environ.get("HTTP_DESTINATION")))
if environ.get("CONTENT_LENGTH", "") != "":
extra.append("length={}".format(environ.get("CONTENT_LENGTH")))
if "HTTP_DEPTH" in environ:
extra.append("depth={}".format(environ.get("HTTP_DEPTH")))
if "HTTP_RANGE" in environ:
extra.append("range={}".format(environ.get("HTTP_RANGE")))
if "HTTP_OVERWRITE" in environ:
extra.append("overwrite={}".format(environ.get("HTTP_OVERWRITE")))
if self.verbose >= 3 and "HTTP_EXPECT" in environ:
extra.append('expect="{}"'.format(environ.get("HTTP_EXPECT")))
if self.verbose >= 4 and "HTTP_CONNECTION" in environ:
extra.append(
'connection="{}"'.format(environ.get("HTTP_CONNECTION"))
)
if self.verbose >= 4 and "HTTP_USER_AGENT" in environ:
extra.append('agent="{}"'.format(environ.get("HTTP_USER_AGENT")))
if self.verbose >= 4 and "HTTP_TRANSFER_ENCODING" in environ:
extra.append(
"transfer-enc={}".format(environ.get("HTTP_TRANSFER_ENCODING"))
)
if self.verbose >= 3:
extra.append("elap={:.3f}sec".format(time.time() - start_time))
extra = ", ".join(extra)
# This is the CherryPy format:
# 127.0.0.1 - - [08/Jul/2009:17:25:23] "GET /loginPrompt?redirect=/renderActionList%3Frelation%3Dpersonal%26key%3D%26filter%3DprivateSchedule&reason=0 HTTP/1.1" 200 1944 "http://127.0.0.1:8002/command?id=CMD_Schedule" "Mozilla/5.0 (Windows; U; Windows NT 6.0; de; rv:1.9.1) Gecko/20090624 Firefox/3.5" # noqa
_logger.info(
'{addr} - {user} - [{time}] "{method} {path}" {extra} -> {status}'.format(
addr=environ.get("REMOTE_ADDR", ""),
user=userInfo,
time=util.get_log_time(),
method=environ.get("REQUEST_METHOD"),
path=safe_re_encode(
environ.get("PATH_INFO", ""), sys.stdout.encoding
),
extra=extra,
status=status,
# response_headers.get(""), # response Content-Length
# referer
)
)
return start_response(status, response_headers, exc_info)
def __call__(self, environ, start_response):
""""""
# srvcfg = environ["wsgidav.config"]
verbose = self._config.get("verbose", 3)
method = environ["REQUEST_METHOD"]
debugBreak = False
dumpRequest = False
dumpResponse = False
if verbose >= 5:
dumpRequest = dumpResponse = True
# Process URL commands
if "dump_storage" in environ.get("QUERY_STRING", ""):
dav = environ.get("wsgidav.provider")
if dav.lockManager:
dav.lockManager._dump()
if dav.propManager:
dav.propManager._dump()
# Turn on max. debugging for selected litmus tests
litmusTag = environ.get("HTTP_X_LITMUS",
environ.get("HTTP_X_LITMUS_SECOND"))
if litmusTag and verbose >= 3:
_logger.info("----\nRunning litmus test '{}'...".format(litmusTag))
for litmusSubstring in self.debug_litmus:
if litmusSubstring in litmusTag:
verbose = 5
debugBreak = True
dumpRequest = True
dumpResponse = True
break
for litmusSubstring in self.break_after_litmus:
if litmusSubstring in self.passedLitmus and litmusSubstring not in litmusTag:
_logger.info(
" *** break after litmus {}".format(litmusTag))
sys.exit(-1)
if litmusSubstring in litmusTag:
self.passedLitmus[litmusSubstring] = True
# Turn on max. debugging for selected request methods
if verbose >= 3 and method in self.debug_methods:
verbose = 5
debugBreak = True
dumpRequest = True
dumpResponse = True
# Set debug options to environment
environ["wsgidav.verbose"] = verbose
# environ["wsgidav.debug_methods"] = self.debug_methods
environ["wsgidav.debug_break"] = debugBreak
environ["wsgidav.dump_request_body"] = dumpRequest
environ["wsgidav.dump_response_body"] = dumpResponse
# Dump request headers
if dumpRequest:
_logger.info("{} Request ---".format(method))
# _logger.info("<{}> --- {} Request ---".format(
# threading.currentThread().ident, method))
for k, v in environ.items():
if k == k.upper():
_logger.info("{:<20}: '{}'".format(
k, safe_re_encode(v, "utf8")))
_logger.info("\n")
# Intercept start_response
#
sub_app_start_response = util.SubAppStartResponse()
nbytes = 0
first_yield = True
app_iter = self.next_app(environ, sub_app_start_response)
for v in app_iter:
# Start response (the first time)
if first_yield:
# Success!
start_response(sub_app_start_response.status,
sub_app_start_response.response_headers,
sub_app_start_response.exc_info)
# Dump response headers
if first_yield and dumpResponse:
_logger.info("<{}> ---{} Response({}): ---".format(
threading.currentThread().ident, method,
sub_app_start_response.status))
headersdict = dict(sub_app_start_response.response_headers)
for envitem in headersdict.keys():
_logger.info("{}: {}".format(envitem,
repr(headersdict[envitem])))
_logger.info("")
# Check, if response is a binary string, otherwise we probably have
# calculated a wrong content-length
assert compat.is_bytes(v), v
# Dump response body
drb = environ.get("wsgidav.dump_response_body")
if compat.is_basestring(drb):
# Middleware provided a formatted body representation
_logger.info(drb)
drb = environ["wsgidav.dump_response_body"] = None
elif drb is True:
# Else dump what we get, (except for long GET responses)
if method == "GET":
if first_yield:
_logger.info("{}...".format(v[:50]))
elif len(v) > 0:
_logger.info(v)
nbytes += len(v)
first_yield = False
yield v
if hasattr(app_iter, "close"):
app_iter.close()
# Start response (if it hasn't been done yet)
if first_yield:
# Success!
start_response(sub_app_start_response.status,
sub_app_start_response.response_headers,
sub_app_start_response.exc_info)
if dumpResponse:
_logger.info("<{}> --- End of {} Response ({:d} bytes) ---".format(
threading.currentThread().ident, method, nbytes))
return
def __call__(self, environ, start_response):
""""""
# srvcfg = environ["wsgidav.config"]
verbose = self._config.get("verbose", 3)
method = environ["REQUEST_METHOD"]
debugBreak = False
dumpRequest = False
dumpResponse = False
if verbose >= 5:
dumpRequest = dumpResponse = True
# Process URL commands
if "dump_storage" in environ.get("QUERY_STRING", ""):
dav = environ.get("wsgidav.provider")
if dav.lock_manager:
dav.lock_manager._dump()
if dav.prop_manager:
dav.prop_manager._dump()
# Turn on max. debugging for selected litmus tests
litmusTag = environ.get("HTTP_X_LITMUS", environ.get("HTTP_X_LITMUS_SECOND"))
if litmusTag and verbose >= 3:
_logger.info("----\nRunning litmus test '{}'...".format(litmusTag))
for litmusSubstring in self.debug_litmus:
if litmusSubstring in litmusTag:
verbose = 5
debugBreak = True
dumpRequest = True
dumpResponse = True
break
for litmusSubstring in self.break_after_litmus:
if (
litmusSubstring in self.passedLitmus
and litmusSubstring not in litmusTag
):
_logger.info(" *** break after litmus {}".format(litmusTag))
sys.exit(-1)
if litmusSubstring in litmusTag:
self.passedLitmus[litmusSubstring] = True
# Turn on max. debugging for selected request methods
if verbose >= 3 and method in self.debug_methods:
verbose = 5
debugBreak = True
dumpRequest = True
dumpResponse = True
# Set debug options to environment
environ["wsgidav.verbose"] = verbose
# environ["wsgidav.debug_methods"] = self.debug_methods
environ["wsgidav.debug_break"] = debugBreak
environ["wsgidav.dump_request_body"] = dumpRequest
environ["wsgidav.dump_response_body"] = dumpResponse
# Dump request headers
if dumpRequest:
_logger.info("{} Request ---".format(method))
# _logger.info("<{}> --- {} Request ---".format(
# threading.currentThread().ident, method))
for k, v in environ.items():
if k == k.upper():
_logger.info("{:<20}: '{}'".format(k, safe_re_encode(v, "utf8")))
_logger.info("\n")
# Intercept start_response
#
sub_app_start_response = util.SubAppStartResponse()
nbytes = 0
first_yield = True
app_iter = self.next_app(environ, sub_app_start_response)
for v in app_iter:
# Start response (the first time)
if first_yield:
# Success!
start_response(
sub_app_start_response.status,
sub_app_start_response.response_headers,
sub_app_start_response.exc_info,
)
# Dump response headers
if first_yield and dumpResponse:
_logger.info(
"<{}> ---{} Response({}): ---".format(
threading.currentThread().ident,
method,
sub_app_start_response.status,
)
)
headersdict = dict(sub_app_start_response.response_headers)
for envitem in headersdict.keys():
_logger.info("{}: {}".format(envitem, repr(headersdict[envitem])))
_logger.info("")
# Check, if response is a binary string, otherwise we probably have
# calculated a wrong content-length
assert compat.is_bytes(v), v
# Dump response body
drb = environ.get("wsgidav.dump_response_body")
if compat.is_basestring(drb):
# Middleware provided a formatted body representation
_logger.info(drb)
drb = environ["wsgidav.dump_response_body"] = None
elif drb is True:
# Else dump what we get, (except for long GET responses)
if method == "GET":
if first_yield:
_logger.info("{}...".format(v[:50]))
elif len(v) > 0:
_logger.info(v)
nbytes += len(v)
first_yield = False
yield v
if hasattr(app_iter, "close"):
app_iter.close()
# Start response (if it hasn't been done yet)
if first_yield:
# Success!
start_response(
sub_app_start_response.status,
sub_app_start_response.response_headers,
sub_app_start_response.exc_info,
)
if dumpResponse:
_logger.info(
"<{}> --- End of {} Response ({:d} bytes) ---".format(
threading.currentThread().ident, method, nbytes
)
)
return
def _start_response_wrapper(status, response_headers, exc_info=None):
# Postprocess response headers
headerDict = {}
for header, value in response_headers:
if header.lower() in headerDict:
_logger.error("Duplicate header in response: {}".format(header))
headerDict[header.lower()] = value
# Check if we should close the connection after this request.
# http://www.w3.org/Protocols/rfc2616/rfc2616-sec4.html#sec4.4
forceCloseConnection = False
currentContentLength = headerDict.get("content-length")
statusCode = int(status.split(" ", 1)[0])
contentLengthRequired = (
environ["REQUEST_METHOD"] != "HEAD"
and statusCode >= 200
and statusCode not in (204, 304)
)
# _logger.info(environ["REQUEST_METHOD"], statusCode, contentLengthRequired)
if contentLengthRequired and currentContentLength in (None, ""):
# A typical case: a GET request on a virtual resource, for which
# the provider doesn't know the length
_logger.error(
"Missing required Content-Length header in {}-response: closing connection".format(
statusCode
)
)
forceCloseConnection = True
elif not type(currentContentLength) is str:
_logger.error(
"Invalid Content-Length header in response ({!r}): closing connection".format(
headerDict.get("content-length")
)
)
forceCloseConnection = True
# HOTFIX for Vista and Windows 7 (GC issue 13, issue 23)
# It seems that we must read *all* of the request body, otherwise
# clients may miss the response.
# For example Vista MiniRedir didn't understand a 401 response,
# when trying an anonymous PUT of big files. As a consequence, it
# doesn't retry with credentials and the file copy fails.
# (XP is fine however).
util.read_and_discard_input(environ)
# Make sure the socket is not reused, unless we are 100% sure all
# current input was consumed
if util.get_content_length(environ) != 0 and not environ.get(
"wsgidav.all_input_read"
):
_logger.warning(
"Input stream not completely consumed: closing connection."
)
forceCloseConnection = True
if forceCloseConnection and headerDict.get("connection") != "close":
_logger.warning("Adding 'Connection: close' header.")
response_headers.append(("Connection", "close"))
# Log request
if self.verbose >= 3:
userInfo = environ.get("wsgidav.auth.user_name")
if not userInfo:
userInfo = "(anonymous)"
extra = []
if "HTTP_DESTINATION" in environ:
extra.append('dest="{}"'.format(environ.get("HTTP_DESTINATION")))
if environ.get("CONTENT_LENGTH", "") != "":
extra.append("length={}".format(environ.get("CONTENT_LENGTH")))
if "HTTP_DEPTH" in environ:
extra.append("depth={}".format(environ.get("HTTP_DEPTH")))
if "HTTP_RANGE" in environ:
extra.append("range={}".format(environ.get("HTTP_RANGE")))
if "HTTP_OVERWRITE" in environ:
extra.append("overwrite={}".format(environ.get("HTTP_OVERWRITE")))
if self.verbose >= 3 and "HTTP_EXPECT" in environ:
extra.append('expect="{}"'.format(environ.get("HTTP_EXPECT")))
if self.verbose >= 4 and "HTTP_CONNECTION" in environ:
extra.append(
'connection="{}"'.format(environ.get("HTTP_CONNECTION"))
)
if self.verbose >= 4 and "HTTP_USER_AGENT" in environ:
extra.append('agent="{}"'.format(environ.get("HTTP_USER_AGENT")))
if self.verbose >= 4 and "HTTP_TRANSFER_ENCODING" in environ:
extra.append(
"transfer-enc={}".format(environ.get("HTTP_TRANSFER_ENCODING"))
)
if self.verbose >= 3:
extra.append("elap={:.3f}sec".format(time.time() - start_time))
extra = ", ".join(extra)
# This is the CherryPy format:
# 127.0.0.1 - - [08/Jul/2009:17:25:23] "GET /loginPrompt?redirect=/renderActionList%3Frelation%3Dpersonal%26key%3D%26filter%3DprivateSchedule&reason=0 HTTP/1.1" 200 1944 "http://127.0.0.1:8002/command?id=CMD_Schedule" "Mozilla/5.0 (Windows; U; Windows NT 6.0; de; rv:1.9.1) Gecko/20090624 Firefox/3.5" # noqa
_logger.info(
'{addr} - {user} - [{time}] "{method} {path}" {extra} -> {status}'.format(
addr=environ.get("REMOTE_ADDR", ""),
user=userInfo,
time=util.get_log_time(),
method=environ.get("REQUEST_METHOD"),
path=safe_re_encode(
environ.get("PATH_INFO", ""),
sys.stdout.encoding if sys.stdout.encoding else "utf-8",
),
extra=extra,
status=status,
# response_headers.get(""), # response Content-Length
# referer
)
)
return start_response(status, response_headers, exc_info)
