Logging contains newlines (because it uses ByteBuffer.debugDescription which IMHO it shouldn't)
weissi opened this issue · 11 comments
AHC logs bytes of the HTTP connection (which is in itself questionable #689). But even if we think that's okay I don't think it should just log ByteBuffer.debugDescription which contains newlines and is supposed to be human readable.
If AHC thinks it needs to log the bytes then it should do so without logging all the other crap that ByteBuffer.debugDescription contains (especially the newlines, don't think we usually want to have newlines in our log metadata?).
body(ByteBuffer { readerIndex: 0, writerIndex: 98, readableBytes: 98, capacity: 98, storageCapacity: 128, slice: _ByteBufferSlice { 4..<102 }, storage: 0x0000600002c26500 (128 bytes) }
readable bytes (max 1k): [ 20 20 20 7b 0a 20 20 20 20 20 20 22 73 74 61 74 75 73 22 3a 20 22 30 22 2c 0a 20 20 20 20 20 20 22 70 72 73 49 64 22 3a 20 22 31 22 2c 0a 20 20 20 20 20 20 22 77 65 20 77 61 6e 74 20 74 6f 20 68 61 76 65 20 73 6f 6d 65 20 6e 65 77 6c 69 6e 65 73 20 68 65 72 65 22 3a 20 22 22 0a 20 20 20 20 7d ])
Much easier once apple/swift-nio#2447 is done (e.g. by getting apple/swift-nio#2475 in)
Happy to clean this up as well once I'm done with apple/swift-nio#2475.
@weissi, okay, here's the plan:
- I'll temporarily switch to
natikgadzhi:feature/byte-buffer-hexdumpbranch forSwiftNIOinPackage.swiftso I can usehexDump - I'll replace
buffer.debugDescriptionwithbuffer.hexDump(format: .xxdCompatible(maxLength: 1_000)). - Once apple/swift-nio#2475 gets merged, I'll cleanup
Package.swiftand we can merge that in, right?
@weissi, okay, here's the plan:
- I'll temporarily switch to
natikgadzhi:feature/byte-buffer-hexdumpbranch forSwiftNIOinPackage.swiftso I can usehexDump- I'll replace
buffer.debugDescriptionwithbuffer.hexDump(format: .xxdCompatible(maxLength: 1_000)).- Once Adding ByteBuffer.hexDump in xxd and hexdump -C formats apple/swift-nio#2475 gets merged, I'll cleanup
Package.swiftand we can merge that in, right?
Works for me assuming you mark it as "Work in Progress" PR such that the PR won't accidentally get merged ;)
Okay! I looked around in the code, and it's not immediately obvious where the buffer gets logged. If you have a hint on where to look — now is the time. My next step is to put together a minimal project that uses AHC so I can debug it stumble at the code that outputs the request/response bytes. Once I find where it is, it should be straightforward to swap out what/how it gets logged.
I think it is coming from here:
What I learned today is that the default struct and enum string representation will use the debugDescription of any properties/associated types if available. Therefore the debugDescription of ByteBuffer is picked up here as httpPart is an enum HTTPPart and not directly a ByteBuffer.
After that discovery I think we should rethink the debugDescription of ByteBuffer.
Yep! @dnadoba
I think it is coming from here:
That's what I found, too — assumed that httpPart is some struct / class that wraps or has a ByteBuffer property in it, and then it gets serialized into a String with debugDescription() by default.
After that discovery I think we should rethink the debugDescription of ByteBuffer.
Since there is no code that handles specific logging output of a ByteBuffer in AHC, and it just logs the whole thing — I agree, it would be easier to just have ByteBuffer provide a better format for the logs.
The big question is whether AHC or anything else should use debugDescription() for logging, or if we should explicitly add a metadataKey with a hex dump instead.
Option A: Rework ByteBuffer.debugDescrpiption() to support formats
@weissi, should we consider something like this in ByteBuffer?
func debugDescription(format: HexDumpFormat = .debug) -> String {
return self.hexDump(format: format)
}And then add additional format (let's say there will be .xxd, .hexdump, and .debug). Debug format will default to what it currently outputs — some basic metadata, and the hex dump, where we can replace _storage.dumpBytes with .hexDump(format: .plain).
Additionally, we could remove _storage.dumpBytes altogether. I can file an issue and work on this with @glbrntt.
Option B: Rework AHC logging to not use debugDescription
That would probably be around the part that @dnadoba highlighted:
self.logger.trace("HTTP response part received", metadata: [
"ahc-http-part": "\(httpPart)",
]) We'll need to cast httpPart to something we can grab the ByteBuffer from first, and then do something like
self.logger.trace("HTTP response part received", metadata: [
"ahc-http-bytes": "\((httpPart as? WhateverHasTheByteBuffer).bytes?.hexDump(format: .xxdCompatible))",
]) What I learned today is that the default
structandenumstring representation will use thedebugDescriptionof any properties/associated types if available. Therefore thedebugDescriptionofByteBufferis picked up here ashttpPartis an enumHTTPPartand not directly aByteBuffer.After that discovery I think we should rethink the
debugDescriptionofByteBuffer.
We need to fix HTTPPart's description to not call into ByteBuffer's debugDescription. ByteBuffer's debugDescription is useful to debug ByteBuffers (which is what it's meant to do).
debugDescription should just be a version of description that is suitable for structural display as described and changed in this PR: apple/swift-nio#2495.
Afterwards we no longer have new lines in the output and we need to think about #689 and decided if the full contents of a request/response should actually be included in the trace log or not. We can close this issue then and shift the discussion over to #689.
@natikgadzhi sorry for kind of taking over this issue. I have discovered this issue in related work over in swift-certificates and as this is against the documented behaviour I though this might be a controversial PR.
All good! Thank you for keeping the discussion in the open, so I can follow along. Good to close this, I'll keep an eye on the follow up issues.