Merge pull request #1433 from palmtenor/logmsg

Unify DEBUG_BPF logging to be handled in libbpf

src/cc/api/BPF.cc

@@ -483,9 +483,8 @@ StatusTuple BPF::load_func(const std::string& func_name,
   fd = bpf_prog_load(type, func_name.c_str(),
                      reinterpret_cast<struct bpf_insn*>(func_start),
                      func_size, bpf_module_->license(),
-                     bpf_module_->kern_version(), nullptr,
-                     0  // BPFModule will handle error printing
-                    );
+                     bpf_module_->kern_version(),
+                     flag_ & DEBUG_BPF ? 1 : 0, nullptr, 0);
 
   if (fd < 0)
     return StatusTuple(-1, "Failed to load %s: %d", func_name.c_str(), fd);

src/cc/api/BPF.h

@@ -46,7 +46,7 @@ public:
   static const int BPF_MAX_STACK_DEPTH = 127;
 
   explicit BPF(unsigned int flag = 0, TableStorage* ts = nullptr)
-      : bpf_module_(new BPFModule(flag, ts)) {}
+      : flag_(flag), bpf_module_(new BPFModule(flag, ts)) {}
   StatusTuple init(const std::string& bpf_program,
                    const std::vector<std::string>& cflags = {},
                    const std::vector<USDT>& usdt = {});
@@ -185,6 +185,8 @@ private:
                                   std::string &module_res,
                                   uint64_t &offset_res);
 
+  int flag_;
+
   std::unique_ptr<BPFModule> bpf_module_;
 
   std::map<std::string, int> funcs_;

src/cc/libbpf.c

@@ -199,10 +199,17 @@ int bpf_get_next_key(int fd, void *key, void *next_key)
   return syscall(__NR_bpf, BPF_MAP_GET_NEXT_KEY, &attr, sizeof(attr));
 }
 
-static void bpf_print_hints(char *log)
+static void bpf_print_hints(int ret, char *log)
 {
+  if (ret < 0)
+    fprintf(stderr, "bpf: Failed to load program: %s\n", strerror(errno));
   if (log == NULL)
     return;
+  else
+    fprintf(stderr, "%s\n", log);
+
+  if (ret >= 0)
+    return;
 
   // The following error strings will need maintenance to match LLVM.
 
@@ -344,39 +351,58 @@ int bpf_prog_get_tag(int fd, unsigned long long *ptag)
 int bpf_prog_load(enum bpf_prog_type prog_type, const char *name,
                   const struct bpf_insn *insns, int prog_len,
                   const char *license, unsigned kern_version,
-                  char *log_buf, unsigned log_buf_size)
+                  int log_level, char *log_buf, unsigned log_buf_size)
 {
   size_t name_len = name ? strlen(name) : 0;
   union bpf_attr attr;
-  char *bpf_log_buffer = NULL;
-  unsigned buffer_size = 0;
+  char *tmp_log_buf = NULL;
+  unsigned tmp_log_buf_size = 0;
   int ret = 0;
 
   memset(&attr, 0, sizeof(attr));
-  attr.prog_type = prog_type;
-  attr.insns = ptr_to_u64((void *) insns);
-  attr.insn_cnt = prog_len / sizeof(struct bpf_insn);
-  attr.license = ptr_to_u64((void *) license);
-  attr.log_buf = ptr_to_u64(log_buf);
-  attr.log_size = log_buf_size;
-  attr.log_level = log_buf ? 1 : 0;
-  memcpy(attr.prog_name, name, min(name_len, BPF_OBJ_NAME_LEN - 1));
 
+  attr.prog_type = prog_type;
   attr.kern_version = kern_version;
-  if (log_buf)
-    log_buf[0] = 0;
+  attr.license = ptr_to_u64((void *)license);
 
+  attr.insns = ptr_to_u64((void *)insns);
+  attr.insn_cnt = prog_len / sizeof(struct bpf_insn);
   if (attr.insn_cnt > BPF_MAXINSNS) {
-    ret = -1;
     errno = EINVAL;
     fprintf(stderr,
             "bpf: %s. Program too large (%u insns), at most %d insns\n\n",
             strerror(errno), attr.insn_cnt, BPF_MAXINSNS);
-    return ret;
+    return -1;
   }
 
-  ret = syscall(__NR_bpf, BPF_PROG_LOAD, &attr, sizeof(attr));
+  attr.log_level = log_level;
+  if (attr.log_level > 0) {
+    if (log_buf_size > 0) {
+      // Use user-provided log buffer if availiable.
+      log_buf[0] = 0;
+      attr.log_buf = ptr_to_u64(log_buf);
+      attr.log_size = log_buf_size;
+    } else {
+      // Create and use temporary log buffer if user didn't provide one.
+      tmp_log_buf_size = LOG_BUF_SIZE;
+      tmp_log_buf = malloc(tmp_log_buf_size);
+      if (!tmp_log_buf) {
+        fprintf(stderr, "bpf: Failed to allocate temporary log buffer: %s\n\n",
+                strerror(errno));
+        attr.log_level = 0;
+      } else {
+        tmp_log_buf[0] = 0;
+        attr.log_buf = ptr_to_u64(tmp_log_buf);
+        attr.log_size = tmp_log_buf_size;
+      }
+    }
+  }
+
+  memcpy(attr.prog_name, name, min(name_len, BPF_OBJ_NAME_LEN - 1));
 
+  ret = syscall(__NR_bpf, BPF_PROG_LOAD, &attr, sizeof(attr));
+  // BPF object name is not supported on older Kernels.
+  // If we failed due to this, clear the name and try again.
   if (ret < 0 && name_len && (errno == E2BIG || errno == EINVAL)) {
     memset(attr.prog_name, 0, BPF_OBJ_NAME_LEN);
     ret = syscall(__NR_bpf, BPF_PROG_LOAD, &attr, sizeof(attr));
@@ -390,7 +416,6 @@ int bpf_prog_load(enum bpf_prog_type prog_type, const char *name,
     // mem for the user, so an accurate calculation of how much memory to lock
     // for this new program is difficult to calculate. As a hack, bump the limit
     // to unlimited. If program load fails again, return the error.
-
     struct rlimit rl = {};
     if (getrlimit(RLIMIT_MEMLOCK, &rl) == 0) {
       rl.rlim_max = RLIM_INFINITY;
@@ -400,40 +425,65 @@ int bpf_prog_load(enum bpf_prog_type prog_type, const char *name,
     }
   }
 
-  if (ret < 0 && !log_buf) {
+  // The load has failed. Handle log message.
+  if (ret < 0) {
+    // User has provided a log buffer.
+    if (log_buf_size) {
+      // If logging is not already enabled, enable it and do the syscall again.
+      if (attr.log_level == 0) {
+        attr.log_level = 1;
+        attr.log_buf = ptr_to_u64(log_buf);
+        attr.log_size = log_buf_size;
+        ret = syscall(__NR_bpf, BPF_PROG_LOAD, &attr, sizeof(attr));
+      }
+      // Print the log message and return.
+      bpf_print_hints(ret, log_buf);
+      if (errno == ENOSPC)
+        fprintf(stderr, "bpf: log_buf size may be insufficient\n");
+      goto return_result;
+    }
 
-    buffer_size = LOG_BUF_SIZE;
-    // caller did not specify log_buf but failure should be printed,
-    // so repeat the syscall and print the result to stderr
+    // User did not provide log buffer. We will try to increase size of
+    // our temporary log buffer to get full error message.
+    if (tmp_log_buf)
+      free(tmp_log_buf);
+    tmp_log_buf_size = LOG_BUF_SIZE;
+    attr.log_level = 1;
     for (;;) {
-         bpf_log_buffer = malloc(buffer_size);
-         if (!bpf_log_buffer) {
-             fprintf(stderr,
-                     "bpf: buffer log memory allocation failed for error %s\n\n",
-                     strerror(errno));
-             return ret;
-         }
-         bpf_log_buffer[0] = 0;
-
-         attr.log_buf = ptr_to_u64(bpf_log_buffer);
-         attr.log_size = buffer_size;
-         attr.log_level = bpf_log_buffer ? 1 : 0;
-
-         ret = syscall(__NR_bpf, BPF_PROG_LOAD, &attr, sizeof(attr));
-         if (ret < 0 && errno == ENOSPC) {
-             free(bpf_log_buffer);
-             bpf_log_buffer = NULL;
-             buffer_size <<= 1;
-         } else {
-             break;
-         }
+      tmp_log_buf = malloc(tmp_log_buf_size);
+      if (!tmp_log_buf) {
+        fprintf(stderr, "bpf: Failed to allocate temporary log buffer: %s\n\n",
+                strerror(errno));
+        goto return_result;
+      }
+      tmp_log_buf[0] = 0;
+      attr.log_buf = ptr_to_u64(tmp_log_buf);
+      attr.log_size = tmp_log_buf_size;
+
+      ret = syscall(__NR_bpf, BPF_PROG_LOAD, &attr, sizeof(attr));
+      if (ret < 0 && errno == ENOSPC) {
+        // Temporary buffer size is not enough. Double it and try again.
+        free(tmp_log_buf);
+        tmp_log_buf = NULL;
+        tmp_log_buf_size <<= 1;
+      } else {
+        break;
+      }
     }
+  }
 
-    fprintf(stderr, "bpf: %s\n%s\n", strerror(errno), bpf_log_buffer);
-    bpf_print_hints(bpf_log_buffer);
-
-    free(bpf_log_buffer);
+  // If log_level is not 0, either speficied by user or set due to error,
+  // print the log message.
+  if (attr.log_level > 0) {
+    if (log_buf)
+      bpf_print_hints(ret, log_buf);
+    else if (tmp_log_buf)
+      bpf_print_hints(ret, tmp_log_buf);
   }
+
+return_result:
+  if (tmp_log_buf)
+    free(tmp_log_buf);
   return ret;
 }
 

src/cc/libbpf.h

@@ -38,10 +38,27 @@ int bpf_delete_elem(int fd, void *key);
 int bpf_get_first_key(int fd, void *key, size_t key_size);
 int bpf_get_next_key(int fd, void *key, void *next_key);
 
+/*
+ * Load a BPF program, and return the FD of the loaded program.
+ *
+ * On newer Kernels, the parameter name is used to identify the loaded program
+ * for inspection and debugging. It could be different from the function name.
+ *
+ * If log_level has value greater than 0, or the load failed, it will enable
+ * extra logging of loaded BPF bytecode and register status, and will print the
+ * logging message to stderr. In such cases:
+ *   - If log_buf and log_buf_size are provided, it will use and also write the
+ *     log messages to the provided log_buf. If log_buf is insufficient in size,
+ *     it will not to any additional memory allocation.
+ *   - Otherwise, it will allocate an internal temporary buffer for log message
+ *     printing, and continue to attempt increase that allocated buffer size if
+ *     initial attemp was insufficient in size.
+ */
 int bpf_prog_load(enum bpf_prog_type prog_type, const char *name,
                   const struct bpf_insn *insns, int insn_len,
                   const char *license, unsigned kern_version,
-                  char *log_buf, unsigned log_buf_size);
+                  int log_level, char *log_buf, unsigned log_buf_size);
+
 int bpf_attach_socket(int sockfd, int progfd);
 
 /* create RAW socket and bind to interface 'name' */

src/lua/bcc/bpf.lua

@@ -160,7 +160,8 @@ function Bpf:load_func(fn_name, prog_type)
     libbcc.bpf_function_start(self.module, fn_name),
     libbcc.bpf_function_size(self.module, fn_name),
     libbcc.bpf_module_license(self.module),
-    libbcc.bpf_module_kern_version(self.module), nil, 0)
+    libbcc.bpf_module_kern_version(self.module),
+    0, nil, 0)
 
   assert(fd >= 0, "failed to load BPF program "..fn_name)
   log.info("loaded %s (%d)", fn_name, fd)

src/lua/bcc/libbcc.lua

@@ -32,7 +32,8 @@ int bpf_get_next_key(int fd, void *key, void *next_key);
 
 int bpf_prog_load(enum bpf_prog_type prog_type, const char *name,
   const struct bpf_insn *insns, int insn_len,
-  const char *license, unsigned kern_version, char *log_buf, unsigned log_buf_size);
+  const char *license, unsigned kern_version,
+  int log_level, char *log_buf, unsigned log_buf_size);
 int bpf_attach_socket(int sockfd, int progfd);
 
 /* create RAW socket and bind to interface 'name' */

src/python/bcc/__init__.py

@@ -320,23 +320,13 @@ class BPF(object):
             return self.funcs[func_name]
         if not lib.bpf_function_start(self.module, func_name.encode("ascii")):
             raise Exception("Unknown program %s" % func_name)
-        buffer_len = LOG_BUFFER_SIZE
-        while True:
-            log_buf = ct.create_string_buffer(buffer_len) if self.debug else None
-            fd = lib.bpf_prog_load(prog_type,
-                    func_name.encode("ascii"),
-                    lib.bpf_function_start(self.module, func_name.encode("ascii")),
-                    lib.bpf_function_size(self.module, func_name.encode("ascii")),
-                    lib.bpf_module_license(self.module),
-                    lib.bpf_module_kern_version(self.module),
-                    log_buf, ct.sizeof(log_buf) if log_buf else 0)
-            if fd < 0 and ct.get_errno() == errno.ENOSPC and self.debug:
-                buffer_len <<= 1
-            else:
-                break
-
-        if self.debug & DEBUG_BPF and log_buf.value:
-            print(log_buf.value.decode(), file=sys.stderr)
+        fd = lib.bpf_prog_load(prog_type,
+                func_name.encode("ascii"),
+                lib.bpf_function_start(self.module, func_name.encode("ascii")),
+                lib.bpf_function_size(self.module, func_name.encode("ascii")),
+                lib.bpf_module_license(self.module),
+                lib.bpf_module_kern_version(self.module),
+                1 if (self.debug & DEBUG_BPF) else 0, None, 0);
 
         if fd < 0:
             atexit.register(self.donothing)

src/python/bcc/libbcc.py

@@ -84,7 +84,7 @@ lib.bpf_attach_socket.restype = ct.c_int
 lib.bpf_attach_socket.argtypes = [ct.c_int, ct.c_int]
 lib.bpf_prog_load.restype = ct.c_int
 lib.bpf_prog_load.argtypes = [ct.c_int, ct.c_char_p, ct.c_void_p,
-        ct.c_size_t, ct.c_char_p, ct.c_uint, ct.c_char_p, ct.c_uint]
+        ct.c_size_t, ct.c_char_p, ct.c_uint, ct.c_int, ct.c_char_p, ct.c_uint]
 lib.bpf_attach_kprobe.restype = ct.c_void_p
 _CB_TYPE = ct.CFUNCTYPE(None, ct.py_object, ct.c_int,
         ct.c_ulonglong, ct.POINTER(ct.c_ulonglong))