blender学习系列之--CLOG

CLOG为blender提供的日志记录模块，它实现了日志记录的基本功能，同时提供了过滤功能，可通过参数来控制，实现准确记录所关注的记录，来帮助定位问题关键点。

该模块只有二个文件:CLG_log.h，clog.c。

在CLG_log.h文件最后有以下定义：

#define CLOG_INFO(clg_ref, level, ...) \
  CLOG_AT_SEVERITY(clg_ref, CLG_SEVERITY_INFO, level, __VA_ARGS__)
#define CLOG_WARN(clg_ref, ...) CLOG_AT_SEVERITY(clg_ref, CLG_SEVERITY_WARN, 0, __VA_ARGS__)
#define CLOG_ERROR(clg_ref, ...) CLOG_AT_SEVERITY(clg_ref, CLG_SEVERITY_ERROR, 0, __VA_ARGS__)
#define CLOG_FATAL(clg_ref, ...) CLOG_AT_SEVERITY(clg_ref, CLG_SEVERITY_FATAL, 0, __VA_ARGS__)

#define CLOG_STR_INFO(clg_ref, level, str) \
  CLOG_STR_AT_SEVERITY(clg_ref, CLG_SEVERITY_INFO, level, str)
#define CLOG_STR_WARN(clg_ref, str) CLOG_STR_AT_SEVERITY(clg_ref, CLG_SEVERITY_WARN, 0, str)
#define CLOG_STR_ERROR(clg_ref, str) CLOG_STR_AT_SEVERITY(clg_ref, CLG_SEVERITY_ERROR, 0, str)
#define CLOG_STR_FATAL(clg_ref, str) CLOG_STR_AT_SEVERITY(clg_ref, CLG_SEVERITY_FATAL, 0, str)

/* Allocated string which is immediately freed. */
#define CLOG_STR_INFO_N(clg_ref, level, str) \
  CLOG_STR_AT_SEVERITY_N(clg_ref, CLG_SEVERITY_INFO, level, str)
#define CLOG_STR_WARN_N(clg_ref, str) CLOG_STR_AT_SEVERITY_N(clg_ref, CLG_SEVERITY_WARN, 0, str)
#define CLOG_STR_ERROR_N(clg_ref, str) CLOG_STR_AT_SEVERITY_N(clg_ref, CLG_SEVERITY_ERROR, 0, str)
#define CLOG_STR_FATAL_N(clg_ref, str) CLOG_STR_AT_SEVERITY_N(clg_ref, CLG_SEVERITY_FATAL, 0, str)

总结来说，上面的代码定义了一组宏，方便用于程序中添加日志记录。分为三组，每组按严重程序分为4级，分别对应：INOF,WARN,ERROR,FATAL;

所有宏最终对应定义到CLOG_AT_SEVERITY,CLOG_STR_AT_SEVERITY,CLOG_STR_AT_SEVERITY_N这三个宏。

#define CLOG_AT_SEVERITY(clg_ref, severity, verbose_level, ...) \
  { \
    CLG_LogType *_lg_ty = CLOG_ENSURE(clg_ref); \
    if (((_lg_ty->flag & CLG_FLAG_USE) && (_lg_ty->level >= verbose_level)) || \
        (severity >= CLG_SEVERITY_WARN)) { \
      CLG_logf(_lg_ty, severity, __FILE__ ":" STRINGIFY(__LINE__), __func__, __VA_ARGS__); \
    } \
  } \
  ((void)0)

#define CLOG_STR_AT_SEVERITY(clg_ref, severity, verbose_level, str) \
  { \
    CLG_LogType *_lg_ty = CLOG_ENSURE(clg_ref); \
    if (((_lg_ty->flag & CLG_FLAG_USE) && (_lg_ty->level >= verbose_level)) || \
        (severity >= CLG_SEVERITY_WARN)) { \
      CLG_log_str(_lg_ty, severity, __FILE__ ":" STRINGIFY(__LINE__), __func__, str); \
    } \
  } \
  ((void)0)

#define CLOG_STR_AT_SEVERITY_N(clg_ref, severity, verbose_level, str) \
  { \
    CLG_LogType *_lg_ty = CLOG_ENSURE(clg_ref); \
    if (((_lg_ty->flag & CLG_FLAG_USE) && (_lg_ty->level >= verbose_level)) || \
        (severity >= CLG_SEVERITY_WARN)) { \
      const char *_str = str; \
      CLG_log_str(_lg_ty, severity, __FILE__ ":" STRINGIFY(__LINE__), __func__, _str); \
      MEM_freeN((void *)_str); \
    } \
  } \
  ((void)0)

 这三个宏的定义仅有细微差别，CLOG_AT_SEVERITY接受可变参数，最终调用CLOG_logf函数完成日志记录，CLOG_STR_AT_SEVERITY,CLOG_STR_AT_SEVERITY_N这两个宏均接受字符串作为记录内容，调用CLG_log_str函数记录到日志，后一个害在完成日志记录后立即释放字符串占用内存。

这三个宏在记录之前均对记录器类型进行检查，严重性大于或等于CLG_SEVERITY_WARN的准予记录，或者记录器类型标志为CLG_FLAG_USE且level大于或等于verbose_level的才准予记录，主要是为了过滤INFO类型记录过多而设置。

最终这些宏均调用CLG_logf或CLG_log_str来实现日志的记录。

在进一步分析时，来看看日志的几个结构：

1、日志上下文结构

typedef struct CLogContext {
   CLG_LogType *types;  //记录器类型的单链表 
   CLG_LogRef *refs;  //记录器引用的单链表
#ifdef WITH_CLOG_PTHREADS
  pthread_mutex_t types_lock;
#endif

  CLG_IDFilter *filters[2]; //记录过滤器，用于包含或排除某些信息的记录
  bool use_color;
  bool use_basename;
  bool use_timestamp;

  /** Borrowed, not owned. */
  int output;
  FILE *output_file;

  /** For timer (use_timestamp). */
  uint64_t timestamp_tick_start;

  /** For new types. */
  struct {
    int level;
  } default_type;

  //定义回调函数
  struct {
    void (*error_fn)(void *file_handle);
    void (*fatal_fn)(void *file_handle);
    void (*backtrace_fn)(void *file_handle);
  } callbacks;
} CLogContext;

 在clog.c中定义了g_ctx全局静态变量，在Blender中，只实现了单一的全局上下文。在CLG_init函数中调用CLG_ctx_init函数对g_ctx进行了初始化。代码如下：

/* 我们可以同时支持多个，但现在似乎不需要。 */
static struct CLogContext *g_ctx = NULL;

void CLG_init(void)
{
  g_ctx = CLG_ctx_init();

  clg_color_table_init(g_ctx->use_color);
}

static CLogContext *CLG_ctx_init(void)
{
  CLogContext *ctx = MEM_callocN(sizeof(*ctx), __func__);
#ifdef WITH_CLOG_PTHREADS
  pthread_mutex_init(&ctx->types_lock, NULL);
#endif
  ctx->default_type.level = 1;//这个定义了冗余信息显示级别，仅当记录的冗余级别小于或等于该值时才被记录
  CLG_ctx_output_set(ctx, stdout);

  return ctx;
}

static void CLG_ctx_output_set(CLogContext *ctx, void *file_handle)
{
  ctx->output_file = file_handle;
  ctx->output = fileno(ctx->output_file);//output中保存文件描述符
#if defined(__unix__) || defined(__APPLE__)
  ctx->use_color = isatty(ctx->output);
#elif defined(WIN32)
  /* 根据windows10构建18298，所有的标准控制台都支持颜色 
   *就像linux终端一样，但它需要被打开。 
   *要打开颜色，我们需要通过传递标志ENABLE_VIRTUAL_TERMINAL_PROCESSING到SetConsoleMode来启用虚拟终端处理 
   *如果系统不支持虚拟终端处理，它将悄然失败和标志 
   *将不会被设置。*/
    
  GetConsoleMode(GetStdHandle(STD_OUTPUT_HANDLE), &clg_previous_console_mode);

  ctx->use_color = 0;
  if (IsWindows10OrGreater() && isatty(ctx->output)) {
    DWORD mode = clg_previous_console_mode | ENABLE_VIRTUAL_TERMINAL_PROCESSING;
    if (SetConsoleMode(GetStdHandle(STD_OUTPUT_HANDLE), mode)) {
      ctx->use_color = 1;
    }
  }
#endif
}

从上面代码看出，在g_ctx初始化时，仅初始化了default_type和output二个字段，对两个列表并没有初始化。这就要求在使用时对链表进行维护，同时也提供了灵活性（lazyer access)。

 全局上下文中设置了日志输出，所有与它相关记录器具有了相同的上下文。从上下文定义可以看出，一个上下文可以有多种记录器类型，多个记录器，它们构成了上下文中的单链表。

再来看具体的记录器和类型： 

/* Don't typedef enums. */
enum CLG_LogFlag {
  CLG_FLAG_USE = (1 << 0),
};
//定义记录严重程序
enum CLG_Severity {
  CLG_SEVERITY_INFO = 0,
  CLG_SEVERITY_WARN,
  CLG_SEVERITY_ERROR,
  CLG_SEVERITY_FATAL,
};

/* Each logger ID has one of these. */
typedef struct CLG_LogType {
  struct CLG_LogType *next;
  char identifier[64];
  /** FILE output. */
  struct CLogContext *ctx;
  /** Control behavior. */
  int level;
  enum CLG_LogFlag flag;
} CLG_LogType;

//记录器
typedef struct CLG_LogRef {
  const char *identifier;    //记录器标识
  CLG_LogType *type;         //记录器类型
  struct CLG_LogRef *next;   //记录器链表指针
} CLG_LogRef;

从代码中可知，记录器和类型结构定义了日志上下文的链表项，记录器项主要有二个字段，标识和类型。类型项包含类型标识、上下文指针、冗余信息控制级及是否可用标志。

Blender由众多模块构成，在调试时为区分信息，在第个模块中定义了各自记录器，给出了标识符。如下面代码位于wm_init_exit.c：

CLG_LOGREF_DECLARE_GLOBAL(WM_LOG_OPERATORS, "wm.operator");
CLG_LOGREF_DECLARE_GLOBAL(WM_LOG_HANDLERS, "wm.handler");
CLG_LOGREF_DECLARE_GLOBAL(WM_LOG_EVENTS, "wm.event");
CLG_LOGREF_DECLARE_GLOBAL(WM_LOG_KEYMAPS, "wm.keymap");
CLG_LOGREF_DECLARE_GLOBAL(WM_LOG_TOOLS, "wm.tool");
CLG_LOGREF_DECLARE_GLOBAL(WM_LOG_MSGBUS_PUB, "wm.msgbus.pub");
CLG_LOGREF_DECLARE_GLOBAL(WM_LOG_MSGBUS_SUB, "wm.msgbus.sub");

上面代码定义了窗口管理的几个日志记录器。它使用了CLG_LOGREF_DECLARE_GLOBAL宏来定义，在定义了static变量同时也定义了一个同名的非静态指针变量。也可直接如action.c：

static CLG_LogRef LOG = {"bke.action"};

在相关模块记录信息时可直接如下使用：

CLOG_INFO(WM_LOG_OPERATORS, 0, "search for unknown operator '%s', '%s'\n", idname_bl, idname);

CLOG_ERROR(&LOG, "Pose copy error, pose to:%p from:%p", (void *)to, (void *)from);

到这里，我们并没有将记录器、类型、上下文进行关联，在哪里使它们组合在一起的呢？

参考上面CLOG_AT_SEVERITY等几个宏的定义，在记录信息时，调用了CLOG_ENSURE宏，它在第一次使用该记录器时会调用CLG_logref_init函数

void CLG_logref_init(CLG_LogRef *clg_ref)
{
#ifdef WITH_CLOG_PTHREADS
  /* 在大多数情况下，初始化静态类型时仅运行一次 */
  pthread_mutex_lock(&g_ctx->types_lock);
#endif
  if (clg_ref->type == NULL) {
    /* 将记录器添加到上下文链表*/
    clg_ref->next = g_ctx->refs;
    g_ctx->refs = clg_ref;

    //根据记录器标识查找类型，如没找到则添加类型并关联到上下文
    CLG_LogType *clg_ty = clg_ctx_type_find_by_name(g_ctx, clg_ref->identifier);
    if (clg_ty == NULL) {
      clg_ty = clg_ctx_type_register(g_ctx, clg_ref->identifier);
    }
#ifdef WITH_CLOG_PTHREADS
    atomic_cas_ptr((void **)&clg_ref->type, clg_ref->type, clg_ty);
#else
    clg_ref->type = clg_ty;
#endif
  }
#ifdef WITH_CLOG_PTHREADS
  pthread_mutex_unlock(&g_ctx->types_lock);
#endif
}

static CLG_LogType *clg_ctx_type_register(CLogContext *ctx, const char *identifier)
{
  assert(clg_ctx_type_find_by_name(ctx, identifier) == NULL);
  CLG_LogType *ty = MEM_callocN(sizeof(*ty), __func__);
  ty->next = ctx->types;
  ctx->types = ty;
  strncpy(ty->identifier, identifier, sizeof(ty->identifier) - 1);
  ty->ctx = ctx;
  ty->level = ctx->default_type.level;

  //这里通过过滤器检查确定当前记录器是否记录到日志，设定flag
  if (clg_ctx_filter_check(ctx, ty->identifier)) {
    ty->flag |= CLG_FLAG_USE;
  }
  return ty;
}

在初始化记录器时，如果是新的记录器，则链接到上下文中，检查是否有相关的记录器类型，没有则创建一个，也链接到上下文。同时检查过滤器是否包含该类型，如果不包含，则设置flag为不使用。

延后处理记录器和类型的好处是灵活多变，可在任何模块中灵活使用。

当我们在代码中调用了相关记录宏，但可能日志并没有真正输出，是因为有二个地方判定不输出导致的，一个就是冗余级别超出了类型设定的级别；另一个就是过滤器排除了它的输出。也就是通过这二个来更精准地控制日志的输出。

 

最基本的使用如下代码：

static CLG_LogRef LOG = { "CLOG.test" };

int main()
{
    CLG_init();
    const char* test_filter = "CLOG.*";
    //必须设置过滤器，默认不显示任何记录
    //在blender中，可通过启动程序参数来设置需要过滤显示的日志记录，具体代码见creator_args.c中arg_handle_log_set函数
    CLG_type_filter_include(test_filter, strlen(test_filter));
  
    //仅显示level<=1的日志
    CLOG_INFO(&LOG, 1, "test log!");
    CLOG_INFO(&LOG, 2, "不会显示!");
    
    std::cout << "Hello World!\n";

    CLG_exit();
}

如果在window环境下控制台不能正确显示中文，可使用下面的代码来设置：

SetConsoleOutputCP(CP_UTF8);