KestrelTrace refactored and added to the ServiceContext. Close aspnet/KestrelHttpServer#141

samples/SampleApp/Startup.cs

@@ -4,13 +4,16 @@
 using System;
 using Microsoft.AspNet.Builder;
 using Microsoft.AspNet.Http;
+using Microsoft.Framework.Logging;
 
 namespace SampleApp
 {
     public class Startup
     {
-        public void Configure(IApplicationBuilder app)
+        public void Configure(IApplicationBuilder app, ILoggerFactory loggerFactory)
         {
+            loggerFactory.MinimumLevel = LogLevel.Debug;
+            loggerFactory.AddConsole(LogLevel.Debug);
             app.Run(context =>
             {
                 Console.WriteLine("{0} {1}{2}{3}",

samples/SampleApp/project.json

@@ -1,7 +1,9 @@
 {
     "version": "1.0.0-*",
     "dependencies": {
-        "Microsoft.AspNet.Server.Kestrel": "1.0.0-*"
+        "Microsoft.AspNet.Server.Kestrel": "1.0.0-*",
+        "Microsoft.Framework.Logging.Abstractions": "1.0.0-*",
+        "Microsoft.Framework.Logging.Console": "1.0.0-*"
     },
     "frameworks": {
         "dnx451": { },

src/Microsoft.AspNet.Server.Kestrel/Http/Connection.cs

@@ -30,10 +30,10 @@ namespace Microsoft.AspNet.Server.Kestrel.Http
 
         public void Start()
         {
-            KestrelTrace.Log.ConnectionStart(_connectionId);
+            Log.ConnectionStart(_connectionId);
 
             SocketInput = new SocketInput(Memory);
-            SocketOutput = new SocketOutput(Thread, _socket);
+            SocketOutput = new SocketOutput(Thread, _socket, Log);
             _frame = new Frame(this);
             _socket.ReadStart(_allocCallback, _readCallback, this);
         }
@@ -65,11 +65,11 @@ namespace Microsoft.AspNet.Server.Kestrel.Http
 
             if (normalRead)
             {
-                KestrelTrace.Log.ConnectionRead(_connectionId, status);
+                Log.ConnectionRead(_connectionId, status);
             }
             else if (normalDone || errorDone)
             {
-                KestrelTrace.Log.ConnectionReadFin(_connectionId);
+                Log.ConnectionReadFin(_connectionId);
                 SocketInput.RemoteIntakeFin = true;
                 _socket.ReadStop();
 
@@ -92,13 +92,13 @@ namespace Microsoft.AspNet.Server.Kestrel.Http
 
         void IConnectionControl.Pause()
         {
-            KestrelTrace.Log.ConnectionPause(_connectionId);
+            Log.ConnectionPause(_connectionId);
             _socket.ReadStop();
         }
 
         void IConnectionControl.Resume()
         {
-            KestrelTrace.Log.ConnectionResume(_connectionId);
+            Log.ConnectionResume(_connectionId);
             _socket.ReadStart(_allocCallback, _readCallback, this);
         }
 
@@ -115,17 +115,17 @@ namespace Microsoft.AspNet.Server.Kestrel.Http
                         }
                         _connectionState = ConnectionState.Shutdown;
 
-                        KestrelTrace.Log.ConnectionWriteFin(_connectionId, 0);
+                        Log.ConnectionWriteFin(_connectionId, 0);
                         Thread.Post(
                             state =>
                             {
-                                KestrelTrace.Log.ConnectionWriteFin(_connectionId, 1);
+                                Log.ConnectionWriteFin(_connectionId, 1);
                                 var self = (Connection)state;
                                 var shutdown = new UvShutdownReq();
                                 shutdown.Init(self.Thread.Loop);
                                 shutdown.Shutdown(self._socket, (req, status, _) =>
                                 {
-                                    KestrelTrace.Log.ConnectionWriteFin(_connectionId, 1);
+                                    Log.ConnectionWriteFin(_connectionId, 1);
                                     req.Dispose();
                                 }, null);
                             },
@@ -137,7 +137,7 @@ namespace Microsoft.AspNet.Server.Kestrel.Http
                             return;
                         }
 
-                        KestrelTrace.Log.ConnectionKeepAlive(_connectionId);
+                        Log.ConnectionKeepAlive(_connectionId);
                         _frame = new Frame(this);
                         Thread.Post(
                             state => ((Frame)state).Consume(),
@@ -150,11 +150,11 @@ namespace Microsoft.AspNet.Server.Kestrel.Http
                         }
                         _connectionState = ConnectionState.Disconnected;
 
-                        KestrelTrace.Log.ConnectionDisconnect(_connectionId);
+                        Log.ConnectionDisconnect(_connectionId);
                         Thread.Post(
                             state =>
                             {
-                                KestrelTrace.Log.ConnectionStop(_connectionId);
+                                Log.ConnectionStop(_connectionId);
                                 ((UvHandle)state).Dispose();
                             },
                             _socket);

src/Microsoft.AspNet.Server.Kestrel/Http/ListenerContext.cs

@@ -3,6 +3,7 @@
 
 using System;
 using System.Threading.Tasks;
+using Microsoft.AspNet.Server.Kestrel.Infrastructure;
 
 namespace Microsoft.AspNet.Server.Kestrel.Http
 {
@@ -13,6 +14,7 @@ namespace Microsoft.AspNet.Server.Kestrel.Http
         public ListenerContext(ServiceContext serviceContext)
         {
             Memory = serviceContext.Memory;
+            Log = serviceContext.Log;
         }
 
         public ListenerContext(ListenerContext listenerContext)
@@ -20,6 +22,7 @@ namespace Microsoft.AspNet.Server.Kestrel.Http
             Thread = listenerContext.Thread;
             Application = listenerContext.Application;
             Memory = listenerContext.Memory;
+            Log = listenerContext.Log;
         }
 
         public KestrelThread Thread { get; set; }
@@ -27,5 +30,7 @@ namespace Microsoft.AspNet.Server.Kestrel.Http
         public Func<Frame, Task> Application { get; set; }
 
         public IMemoryPool Memory { get; set; }
+
+        public IKestrelTrace Log { get; }
     }
 }

src/Microsoft.AspNet.Server.Kestrel/Http/SocketOutput.cs

@@ -5,6 +5,7 @@ using System;
 using System.Collections.Generic;
 using System.Diagnostics;
 using System.Threading;
+using Microsoft.AspNet.Server.Kestrel.Infrastructure;
 using Microsoft.AspNet.Server.Kestrel.Networking;
 
 namespace Microsoft.AspNet.Server.Kestrel.Http
@@ -16,6 +17,7 @@ namespace Microsoft.AspNet.Server.Kestrel.Http
 
         private readonly KestrelThread _thread;
         private readonly UvStreamHandle _socket;
+        private readonly IKestrelTrace _log;
 
         // This locks access to to all of the below fields
         private readonly object _lockObj = new object();
@@ -29,10 +31,11 @@ namespace Microsoft.AspNet.Server.Kestrel.Http
         private WriteContext _nextWriteContext;
         private readonly Queue<CallbackContext> _callbacksPending;
 
-        public SocketOutput(KestrelThread thread, UvStreamHandle socket)
+        public SocketOutput(KestrelThread thread, UvStreamHandle socket, IKestrelTrace log)
         {
             _thread = thread;
             _socket = socket;
+            _log = log;
             _callbacksPending = new Queue<CallbackContext>();
         }
 
@@ -43,7 +46,7 @@ namespace Microsoft.AspNet.Server.Kestrel.Http
             Array.Copy(buffer.Array, buffer.Offset, copy, 0, buffer.Count);
             buffer = new ArraySegment<byte>(copy);
 
-            KestrelTrace.Log.ConnectionWrite(0, buffer.Count);
+            _log.ConnectionWrite(0, buffer.Count);
 
             bool triggerCallbackNow = false;
 
@@ -152,7 +155,7 @@ namespace Microsoft.AspNet.Server.Kestrel.Http
         // This is called on the libuv event loop
         private void OnWriteCompleted(Queue<ArraySegment<byte>> writtenBuffers, UvWriteReq req, int status, Exception error)
         {
-            KestrelTrace.Log.ConnectionWriteCallback(0, status);
+            _log.ConnectionWriteCallback(0, status);
 
             lock (_lockObj)
             {

src/Microsoft.AspNet.Server.Kestrel/Infrastructure/IKestrelTrace.cs

@@ -0,0 +1,29 @@
+using Microsoft.Framework.Logging;
+
+namespace Microsoft.AspNet.Server.Kestrel.Infrastructure
+{
+    public interface IKestrelTrace : ILogger
+    {
+        void ConnectionStart(long connectionId);
+
+        void ConnectionStop(long connectionId);
+
+        void ConnectionRead(long connectionId, int status);
+
+        void ConnectionPause(long connectionId);
+
+        void ConnectionResume(long connectionId);
+
+        void ConnectionReadFin(long connectionId);
+
+        void ConnectionWriteFin(long connectionId, int step);
+
+        void ConnectionKeepAlive(long connectionId);
+
+        void ConnectionDisconnect(long connectionId);
+
+        void ConnectionWrite(long connectionId, int count);
+
+        void ConnectionWriteCallback(long connectionId, int status);
+    }
+}

src/Microsoft.AspNet.Server.Kestrel/Infrastructure/KestrelTrace.cs

@@ -1,85 +1,92 @@
 // Copyright (c) .NET Foundation. All rights reserved.
 // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
 
-//using System.Diagnostics.Tracing;
+using System;
+using Microsoft.AspNet.Server.Kestrel.Infrastructure;
+using Microsoft.Framework.Logging;
 
 namespace Microsoft.AspNet.Server.Kestrel
 {
     /// <summary>
     /// Summary description for KestrelTrace
     /// </summary>
-    public class KestrelTrace //: EventSource
+    public class KestrelTrace : IKestrelTrace
     {
-        public static KestrelTrace Log = new KestrelTrace();
+        private readonly ILogger _logger;
-  //      static EventTask Connection = (EventTask)1;
-    //    static EventTask Frame = (EventTask)1;
 
+        public KestrelTrace(ILogger logger)
+        {
+            _logger = logger;
+        }
 
-      //  [Event(13, Level = EventLevel.Informational, Message = "Id {0}")]
         public void ConnectionStart(long connectionId)
         {
-         //   WriteEvent(13, connectionId);
+            _logger.LogDebug(13, $"{nameof(ConnectionStart)} -> Id: {connectionId}");
         }
 
-      //  [Event(14, Level = EventLevel.Informational, Message = "Id {0}")]
         public void ConnectionStop(long connectionId)
         {
-       //     WriteEvent(14, connectionId);
+            _logger.LogDebug(14, $"{nameof(ConnectionStop)} -> Id: {connectionId}");
         }
 
-
+        public void ConnectionRead(long connectionId, int status)
-   //     [Event(4, Message = "Id {0} Status {1}")]
-        internal void ConnectionRead(long connectionId, int status)
         {
-     //       WriteEvent(4, connectionId, status);
+            _logger.LogDebug(4, $"{nameof(ConnectionRead)} -> Id: {connectionId}, Status: {status}");
         }
 
- //       [Event(5, Message = "Id {0}")]
+        public void ConnectionPause(long connectionId)
-        internal void ConnectionPause(long connectionId)
         {
-   //         WriteEvent(5, connectionId);
+            _logger.LogDebug(5, $"{nameof(ConnectionPause)} -> Id: {connectionId}");
         }
 
- //       [Event(6, Message = "Id {0}")]
+        public void ConnectionResume(long connectionId)
-        internal void ConnectionResume(long connectionId)
         {
-   //         WriteEvent(6, connectionId);
+            _logger.LogDebug(6, $"{nameof(ConnectionResume)} -> Id: {connectionId}");
         }
 
-  //      [Event(7, Message = "Id {0}")]
+        public void ConnectionReadFin(long connectionId)
-        internal void ConnectionReadFin(long connectionId)
         {
-    //        WriteEvent(7, connectionId);
+            _logger.LogDebug(7, $"{nameof(ConnectionReadFin)} -> Id: {connectionId}");
         }
 
-//        [Event(8, Message = "Id {0} Step {1}")]
+        public void ConnectionWriteFin(long connectionId, int step)
-        internal void ConnectionWriteFin(long connectionId, int step)
         {
-  //          WriteEvent(8, connectionId, step);
+            _logger.LogDebug(8, $"{nameof(ConnectionWriteFin)} -> Id: {connectionId}, Step: {step}");
         }
 
- //       [Event(9, Message = "Id {0}")]
+        public void ConnectionKeepAlive(long connectionId)
-        internal void ConnectionKeepAlive(long connectionId)
         {
-   //         WriteEvent(9, connectionId);
+            _logger.LogDebug(9, $"{nameof(ConnectionKeepAlive)} -> Id: {connectionId}");
         }
 
- //       [Event(10, Message = "Id {0}")]
+        public void ConnectionDisconnect(long connectionId)
-        internal void ConnectionDisconnect(long connectionId)
         {
-   //         WriteEvent(10, connectionId);
+            _logger.LogDebug(10, $"{nameof(ConnectionDisconnect)} -> Id: {connectionId}");
         }
 
-  //      [Event(11, Message = "Id {0} Count {1}")]
+        public void ConnectionWrite(long connectionId, int count)
-        internal void ConnectionWrite(long connectionId, int count)
         {
-    //        WriteEvent(11, connectionId, count);
+            _logger.LogDebug(11, $"{nameof(ConnectionWrite)} -> Id: {connectionId}, Count: {count}");
         }
 
- //       [Event(12, Message = "Id {0} Status {1}")]
+        public void ConnectionWriteCallback(long connectionId, int status)
-        internal void ConnectionWriteCallback(long connectionId, int status)
         {
-   //         WriteEvent(12, connectionId, status);
+            _logger.LogDebug(12, $"{nameof(ConnectionWriteCallback)} -> Id: {connectionId}, Status: {status}");
+        }
+
+        public void Log(LogLevel logLevel, int eventId, object state, Exception exception, Func<object, Exception, string> formatter)
+        {
+            _logger.Log(logLevel, eventId, state, exception, formatter);
+        }
+
+        public bool IsEnabled(LogLevel logLevel)
+        {
+            return _logger.IsEnabled(logLevel);
+        }
+
+        public IDisposable BeginScopeImpl(object state)
+        {
+            return _logger.BeginScopeImpl(state);
         }
     }
 }

src/Microsoft.AspNet.Server.Kestrel/KestrelEngine.cs

@@ -9,6 +9,7 @@ using Microsoft.AspNet.Server.Kestrel.Http;
 using Microsoft.AspNet.Server.Kestrel.Infrastructure;
 using Microsoft.AspNet.Server.Kestrel.Networking;
 using Microsoft.Dnx.Runtime;
+using Microsoft.Framework.Logging;
 
 namespace Microsoft.AspNet.Server.Kestrel
 {
@@ -16,8 +17,8 @@ namespace Microsoft.AspNet.Server.Kestrel
     {
         private readonly ServiceContext _serviceContext;
 
-        public KestrelEngine(ILibraryManager libraryManager, IApplicationShutdown appShutdownService)
+        public KestrelEngine(ILibraryManager libraryManager, IApplicationShutdown appShutdownService, ILogger logger)
-            : this(appShutdownService)
+            : this(appShutdownService, logger)
         {
             Libuv = new Libuv();
 
@@ -62,18 +63,19 @@ namespace Microsoft.AspNet.Server.Kestrel
         }
 
         // For testing
-        internal KestrelEngine(Libuv uv, IApplicationShutdown appShutdownService)
+        internal KestrelEngine(Libuv uv, IApplicationShutdown appShutdownService, ILogger logger)
-           : this(appShutdownService)
+           : this(appShutdownService, logger)
         {
             Libuv = uv;
         }
 
-        private KestrelEngine(IApplicationShutdown appShutdownService)
+        private KestrelEngine(IApplicationShutdown appShutdownService, ILogger logger)
         {
             _serviceContext = new ServiceContext
             {
                 AppShutdown = appShutdownService,
-                Memory = new MemoryPool()
+                Memory = new MemoryPool(),
+                Log = new KestrelTrace(logger)
             };
 
             Threads = new List<KestrelThread>();

src/Microsoft.AspNet.Server.Kestrel/ServerFactory.cs

@@ -8,6 +8,7 @@ using Microsoft.AspNet.Hosting.Server;
 using Microsoft.AspNet.Http.Features;
 using Microsoft.Dnx.Runtime;
 using Microsoft.Framework.Configuration;
+using Microsoft.Framework.Logging;
 
 namespace Microsoft.AspNet.Server.Kestrel
 {
@@ -18,11 +19,13 @@ namespace Microsoft.AspNet.Server.Kestrel
     {
         private readonly ILibraryManager _libraryManager;
         private readonly IApplicationShutdown _appShutdownService;
+        private readonly ILogger _logger;
 
-        public ServerFactory(ILibraryManager libraryManager, IApplicationShutdown appShutdownService)
+        public ServerFactory(ILibraryManager libraryManager, IApplicationShutdown appShutdownService, ILoggerFactory loggerFactory)
         {
             _libraryManager = libraryManager;
             _appShutdownService = appShutdownService;
+            _logger = loggerFactory.CreateLogger("Microsoft.AspNet.Server.Kestrel");
         }
 
         public IFeatureCollection Initialize(IConfiguration configuration)
@@ -48,7 +51,7 @@ namespace Microsoft.AspNet.Server.Kestrel
             try
             {
                 var information = (KestrelServerInformation)serverFeatures.Get<IKestrelServerInformation>();
-                var engine = new KestrelEngine(_libraryManager, _appShutdownService);
+                var engine = new KestrelEngine(_libraryManager, _appShutdownService, _logger);
 
                 disposables.Push(engine);
 

src/Microsoft.AspNet.Server.Kestrel/ServiceContext.cs

@@ -2,6 +2,7 @@
 // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
 
 using Microsoft.AspNet.Server.Kestrel.Http;
+using Microsoft.AspNet.Server.Kestrel.Infrastructure;
 using Microsoft.Dnx.Runtime;
 
 namespace Microsoft.AspNet.Server.Kestrel
@@ -11,5 +12,7 @@ namespace Microsoft.AspNet.Server.Kestrel
         public IApplicationShutdown AppShutdown { get; set; }
 
         public IMemoryPool Memory { get; set; }
+
+        public IKestrelTrace Log { get; set; }
     }
 }

src/Microsoft.AspNet.Server.Kestrel/project.json

@@ -11,7 +11,8 @@
         "Microsoft.StandardsPolice": {
             "version": "1.0.0-*",
             "type": "build"
-        }
+        },
+        "Microsoft.Framework.Logging.Abstractions": "1.0.0-*"
     },
     "frameworks": {
         "dnx451": { },

test/Microsoft.AspNet.Server.KestrelTests/EngineTests.cs

@@ -86,7 +86,7 @@ namespace Microsoft.AspNet.Server.KestrelTests
         [Fact]
         public void EngineCanStartAndStop()
         {
-            var engine = new KestrelEngine(LibraryManager, new ShutdownNotImplemented());
+            var engine = new KestrelEngine(LibraryManager, new ShutdownNotImplemented(), new TestLogger());
             engine.Start(1);
             engine.Dispose();
         }
@@ -94,7 +94,7 @@ namespace Microsoft.AspNet.Server.KestrelTests
         [Fact]
         public void ListenerCanCreateAndDispose()
         {
-            var engine = new KestrelEngine(LibraryManager, new ShutdownNotImplemented());
+            var engine = new KestrelEngine(LibraryManager, new ShutdownNotImplemented(), new TestLogger());
             engine.Start(1);
             var started = engine.CreateServer("http", "localhost", 54321, App);
             started.Dispose();
@@ -105,7 +105,7 @@ namespace Microsoft.AspNet.Server.KestrelTests
         [Fact]
         public void ConnectionCanReadAndWrite()
         {
-            var engine = new KestrelEngine(LibraryManager, new ShutdownNotImplemented());
+            var engine = new KestrelEngine(LibraryManager, new ShutdownNotImplemented(), new TestLogger());
             engine.Start(1);
             var started = engine.CreateServer("http", "localhost", 54321, App);
 

test/Microsoft.AspNet.Server.KestrelTests/MultipleLoopTests.cs

@@ -16,7 +16,7 @@ namespace Microsoft.AspNet.Server.KestrelTests
         Libuv _uv;
         public MultipleLoopTests()
         {
-            var engine = new KestrelEngine(LibraryManager, new ShutdownNotImplemented());
+            var engine = new KestrelEngine(LibraryManager, new ShutdownNotImplemented(), new TestLogger());
             _uv = engine.Libuv;
         }
 

test/Microsoft.AspNet.Server.KestrelTests/NetworkingTests.cs

@@ -22,7 +22,7 @@ namespace Microsoft.AspNet.Server.KestrelTests
         Libuv _uv;
         public NetworkingTests()
         {
-            var engine = new KestrelEngine(LibraryManager, new ShutdownNotImplemented());
+            var engine = new KestrelEngine(LibraryManager, new ShutdownNotImplemented(), new TestLogger());
             _uv = engine.Libuv;
         }
 

test/Microsoft.AspNet.Server.KestrelTests/SocketOutputTests.cs

@@ -31,13 +31,14 @@ namespace Microsoft.AspNet.Server.KestrelTests
                 }
             };
 
-            using (var kestrelEngine = new KestrelEngine(mockLibuv, new ShutdownNotImplemented()))
+            using (var kestrelEngine = new KestrelEngine(mockLibuv, new ShutdownNotImplemented(), new TestLogger()))
             {
                 kestrelEngine.Start(count: 1);
 
                 var kestrelThread = kestrelEngine.Threads[0];
                 var socket = new MockSocket(kestrelThread.Loop.ThreadId);
-                var socketOutput = new SocketOutput(kestrelThread, socket);
+                var trace = new KestrelTrace(new TestLogger());
+                var socketOutput = new SocketOutput(kestrelThread, socket, trace);
 
                 // I doubt _maxBytesPreCompleted will ever be over a MB. If it is, we should change this test.
                 var bufferSize = 1048576;
@@ -75,13 +76,14 @@ namespace Microsoft.AspNet.Server.KestrelTests
                 }
             };
 
-            using (var kestrelEngine = new KestrelEngine(mockLibuv, new ShutdownNotImplemented()))
+            using (var kestrelEngine = new KestrelEngine(mockLibuv, new ShutdownNotImplemented(), new TestLogger()))
             {
                 kestrelEngine.Start(count: 1);
 
                 var kestrelThread = kestrelEngine.Threads[0];
                 var socket = new MockSocket(kestrelThread.Loop.ThreadId);
-                var socketOutput = new SocketOutput(kestrelThread, socket);
+                var trace = new KestrelTrace(new TestLogger());
+                var socketOutput = new SocketOutput(kestrelThread, socket, trace);
 
                 var bufferSize = maxBytesPreCompleted;
                 var buffer = new ArraySegment<byte>(new byte[bufferSize], 0, bufferSize);

test/Microsoft.AspNet.Server.KestrelTests/TestLogger.cs

@@ -0,0 +1,23 @@
+using System;
+using Microsoft.AspNet.Server.Kestrel;
+using Microsoft.Framework.Logging;
+
+namespace Microsoft.AspNet.Server.KestrelTests
+{
+    public class TestLogger : ILogger
+    {
+        public void Log(LogLevel logLevel, int eventId, object state, Exception exception, Func<object, Exception, string> formatter)
+        {
+        }
+
+        public bool IsEnabled(LogLevel logLevel)
+        {
+            return true;
+        }
+
+        public IDisposable BeginScopeImpl(object state)
+        {
+            return new Disposable(() => { });
+        }
+    }
+}

test/Microsoft.AspNet.Server.KestrelTests/TestServer.cs

@@ -45,7 +45,7 @@ namespace Microsoft.AspNet.Server.KestrelTests
 
         public void Create(Func<Frame, Task> app)
         {
-            _engine = new KestrelEngine(LibraryManager, new ShutdownNotImplemented());
+            _engine = new KestrelEngine(LibraryManager, new ShutdownNotImplemented(), new TestLogger());
             _engine.Start(1);
             _server = _engine.CreateServer(
                 "http",