Logging
Logging Framework
Photon uses log4net as a logging framework.
Documentation:
https://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:
XML
<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:
XML
<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 theSetup()
method of your application.
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);
}
}
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>
Frequently Asked Questions
How to write a log entry each time a client connects or disconnects?
Add this to your application's log4net.config:
XML
<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":
XML
<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
).
XML
<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.
C#
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.
XML
<logger name="Photon.Hive.HivePeer">
<level value="DEBUG"/>
</logger>
In your Peer class (which inherits from HivePeer
), your OnDisconnect()
method should look like this:
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);
}
//
}
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.
Back to top