Log received ICP packets using debuging level 2

[yadij]

Initially just received packets which pass basic validity
and origin filters.

cache.log output looks like:

... icpHandleUdp: ICP Client remote=127.0.0.1:35844 FD 15
... icpHandleUdp: ICP Client REQUEST:
---------
ICP_QUERY #10 ICP/2
:length: 28
:flags: 0x40000000
      payload=
7f000001697474713a2f2f7777772e6578616d706c652f636f6d2f00
----------

[rousskov]

I stopped reviewing due to too many problems, but this partial/quick review should allow you to make progress.

[rousskov]

Consider dropping the minLevel() part -- IIRC, it will be added automatically for large pkt-length values.

[yadij]

I considered it. But to keep the log output consistent and because even short URI which most of these will be may contain credentials I am putting level-9 along with all other full-data dumps.

[rousskov]

Not sure what inconsistencies you perceive.

If we are concerned about credentials, then we should make that concern explicit IMO. If you are not around, somebody else can easily change or remove that debugging level without realizing that the information is sensitive. Not all level-9 information is sensitive, of course! We can address this by adding and using Raw::sensitive() or a similar method (which can just call minLevel(9) today, I guess, but future implementations could be different).

[yadij]

I am trying to make this output as similar as possible to the level-2 output already used by HTTP and FTP. Those displays are header only, without any payload logged until higher levels (ie DBG_DATA / 9).

Also, I think it a bad idea to create any distinction between small vs large payloads. "KISS" principle, etc. if not to avoid issues from mistakes in admin expectations.

[yadij]

@rousskov, pushing back to you to close off all the resolved review threads. Hopefully my response about consistency on the payload info resolves or removes the other related comments.

[rousskov]

Hopefully my response about consistency on the payload info resolves or removes the other related comments.

Unfortunately, it does not, but I think I now know where the misunderstanding is coming from.

[rousskov]

... Continuing from now-outdated #827 (comment) after #827 (comment)

I am trying to make this output as similar as possible to the level-2 output already used by HTTP and FTP. Those displays are header only, without any payload logged until higher levels (ie DBG_DATA / 9).

I think there is a misunderstanding of ICP format here. What we call "payload" in this ICP context is called "headers" in HTTP context. In other words, the ICP payload contains the same information that an HTTP header would contain -- usually the URL. In ICP, payload is just a variable-length part of the header-only message. In HTTP, the whole header is variable-length.

I also disagree that adding explicit minLevel() is consistent with the KISS principle or that showing this specific "payload" (usually containing URLs) at level 2 would make this dump inconsistent with HTTP/FTP header dumps (that also show URLs and a lot of other "sensitive" info).

[yadij]

This output is displaying ICP protocol syntax received (if valid), not HTTP or whatever protocol meta got sent in the payload. In Squid cache.log payload data is at level-9 / DBG_DATA.

The KISS relevance is that the ICP payload is being added to the same debugs() statement as the ICP header display (at the level-9). The slightly more complex variant would have it as a second debugs() statement with a repeated set of prefix connection details to identify it (in case of overlapping worker outputs).

Also, FTR I thought it was just URLs too initially but when you requested hex I looked at the RFC closely to see if that was necessary (it doubles the log increase per packet). Some of the packets do have non-URL data and binary blobs.

From the security / "safety" aspect, the principle being followed is to reduce the attack surface. In this case the surface area is number of places any potential sensitive info in the URL is available to attackers (CWE "Information Leak"). It is not necessary to log the ICP payload to perform basic traffic flow accounting / tracing, so it should not be done at the log level-2 provided for that. The only reason it is logged at all is for advance troubleshooting of URl mangling and normalization between proxies using ICP.

[rousskov]

These arguments are pretty much invalidated by the fact that ICP "payload" is not really payload in any true sense of that word when interpreted in relevant/Squid context. It is just a variable-size portion of the header. HTTP has one mechanism to supply such variable-size header information, PROXY protocol has another, ICP has its own way. Yes, the word is spelled "payload" in the RFC, but that is just letters. Sometimes, letters mislead if interpreted too literally. We need to think about the meaning of the ICAP message part we are printing. And that meaning is no different than a part of an HTTP or PROXY protocol header. We should use the same approach to report all those parts.

The fact that some headers carry binary data is not relevant to this change request. That fact only affects how we render the data, and we are in agreement that it should be rendered using hex (unless somebody wants to invest even more time to make that decision based on message type and payload field contents).

But I give up. This problem is just not worth my time. If I failed to convince you, leave minLevel(). No need to explain why I have not convinced you.

---

with a repeated set of prefix connection details to identify it (in case of overlapping worker outputs).

This is out of topic here, but just in case this resurfaces elsewhere: We should not repeat details. Squid cache.log format already identifies which worker the record is coming from.

[yadij]

These arguments are pretty much invalidated by the fact that ICP "payload" is not really payload in any true sense of that word when interpreted in relevant/Squid context. It is just a variable-size portion of the header.

The relevant context is that we are displaying a single message from a message-based protocol. Using that protocols terminology, in ICP specific code.

RFC 2816 section 1 is very explicit how to interpret the octets received:
"
ICP Message Format

The ICP message format consists of a 20-octet fixed header plus a
variable sized payload (see Figure 1).
"

The "Squid way" (er, context?) to display messages is level-2 for header, level-9 for payload.

[rousskov]

This hides all errors from the admin, including previously reported "abnormal" or "unexpected" errors from trusted peers. Even ICP access logs will not disclose them AFAICT. Please update the PR description to disclose and justify this significant change.

[yadij]

Reverted the in meaningful debugs error message in 36d79a3.

The high level message about unknown ICP version being ignored does not need to be logged at level-1.

[rousskov]

Still buggy AFAICT. I also left a few polishing suggestions.

When you are done with the next iteration, please either update the PR description to show the actual ICP message printout or just remove the misleading (made up?) sample.

[rousskov]

AFAICT, there is no guarantee we read or even allocated the last sizeof(icp_common_t) bytes that this code gives Raw(). Please note that pkt.length is the total packet size rather the payload size.

This is the second (at least) time this code gets it wrong. I recommend adding packetSize() and payloadSize() methods to icp_common_t while hiding the dangerous length data member from icp_common_t users.

[rousskov]

Please undo this out-of-scope formatting change. This new line is actually correct/useful IMO.

[rousskov]

Please make const if possible.

Suggested change

	auto len = comm_udp_recvfrom(sock,
	const auto len = comm_udp_recvfrom(sock,

[rousskov]

Please consider moving the dumping code to icp_common_t::print() instead of inspecting the pkt internals here.

[rousskov]

As discussed earlier, this hides the "unknown ICP version" error messages from the admin. That message was probably a good canary for an attack on the ICP port with random data.

Amos: The high level message about unknown ICP version being ignored does not need to be logged at level-1.

If the PR hides that error, I am not going to block it on those grounds because I do not have the time to argue and detail a good solution for the overall problem. However, if the PR hides that error, its description must disclose and justify that important reporting change. This is the second time I am requesting that disclosure.

As always, to save time, please add your justifications to the PR description rather than (just to) this change request thread.

[rousskov]

Given that this is a multiline output that follows very special formatting, the Debug::Extra trick does not work well here -- the payload dump gets misaligned. There is also a problem with Raw() printing an extra space when labeled. I suggest doing something like this to fix those problems:

":flags: " << asHex(pkt.flags) << '\n' <<
":payload:" << Raw("raw", (buf+sizeof(icp_common_t)), pkt.length).minLevel(DBG_DATA).hex() << '\n' <<
"----------");

We can also use "bytes" (or something else) instead of "raw" as the Raw() label. We could use nullptr label instead (and add a space after : before Raw()), but that will hide the payload size. Your call. And please test this. I may be missing some formatting nuances.

[rousskov]

I also adjusted PR title to be a bit more specific. Please polish further as needed, of course.