Use 'trace' level logging to log frames in each direction.

[tomchristie]

This proposal modifies the logging at 'trace' level, so that it provides HTTP/2 frame-level logging in both directions.

From my perspective this is both more useful and more consistent than the existing trace-level logging, which logs incoming data and incoming frames.

Also related: encode/httpcore#686

example.py:

import httpx
import logging

logging.basicConfig(
    format="%(levelname)s [%(asctime)s] %(name)s - %(message)s",
    datefmt="%Y-%m-%d %H:%M:%S",
    level=logging.INFO
)
logging.getLogger("httpcore.h2frames").setLevel(logging.DEBUG)

with httpx.Client(http2=True) as client:
    client.get("https://www.example.com/")

console:

$ python -m venv venv
$ venv/bin/pip install git+https://github.com/python-hyper/h2.git@frame-level-logging  # `h2`, updated with frame-level logging
$ venv/bin/pip install git+https://github.com/encode/httpcore.git@add-h2-logging  # `httpcore`, updated to include h2 loggers.
$ venv/bin/pip install httpx
$ venv/bin/python example.py 
DEBUG [2023-05-17 11:34:12] httpcore.h2frames - Sending frame: SettingsFrame(stream_id=0, flags=[]): settings={<SettingCodes.HEADER_TABLE_SIZE: 1>: 4096, <SettingCodes.ENABLE_PUSH: 2>: 0, <SettingCodes.INITIAL_WINDOW_SIZE: 4>: 65535, <SettingCodes.MAX_FRAME_SIZE: 5>: 16384, <SettingCodes.MAX_CONCURRENT_STREAMS: 3>: 100, <SettingCodes.MAX_HEADER_LIST_SIZE: 6>: 65536}
DEBUG [2023-05-17 11:34:12] httpcore.h2frames - Sending frame: WindowUpdateFrame(stream_id=0, flags=[]): window_increment=16777216
DEBUG [2023-05-17 11:34:12] httpcore.h2frames - Sending frame: HeadersFrame(stream_id=1, flags=['END_HEADERS', 'END_STREAM']): exclusive=False, depends_on=0, stream_weight=0, data=<hex:82418cf1e3c2e5f23a6b...>
DEBUG [2023-05-17 11:34:12] httpcore.h2frames - Sending frame: WindowUpdateFrame(stream_id=1, flags=[]): window_increment=16777216
DEBUG [2023-05-17 11:34:12] httpcore.h2frames - Received frame: SettingsFrame(stream_id=0, flags=[]): settings={1: 4096, 3: 100, 4: 1048576, 5: 16384, 6: 16384}
DEBUG [2023-05-17 11:34:12] httpcore.h2frames - Sending frame: SettingsFrame(stream_id=0, flags=['ACK']): settings={}
DEBUG [2023-05-17 11:34:12] httpcore.h2frames - Received frame: WindowUpdateFrame(stream_id=0, flags=[]): window_increment=983041
DEBUG [2023-05-17 11:34:12] httpcore.h2frames - Received frame: SettingsFrame(stream_id=0, flags=['ACK']): settings={}
DEBUG [2023-05-17 11:34:12] httpcore.h2frames - Received frame: HeadersFrame(stream_id=1, flags=['END_HEADERS']): exclusive=False, depends_on=0, stream_weight=0, data=<hex:3fe11f885a839bd9ab52...>
INFO [2023-05-17 11:34:12] httpx - HTTP Request: GET https://www.example.com/ "HTTP/2 200 OK"
DEBUG [2023-05-17 11:34:12] httpcore.h2frames - Received frame: DataFrame(stream_id=1, flags=['END_STREAM']): <hex:1f8b0800c215a85d0003...>
DEBUG [2023-05-17 11:34:12] httpcore.h2frames - Sending frame: GoAwayFrame(stream_id=0, flags=[]): last_stream_id=0, error_code=0, additional_data=b''