server | v4 switch to v3  

Logging

Content

If you are running a local Photon Server and noticed a bad event rate then this is most likely caused by logging. For instance, we noticed that enabling both Photon Server logging and Windows Defender may cause the event rate to slow down considerably. That is why we recommend disabling all virus scanners and firewalls when enabling Photon logging so you can have the expected events rate. You can enable back the virus scanners and firewalls once you stop logging on Photon Servers.

Logging Framework

Photon uses log4net as a logging framework.

Documentation: http://logging.apache.org/log4net/

Log files and locations

There are 3 types of log files:

The Unmanaged Photon Socket Server Log

  • Content: Written by the unmanaged "PhotonSocketServer.exe" core. All status messages from Photon's start / stop sequence are logged here, as well as exceptions from the native core (like: bugs in Photon itself, serialization errors from invalid client data and so on).
  • Name: "Photon-{InstanceName}-Timestamp.log"
  • Log Level Configuration: n/a
  • Location: Default is "/bin_WinXXX/log". To change the log file location set the "LogFileLocation" attribute on each Instance node in "PhotonServer.config". The "LogFileLocation" can be either an absolute path or relative to "PhotonSocketServer.exe".

Example:


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

The Managed CLR Log

  • Content: Written by the managed .NET runtime that hosts your application. All status messages from the CLR are logged here (for example: information about loaded .NET applications & assemblies) and ALL unhandled exceptions from your custom .NET applications.
  • Name: "PhotonCLR.log"
  • Log Level Configuration: configure the appropriate log4net appender in "/deploy/bin_WinXXX/Photon.local.log4net".
  • Location: Default is "/bin_WinXXX/log". To change the log file location configure the appropriate log4net appender in "/deploy/bin_WinXXX/Photon.local.log4net". You can use the "Photon:UnmanagedLogDirectory" property, which contains the value of the "LogFileLocation" attribute from "PhotonServer.config".

Example:


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

The Application Logs

  • Content: each .NET application that is hosted by Photon writes its own application log file. It contains all debug output from the application.
  • Name: "{MyApplication}.log".
  • Log Level Configuration: You can configure the appropriate log4net appender in "/deploy/{MyApplication}/bin/log4net.config".
  • Location: Default is "/deploy/log". To change the log file location configure the appropriate log4net appender in "/deploy/{MyApplication}/bin/log4net.config". You can use the "Photon:ApplicationLogPath" property, which is set to "/deploy/log" per default which can be changed in the Setup() method of your application.
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);
    }
}
<?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>

Frequently Asked Questions

How to write a log entry each time a client connects or disconnects?

Add this to your application's log4net.config:


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

Output from "{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

How to write a log entry when Photon sends an operation response to a client?

Add this to your application's "log4net.config":


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

Output from "{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

How to write a log entry when Photon receives an operation request from a client?

This kind of logging is best done in your application's Peer class (which inherits from HivePeer).


<logger name="Photon.Hive.HivePeer">
    <level value="DEBUG"/>
</logger>

Output from "{MyApplication}.log":

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

You can modify the contents of the log entry in OnOperationRequest method.

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

Why are my clients disconnecting? How can I debug timeouts?

To see why your client disconnects, configure your application to write a debug log entry when OnDisconnect is called on your Peer.


<logger name="Photon.Hive.HivePeer">
    <level value="DEBUG"/>
</logger>

In your Peer class (which inherits from HivePeer), your OnDisconnect() method should look like this:

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

Output from "{MyApplication}.log":

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

If you are using UDP: in case of "TimeoutDisconnect", the "reasonDetail" will contain the RoundTripTime history, like this:

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 ...

Each line consist of these values:

  • Index (0...49, where 0 is latest and 49 is oldest. Only the last 50 entries are shown.)
  • Sequence - an increasing sequence number
  • rtt (RoundTripTime - the current RTT in ms - available after processing the an ACK or a Timeout occurred)
  • variance (current Variance in ms)
  • sentTime (Time when command was sent)
  • recvTime (Time when ACK was recieved)
  • cmd_rtt (Timespan between the time when the command was sent and the ACK was received, in ms)

In the example above, the client had a cmd_rtt between 62ms and 124ms; it was disconnected after no ACK was received for the last command for 11 seconds.

 To Document Top