로깅(Logging) 하기

원문 : http://kwon37xi.egloos.com/2971666
개발시 디버깅을 위해 필수적으로 필요한 것이 로그이다. 이는 개발시 뿐만 아니라 운영중에 오류가 발생했을 때도 오류의 원인을 찾는데 커다란 역할을 하는 중요한 개발 요소 중의 하나이다.

PHP에서 개발자의 로그를 어떻게 남기는지 몰라서 계속해서 var_dump($variable);로 브라우저 화면에 로그를 남겨서 본 뒤에 그 로그 출력 코드를 삭제해 버리는 방식으로 작업을 했다.
대다수의 PHP 개발자들이 var_dump(), print_r() 함수등을 이용해서 위와 같은 방식으로 로그를 기록해서 디버깅을 하는 것 같다. 하지만 이는 매우 좋지 못한 방식이다.

    * 로그를 출력 한 뒤에 로그 출력 코드를 항상 지워야만 한다. 그렇지 않으면 로그가 브라우저를 통해 사용자에게 전달 돼 버리므로.
    * 이로인해 매우 개발이 귀찮기 짝이 없는 작업이 된다.
    * 실제 운영 시간에 발생한 오류에 대해 에러 메시지만을 얻을 수 있을 뿐 그 당시 상태에 관한 로그를 전혀 얻을 수가 없다.


그러다가, 너무 짜증이나서 간단한 로깅 함수를 만들어서 바꾸었다.
그러나 여전히 맘에 안든다. 로그 레벨 지정이나, 로그 파일 날짜별로 돌리기 등 기능이 너무 부족하다.

PHP에서 로깅 전략에 대한 글을 찾아보니 우리나라에서는 거의 없는거 같고, devshed에 Logging With PHP라는 좋은 글이 있었다.
그 중에서도 PEAR Log Package를 이용하기로 하였다. PEAR에는 여러 좋은 패키지들이 많이 깔끔하게 정리되어 있는 것 같다. 근데, 우리나라 PHP 개발자들은 아직 잘 안쓰는건가? 관련 글을 찾아보기가 쉽지 않네.

그 외에도 Log4PHP가 있는데, 사실 이걸 쓰고 싶은 생각이 정말 많이 들었었다. Apache에서 만든 것이고, 이미 내게 익숙한 Log4J의 PHP 포팅이기 때문이다. 게다가 설정 파일을 통해 언제든지 로깅 방식을 변경할 수도 있다(Log4J처럼). 하지만, 참은 이유는.... 2003년 이후 버전업이 전혀 안되고 있기 때문이다. 4년씩이나 버전 업이 안되는 건 좀 이해가 안간다.

PEAR::Log 사용법과 로그 레벨 지정, 날짜별 파일로 로그 남기기, 로그를 남길 때마다 어떤 PHP파일의 몇 번째 줄에서 로그를 남겼는지 출력하기, PHP의 오류 메시지를 PEAR::Log를 이용해 로그로 남기기 등의 기법을 정리해 본다. 대부분의 내용은 PEAR::Log의 매뉴얼을 정리한 것이다.

설치

    $ pear install log



로깅 객체 얻기

    require_once 'Log.php';

    $logger = &Log::singletone('file', 'C:/temp/test.log', 'Test'); # 로깅을 위한 객체 얻기
    $logger->log('이래 저래 에러가 났잖아욧!'); # 로그 메시지 출력하기


싱글턴으로 객체를 가져옴으로써 불필요한 객체 생성과, 객체가 소유하고 있는 리소스의 중복 정의를 방지한다.

&Log::singleton($handler, $name, $ident, $conf, $maxLevel);

 * $handler : 로그 핸들러 타입. console, file 등 로그 출력을 처리하는 방식을 지정한다.$name : 파일 이름과 같이, 로그를 기록할 자원을 지정한다. 핸들러 구현체에 따라서 이 파라미터가 뭘로 사용될지 결정된다.
 * $name : 로그 파일명 등을 의미한다. $handler에 따라 의미가 달라진다.
 * $ident : 로그 구분자이다. Java의 Log4j에서 클래스 FQCN과 같은 역할을 한다.
 * $conf : 연관 배열로 핸들러에 사용자 정의 설정 정보를 넘겨준다.
 * $maxLevel : 최대 로그 레벨을 결정한다. 기본값은 PEAR_LOG_DEBUG(최대값)이다. 이 레벨보다 낮아야 로그가 기록된다.

$logger->log("로그메시지", PEAR_LOG_NOTICE);와 같은 방식으로 로그를 기록한다.

로 그 메시지 부분에는 문자열 뿐만 아니라, 일반 객체를 지정해도 된다. 객체가 getString(), toString() 혹은 __toString() 메소드를 구현하고 있다면 그 메소드를 실행해서 메시지를 기록한다. 모두 없다면 객체를 직렬화한 값을 출력할 것이다.

만약 배열과 같이 복잡한 타입의 변수 값을 제대로 찍고 싶다면 $logger->log($variable) 처럼, 문자열로 바꾸지 말고, 변수를 그대로 인자로 넘겨주면, var_dump($variable) 한 것처럼 변수 내용을 찍어준다.

로그 레벨

로그 레벨 옆의 메소드명은 log() 메소드에 로그 레벨을 지정하는 대신, 해당 메소드를 직접 호출하면, 그 로그 레벨로 로그가 남게 됨을 의미한다.
즉, $logger->log("로그메시지", PEAR_LOG_DEBUG) 는 $logger->debug(" 로그메시지") 와 동일한 역할을 한다.
 * PEAR_LOG_EMERG emerg() 시스템이 사용 불가 상태에 빠졌다.
 * PEAR_LOG_ALERT!! alert!!() 즉시 처리가 필요하다.
 * PEAR_LOG_CRIT crit() 심각한 상태이다.
 * PEAR_LOG_ERR err() 오류
 * PEAR_LOG_WARNING warning() 경고
 * PEAR_LOG_NOTICE notice() 주의
 * PEAR_LOG_INFO info() 정보
 * PEAR_LOG_DEBUG debug() 디버그 메시지

로그 레벨 마스크(mask)

특정 로그 레벨의 로그 메시지만 출력하도록 지정한다.

    $mask = Log::UPTO(PEAR_LOG_INFO);
    $logger->setMask($mask);


최소 PEAR_LOG_INFO 까지 로그 메시지만 출력한다. 즉, PEAR_LOG_EMER ~ PEAR_LOG_INFO 까지 메시지만 로그로 남긴다.

    $mask = Log::MASK(PEAR_LOG_NOTICE) | Log::MASK(PEAR_LOG_DEBUG);


PEAR_LOG_NOTICE와 PEAR_LOG_DEBUG 레벨의 메시지만을 로그로 남긴다.
 * PEAR_LOG_ALL 모든 로그 레벨을 포함하고 있는 마스크
 * PEAR_LOG_NONE 어떤 로그 레벨도 포함하지 않고 있는 마스크

    $mask =PEAR_LOG_ALL ^ Log::MASK(PEAR_LOG_NOTICE);


PEAR_LOG_NOTICE만 제외하고 로그를 남긴다.

    $logger->getMask();


현재 로거의 로그 마스크를 가져온다.

로그 이벤트 내보내기

몇몇 로그 핸들러는 로그 메시지를 버퍼링 한다. 버퍼링된 로그 메시지를 모두 출력하도록 하려면,

    $logger->flush();
    혹은,
    $logger->close();


로거를 닫아도 flush가 된다.

로그 핸들러

로그 핸들러는 로그를 어떤식으로 처리할지를 결정하는 것이다. 모든 로거는 로그 핸들러를 지정해야 한다.
로그 객체를가져올 때 'console' 하는 식으로 지정하는 것이다. 구체적인 사용법은 매뉴얼을 참조한다.
 * console : 화면상에 로그를 출력한다.
 * display : 웹 브라우저에 로그를 출력한다.
 * error_log : PHP의 error_log 함수를 사용해서 로그를 출력한다.
 * file : 파일로 로그를 출력한다.
 * mail : 이메일로 로그를 전송한다.
 * null : 로그를 무시한다.
 * sql : DB에 로그를 저장한다.
 * sqlite : SQLite DB에 로그를 저장한다.
 * syslog : PHP의 syslog() 함수를 이용해서 로그를 저장한다.
 * win : 브라우저의 새창으로 로그를 출력한다.
 * composite : 여러 핸들러를 함께 사용할 수 있게 해준다.

    $console = &Log::singleton('console', '', 'TEST');
    $file = &Log::singletone('file', 'out.log', 'TEST');
    $composite = &Log::singleton('composite');
    $composite->addChild(&console);
    $composite->addChild($file);
    $composite->log('blah blah blah...');
    $composite->removeChild($file); # 로그 핸들러 삭제



File 로그 핸들러

file 로그 핸들러를 제일 많이 사용할 것이기 때문에, 이에대해 정리한다.
 * 설정값 : 설정키(Type, 기본값)
  o append(boolean, true) : true이면 기존의 로그파일에 계속 추가해서 쓰고, false이면 기존 파일을 삭제하고 새로 쓴다.
  o mode(integer, 0644) : Unix 계열에서 파일의 허가권 지정
  o eol(string, OS default) : 줄끝 문자
  o lineFormat(string ,%1$s %2$s [%3$s] %4$s]) 로그 출력 형태 지정
  o timeFormat(string, %b %d %H:%M:%S) : 시간 출력 형태 지정(strftime 함수로 시간을 출력한다.)
 * 설정값의 lineFormat
  o %1$s : 날짜와 시간
  o %2$s : $ident
  o %3$s : 로그 레벨
  o %4$s : 로그 메시지
  o %5$s : log() 메소드를 호출한 파일명
  o %6$s : log()메소드를 호출한 줄 번호
  o %7$s : log()메소드를 호출한 함수명
 * 예제

    $conf = array('mode'=>0600, 'timeFormat'=>'%X %x');
    $logger = &Log::singletone('file', 'out.log', 'ident', $conf);
    for ($i = 0; $i < 10; $i++) {
        $logger->log("Log entry $1");
    }



표준 오류 출력을 PEAR::Log 패키지로 위임하기

PHP 사용중 발생하는 예외와 오류를 PEAR::Log 패키지를 이용해 처리하도록 지정할 수 있다.
이것은 set_error_handler() 함수를 이용해서 가능하다.

    function errorHandler($code, $message, $file, $line)
    {
        global $logger;
        /* Map the PHP error to a Log priority. */
        switch ($code) {
            case E_WARNING:
            case E_USER_WARNING:
                $priority = PEAR_LOG_WARNING;
                break;

            case E_NOTICE:
            case E_USER_NOTICE:
                $priority=PEAR_LOG_NOTICE;
                break;

            case E_ERROR:
            case E_USER_ERROR:
                $priority = PEAR_LOG_ERR;
                break;

            default:
                $priority = PEAR_LOG_INFO;
        }
        $logger->log($message . ' in ' . $file . ' at line ' . $line, $priority);
    } // end of function

    set_error_handler('errorHandler');

    # test
    trigger_error('This is an information log message.', E_USER_NOTICE);



나는 이렇게 사용한다

강력한 설정기능 등이 Log4php에 비해 많이 딸리는 편인데, 어쨌든, 나는 아래 처럼 사용한다.
아래에서 정의한 logger() 함수는 PEAR::Log를 이용해서, 날짜별로 로그 파일을 남기는 것이다.
그리고, 로그를 남길 때는 항상 로그를 찍은 소스 파일명과 로그를 찍은 코드의 줄 번호도 함께 출력하도록 하였다.
파일 이름은 logger.php라고 치자.

    <?php
    require_once 'Log.php';

    // PHP 5.1.x 의 set_error_handler()로 지정된 함수 내부에서
    // 클래스 정의를 가진 PHP 파일을 require/include 할 경우에
    // 오류가 발생하는 문제를 해결하기 위해
    // 미리 필요한 클래스를 require 해둬야 한다.
    // 관련 URL : http://bugs.php.net/35634
    require_once 'Log/file.php';

    /**
    * 사용자가 명시적으로 LOG_FILENAME 상수를 지정하지 않았다면,
    * 오류를 발생시킨다.
    */
    if (!defined('LOG_FILENAME')) {
        trigger_error("You have to define LOG_FILENAME for logger", E_USER_ERROR);
    }

    /**
    * 사용자가 명시적으로 LOG_LEVEL 상수를 정의하지 않았다면,
    * DEBUG 로그 레벨로 강제 지정한다.
    *
    * 이 파일 외부에서 로그 레벨을 지정할 경우, require_once 'Log.php'; 를 실행한
    * 이후에 상수에 PEAR_LOG_* 값을 줘야 함을 잊어서는 안된다.
    */
    if (!defined('LOG_LEVEL')) {
        define ('LOG_LEVEL', PEAR_LOG_DEBUG);
    }

    /**
    * PHP자체에서 발생하는 로그의 레벨을 지정한다.
    * errorHandler() 함수에서 이 로그레벨을 넘지 않으면, 오류를 출력하지 않도록
    * 만들어져 있다.
    *
    * 이 파일 외부에서 로그 레벨을 지정할 경우, require_once 'Log.php'; 를 실행한
    * 이후에 상수에 PEAR_LOG_* 값을 줘야 함을 잊어서는 안된다.
    */
    if (!defined('PHP_LOG_LEVEL')) {
        define('PHP_LOG_LEVEL', PEAR_LOG_WARNING);
    }

    // PHP 에러 핸들러를 PEAR::Log 를 사용하도록 변경한다.
    set_error_handler('errorHandler');

    /**
    * 파일로 로그를 저장하는 로거 객체를 리턴한다.
    * Log 클래스를 직접 호출하지 말고, 일관성 있게 get_logger() 메소드를 사용해서
    * 로거 객체를 얻도록 한다.
    *
    * LOG_FILENAME 상수로 지정된 파일 이름에 .yyyymmdd 형태로 날짜를 붙여 로그 파일을
    * 생성한다.
    *
    * @param string $ident 로거 구분 문자열. 일반적으로 "클래스명.Method명" 혹은  "function명"
    * 처럼 지정하면 된다. 이 파라미터를 지정하지 않으면 항상 get_logger를 호출한 파일의 이름으로
    * 지정된다.
    * @param integer 로그 레벨을 지정한다. PEAR_LOG_XXX 형태의 상수로 정의 되어있다.
    * @return Log 로거 객체
    */
    function logger($ident = "GlobalLogger", $logLevel = LOG_LEVEL)
    {
        $today_date = date('Ymd', mktime()); // 오늘날짜 yyyymmdd 형태
       
        $conf = array(
            'buffering' => false,
            'lineFormat' => '[%3$s] %2$s %1$s (%5$s %6$s %7$s) %4$s',
            'timeFormat' => '%Y%m%d %H:%M:%S'
        );
       
        $logger = &Log::singleton('file', LOG_FILENAME . "." . $today_date, $ident, $conf);
       
        $mask = Log::UPTO($logLevel);
        $logger->setMask($mask);

        return $logger;
    }

    /**
    * PHP 기본 에러 핸들러를 변경한다.
    */
    function errorHandler($code, $message, $file, $line)
    {
        /* Map the PHP error to a Log priority. */

        switch ($code) {
            case E_STRICT:
            case E_NOTICE:
            case E_USER_NOTICE:
                $priority = PEAR_LOG_NOTICE;
                break;
            case E_WARNING:
            case E_USER_WARNING:
                $priority = PEAR_LOG_WARNING;
                break;
            case E_ERROR:
            case E_USER_ERROR:
                $priority = PEAR_LOG_ERR;
                break;
            default:
                $priority = PEAR_LOG_WARNING;
        }
       
        $logger = logger("PHPError", PHP_LOG_LEVEL);

        $logger->log($message . ' in ' . $file . ' at line ' . $line, $priority);
    }


    /**
    * 변수를 받아서 var_export()한 결과를 문자열로 저장하여 넘겨준다.
    * 로그 메시지로 복잡한 형태의 변수나 배열을 출력하고 싶을 때 사용한다.
    *
    * @param mixed $variable 출력할 변수
    */
    function var_export_str($variable) {
        ob_start();
        var_export($variable);
        $logmsg .= ob_get_contents();
        ob_end_clean();
       
        return $logmsg;
    }
    ?>


위 logger()메소드는 다음 처럼 간단히 활용할 수 있다.

    <?php
    // 로그레벨 설정 상수가 Log.php에 들어 있기 때문에
    // 로그 레벨 설정과 logger.php보다 Log.php를 먼저 require 해줘야 한다.
    require_once 'Log.php';

    define('LOG_FILENAME', 'C:/Temp/test.log');
    define('LOG_LEVEL', PEAR_LOG_DEBUG);
    define('PHP_LOG_LEVEL', PEAR_LOG_WARNING);

    require_once 'logger.php';

    echo "Why?<br/>";

    logger()->log("하하..", PEAR_LOG_INFO);
    logger()->debug("허허.. 이건 DEBUG레벨");
    logger()->alert!!("경고야!!");
    $arr = array("key" => "value",
        "array-" => "var_export_str 함수를 이용해서 감싸서 로그를 남기세요."
    );
    logger()->info("객체나 배열같은 변수를 로깅 하는 방법은 두가지가 있다.");
    logger()->info($arr); # 이처럼 변수를 그냥 넘기는 방법과
    logger()->info("배열 : " . var_export_str($arr)); # 이렇게 var_export_str()로 감싸는 방법
    ?>


위를 실행하면 C:\Temp\test.log.오늘날짜 파일로 다음과 같이 로그가 남는다.

    [info] GlobalLogger 20070207 18:38:03 (C:\test\test.php 14 (none)) 하하..
    [debug] GlobalLogger 20070207 18:38:03 (C:\test\test.php 15 (none)) 허허.. 이건 DEBUG레벨
    [alert!!] GlobalLogger 20070207 18:38:03 (C:\test\test.php 16 (none)) 경고야!!
    [info] GlobalLogger 20070207 18:38:03 (C:\test\test.php 20 (none)) 객체나 배열같은 변수를 로깅 하는 방법은 두가지가 있다.
    [info] GlobalLogger 20070207 18:38:03 (C:\test\test.php 21 (none)) Array
    (
        [key] => value
        [array-] => var_export_str 함수를 이용해서 감싸서 로그를 남기세요.
    )

    [info] GlobalLogger 20070207 18:38:03 (E:\Workspace\ServiceCSTool2\test.php 22 (none)) 배열 : array (
      'key' => 'value',
      'array-' => 'var_export_str 함수를 이용해서 감싸서 로그를 남기세요.',
    )