On Mon, Mar 20, 2023 at 9:10 AM Lorenz Bauer <lmb@xxxxxxxxxxxxx> wrote: > > Hi Andrii! > > This is a great idea. Preserving the end of the log is the right thing > to do, and I agree that it would've been nice to do this from the > start. Some thoughts on the approach below, based on a discussion I > had with Robin and Timo. > > On Fri, Mar 17, 2023 at 11:13 PM Andrii Nakryiko > <andrii.nakryiko@xxxxxxxxx> wrote: > > > > Libbpf by default uses 16MB right now, I didn't touch that part yet, > > but it might be good to reduce this size if the kernel supports this > > new behavior. Go library seems to be using 64KB, which probably would > > be adequate for a lot of cases, but yeah, maybe Go library would like > > to use slightly bigger default if rotating log behavior is supported > > by kernel? > > cilium/ebpf relies on ENOSPC to figure out if the verifier log has > been truncated, and makes that information available in the API via > VerifierError.Truncated [0]. This happens so that cilium can retry the > program load with successively larger log buffers to capture the full > verifier log. The full log is very valuable to us since we don't > operate on our own infrastructure, so reproducing an error that a > customer has on our own hardware is not always straightforward. > Instead we include the full log in sysdumps. We want to preserve this > as much as possible. > > Arguably 64KB might already be on the large side! The library > currently does the "execute PROG_LOAD with log disabled first, get > debug output later" trick (which libbpf also does I think?). It'd be > nice if we could right-size the buffer on the retry. > > > Alternative would be to make this rotating behavior opt-in, but that > > would require active actions by multiple libraries and applications to > > actively detect support. Given the rotating behavior seems like a good > > default behavior I wish we had from the very beginning, I went for > > making it default. > > Given the above, taking away ENOSPC is problematic because an old > cilium/ebpf on a new kernel doesn't know how to get the full log. I > think it's better to make this opt in, since it also makes it easier > to reason about from user space. Working with UAPI that changes > behaviour based on kernel version is harder than doing feature > probing. > > I do agree that ENOSPC is not a great API however and that it doesn't > make sense for the rotated log to return it. It's a really big hammer > that doesn't actually give us a key bit of information: how big should > the buffer have been to obtain the full log. To recap, cilium/ebpf > needs to know when the log was truncated and would like to know how > big the buffer should be. How about the following: > > - To avoid breaking old libs on new kernels we make the behaviour opt > in via BPF_LOG_TRUNCATE_HEAD or similar. > - We add a field log_size_full to bpf_attr for PROG_LOAD. In the > kernel we populate it with the buffer size that is required to > retrieve an untruncated log for the given flags. log_size_full must be > 0 when entering the syscall. > - If BPF_LOG_TRUNCATE_HEAD is specified, we enable rotation and never > return ENOSPC. > > From the user space side, we can use the API as follows: > > - If errno = ENOSPC or log_size < log_size_full we can deduce that the > log was truncated. > - If log_size_full > 0, we can use it to right-size the log buffer and > retry only once instead of the increase-buf-size-and-retry loop. > 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. 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). 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? 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. So feature detection is not hard for library. 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. 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. But in summary, what do you think about just returning -ENOSPC even with new behavior and keep rotating log behavior default? Additionally, for rotating mode we can return required max log buffer size in a new UAPI field. Would this address all your concerns? > FWIW, BTF_LOAD would benefit from the same improvements! 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. > > Best > Lorenz > > 0: https://pkg.go.dev/github.com/cilium/ebpf@v0.10.0/internal#VerifierError
