Logging with log4net and no nhibernate log

Options
xanlosch
xanlosch
edited March 2014 in Photon Server
Hi,

I had a small problem: I extends general photon logging for NHibernate logging to catch a nasty sql error. The log4net.config looks like:
	<appender name="SqlLogFileAppender" type="log4net.Appender.RollingFileAppender">
		<file type="log4net.Util.PatternString" value="log\MasterServer-SQL-%date{yyyy-MM-dd}.log" />
		<param name="AppendToFile" value="true" />
		<!-- <param name="RollingStyle" value="Date" /> -->
		<!-- <param name="DatePattern" value="yyyy.MM.dd" /> -->
		<!-- <param name="StaticLogFileName" value="true" /> -->
		<!-- <param name="LockingModel" type="log4net.Appender.FileAppender+MinimalLock" /> -->
		<layout type="log4net.Layout.PatternLayout">
			<param name="ConversionPattern" value="%d [%t] %-5p %c - %m%n" />
		</layout>
	</appender>
	<!-- logger -->
	<root>
		<priority value="DEBUG" />
		<appender-ref ref="ConsoleAppender" />
	</root>
        <!-- ... some more logging ... -->
	<!-- hibernate related logging -->
	<logger name="NHibernate" additivity="false">
		<level value="WARN" />		
		<appender-ref ref="SqlLogFileAppender" />
	</logger>
	<logger name="NHibernate.SQL" additivity="false">
		<level value="DEBUG" />
		<appender-ref ref="ConsoleAppender" />
		<appender-ref ref="SqlLogFileAppender" />
	</logger>

The SQL log will be created if I start my project with photon control but no single SQL access will be logded :(

I wrote a small test client which makes nothing else than the server application: initialize logging and database access and then authenticate an user. The test client used the same log4net.config and NHiberate logs every access to the database to the SQL log file. Any else log will be delivered to log too.

Any ideas why logging with photon "hides" the NHibernate log?

Comments

  • afuzzyllama
    afuzzyllama
    Options
    What does the code look like to log your SQL error? Are you sure it is being called?
  • xanlosch
    xanlosch
    Options
    The SQL error gone away after I restructured the NHibernate Criteria :D

    But some nice feature doesn't work: Logging of Nhibernate generated code. NHibernate provides them self a Log4Net Interface, which should use in general the Log4Net instance of the application. This way works perfect in my test application. I have multiple methods which access the database through a singleton handler and all of them get reached during runtime (for example user authentication, getting game data, ...). But no SQL statements appears in the log when using Photon :/

    Any help possible?

    Edit: My test application, which works:
    using System;
using System.IO;
using Database;
using ExitGames.Logging;
using log4net.Config;
using NHibernate;
using UserManagement;
using LogManager = ExitGames.Logging.LogManager;

namespace dbclient
{
    class MainClass
    {
        private static readonly ILogger log = LogManager.GetCurrentClassLogger ();
        private static ISessionFactory sessionFactory;
        private static UserManagement.UserManagement userManagement;
        private static HibernateHandler handler;

        private static void initLogging ()
        {
            LogManager.SetLoggerFactory (ExitGames.Logging.Log4Net.Log4NetLoggerFactory.Instance);
            XmlConfigurator.ConfigureAndWatch (new FileInfo ("log4net.config"));
            if (log.IsInfoEnabled) {
                log.Info ("Startup application.");
            }
        }

        private static void initDatabase ()
        {
            handler = HibernateHandler.getInstance ();
            userManagement = UserManagement.UserManagement.getInstance (handler);
            sessionFactory = handler.getSessionFactory ();
        }

        public static void Main (string[] args)
        {
            String userName;
            String password;
            Boolean authenticated;

            System.Console.WriteLine ("Start application");

            initLogging ();
            initDatabase ();

            Console.WriteLine ();
            Console.WriteLine ("username:");
            userName = Console.ReadLine ();
            Console.WriteLine ("password:");
            password = Console.ReadLine ();
            authenticated = userManagement.isAuthorized (userName, password);
            Console.WriteLine ("auth? " + authenticated.ToString ());

            Console.ReadLine ();
        }
    }
}

    2nd edit: I stripped down the photon application to its smallest code base:
    using System;
using System.IO;
using Database;
using ExitGames.Logging;
using log4net.Config;
using NHibernate;
using Photon.SocketServer.ServerToServer;
using UserManagement;
using LogManager = ExitGames.Logging.LogManager;

namespace ServerTest
{
    public class ServerTestApp : NodeResolverBase
    {

        #region member variables
        private static readonly ILogger log = LogManager.GetCurrentClassLogger ();
        private ISessionFactory sessionFactory;
        private UserManagement.UserManagement userManagement;
        private HibernateHandler handler;

        #endregion

        #region implemented abstract members of Photon.SocketServer.ServerToServer.NodeResolverBase
        protected override void OnNodeConnected (byte nodeId, int port)
        {
            throw new NotImplementedException ();
        }

        protected override void OnNodeDisconnected (byte nodeId, int port)
        {
            throw new NotImplementedException ();
        }
        #endregion

        public ServerTestApp ()
        {
        }

        #region abstract / override methodes of ApplicationBase
        protected override Photon.SocketServer.PeerBase CreatePeer (Photon.SocketServer.InitRequest initRequest)
        {
            throw new NotImplementedException ();
        }

        protected override ServerPeerBase CreateServerPeer (Photon.SocketServer.InitResponse initResponse, object state)
        {
            return base.CreateServerPeer (initResponse, state);
        }

        protected override void OnServerConnectionFailed (int errorCode, string errorMessage, object state)
        {
            base.OnServerConnectionFailed (errorCode, errorMessage, state);
        }

        protected override void OnStopRequested ()
        {
            base.OnStopRequested ();
        }

        protected override void Setup ()
        {
            initLogging ();
            initDatabase ();
            log.InfoFormat ("Debugging Mode? {0}", log.IsDebugEnabled);
            userAuth ();
        }

        protected override void TearDown ()
        {
            if (log.IsInfoEnabled) {
                log.Info ("Tear down of application.");
            }
        }
        #endregion

        private void initLogging ()
        {
            LogManager.SetLoggerFactory (ExitGames.Logging.Log4Net.Log4NetLoggerFactory.Instance);
            FileInfo log4netFile = new FileInfo (Path.Combine (this.BinaryPath, "log4net.config"));
            if (! log4netFile.Exists) {
                throw new FileNotFoundException (log4netFile.FullName + " file not found!");
            }
            XmlConfigurator.ConfigureAndWatch (log4netFile);
            if (log.IsInfoEnabled) {
                log.Info ("Startup application.");
            }
        }

        private void initDatabase ()
        {
            handler = HibernateHandler.getInstance ();
            userManagement = UserManagement.UserManagement.getInstance (handler);
            sessionFactory = handler.getSessionFactory ();
        }

        private void userAuth ()
        {
            String userName = "...";
            String password = "...";
            Boolean authenticated = userManagement.isAuthorized (userName, password);
            if (log.IsInfoEnabled) {
                log.Info ("auth? " + authenticated.ToString ());
            }

        }
    }
}

    Ok, now the log files.

    First log file from test application (standalone application): 
    20:21:42,022 [1] INFO  dbclient.MainClass [(null)] - Startup application.
20:21:42,069 [1] INFO  Database.HibernateHandler [(null)] - Inside HibernateHandler
20:21:44,709 [1] INFO  UserManagement.UserManagement [(null)] - HibernateHandler has been added to Usermanagement
2012-03-13 20:21:46,866 [1] INFO  dbclient.MainClass [(null)] - auth? True
20:21:49,912 [1] INFO  dbclient.MainClass [(null)] - Application stops.

    associated sql log file:
    2012-03-13 20:21:46,553 [1] DEBUG NHibernate.SQL - SELECT this_.Id as Id0_0_, this_.Name as Name0_0_, this_.Password as Password0_0_, this_.Email as Email0_0_, this_.Locked as Locked0_0_, this_.CharacterFk as Characte6_0_0_ FROM `Account` this_ WHERE this_.Name = ?p0;?p0 = '...' [Type: String (3)]

    Now the log files from photon application:
    19:39:52,130 [1] INFO  ServerTest.ServerTestApp [(null)] - Startup application.
19:39:52,224 [1] DEBUG PhotonHostRuntime.PhotonDomainManager [(null)] - AssemblyLoadEvent: CommonMasterSlave, Version=1.0.4455.35380, Culture=neutral, PublicKeyToken=null
19:39:52,302 [1] DEBUG PhotonHostRuntime.PhotonDomainManager [(null)] - AssemblyLoadEvent: UserManagement, Version=1.0.4455.35380, Culture=neutral, PublicKeyToken=null
19:39:52,427 [1] DEBUG PhotonHostRuntime.PhotonDomainManager [(null)] - AssemblyLoadEvent: NHibernate, Version=3.1.0.4000, Culture=neutral, PublicKeyToken=aa95f207798dfdb4
19:39:52,427 [1] INFO  Database.HibernateHandler [(null)] - Inside HibernateHandler
19:39:52,505 [1] DEBUG PhotonHostRuntime.PhotonDomainManager [(null)] - AssemblyLoadEvent: FluentNHibernate, Version=1.2.0.712, Culture=neutral, PublicKeyToken=8aa435e3cb308880
19:39:52,521 [1] DEBUG PhotonHostRuntime.PhotonDomainManager [(null)] - AssemblyResolveEvent: NHibernate.XmlSerializers, Version=3.1.0.4000, Culture=neutral, PublicKeyToken=aa95f207798dfdb4
19:39:52,599 [1] DEBUG PhotonHostRuntime.PhotonDomainManager [(null)] - AssemblyResolveEvent: System.Xml.resources, Version=4.0.0.0, Culture=de-DE, PublicKeyToken=b77a5c561934e089
19:39:52,599 [1] DEBUG PhotonHostRuntime.PhotonDomainManager [(null)] - AssemblyResolveEvent: System.Xml.resources, Version=4.0.0.0, Culture=de-DE, PublicKeyToken=b77a5c561934e089
19:39:52,599 [1] DEBUG PhotonHostRuntime.PhotonDomainManager [(null)] - AssemblyLoadEvent: System.xml.resources, Version=4.0.0.0, Culture=de, PublicKeyToken=b77a5c561934e089
19:39:53,287 [1] DEBUG PhotonHostRuntime.PhotonDomainManager [(null)] - AssemblyLoadEvent: lqyvrhbi, Version=3.1.0.4000, Culture=neutral, PublicKeyToken=null
19:39:53,349 [1] DEBUG PhotonHostRuntime.PhotonDomainManager [(null)] - AssemblyLoadEvent: Iesi.Collections, Version=1.0.1.0, Culture=neutral, PublicKeyToken=aa95f207798dfdb4
19:39:53,396 [1] DEBUG PhotonHostRuntime.PhotonDomainManager [(null)] - AssemblyLoadEvent: System.Data, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089
19:39:53,490 [1] DEBUG PhotonHostRuntime.PhotonDomainManager [(null)] - AssemblyLoadEvent: Common, Version=1.0.4455.35380, Culture=neutral, PublicKeyToken=null
19:39:54,005 [1] DEBUG PhotonHostRuntime.PhotonDomainManager [(null)] - AssemblyLoadEvent: System.Transactions, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089
19:39:54,021 [1] DEBUG PhotonHostRuntime.PhotonDomainManager [(null)] - AssemblyLoadEvent: System.EnterpriseServices, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a
19:39:54,021 [1] DEBUG PhotonHostRuntime.PhotonDomainManager [(null)] - AssemblyLoadEvent: System.Numerics, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089
19:39:54,084 [1] DEBUG PhotonHostRuntime.PhotonDomainManager [(null)] - AssemblyLoadEvent: System.Xml.Linq, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089
19:39:54,209 [1] DEBUG PhotonHostRuntime.PhotonDomainManager [(null)] - TypeResolveHandler: nop
19:39:54,380 [1] DEBUG PhotonHostRuntime.PhotonDomainManager [(null)] - AssemblyLoadEvent: NHibernate.ByteCode.Castle, Version=3.1.0.4000, Culture=neutral, PublicKeyToken=aa95f207798dfdb4
19:39:54,490 [1] DEBUG PhotonHostRuntime.PhotonDomainManager [(null)] - AssemblyLoadEvent: MySql.Data, Version=6.4.3.0, Culture=neutral, PublicKeyToken=c5687fc88969c44d
19:39:54,552 [1] DEBUG PhotonHostRuntime.PhotonDomainManager [(null)] - AssemblyResolveEvent: MySql.Data.resources, Version=6.4.3.0, Culture=de-DE, PublicKeyToken=c5687fc88969c44d
19:39:54,568 [1] DEBUG PhotonHostRuntime.PhotonDomainManager [(null)] - AssemblyResolveEvent: MySql.Data.resources, Version=6.4.3.0, Culture=de-DE, PublicKeyToken=c5687fc88969c44d
19:39:54,568 [1] DEBUG PhotonHostRuntime.PhotonDomainManager [(null)] - AssemblyResolveEvent: MySql.Data.resources, Version=6.4.3.0, Culture=de, PublicKeyToken=c5687fc88969c44d
19:39:54,568 [1] DEBUG PhotonHostRuntime.PhotonDomainManager [(null)] - AssemblyResolveEvent: MySql.Data.resources, Version=6.4.3.0, Culture=de, PublicKeyToken=c5687fc88969c44d
19:39:54,927 [1] INFO  UserManagement.UserManagement [(null)] - HibernateHandler has been added to Usermanagement
19:39:54,943 [1] INFO  ServerTest.ServerTestApp [(null)] - Debugging Mode? True
19:39:55,130 [1] DEBUG PhotonHostRuntime.PhotonDomainManager [(null)] - AssemblyLoadEvent: Castle.Core, Version=2.5.1.0, Culture=neutral, PublicKeyToken=407dd0808d44fbdc
19:39:55,209 [1] DEBUG PhotonHostRuntime.PhotonDomainManager [(null)] - AssemblyLoadEvent: DynamicProxyGenAssembly2, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null
19:39:55,271 [1] DEBUG PhotonHostRuntime.PhotonDomainManager [(null)] - AssemblyLoadEvent: DynamicProxyGenAssembly2, Version=0.0.0.0, Culture=neutral, PublicKeyToken=a621a9e7e5c32e69
19:39:55,380 [1] INFO  ServerTest.ServerTestApp [(null)] - auth? True
19:39:55,380 [1] INFO  Photon.SocketServer.ApplicationBase [(null)] - Application start: AppId=ServerTest; AppPath=E:\Projects\Photon\ExitGames-Photon-Server-SDK\deploy\ServerTest
19:54:50,938 [1] DEBUG PhotonHostRuntime.PhotonDomainManager [(null)] - RequestStop
19:54:50,938 [1] INFO  Photon.SocketServer.ApplicationBase [(null)] - Application is stopping: AppId=ServerTest
19:54:50,969 [1] INFO  PhotonHostRuntime.PhotonDomainManager [(null)] - Stop
19:54:50,969 [1] INFO  ServerTest.ServerTestApp [(null)] - Tear down of application.
19:54:50,969 [1] INFO  Photon.SocketServer.ApplicationBase [(null)] - Application stop: AppId=ServerTest

    I hope this helps.
  • xanlosch
    xanlosch
    Options
    Nobody any idea or hint? If something is missing or not clear then please ask.
  • poelam
    poelam
    Options
    Did you solve this problem finally? I'm currently facing the same problem that I cannot enable NHibernate log in Photon server
  • [Deleted User]
    [Deleted User] ✭
    Options
    Interesting...

    Have you made sure that the log level for the NHibernate classes is set correctly (to Debug?) in the log4net config?

    We are using a custom-built version of the log4net dll (1.2.10.1, which is admittedly quite outdated as well), maybe there is a conflict between our version and the one which ships with NHibernate. (It should work, but who knows...)

    By any chance, do you know which version of log4net comes with NHibernate? If you have a NHIbernate project in which the logging is working - can you try if that works with the log4net.dll that comes with Photon?

    Your input would be greatly appreciated. :) And we will upgrade to the most recent log4net version for the next major Photon release as well.

Cookies,
anyone?

We use cookies and related technologies to enhance your experience, show you personalised content and analyze performance and traffic on our website. By clicking on the „Accept All“ button you consent to the use of non-functional cookies and the subsequent processing of personal data to optimize our website and services as described in more detail in our Privacy and Cookie Policy.

By clicking on the „Customize or Deny all“ button you can decide otherwise. Clicking on the „Customize“ button will take you to a page where you can configure the usage of non-functional cookies (and related technologies) or deny all of them. You can access these settings at any time and also subsequently deselect cookies at any time in the footer area of our website.

ACCEPT ALL

Cookie Overview

We use the following categories of cookies and related technologies to enhance your experience, show you personalized content, and analyze performance and traffic on our website. We respect your right to privacy and accordingly you can chose to not allow some types of cookies (and related technologies). Click on the different category sliders and change our default settings to manage your cookie settings.

For more information on the specific cookies/related technologies we use and on how we use these, please see section 15 E. of our Privacy and Cookie Policy.

ABSOLUTELY NECESSARY

Authentication cookies we use are required to run our services … Cookies are required: Link

FUNCTIONAL AND MARKETING COOKIES

These cookies collect anonymous data and allow us to optimize our website and user experience. These cookies are listed here:

ANALYTICS

Help us to understand how visitors interact with our services, enables us to analyze and improve our services (also through third party analytics).