[eBPF] bpf_trace_printk 출력 방법

배경

LSM-BPF를 하면서, LSM hook이 걸렸지만, 실제로 실행이 되지 않는 상황이 발생했다. 그래서 이를 해결하기 위해서, 그리고 이게 정말로 동작하는지를 확인하기 위해서 bpf_trace_printk를 사용하게 되었다. 이런 과정에서 알게된 삽질 내용이다. 따라서, 간만에 본업 중 하나인 eBPF에 관한 글을 적게 되었다.

 

시작하기 전에...

알 사람들은 알겠지만, 나는 cilium의 eBPF를 사용한다. 만약 bcc 또는 그냥 bpftool로 로딩하는 eBPF를 사용하는 경우에는 이게 잘 동작하지 않을 수 있다. 사실 물론 다 같이 동작하긴 하지만, 살짝의 차이점이 있을 수 있다는 것을 인지했으면 좋겠다.

 

우선 배경지식으로 알고가면 좋을 내용에 대해서 먼저 알아보도록 하려고 한다. 우선 흔히 알고 있는 bpf_trace_printk 그리고 bpf_printk 이런 두개의 함수가 존재한다. 함수들은 bpf_helper_defs.h에 정의가 되어있으며, 커널 코드 기준으로는 kernel/trace/bpf_trace.c 에 존재한다. 인터넷에 고맙게 잘 정리된 글이 있다.

 

https://nakryiko.com/posts/bpf-tips-printk/

BPF tips & tricks: the guide to bpf_trace_printk() and bpf_printk()

요약하자면 다음과 같다:

 

bpf_trace_printk

bpf_trace_printk의 경우, format string, string size 그리고 기타 값들이 들어간다. 예시 함수는 다음과 같다. 

char buff[20];
const char fmt_str[] = "uprobe/bash_readline called! PID: %d, buff %s\n";

bpf_probe_read(buff, sizeof(buff), (void *)PT_REGS_RC(ctx));
int pid = bpf_get_current_pid_tgid() >> 32;
bpf_trace_printk(fmt_str, sizeof(fmt_str), pid, buff);

이처럼, fmt_str, sizeof(fmt_str) 그리고 printf와 같이 변수들이 들어간다. 이렇게 되면 귀찮은게, 매번 const char를 만들어줘야 하는 번거로움과, sizeof를 확인해주는 번거로움이 생긴다. 이를 보완하고 간단하게 쓰고자 나온 것이 bpf_printk 이다.

bpf_printk

bpf_printk의 경우 사실상 bpf_trace_printk를 조금 더 쉽게 쓰고자 해서 만들어진 매크로이다. bpf_helpers.h에 다음과 같이 매크로로 정의 되어있다.

/* Helper macro to print out debug messages */
#define bpf_printk(fmt, args...) ___bpf_pick_printk(args)(fmt, ##args)

예시 사용법은 다음과 같다.

int pid = bpf_get_current_pid_tgid() >> 32;
bpf_printk("lsm: auditing!! PID: %d", pid);

예시

알다시피, printf는 화면에 문자열을 출력한다. (물론 pipe를 쓴다면 얘기가 달라지지만, 그냥 그렇다고 치고 넘어가자...) 그렇다면 이렇게 생성된 문자열들은 어디 출력이 되는 것일까? bpf_helpers.h 에 따르면 다음과 같이 출력된다고 한다

 

It prints a message defined by format *fmt* (of size *fmt_size*) * to file */sys/kernel/debug/tracing/trace* from DebugFS. 
...
Each time the helper is called, it appends a line to the trace. * Lines are discarded while */sys/kernel/debug/tracing/trace* is * open, use */sys/kernel/debug/tracing/trace_pipe* to avoid this.

 

간단하게 그러면 다음의  Uprobe를 만들어서 사용해보자

SEC("uretprobe/bash_readline")
int uretprobe_bash_readline(struct pt_regs *ctx) {
	char buff[20];
    const char fmt_str[] = "uprobe/bash_readline called! PID: %d, buff %s\n";

    bpf_probe_read(buff, sizeof(buff), (void *)PT_REGS_RC(ctx));
    int pid = bpf_get_current_pid_tgid() >> 32;
    bpf_trace_printk(fmt_str, sizeof(fmt_str), pid, buff);

	return 0;
}

이후, main.go에다가

// Open an ELF binary and read its symbols.
ex, err := link.OpenExecutable("/bin/bash")
if err != nil {
    log.Fatalf("opening executable: %s", err)
}

// Open a Uretprobe at the exit point of the symbol and attach
// the pre-compiled eBPF program to it.
up, err := ex.Uretprobe("readline", objs.UretprobeBashReadline, nil)
if err != nil {
    log.Fatalf("creating uretprobe: %s", err)
}
defer up.Close()

를 통해서 /bin/bash의 readline에 부착하자. 코드 전체는 귀찮아서 복붙을 하지 않았다. 이후 컴파일 및 실행을 하면 동작할 것이다.

 

일부 distro의 경우, bash에 readline 함수가 외부 shared lib로 사용하는 경우가 있다. 아마 최신 distro는 다 static linking을 사용하지만, 그럴 수도 있다. 모두 알다시피, uprobe는 shared lib에 부착이 안되기 때문에, 코드가 동작하지 않을 수 있다. ldd를 통해 /bin/bash가 readline을 static 또는 dynamic linking을 하는지 확인하고 진행하는 것을 추천한다.

예시 출력

아까 말한 것 처럼 /sys/kernel/debug/tracing/trace 에 기록이 남는다고 했다. 따라서 이걸 cat 해보자

 sudo cat /sys/kernel/debug/tracing/trace

내 문제인지 모르겠으나, tail -f 는 동작하지 않는 것 같다. 아무튼 bash에 다음과 같은 명령어를 입력했다.

isu@isu-lab:~$ ls | grep isu
isu@isu-lab:~$ ps | grep isu

이후, cat 을 통해 확인시

bash-160418  [003] d...1 27002.297701: bpf_trace_printk: uprobe/bash_readline called! PID: 160418, buff ls | grep isu
bash-160418  [003] d...1 27007.165735: bpf_trace_printk: uprobe/bash_readline called! PID: 160418, buff ps | grep isu

내용물이 나오는 것을 확인할 수 있다.

 

결론

간단하게 bash의 출력을 uprobe로 readline을 읽은 후 bpf_trace_printk로 출력했다. 이를 통해 더 빠른 디버깅이 가능할 것이다. bpf_trace_printk의 경우, 디버깅 용도로만 사용하라고 권장하고 있다. 생각해보면, tracepoint/syscall/sys_enter_write와 같이 엄청나게 쓰이는 곳의 경우, bpf_trace_printk를 사용하면 큰일이 날 것이다.