switch to stdlib logging

mitmproxy previously used a homegrown logging mechanism based around
`mitmproxy.ctx.log` and the `add_log` hook. This worked well for everything
we control, but does not work outside the mitmproxy universe.
For now we have simply ignored logging in e.g. tornado or h2, but with the
upcoming introduction of mitmproxy_wireguard we now have a dependency
on some Rust/PyO3 code for which we definitely want logs, but which also
cannot easily be changed to use our homegrown logging (PyO3 does the heavy
lifting to add interoperability with stdlib logging). Long story short,
we want to introduce a log handler for stdlib logging.

Now there are two ways how such a handler could operate:

 1. We could build a handler that forwards all stdlib log events
    into our homegrown mechanism.
 2. We embrace stdlib's logging as the correct way to do things,
    and get rid of our homegrown stuff.

This PR follows the second approach by removing the `add_log` hook and
rewriting the `TermLog` and `EventStore` addons to listen for stdlib log records.
This means that all `mitmproxy.ctx.log.info` events are now simply `logging.info` etc.

One upside of this approach is that many parts of the codebase now don't depend
on the existence of `mitmproxy.ctx` and we can use off-the-shelf things like pytest's
`caplog`. We can also now better colorize log output and/or add timestamps.
This commit is contained in:
Maximilian Hils 2022-09-17 15:41:54 +02:00
parent 0afc48b714
commit c69239bb90
120 changed files with 1100 additions and 822 deletions

View file

@ -3,7 +3,7 @@ Basic skeleton of a mitmproxy addon.
Run as follows: mitmproxy -s anatomy.py
"""
from mitmproxy import ctx
import logging
class Counter:
@ -12,7 +12,7 @@ class Counter:
def request(self, flow):
self.num = self.num + 1
ctx.log.info("We've seen %d flows" % self.num)
logging.info("We've seen %d flows" % self.num)
addons = [Counter()]

View file

@ -1,10 +1,11 @@
"""Handle flows as command arguments."""
import logging
from collections.abc import Sequence
from mitmproxy import command
from mitmproxy import ctx
from mitmproxy import flow
from mitmproxy import http
from mitmproxy.log import ALERT
class MyAddon:
@ -13,7 +14,7 @@ class MyAddon:
for f in flows:
if isinstance(f, http.HTTPFlow):
f.request.headers["myheader"] = "value"
ctx.log.alert("done")
logging.log(ALERT, "done")
addons = [MyAddon()]

View file

@ -1,11 +1,12 @@
"""Handle file paths as command arguments."""
import logging
from collections.abc import Sequence
from mitmproxy import command
from mitmproxy import ctx
from mitmproxy import flow
from mitmproxy import http
from mitmproxy import types
from mitmproxy.log import ALERT
class MyAddon:
@ -24,7 +25,7 @@ class MyAddon:
for cnt, dom in sorted((v, k) for (k, v) in totals.items()):
fp.write(f"{cnt}: {dom}\n")
ctx.log.alert("done")
logging.log(ALERT, "done")
addons = [MyAddon()]

View file

@ -1,6 +1,7 @@
"""Add a custom command to mitmproxy's command prompt."""
import logging
from mitmproxy import command
from mitmproxy import ctx
class MyAddon:
@ -10,7 +11,7 @@ class MyAddon:
@command.command("myaddon.inc")
def inc(self) -> None:
self.num += 1
ctx.log.info(f"num = {self.num}")
logging.info(f"num = {self.num}")
addons = [MyAddon()]

View file

@ -1,8 +1,10 @@
"""
Use mitmproxy's filter pattern in scripts.
"""
from mitmproxy import flowfilter
import logging
from mitmproxy import ctx, http
from mitmproxy import flowfilter
class Filter:
@ -18,8 +20,8 @@ class Filter:
def response(self, flow: http.HTTPFlow) -> None:
if flowfilter.match(self.filter, flow):
ctx.log.info("Flow matches filter:")
ctx.log.info(flow)
logging.info("Flow matches filter:")
logging.info(flow)
addons = [Filter()]

View file

@ -1,8 +1,11 @@
"""Post messages to mitmproxy's event log."""
from mitmproxy import ctx
import logging
from mitmproxy.log import ALERT
def load(l):
ctx.log.info("This is some informative text.")
ctx.log.warn("This is a warning.")
ctx.log.error("This is an error.")
logging.info("This is some informative text.")
logging.warning("This is a warning.")
logging.error("This is an error.")
logging.log(ALERT, "This is an alert. It has the same urgency as info, but will also pop up in the status bar.")

View file

@ -2,18 +2,19 @@
Make events hooks non-blocking using async or @concurrent
"""
import asyncio
import logging
import time
from mitmproxy.script import concurrent
from mitmproxy import ctx
# Hooks can be async, which allows the hook to call async functions and perform async I/O
# without blocking other requests. This is generally preferred for new addons.
async def request(flow):
ctx.log.info(f"handle request: {flow.request.host}{flow.request.path}")
logging.info(f"handle request: {flow.request.host}{flow.request.path}")
await asyncio.sleep(5)
ctx.log.info(f"start request: {flow.request.host}{flow.request.path}")
logging.info(f"start request: {flow.request.host}{flow.request.path}")
# Another option is to use @concurrent, which launches the hook in its own thread.
@ -21,7 +22,6 @@ async def request(flow):
# Rename the function below to request(flow) to try it out.
@concurrent # Remove this to make it synchronous and see what happens
def request_concurrent(flow):
# This is ugly in mitmproxy's UI, but you don't want to use mitmproxy.ctx.log from a different thread.
print(f"handle request: {flow.request.host}{flow.request.path}")
logging.info(f"handle request: {flow.request.host}{flow.request.path}")
time.sleep(5)
print(f"start request: {flow.request.host}{flow.request.path}")
logging.info(f"start request: {flow.request.host}{flow.request.path}")

View file

@ -8,11 +8,13 @@ Usage:
and then send a HTTP request to trigger the shutdown:
curl --proxy localhost:8080 http://example.com/path
"""
import logging
from mitmproxy import ctx, http
def request(flow: http.HTTPFlow) -> None:
# a random condition to make this example a bit more interactive
if flow.request.pretty_url == "http://example.com/path":
ctx.log.info("Shutting down everything...")
logging.info("Shutting down everything...")
ctx.master.shutdown()

View file

@ -10,8 +10,9 @@ Example Invocation:
mitmdump --rawtcp --tcp-hosts ".*" -s examples/tcp-simple.py
"""
import logging
from mitmproxy.utils import strutils
from mitmproxy import ctx
from mitmproxy import tcp
@ -19,6 +20,6 @@ def tcp_message(flow: tcp.TCPFlow):
message = flow.messages[-1]
message.content = message.content.replace(b"foo", b"bar")
ctx.log.info(
logging.info(
f"tcp_message[from_client={message.from_client}), content={strutils.bytes_to_escaped_str(message.content)}]"
)

View file

@ -1,6 +1,8 @@
"""Process individual messages from a WebSocket connection."""
import logging
import re
from mitmproxy import ctx, http
from mitmproxy import http
def websocket_message(flow: http.HTTPFlow):
@ -10,9 +12,9 @@ def websocket_message(flow: http.HTTPFlow):
# was the message sent from the client or server?
if message.from_client:
ctx.log.info(f"Client sent a message: {message.content!r}")
logging.info(f"Client sent a message: {message.content!r}")
else:
ctx.log.info(f"Server sent a message: {message.content!r}")
logging.info(f"Server sent a message: {message.content!r}")
# manipulate the message content
message.content = re.sub(rb"^Hello", b"HAPPY", message.content)

View file

@ -4,8 +4,7 @@ This module is for blocking DNS over HTTPS requests.
It loads a blocklist of IPs and hostnames that are known to serve DNS over HTTPS requests.
It also uses headers, query params, and paths to detect DoH (and block it)
"""
from mitmproxy import ctx
import logging
# known DoH providers' hostnames and IP addresses to block
default_blocklist: dict = {
@ -147,7 +146,7 @@ def _request_has_doh_looking_path(flow):
:return: True if path looks like it's DoH, otherwise False
"""
doh_paths = [
'/dns-query', # used in example in RFC 8484 (see https://tools.ietf.org/html/rfc8484#section-4.1.1)
'/dns-query', # used in example in RFC 8484 (see https://tools.ietf.org/html/rfc8484#section-4.1.1)
]
path = flow.request.path.split('?')[0]
return path in doh_paths
@ -180,6 +179,6 @@ def request(flow):
for check in doh_request_detection_checks:
is_doh = check(flow)
if is_doh:
ctx.log.warn("[DoH Detection] DNS over HTTPS request detected via method \"%s\"" % check.__name__)
logging.warning("[DoH Detection] DNS over HTTPS request detected via method \"%s\"" % check.__name__)
flow.kill()
break

View file

@ -8,6 +8,8 @@ Example usage:
- mitmdump -s custom_next_layer.py
- curl -x localhost:8080 -k https://example.com
"""
import logging
from mitmproxy import ctx
from mitmproxy.proxy import layer, layers
@ -19,7 +21,7 @@ def running():
def next_layer(nextlayer: layer.NextLayer):
ctx.log(
logging.info(
f"{nextlayer.context=}\n"
f"{nextlayer.data_client()[:70]=}\n"
f"{nextlayer.data_server()[:70]=}\n"

View file

@ -8,22 +8,21 @@ filename endwith '.zhar' will be compressed:
mitmdump -s ./har_dump.py --set hardump=./dump.zhar
"""
import json
import base64
import zlib
import json
import logging
import os
from datetime import datetime
from datetime import timezone
import mitmproxy
import zlib
import mitmproxy
from mitmproxy import connection
from mitmproxy import version
from mitmproxy import ctx
from mitmproxy.utils import strutils
from mitmproxy import version
from mitmproxy.net.http import cookies
from mitmproxy.utils import strutils
HAR: dict = {}
@ -166,7 +165,7 @@ def done():
json_dump: str = json.dumps(HAR, indent=2)
if ctx.options.hardump == '-':
mitmproxy.ctx.log(json_dump)
print(json_dump)
else:
raw: bytes = json_dump.encode()
if ctx.options.hardump.endswith('.zhar'):
@ -175,7 +174,7 @@ def done():
with open(os.path.expanduser(ctx.options.hardump), "wb") as f:
f.write(raw)
mitmproxy.ctx.log("HAR dump finished (wrote %s bytes to file)" % len(json_dump))
logging.info("HAR dump finished (wrote %s bytes to file)" % len(json_dump))
def format_cookies(cookie_list):

View file

@ -9,12 +9,13 @@
# remember to add your own mitmproxy authorative certs in your browser/os!
# certs docs: https://docs.mitmproxy.org/stable/concepts-certificates/
# filter expressions docs: https://docs.mitmproxy.org/stable/concepts-filters/
import os
import logging
import mimetypes
import os
from pathlib import Path
from mitmproxy import flowfilter
from mitmproxy import ctx, http
from mitmproxy import flowfilter
class HTTPDump:
@ -22,16 +23,16 @@ class HTTPDump:
self.filter = ctx.options.dumper_filter
loader.add_option(
name = "dumper_folder",
typespec = str,
default = "httpdump",
help = "content dump destination folder",
name="dumper_folder",
typespec=str,
default="httpdump",
help="content dump destination folder",
)
loader.add_option(
name = "open_browser",
typespec = bool,
default = True,
help = "open integrated browser at start"
name="open_browser",
typespec=bool,
default=True,
help="open integrated browser at start"
)
def running(self):
@ -66,7 +67,7 @@ class HTTPDump:
if flow.response.content:
with open(filepath, "wb") as f:
f.write(flow.response.content)
ctx.log.info(f"Saved! {filepath}")
logging.info(f"Saved! {filepath}")
addons = [HTTPDump()]

View file

@ -30,10 +30,12 @@ Configuration:
dump_destination: "/user/rastley/output.log"
EOF
"""
from threading import Lock, Thread
from queue import Queue
import base64
import json
import logging
from queue import Queue
from threading import Lock, Thread
import requests
from mitmproxy import ctx
@ -48,6 +50,7 @@ class JSONDumper:
for out-of-the-box Elasticsearch support, and then either writes
the result to a file or sends it to a URL.
"""
def __init__(self):
self.outfile = None
self.transformations = None
@ -88,7 +91,7 @@ class JSONDumper:
('client_conn', 'address'),
),
'ws_messages': (
('messages', ),
('messages',),
),
'headers': (
('request', 'headers'),
@ -207,15 +210,15 @@ class JSONDumper:
if ctx.options.dump_destination.startswith('http'):
self.outfile = None
self.url = ctx.options.dump_destination
ctx.log.info('Sending all data frames to %s' % self.url)
logging.info('Sending all data frames to %s' % self.url)
if ctx.options.dump_username and ctx.options.dump_password:
self.auth = (ctx.options.dump_username, ctx.options.dump_password)
ctx.log.info('HTTP Basic auth enabled.')
logging.info('HTTP Basic auth enabled.')
else:
self.outfile = open(ctx.options.dump_destination, 'a')
self.url = None
self.lock = Lock()
ctx.log.info('Writing all data frames to %s' % ctx.options.dump_destination)
logging.info('Writing all data frames to %s' % ctx.options.dump_destination)
self._init_transformations()

View file

@ -1,8 +1,9 @@
import base64
import binascii
import logging
import socket
from typing import Any, Optional
import binascii
from ntlm_auth import gss_channel_bindings, ntlm
from mitmproxy import addonmanager, http
@ -25,7 +26,7 @@ class NTLMUpstreamAuth:
"""
def load(self, loader: addonmanager.Loader) -> None:
ctx.log.info("NTLMUpstreamAuth loader")
logging.info("NTLMUpstreamAuth loader")
loader.add_option(
name="upstream_ntlm_auth",
typespec=Optional[str],
@ -60,7 +61,7 @@ class NTLMUpstreamAuth:
Valid values are 0-5 (Default: 3)
"""
)
ctx.log.debug("AddOn: NTLM Upstream Authentication - Loaded")
logging.debug("AddOn: NTLM Upstream Authentication - Loaded")
def running(self):
def extract_flow_from_context(context: Context) -> http.HTTPFlow:
@ -73,7 +74,7 @@ class NTLMUpstreamAuth:
def build_connect_flow(context: Context, connect_header: tuple) -> http.HTTPFlow:
flow = extract_flow_from_context(context)
if not flow:
ctx.log.error("failed to build connect flow")
logging.error("failed to build connect flow")
raise
flow.request.content = b"" # we should send empty content for handshake
header_name, header_value = connect_header
@ -96,7 +97,7 @@ class NTLMUpstreamAuth:
try:
token = challenge_message.split(': ')[1]
except IndexError:
ctx.log.error("Failed to extract challenge_message")
logging.error("Failed to extract challenge_message")
raise
return token
@ -130,7 +131,7 @@ class NTLMUpstreamAuth:
HttpUpstreamProxy.receive_handshake_data = patched_receive_handshake_data
def done(self):
ctx.log.info('close ntlm session')
logging.info('close ntlm session')
addons = [
@ -149,8 +150,7 @@ class CustomNTLMContext:
ntlm_compatibility: int = ctx.options.upstream_ntlm_compatibility
username, password = tuple(auth.split(":"))
workstation = socket.gethostname().upper()
ctx.log.debug(f'\nntlm context with the details: "{domain}\\{username}", *****')
self.ctx_log = ctx.log
logging.debug(f'\nntlm context with the details: "{domain}\\{username}", *****')
self.preferred_type = preferred_type
self.ntlm_context = ntlm.NtlmContext(
username=username,
@ -165,7 +165,7 @@ class CustomNTLMContext:
negotiate_message_base_64_in_bytes = base64.b64encode(negotiate_message)
negotiate_message_base_64_ascii = negotiate_message_base_64_in_bytes.decode("ascii")
negotiate_message_base_64_final = f'{self.preferred_type} {negotiate_message_base_64_ascii}'
self.ctx_log.debug(
logging.debug(
f'{self.preferred_type} Authentication, negotiate message: {negotiate_message_base_64_final}'
)
return negotiate_message_base_64_final
@ -175,12 +175,12 @@ class CustomNTLMContext:
try:
challenge_message_ascii_bytes = base64.b64decode(challenge_message, validate=True)
except binascii.Error as err:
self.ctx_log.debug(f'{self.preferred_type} Authentication fail with error {err.__str__()}')
logging.debug(f'{self.preferred_type} Authentication fail with error {err.__str__()}')
return False
authenticate_message = self.ntlm_context.step(challenge_message_ascii_bytes)
negotiate_message_base_64 = '{} {}'.format(self.preferred_type,
base64.b64encode(authenticate_message).decode('ascii'))
self.ctx_log.debug(
logging.debug(
f'{self.preferred_type} Authentication, response to challenge message: {negotiate_message_base_64}'
)
return negotiate_message_base_64

View file

@ -18,16 +18,16 @@ for associating a file with its corresponding flow in the stream saved with
This addon is not compatible with addons that use the same mechanism to
capture streamed data, http-stream-modify.py for instance.
"""
import logging
import os
from datetime import datetime
from pathlib import Path
from typing import Optional
from mitmproxy import ctx
from datetime import datetime
from pathlib import Path
import os
class StreamSaver:
TAG = "save_streamed_data: "
def __init__(self, flow, direction):
@ -58,7 +58,8 @@ class StreamSaver:
return data
if not self.fh:
self.path = datetime.fromtimestamp(self.flow.request.timestamp_start).strftime(ctx.options.save_streamed_data)
self.path = datetime.fromtimestamp(self.flow.request.timestamp_start).strftime(
ctx.options.save_streamed_data)
self.path = self.path.replace('%+T', str(self.flow.request.timestamp_start))
self.path = self.path.replace('%+I', str(self.flow.client_conn.id))
self.path = self.path.replace('%+D', self.direction)
@ -70,18 +71,18 @@ class StreamSaver:
if not parent.exists():
parent.mkdir(parents=True, exist_ok=True)
except OSError:
ctx.log.error(f"{self.TAG}Failed to create directory: {parent}")
logging.error(f"{self.TAG}Failed to create directory: {parent}")
try:
self.fh = open(self.path, "wb", buffering=0)
except OSError:
ctx.log.error(f"{self.TAG}Failed to open for writing: {self.path}")
logging.error(f"{self.TAG}Failed to open for writing: {self.path}")
if self.fh:
try:
self.fh.write(data)
except OSError:
ctx.log.error(f"{self.TAG}Failed to write to: {self.path}")
logging.error(f"{self.TAG}Failed to write to: {self.path}")
return data

View file

@ -1,10 +1,9 @@
import logging
import re
from collections.abc import Sequence
from json import dumps
from mitmproxy import command, ctx, flow
from mitmproxy import command, flow
MARKER = ':mag:'
RESULTS_STR = 'Search Results: '
@ -44,7 +43,7 @@ class Search:
try:
self.exp = re.compile(regex)
except re.error as e:
ctx.log.error(e)
logging.error(e)
return
for _flow in flows:

View file

@ -293,22 +293,6 @@ class TestXSSScanner():
assert xss_info == expected_xss_info
assert sqli_info is None
@pytest.fixture(scope='function')
def logger(self, monkeypatch):
class Logger():
def __init__(self):
self.args = []
def info(self, str):
self.args.append(str)
def error(self, str):
self.args.append(str)
logger = Logger()
monkeypatch.setattr("mitmproxy.ctx.log", logger)
yield logger
@pytest.fixture(scope='function')
def get_request_vuln(self, monkeypatch):
monkeypatch.setattr(requests, 'get', self.mocked_requests_vuln)

View file

@ -15,6 +15,7 @@ Example:
// works again, but mitmproxy does not intercept and we do *not* see the contents
"""
import collections
import logging
import random
from abc import ABC, abstractmethod
from enum import Enum
@ -90,18 +91,18 @@ class MaybeTls:
def tls_clienthello(self, data: tls.ClientHelloData):
server_address = data.context.server.peername
if not self.strategy.should_intercept(server_address):
ctx.log(f"TLS passthrough: {human.format_address(server_address)}.")
logging.info(f"TLS passthrough: {human.format_address(server_address)}.")
data.ignore_connection = True
self.strategy.record_skipped(server_address)
def tls_established_client(self, data: tls.TlsData):
server_address = data.context.server.peername
ctx.log(f"TLS handshake successful: {human.format_address(server_address)}")
logging.info(f"TLS handshake successful: {human.format_address(server_address)}")
self.strategy.record_success(server_address)
def tls_failed_client(self, data: tls.TlsData):
server_address = data.context.server.peername
ctx.log(f"TLS handshake failed: {human.format_address(server_address)}")
logging.info(f"TLS handshake failed: {human.format_address(server_address)}")
self.strategy.record_failure(server_address)

View file

@ -34,18 +34,16 @@ Suggested Exploit: <script>alert(0)</script>
Line: 1029zxcs'd"ao<ac>so[sb]po(pc)se;sl/bsl\eq=3847asd
"""
import logging
import re
import socket
from html.parser import HTMLParser
from typing import NamedTuple, Optional, Union
from urllib.parse import urlparse
import re
import socket
import requests
from mitmproxy import http
from mitmproxy import ctx
# The actual payload is put between a frontWall and a backWall to make it easy
# to locate the payload with regular expressions
@ -92,6 +90,7 @@ def get_cookies(flow: http.HTTPFlow) -> Cookies:
def find_unclaimed_URLs(body, requestUrl):
""" Look for unclaimed URLs in script tags and log them if found"""
def getValue(attrs: list[tuple[str, str]], attrName: str) -> Optional[str]:
for name, value in attrs:
if attrName == name:
@ -115,7 +114,7 @@ def find_unclaimed_URLs(body, requestUrl):
try:
socket.gethostbyname(domain)
except socket.gaierror:
ctx.log.error(f"XSS found in {requestUrl} due to unclaimed URL \"{url}\".")
logging.error(f"XSS found in {requestUrl} due to unclaimed URL \"{url}\".")
def test_end_of_URL_injection(original_body: str, request_URL: str, cookies: Cookies) -> VulnData:
@ -171,22 +170,22 @@ def log_XSS_data(xss_info: Optional[XSSData]) -> None:
# If it is None, then there is no info to log
if not xss_info:
return
ctx.log.error("===== XSS Found ====")
ctx.log.error("XSS URL: %s" % xss_info.url)
ctx.log.error("Injection Point: %s" % xss_info.injection_point)
ctx.log.error("Suggested Exploit: %s" % xss_info.exploit)
ctx.log.error("Line: %s" % xss_info.line)
logging.error("===== XSS Found ====")
logging.error("XSS URL: %s" % xss_info.url)
logging.error("Injection Point: %s" % xss_info.injection_point)
logging.error("Suggested Exploit: %s" % xss_info.exploit)
logging.error("Line: %s" % xss_info.line)
def log_SQLi_data(sqli_info: Optional[SQLiData]) -> None:
""" Log information about the given SQLi to mitmproxy """
if not sqli_info:
return
ctx.log.error("===== SQLi Found =====")
ctx.log.error("SQLi URL: %s" % sqli_info.url)
ctx.log.error("Injection Point: %s" % sqli_info.injection_point)
ctx.log.error("Regex used: %s" % sqli_info.regex)
ctx.log.error("Suspected DBMS: %s" % sqli_info.dbms)
logging.error("===== SQLi Found =====")
logging.error("SQLi URL: %s" % sqli_info.url)
logging.error("Injection Point: %s" % sqli_info.injection_point)
logging.error("Regex used: %s" % sqli_info.regex)
logging.error("Suspected DBMS: %s" % sqli_info.dbms)
return
@ -277,6 +276,7 @@ def paths_to_text(html: str, string: str) -> list[str]:
def get_XSS_data(body: Union[str, bytes], request_URL: str, injection_point: str) -> Optional[XSSData]:
""" Return a XSSDict if there is a XSS otherwise return None """
def in_script(text, index, body) -> bool:
""" Whether the Numberth occurrence of the first string in the second
string is inside a script tag """
@ -302,6 +302,7 @@ def get_XSS_data(body: Union[str, bytes], request_URL: str, injection_point: str
def inject_javascript_handler(html: str) -> bool:
""" Whether you can inject a Javascript:alert(0) as a link """
class injectJSHandlerHTMLParser(HTMLParser):
injectJSHandler = False
@ -313,6 +314,7 @@ def get_XSS_data(body: Union[str, bytes], request_URL: str, injection_point: str
parser = injectJSHandlerHTMLParser()
parser.feed(html)
return parser.injectJSHandler
# Only convert the body to bytes if needed
if isinstance(body, str):
body = bytes(body, 'utf-8')