On Tue, Mar 21, 2023 at 9:18 AM Lorenz Bauer <lmb@xxxxxxxxxxxxx> wrote: > > On Mon, Mar 20, 2023 at 6:55 PM Andrii Nakryiko > <andrii.nakryiko@xxxxxxxxx> wrote: > > > > Great feedback. Let me address all of it in one place. > > > > Let's start with right-sizing the buffer. Curiously, with existing > > (fixed) log behavior, verifier doesn't and can't know the full size of > > the buffer it needs, as we stop producing log after -ENOSPC condition > > was detected. log->ubuf is set to NULL, after which > > bpf_verifier_log_needed() will start returning false. So in existing > > "logging mode" it's impossible to support this without major changes. > > I think that's fine, as long as we keep the door open to later on > extending the log_buf_max_size to append mode. Sure. > > > On the other hand, with rotating log, we could determine this very > > easily! We can just maintain max(log->end_pos, last_max_end_pos) > > throughout the verification process (we need max due to log reset: it > > still might need bigger buffer than final log length). > > Ah, tricky! Nitty gritty detail: can I get the max required size with > log_level > 0 but log_buf == NULL / log_size == 0? See above about ubuf==NULL ignoring any log calls, so no. And currently specifying log_level without specifying log_buf/log_size is -EINVAL. > > > So, to get the full size, we need rotating log behavior. > > > > What if we just make rotating log still return -ENOSPC, and set this > > new "log_buf_max_size" field to actual required full size. That will > > keep existing retry/resize logic intact and would be backwards > > compatible, right? > > There is a subtlety here: with this design it's impossible to load a > program with a rotating log and a buffer that is smaller than > log_buf_max_size. A contrived use case: for each program we load we'd > like to get the verifier stats printed as one of the last lines. > Without ENOSPC this can be done by allocating a buffer of 512 bytes or > something. You can do this with -ENOSPC as well. log_level = 4 will not emit lots of data or require big buffer, verifier will just print out few lines of log. So I think this case is covered just fine. > > Tying errno to log buffer size is wrong imo, so it'd be nice if we > could fix the interface going forward. You are nitpicking a bit here :) What I'd do in practice would be to set a buffer to 128 bytes (minimum size allowed before my changes) requested log_level=2 and would have guaranteed -ENOSPC. E.g. for empty program that just returns 0, I get (with log_level 2): 0: R1=ctx(off=0,imm=0) R10=fp0 0: (b4) w0 = 0 ; R0_w=0 1: (95) exit verification time 210 usec stack depth 0 processed 2 insns (limit 1000000) max_states_per_insn 0 total_states 0 peak_states 0 mark_read 0 Which is 210 bytes. So practically speaking there is no issue at all. But as you mentioned below, passing BPF_LOG_FIXED and expecting -EINVAL is straightforward as well. > > > As for feature detecting this change. Yes, there is no UAPI change > > (unless we add extra field, of course), but as I implemented it right > > now it's trivial to detect the change in behavior: set small buffer > > (few bytes), try load trivial program. If you get -EINVAL, then we > > have old kernel that enforces >=128 bytes for buffer. If you specify a > > bit bigger buffer, you should get -ENOSPC. If you get success, it's > > the new behavior. > > I think a better test would actually be to pass the new BPF_LOG flag > and check for EINVAL. Relying on buffer sizes is maybe a bit too > indirect? Sure, send BPF_LOG_FIXED and expect -EINVAL. Simple and works reliably. So I guess I'd do that. > > > What I'm worried with switching this to opt-in > > (BPF_LOG_TRUNCATE_HEAD), is that for various application that would > > want to use log_level 1/2 for some diagnostics in runtime, *they* > > would need to perform this feature detection just to know that it's > > safe to provide BPF_LOG_TRUNCATE_HEAD. > > Can you sketch this out a bit more, what kind of diagnostics do you > have in mind? If the application wants to parse the log it kind of > needs to know anyways? Going back to my "get verifier stats from prog > load" example above, if the rotating log isn't available I need to > either > > - skip getting verifier stats > - allocate a possibly large buffer to get at it in append mode > > That choice isn't one I can make as a library author. See above, if you want only verifier stats, log_level=4 is the way to go. It's guaranteed to fit in 512 buffer, so I don't think there is any issue here. As for user needing to feature-detect BPF_LOG_FIXED vs rotating log. Libbpf provides ability to set custom buffer and log_level per program or per entire BPF object, and libbpf passes this through to kernel. If user wants rotating log and it's opt-in, then they would need to do explicit feature detection, because libbpf can't guess user's intent. Similarly, tools like veristat, they'd need to do their detection. But we all agree that as a default, tail of the too long verifier log is desirable default behavior. So I think it's worth fighting for smooth experience, provided we don't break any reasonable application. > > > So I decided that it's better > > use experience to do opt-out. Just to explain my reasoning, I wanted > > to make users not care about this and just get useful log back. > > Ah, this is probably where our disconnect is. In my mind, detecting > and passing BPF_LOG_TRUNCATE_HEAD is definitely the responsibility of > the library, not the users. At least for the happy / common path. > Rough sketch of how PROG_LOAD and log_buf is handled in Go (probably > similar to libbpf?) > > if PROG_LOAD(user supplied log_level) < 0 && user supplied log_level == 0: > retry PROG_LOAD(log_level=1) > > There is some trickery when the user passes a log_level != 0, but most > PROG_LOAD go through this logic. The way I'd go about it is to add > TRUNCATE_HEAD to the retry PROG_LOAD call if the feature exists. As a > result, most failed program loads would get the benefit of this > feature. Right, this is not a big deal for libbpf and other loader libraries for default "retry with log_level=1 if program load failed". But I'm hoping we can get good default behavior for any other application to get reasonable output when they provide their custom log_level and/or log buffer. > > If a user explicitly requests a log I assume they know what they are > doing and it's probably best not to mess with it. To play the devil's > advocate, I think that making this behaviour opt out does break > expectations that user space has. See [0] for example which will have > to detect that rotating mode is used and deliberately disable that. We > can of course argue whether parsing the log is a wise thing to do, but > it's good to keep that fact in mind. I'm not familiar with coverbee, which specific part will break due to rotating vs fixed verifier log, assuming both return -ENOSPC? CoverBee seems to be parsing verifier log and trying to make sense out it (I see parsing register state, etc), so that tool definitely expects that it would have to follow any verifier log format changes and would have to accommodate them. > > > Heh, it actually does automatically as it uses bpf_verifier_log struct > > as well. So all the BPF_PROG_LOAD changes for log apply to BPF_BTF_LOG > > command. > > Nice :) Yep. So, in short, it still seems like -ENOSPC and rotating log behavior covers all reasonable cases, except some specialized tools that heavily rely on getting strictly head part of verifier log on -ENOSPC. I do think providing needed log buffer size is a nice feature and will add it in the next revision. Please let me know if I addressed your concerns above (e.g., log_level=4 for verifier stats, etc)? > > Best > Lorenz > > 0: https://github.com/cilium/coverbee
