http.client header debug output format

[KimGrsman]

BPO	17233
Nosy	@terryjreedy, @berkerpeksag, @poleto
Files	httpclient.debuglevel.txt: Example of httpclient log output issue17233.patch: Proposed patch

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = None
closed_at = None
created_at = <Date 2013-02-19.06:52:54.641>
labels = ['type-bug', 'library']
title = 'http.client header debug output format'
updated_at = <Date 2019-07-29.11:51:41.347>
user = 'https://bugs.python.org/KimGrsman'

bugs.python.org fields:

activity = <Date 2019-07-29.11:51:41.347>
actor = 'vstinner'
assignee = 'none'
closed = False
closed_date = None
closer = None
components = ['Library (Lib)']
creation = <Date 2013-02-19.06:52:54.641>
creator = 'Kim.Gr\xc3\xa4sman'
dependencies = []
files = ['29120', '42528']
hgrepos = []
issue_num = 17233
keywords = ['patch']
message_count = 5.0
messages = ['182367', '182689', '182694', '263792', '264057']
nosy_count = 4.0
nosy_names = ['terry.reedy', 'berker.peksag', 'Kim.Gr\xc3\xa4sman', 'luiz.poleto']
pr_nums = []
priority = 'normal'
resolution = None
stage = 'needs patch'
status = 'open'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue17233'
versions = ['Python 3.5', 'Python 3.6']

[KimGrsman]

Python 3.2.3 on 64-bit Windows 7.

When I set debuglevel on HTTPConnection to 1, the output seems jumbled, and I'm having trouble interpreting it.

Attached is a full, anonymized log from a conversation I was troubleshooting.

Here's an excerpt:

send: b'GET /a HTTP/1.1\r\nHost: localhost:55380\r\nAccept-Encoding: identity\r\n\r\n'
reply: 'HTTP/1.1 503 Service unavailable\r\n'
header: Connection header: Content-Length header: Content-Type header: Date send: b'GET /a HTTP/1.1\r\nHost: localhost:55380\r\nAccept-Encoding: identity\r\n\r\n'
reply: 'HTTP/1.1 503 Service unavailable\r\n'

• Does line 3, starting with header:, show headers for the request or response? I'm guessing response, but it didn't occur to me until just now, after a full day of looking at it.
• It would be nice if the header dump showed both header key and value
• There's a trailing "send:" at the end of the header: line, shouldn't that be on its own line?

Overall, not printing a newline after these debug statements makes it really hard to combine with other print debugging, as unrelated prints show up at the end of every line of httpclient's debug output.

I find "header" a bit confusing as a prefix, as it doesn't say whether it's request or response headers. Maybe change the prefix to "response-headers:" and also add "request-headers:", even if those are visible in the "send:" lines? Alternatively, why not show the response headers in the "reply:" dump?

Would you consider patches to address these concerns?

Thank you!

[terryjreedy]

The doc is vague on debug output (intentionally so, I suspect).
" Any value greater than 0 will cause all currently defined debug output to be printed to stdout."

I agree that send: and reply: should be formatted the same, so the reply: line should include the headers *with* the values. The current header line seems to be truncated after Date, without even its ':', and it is definitely missing a newline. Are you claiming that there are other missing newlines? I don't understand the lines with
send: bytearray(b'\x00\x00\x00\x00\x00\x00\x00\x00\x00')

Patches are good, but you might wait a few days for other comments as I am definitely not an http expert.

[KimGrsman]

Thanks for your response!

I agree that send: and reply: should be formatted the same,
so the reply: line should include the headers *with* the
values.

OK, yeah, that would avoid having to specify request/response for headers as well, I think.

The current header line seems to be truncated after Date,
without even its ':',

It doesn't look like there are any trailing colons on header names. Rather, all header names have a "header: " prefix. As you can see, it's pretty hard to parse :-)

and it is definitely missing a newline.

Glad we agree!

Are you claiming that there are other missing newlines?

It's not visible in the attached log, but if you add print() statements in a script using http.client, the output usually ends up at the end of one of http.client's log lines. So I think every log output is missing a newline.

I don't understand the lines with
send: bytearray(b'\x00\x00\x00\x00\x00\x00\x00\x00\x00')

We're sending binary data in our HTTP body, so this is the actual content. For some reason, though, the fact that it's binary seems to force it onto its own line.

Patches are good, but you might wait a few days
for other comments as I am definitely not an http expert.

OK, thanks again!

[poleto]

The attached patch fixes 2 of the main issues reported:

• Missing header values
• Missing newline at the end of the header line

I thought about the suggestion to include the response headers with the reply but considering that they are two different elements in an HTTP response message, I think it makes more sense to keep them on separate lines. The names, however, could be changed; perhaps from reply to response-body and headers to response-headers but maybe it could affect other users already expecting these values?

[KimGrsman]

Thanks! I filed this so long ago that I'd forgotten about it.

I ran the code in question with your patch manually hacked into my Python installation (3.4.1) and output is much easier to digest now.

I don't have a strong opinion on key names -- I haven't needed this code path since I filed the bug :) -- it's probably fine as-is if nobody wants to take a stab at it.

Anyway, thanks for this, I can confirm that it solves my problem, and it would be nice if it went into trunk.

[crazymerlyn]

Looks like this was fixed by #6611

[picnixz]

Thank you for digging out this 10y+ issue :') It has indeed been completed in #6611 and #12681.