Entity Framework: logging

I use EF4 CTP5 and I’d like to log ANY!!! SQL commands sent to the DB. You can use the method ToTraceString() to display the SQL commands of any ObjectQuery, but … you are not able to see the queries generated i.e. while saving changes OR lazy loading. You need to use i.e. EFProfiler to log it. EFProfiler is very cool tool but … I need to log it by my application.

So I found out the Tracing and Caching implementation by Jaroslaw Kowalski here which extends EF with tracing/logging and caching capabilities. The main disadvantages I found out are:
a) you need to you both! features otherwise logging/tracing will not work. I wanted to use only logging! After doing so I started to get strange exception (or I had to do something wrong). After enabling also tracing, it started to work. Shame because I needed to use ONLY tracing.
b) your Context classes HAS to be derived from his special classes.

Honestly, I don’t use this solution. It’s too much work.

MS guys, I’m sorry but I must say: IT’S BIG SHAME EF WAS NOT DEVELOPED IN EASY EXTENSIBLE MANNER with i.e. ServiceLocator, interceptors, etc. in place.

As far as I know, and correct me if I’m wrong, adding logging capabilities fits to AOP interceptors.

I.e. EFProfiler has quite hardly injects itself into creating new DB connection logic and then it has a capability to log everything. Their solution is more transparent than a by Mr. Kowalski.

My solution
I used the ideas from NHProfiler and I generalized it little bit. I made base AOP filter called IAopFilter.

public interface IAopFilter

    {

        void CommandDurationAndRowCount(Guid connectionId, long milliseconds, int? rowCount);

        void ConnectionDisposed(Guid connectionId);

        void ConnectionStarted(Guid connectionId);

        void DtcTransactionCompleted(Guid connectionId, TransactionStatus status);

        void DtcTransactionEnlisted(Guid connectionId, IsolationLevel isolationLevel);

        void StatementError(Guid connectionId, Exception exception);

        void StatementExecuted(Guid connectionId, Guid statementId, string statement);

        void StatementRowCount(Guid connectionId, Guid statementId, int rowCount);

        void TransactionBegan(Guid connectionId, System.Data.IsolationLevel isolationLevel);

        void TransactionCommit(Guid connectionId);

        void TransactionDisposed(Guid connectionId);

        void TransactionRolledBack(Guid connectionId);

    }

Due to the short of the time, I made only 1 its implementation and it was using Log4Net capabilities. Then I had to create AOP capable DbProviderFactory class called DbProviderFactoryEx which uses IAopFilters. In addition I had to create whole family of the classes following abstract factory pattern implemented in DbProviderFactory.

The main class is called EntityFrameworkExtender. This class wires-up AOP capabilities into EF. You just need to call:
EntityFrameworkExtender.Initialize();

The class by default uses Log4NetFilter as only the one filter but you can freely configure it.

EntityFrameworkExtender.Filters = () => new[] {new Log4NetFilter(“MyClass”)};

            EntityFrameworkExtender.Initialize();

Using it you are able transparently trace/log every SQL command sent from EF to DB.

I think, we, EF users would profit very much IF the EF team would develope the framework on enterprise level – easily extensible, configurable and if we could get also the unit tests! together with the framework.

[UPDATED!]
I bundled the whole source code into 1 project. The whole source code can be found here – save it as a file to the local disk  and delete .doc extension. It’s  normal zip file.
To use it you will need: log4net 1.2.10.0, EF4 CTP5, .NET 4.0

Entity Framework: Problem/Solution of default connection closing !

I use EF CTP5 on my last project together with NCommon and its UnitOfWork, Repositories, IoC and DI abstracted by MS P&P team and StructureMap as the concrete implemetation of IoC and DI.

Problem :
Let’s have the following example (I took the example from the NCommon unit tests and extend it to do the same Linq query twice):

using (var scope = new UnitOfWorkScope())

{

    var repository = new EFRepository<User>();

 

    User user;

    user = repository.Where(u => u.ComsiID == "login").FirstOrDefault();

    user = repository.Where(u => u.ComsiID == "login").FirstOrDefault();

 

}

 

Just for the completion: creating new UnitOfWorkScope starts the DB transaction. In the above example, using UnitOfWork we create and start the transaction. Then we create new EFRepository instance which creates the ObjectContext. ObjectContext uses the connection identified by the same name AppDb and handles the connection on its own. Then we query the DB. EF opens the connection (this implies that the connection is enlisted into the current running transaction), reads the data and then close the connection. Fine! But then next (in this demo case) same query does the same: opens the connection. Because we run inside the transaction, so the connection is also enlisted into the transaction. And because there was already enlisted connection the transaction mechanism propagates it into DTS.

The result of the above code is that it works and sometimes not! The exception is following:
System.Data.EntityException: The underlying provider failed on Open.
---> System.InvalidOperationException: The connection object can not be enlisted in transaction scope.


THE PROBLEM IS IN ENTITY FRAMEWORK!!!!! and the result of the test depends on the underlying DB. If you use SQLExpress edition (as is used by default in NCommon unit tests), everything works fine! SQLExpress can not elevate the transaction to MS DTC. But if you change the connection to the real SQL server you starts to have the problems.

The problem is that in case you don’t send the concrete connection instance to EF, EF handles the connection status on his own => closes as soon as possible. I understand it but in case of Transaciton is fails! It would be good to have there a switch to configure that behavior. Anyway, the reality is different so how to fix it.

The solution is to manage the connection by your own and while creating the ObjectContext pass already created and open connection. You can find many examples about it on the internet.

Hm, fine but … not so nice. You need manually on all places where ObjectContext, or your class derived from ObjectContext, is used to manage the connection

With NCommon and it’s configuration capabilities you can do the following:

NCommon.Configure.Using(adapter)

    .ConfigureData<EFConfiguration>(config => config.WithObjectContext(

        () =>

        {

            AppDb db = new AppDb();

            if (Transaction.Current != null)

            {

                db.Connection.Open();

            }

            return db;

        }))

.ConfigureUnitOfWork<DefaultScopeUnitOfWorkConfiguration>();

 

 

So you don’t need to do open the connection over and over and on different places. Just configure NCommon on one place and use it. That’s the power of the centralized factory code-enabled configurations. In this case, thanks to StructureMap and NCommon!

---

Here is my full unit test class (using MS Tests):

[TestClass]

    public class SimpleTests

    {

        public IServiceLocator MyServiceLocator;

 

        [TestInitialize]

        public void Setup()

        {

            var _state = new FakeState();

            var _unitOfWorkFactory = new EFUnitOfWorkFactory();

            var _connectionString = ConfigurationManager.ConnectionStrings["AppDb"].ConnectionString;

            _unitOfWorkFactory.RegisterObjectContextProvider(

                () =>

                        {

                            var ctx = new AppDb(_connectionString);

                            if (Transaction.Current != null)

                            {

                                ctx.Connection.Open();

                            }

                            return ctx;

                        });

            var _locator = MockRepository.GenerateStub<IServiceLocator>();

            _locator.Stub(x => x.GetInstance<IUnitOfWorkFactory>()).Return(_unitOfWorkFactory);

            _locator.Stub(x => x.GetInstance<IState>()).Do(new Func<IState>(() => _state));

            ServiceLocator.SetLocatorProvider(() => _locator);

        }

 

        [TestCleanup]

        public void Cleanup()

        {

        }

 

        [TestMethod]

        public void Can_perform_simple_query()

        {

                using (var scope = new UnitOfWorkScope())

                {

                    var repository = new EFRepository<User>();

 

                    User user;

                    user = repository.Where(u => u.ComsiID == "a").FirstOrDefault();

                    user = repository.Where(u => u.ComsiID == "a").FirstOrDefault();

 

                }

        }

I must again say, NCommon and StructureMap rocks!

Happy coding…