Tizen <dlog> Log 출력

시작하기 전에...
Tizen 공부를 시작하며 에도 썼듯이 혼자 공부하며 서술합니다.
실제 사실과 다를 수도 있고, 보이는 대로 사견을 서술할 예정입니다.
잘못되었다 싶은 부분은 댓글이나, 메일로 알려주세요.
Tizen 2.4 Native 기준으로 포스팅 합니다.

System 카테고리의 dlog를 보겠습니다.

App 개발 시에는 항상 중간 중간 Log를 찍어 주는 게 좋습니다. (그래야 중간에 Error가 어디서 났는지 찾기 편하니까요)
Error가 나고 나서 뒤늦게 log를 추가하기 보다는 개발 단계에서 미리미리 찍어두는 게 바람직합니다.

또 팀 플레이를 할 때, 내가 맡은 부분은 background 모듈이라면...
그럼에도 불구하고 API를 Test할 때, 일일이 UI를 만들어 하면 귀찮아집니다.
UI 짜는 건 배우고 나서는 쉽지만, 익히는데 시간이 들죠. 그럴 땐 그냥 dlog로만 다 확인하고 UI는 다른 팀원에게 넘깁시다.

developer.tizen.org -> Development -> API Reference

API Set들을 보겠습니다.

Tizen에서 제일 쉬운 API가 아닐까 합니다.
그렇지만 제일 중요하고 많이 쓰여야 합니다.
Log를 적절하게 잘 찍는 개발자가 노련한 개발자라 생각합니다.

앱이 기본 기능을 하기 까지는 그 진가가 드러나지 않습니다.
그렇지만 집중적으로 App을 Test하고, Bug나 성능 이슈를 분석하려다 보면
Log를 어떻게 적재 적소에 잘 배치 했느냐가 대응 속도를 결정짓습니다.

dlog는, Priority, Tag, 출력 Text로 구성됩니다.

Priority는 출력 레벨로, 출력할 Log의 성격, 중요도에 따라 다르게 set해서 출력합니다.
예를 들어, App이 의도치 않은 상황에 빠진 경우, Warning이나 Error 레벨로 출력하기도 하고,
debug 용도로만 필요하고 별로 안 중요한 내용이면 debug 레벨로 출력하는 식입니다.
나중에 log를 확인할 때 filtering 해서 출력할 수 있습니다.

Tag는 다른 대게 다른 App 들과 구분하기 위해 사용합니다.
보통은 App 이름을 줄여서 사용합니다.
대게 디버깅 할 때는 자기 로그만 중요하므로, 수 많은 로그 중 자기 것만 filtering할 때 사용합니다.

Log priority : 로그의 출력 레벨입니다.

Priority	Description
DLOG_DEBUG	Debug messasge. - Log message which developer want to check.
DLOG_INFO	Information message - Normal operational messages. above of this priority will always be logged.
DLOG_WARN	Warning messages - Not an error, but indication that an error will occur if action is not taken.
DLOG_ERROR	Error message - Indicate error.

API Reference에는 위와 같이 네개가 권장되어 있습니다만,
실제 enum log_priority 를 보게되면 더 많은 type들이 존재합니다.
그렇지만 위 네개만 사용하는 것을 추천합니다.

설명이 더 자세한 다른 Platform의 Log Level을 보면,
Fatal Level 같은 경우는 시스템에 치명적인 오류에서 출력하라고 되어있기도 합니다.

이러한 이유에서 Fatal로 Log 출력을 요청 시, 로그를 출력하고 나서 Platform 정책에 의해 호출한 Process가 종료될 수도 있습니다.

https://review.tizen.org/gerrit/#/admin/projects/framework/system/dlog
에서 dlog의 소스코드를 받아 확인해보겠습니다.

$git clone git clone ssh://<my_gerrit_id>@review.tizen.org:29418/framework/system/dlog

$cd dlog
$git checkout tizen_2.4

src/libdlog/log.c를 보면, API로 제공되는 dlog_print는 다행히 모두 출력 시켜줍니다.

int dlog_print(log_priority prio, const char *tag, const char *fmt, ...)
{
    va_list ap; 
    char buf[LOG_BUF_SIZE];

    if (write_to_log == NULL)
        __dlog_init();

    va_start(ap, fmt);
    vsnprintf(buf, LOG_BUF_SIZE, fmt, ap);
    va_end(ap);

    return write_to_log(LOG_ID_APPS, prio, tag, buf);
}

그런데 internal 함수인 __dlog_print를 보면 다음과 같은 구문이 보입니다.

int __dlog_print(log_id_t log_id, int prio, const char *tag, const char *fmt, ...)
{
    int ret;

 ///////////////////// 중간 생략 //////////////////

    va_start(ap, fmt);
    vsnprintf(buf, LOG_BUF_SIZE, fmt, ap);
    va_end(ap);

    ret = write_to_log(log_id, prio, tag, buf);
#ifdef FATAL_ON
    __dlog_fatal_assert(prio);
#endif
    return ret;
}

#ifdef FATAL_ON (FATAL_ON 이라는 define이 선언되어 있으면),
assert를 호출하여 App을 강제로 종료 시킵니다.

즉, 외부 개발자들이 dlog_print를 사용할 때에는, fatal도 출력해 주지만
internal 함수를 사용하는 Platform 내부 모듈에 대해서는 Platform 정책에 의해 종료되게 만들 수 있음을 의미합니다.

저 FATAL_ON은 어디에 선언되어있는지 끝까지 따라가 보자면,

packaging/dlog.spec 의 %build 구문에 --enable-fatal_on 옵션을 넣고,

%build
cp %{SOURCE101} .
cp %{SOURCE102} .
%autogen --disable-static
%configure  --disable-static \
            --enable-fatal_on \
            --enable-engineer_mode \
            --enable-debug_enable \
            --without-systemd-journal
make %{?jobs:-j%jobs}

configure.ac 의 56 Line 구문에서 define을 추가해 주고 있습니다.

# check for fatal_on
AC_ARG_ENABLE([fatal_on],
    AS_HELP_STRING([--enable-fatal_on Turn on fatal assertion]),
        [fatal_on=yes],
        fatal_on=no)
if test "x$fatal_on" = "xyes" ; then
    DEBUG_CFLAGS+=" -DFATAL_ON"
fi

다시 API 이야기로 돌아와 API 사용법을 보겠습니다.

SDK에서 기본 UI App을 하나 생성합니다.
"hello-dlog"라는 이름으로 생성하니, inc/hello-dlog.h에 자동으로 다음과 같은 구문이 생성됩니다.

LOG_TAG라는 define을 바로 활용할 수 있을 듯 한데요.

src/hello-dlog.c의 app_create() 함수에 다음 구문을 넣어서 잘 출력 되는지 보겠습니다.

dlog_print(DLOG_INFO, LOG_TAG, "hello");

패키지를 build하고 emulator에서 run한 후 SDK의 Log 창으로 확인해보겠습니다.

Log 창을 마우스로 더블 클릭 합니다.

일단은 Info만 잘보이게, "I" 만 활성화 해 보겠습니다.

hello가 출력 되는 걸 볼 수 있습니다.

Log macro 작성

Log를 효율적으로 많이 찍는 게 좋다고 말씀드렸는데,
예제로 썼던 log 함수 Call만 봐도
dlog_print(DLOG_INFO, LOG_TAG, "hello");
중에서 색칠한 앞 부분은 항상 반복하게 될 중복 구문입니다.
생산성을 저하시킬 수 있는 만큼 macro로 만들어서 쓰면 효율적입니다.

API reference에 있는 Macro를 그대로 붙여 넣고 LOGI를 호출해 보았더니 에러가 납니다;;

use of undeclared identifier '__MODULE__'

__MODULE__ 이라는 매크로가 없다는데 무슨 이유인지 모르겠습니다.
github에 있는 tizen app들 보면 다 자기들이 따로 선언해서 쓰고 있네요.

아무리 example이라도 돌아가는 걸 주거나 설명을 더 자세히 썼으면 좋았을걸 싶네요.

Macro를 수정해보겠습니다. __MODULE__ -> __FILE__ 로 하겠습니다.

선언 부

#define LOGI(fmt, arg...) \
    ({ do { \
        dlog_print(DLOG_INFO, LOG_TAG, "%s: %s(%d) > " fmt, \
                __FILE__, __func__, __LINE__, ##arg); \
    } while (0); })

함수 사용부

LOGI("hello dlog macro");
LOGI("print test number : %d", 4270);

이렇게 쓰게 되면 함수 사용도 간편할 뿐더러, log의 출력 여부를 핸들링 하기도 편합니다.

예를 들어, App 개발 후 배포 단계에서는 debug level의 log는 출력하고 싶지 않을 경우,
define 부분만 수정해서 출력을 안하게 할 수 있습니다.

#ifdef PRINT_DEBUG_LOG
#define LOGD(fmt, arg...) \
    ({ do { \
        dlog_print(DLOG_DEBUG, LOG_TAG, "%s: %s(%d) > " fmt, \
                __FILE__, __func__, __LINE__, ##arg); \
    } while (0); })
#else
#define LOGD
#endif

팁1. Terminal에서 dlogutil로 Log 보는 법

sdb shell로 device 접속 후, dlogutil을 이용합니다.

option : -v thread (thread 정보 출력)
option : -v time (시간 정보 출력)
option : -v threadtime (thread, 시간 정보 출력)

팁2. dlogutil에도 색깔 넣어서 log 출력

늘 터미널로만 debug 하는데, 하얀 글자가 너무 많으면 잘 안보입니다.

bash의 font color 입히는 기능을 이용해 색깔을 입혀보겠습니다.
단순히 출력문 앞에 "\033[31m" 등을 같이 출력하는 것 만으로 색깔을 입힐 수 있습니다.
(bash font color 관련 참고할 만한 Link : 링크 1, 링크 2)

#define FONT_RED    "\033[31m"
#define FONT_GREEN  "\033[32m"
#define FONT_YELLOW "\033[33m"
#define FONT_BLUE   "\033[34m"
#define FONT_RESET  "\033[0m"

#define LOGD(fmt, arg...) \
    ({ do { \
        dlog_print(DLOG_DEBUG, LOG_TAG, \
                FONT_GREEN "%s: %s(%d) > " fmt FONT_RESET, \
                __FILE__, __func__, __LINE__, ##arg); \
    } while (0); })

#define LOGI(fmt, arg...) \
    ({ do { \
        dlog_print(DLOG_INFO, LOG_TAG, \
                FONT_BLUE "%s: %s(%d) > " fmt FONT_RESET, \
                __FILE__, __func__, __LINE__, ##arg); \
    } while (0); })

#define LOGW(fmt, arg...) \
    ({ do { \
        dlog_print(DLOG_WARN, LOG_TAG, \
                FONT_YELLOW "%s: %s(%d) > " fmt FONT_RESET, \
                __FILE__, __func__, __LINE__, ##arg); \
    } while (0); })

#define LOGE(fmt, arg...) \
    ({ do { \
        dlog_print(DLOG_ERROR, LOG_TAG, \
                FONT_RED "%s: %s(%d) > " fmt FONT_RESET, \
                __FILE__, __func__, __LINE__, ##arg); \
    } while (0); })

이렇게 출력하면 다음과 같은 결과물을 볼 수 있습니다.

알록달록 아주 예쁘게 출력할 수 있습니다.