로깅

프레임워크 로깅

Photon은 log4net을 이용하여 프레임워크를 로깅합니다.

문서:
https://logging.apache.org/log4net/

로그파일과 위치

3종류의 로그 파일이 있습니다:

1. 관리되지 않는 Photon 소켓 서버 로그:

• Content: 비관리 PhotonSocketServer.exe 코어가 파일에 기록 됩니다.
  코어의 예외( Photon 자체의 버그, 유효하지 않는 클라이언트에 대한 직렬화 오류 등 과 같은)뿐만 아니라 Photon의 시작/종료의 모든 상태 메시지 로그가 여기에 기록 됩니다 .
• 이름: Photon-(인스턴스명)-Timestamp.log
• 위치: /bin_WinXXX/log
• Log 레벨 환경 설정: n/a
• 로그 파일 위치 변경: PhotonServer.config 내의 각 인스턴스 노드의 "LogFileLocation" 속성을 설정합니다."LogFileLocation" 은 절대 경로 또는 PhotonSocketServer.exe 기준의 상대경로가 될 수 있습니다.

예제:

XML

<Default
    MinimumTimeout="5000"
    MaximumTimeout="30000"
    LogFileLocation="..\MyLogFolder"
>

2. 관리되는 CLR 로그:

• 내용:
  어플리케이션을 호스트 하고 있는 매니지드 .NET 런타임에 의해서 기록됩니다. CLR 의 모든 상태 메시지의 로그 (예: 로드된 .NET 어플리케이션 & 어셈블리에 대한 정보) 와 커스텀 .NET 어플리케이션의 모든 처리되지 않은 예외들이 여기에 기록 됩니다.

• 이름: PhotonCLR.log

• 위치: /bin_WinXXX/log

• 로그 레벨 환경설정: /deploy/bin_WinXXX/Photon.local.log4net 에서 적당한 log4net appender 를 설정 하세요.

• 로그파일 위치 변경: /deploy/bin_WinXXX/Photon.local.log4net 에서 적당한 log4net appender 를 설정 하세요 - "Photon:UnmanagedLogDirectory" 프로퍼티를 사용할 수 있는데 여기에는 PhotonServer.config 파일의 "LogFileLocation" 값이 포함되어 있습니다.

예:

XML

<appender name="A1" type="log4net.Appender.RollingFileAppender">
        <file type="log4net.Util.PatternString" value="%property{Photon:UnmanagedLogDirectory}\\PhotonCLR.log" />            
        <!-- snip -->
    </appender>

3. 어플리케이션 로그:

• 내용: Photon 이 호스트 하고 있는 각 .NET 어플리케이션은 각각의 어플리케이션 로그 파일에 로그를 기록 합니다. 여기에는 어플리케이션의 모든 디버그 출력결과가 포함되어 있습니다.
• 이름: {MyApplication}.log
• 위치: /deploy/log
• 로그파일 위치 변경: /deploy/{MyApplication}/bin/log4net.config 에서 적당한 log4net appender 를 설정 하세요.
  "Photon:ApplicationLogPath" 프로퍼티를 사용할 수 있는데 기본값으로 /deploy/log 로 설정되어있으며 어플리케이션에서 Setup() 메소드를 통하여 변경할 수 있습니다.

C#

protected override void Setup()
        {
            // log4net
            log4net.GlobalContext.Properties["Photon:ApplicationLogPath"] = Path.Combine(this.ApplicationRootPath, "log");
            var configFileInfo = new FileInfo(Path.Combine(this.BinaryPath, "log4net.config"));
            if (configFileInfo.Exists)
            {
                LogManager.SetLoggerFactory(Log4NetLoggerFactory.Instance);
                XmlConfigurator.ConfigureAndWatch(configFileInfo);
            }
        }

• 로그 레벨 환경설정: /deploy/{MyApplication}/bin/log4net.config 파일에서 적당한 log4net appender 를 설정 해주세요.

예제:

XML

<?xml version="1.0" encoding="utf-8" ?>
<log4net debug="true" update="Overwrite"> 
    <appender name="LogFileAppender" type="log4net.Appender.RollingFileAppender">
        <file type="log4net.Util.PatternString" value="%property{Photon:ApplicationLogPath}\\{MyApplication}.log" />    
        <!-- snip --> 
    </appender>
    <root>
        <!-- <level value="INFO" /> -->
        <!-- <level value="DEBUG" /> -->
        <level value="ALL" />
        <appender-ref ref="LogFileAppender" /> 
    </root>
</log4net>

FAQ

클라이언트가 연결/연결해제 됐을 때마다 어떻게 로그 항목을 작성하나요?

어플리케이션의 log4net.config 에 다음을 추가해 주세요:

XML

<logger name="Photon.SocketServer.ApplicationBase">
    <level value="DEBUG"/>
</logger>

{MyApplication}.log의 출력결과:
Successful connect:

2013-05-02 11:19:02,506 [23] DEBUG Photon.SocketServer.ApplicationBase [(null)] - OnInit - ConnID=17, IP 127.0.0.1 on port 4530
2013-05-02 11:19:02,506 [23] DEBUG Photon.SocketServer.ApplicationBase [(null)] - OnInit - response sent to ConnId 17 with SendResult Ok

Disconnect:

2013-05-02 11:19:07,608 [24] DEBUG Photon.SocketServer.ApplicationBase [(null)] - OnDisconnect - ConnID=17

Photon 이 클라이언트에게 오퍼레이션 응답을 전송할 때 로그 항목을 어떻게 작성하나요?

어플리케이션의 log4net.config 에 다음을 추가해 주세요:

XML

<logger name="Photon.SocketServer.PeerBase">
    <level value="DEBUG"/>
</logger>

(MyApplication).log 출력결과:

2013-05-02 11:19:02,569 [21] DEBUG Photon.SocketServer.PeerBase [(null)] - SentOpResponse: ConnID=17, opCode=255, return=0, ChannelId=0 result=Ok size=14 bytes

Photon 이 클라이언트로부터 오퍼레이션 요청을 받았을 때 어떻게 로그항목을 작성하나요?

이 종류의 로깅은 어플리케이션의 Peer 클래스에서 처리하는 것이 가장 좋습니다.(Peer 클래스는 PeerBase 에서 상속된 클래스입니다).

Lite의 예제:

XML

<logger name="Lite.LitePeer">
    <level value="DEBUG"/>
</logger>

(MyApplication).log의 출력결과:

2013-05-02 11:19:02,553 [21] DEBUG Lite.LitePeer [(null)] - OnOperationRequest. Code=255

로그 항목의 내용을 OnOperationRequest 메소드에서 변경할 수 있습니다.

Lite.LitePeer의 예제:

C#

protected override void OnOperationRequest(OperationRequest operationRequest, SendParameters sendParameters)
{
    if (log.IsDebugEnabled)
    {
        log.DebugFormat("OnOperationRequest. Code={0}", operationRequest.OperationCode);
    }    
    // snip
}

왜 클라이언트의 연결이 해제 되나요? 어떻게 타임아웃을 디버그 할 수 있나요?

연결 해제에는 4종류가 있습니다.:

• ClientDisconnect: 클라이언트가 연결을 종료
• ManagedDisconnect: 매니지드 .NET 어플리케이션이 PeerBase.Disconnect() 호출
• ServerDisconnect: Photon 내의 예외가 클라이언트의 연결해제의 원인입니다. 비관리되는 Photon 소켓 서버로그에서 예외에 대한 상세내용을 조사 해봐야 합니다.
• TimeoutDisconnect: 특정 시간이 지난 후에도 예상되는 데이터를 수신하지 못한 경우 Photon 이 연결을 종료 하는 경우 입니다.

클라이언트가 왜 연결이 해제 되었는지를 보기 위해서 Peer 에서 OnDisconnect 가 호출 되었을 때 디버그 로그를 작성하도록 어플리케이션을 설정 해 주세요.

Lite 의 예제:

XML

<logger name="Lite.LitePeer">
    <level value="DEBUG"/>
</logger>

PeerBase 에서 상속된 Peer 클래스의 OnDisconnect() 메소드는 다음과 같아야 합니다:

C#

protected override void OnDisconnect(DisconnectReason reasonCode, string reasonDetail)
{
    if (log.IsDebugEnabled)
    {
        log.DebugFormat("OnDisconnect: conId={0}, reason={1}, reasonDetail={2}", this.ConnectionId, reasonCode, reasonDetail);
    }
    // snip    
}

(MyApplication).log 출력결과:

2013-05-02 11:19:07,639 [12] DEBUG Lite.LitePeer [(null)] - OnDisconnect: conId=17, reason=ClientDisconnect, reasonDetail=

UDP 사용시: "TimeoutDisconnect" 의 경우 "reasonDetail" 에는 라운드트립타임 내역을 아래와 같이 포함하고 있습니다:

index - sequence - rtt - variance - sentTime - recvTime - cmd_rtt

0 - 326 - 0 - 0 - 830717056 - 830728351 - 11295
1 - 325 - 89 - 19 - 830715918 - 830716042 - 124
2 - 324 - 85 - 14 - 830714826 - 830714904 - 78
3 - 323 - 86 - 17 - 830712751 - 830712813 - 62
4 - 322 - 89 - 14 - 830711659 - 830711737 - 78
5 - 321 - 90 - 16 - 830710551 - 830710645 - 94
6 - 320 - 90 - 19 - 830709428 - 830709537 - 109
7 - 319 - 88 - 19 - 830708320 - 830708414 - 94
8 - 318 - 88 - 23 - 830707197 - 830707306 - 109
9 - 317 - 86 - 24 - 830706105 - 830706183 - 78
10 - 316 - 87 - 29 - 830704701 - 830704763 - 62
... etc ... 

각 라인은 다음의 값들로 구성되어 있습니다.

• index (0...49, 0 이 가장 최근값이며 49가 가장 오래된 것입니다. 50 개 항목까지만 보여집니다.)
• sequence - 증가하는 일련번호
• rtt (RoundTripTime - 현재 RTT를 ms으로 표시 - ACK 또는 타임아웃이 발생된 이후 사용 가능함)
• variance (현재 변화량 ms)
• sentTime (명령 전송 시간)
• recvTime (ACK 수신 시간)
• cmd_rtt (명령 전송과 ACK 수신된 시간 차이 ms)

위의 예제에서는 클라이언트는 cmd_rtt 가 62 ms 에서 124 ms 의 값을 가지고 있습니다; 마지막 명령어 전송 이후 11초가 경과되어 ACK 를 수신 받지 못했기 때문에 연결이 해제 되었습니다.

Back to top