{"id":3631,"date":"2015-04-29T13:00:27","date_gmt":"2015-04-29T13:00:27","guid":{"rendered":"http:\/\/writeasync.net\/?p=3631"},"modified":"2015-04-29T06:31:55","modified_gmt":"2015-04-29T06:31:55","slug":"blogging-on-logging","status":"publish","type":"post","link":"http:\/\/writeasync.net\/?p=3631","title":{"rendered":"Blogging on logging"},"content":{"rendered":"

Everyone loves a log. A trace log can provide insight into the goings-on of a running system. An audit log gives you an important “paper trail” tracking who did what and when. An error log might be an important aid for exception-driven development<\/a>. While there seems to be broad agreement that logging is essential (especially in distributed systems<\/a>), there is little consensus on specific design patterns and code structures to implement it.<\/p>\n

Here is an illustration of a commonplace (and problematic) strategy:<\/p>\n

\r\nvoid DoSomething(MyData data)\r\n{\r\n    GlobalTraceLog.WriteVerbose("Doing something with {0}...", data.ToString());\r\n    try\r\n    {\r\n        \/\/ ... code goes here ...\r\n    }\r\n    catch (Exception e)\r\n    {\r\n        GlobalTraceLog.WriteError("Something failed! {0}", e.ToString());\r\n        throw;\r\n    }\r\n\r\n    GlobalTraceLog.WriteInfo("Did something.");\r\n}\r\n<\/pre>\n
What’s the problem? There are at least two big ones. The first is the use of a static global log instance — the dreaded singleton anti-pattern<\/a>. With this design it is hard to determine whether a given object will log anything since the dependency is not explicitly declared, not to mention the negative testability implications<\/a>. The data is also completely unstructured<\/a>. As Gregory Szorc<\/a> points out, if you intend for your logs to be read by machines (e.g. to do data mining or alerting) it is unwise to use a raw text format suitable for humans only.<\/p>\n
Let’s say that your logging data is only for humans, by design. Further, it is not associated with any user story<\/a> or specific business value. In that case, maybe the static text logger approach is fine. You are dismissed from this blog post! Otherwise, read on…<\/p>\n
I’ve written before about generating<\/a> and analyzing<\/a> structured trace logs. In those code samples, I used an approach of passing an EventSource<\/a> instance to the classes generating the logs. (Technically this is a bit of an empty gesture given the unfortunate singleton-ish nature of EventSource, but it demonstrates the principle.) One potential improvement on this basic approach which observes the dependency inversion principle<\/a> is to pass a logging interface instead, e.g.:<\/p>\n
\r\n\/\/ The log producer\r\npublic class MyComponent\r\n{\r\n    public MyComponent(IComponentEvents events) { \/* ... *\/ }\r\n    public int DoOperation() { \/* ... *\/ }\r\n}\r\n\r\n\/\/ The typed log event abstraction\r\npublic interface IComponentEvents\r\n{\r\n    void OperationStarted(Guid id);\r\n    void OperationCompleted(Guid id, int result);\r\n}\r\n\r\n\/\/ The concrete EventSource type implements the interface\r\npublic ComponentEventSource : EventSource, IComponentEvents\r\n{\r\n    \/\/ ...\r\n}\r\n<\/pre>\n
This has less coupling to a specific logging technology and can thus facilitate a straightforward set of unit tests which verify the events produced — though at the cost of a test double implementing the necessary event interface:<\/p>\n
\r\n[TestClass]\r\npublic class MyComponentTest\r\n{\r\n    [TestMethod]\r\n    public void ShouldNotifyOnOperationStartAndCompletion()\r\n    {\r\n        MemoryComponentEvents events = new MemoryComponentEvents();\r\n        MyComponent component = new MyComponent(events);\r\n\r\n        int result = component.DoOperation();\r\n\r\n        Assert.AreEqual(1, events.Started.Count);\r\n        Assert.AreEqual(1, events.Completed.Count);\r\n        Assert.AreNotEqual(Guid.Empty, events.Started[0]);\r\n        Assert.AreEqual(events.Started[0], events.Completed[0].Item1);\r\n        Assert.AreEqual(result, events.Completed[0].Item2);\r\n    }\r\n\r\n    \/\/ Keeps track of events in memory, for unit tests\r\n    private sealed class MemoryComponentEvents : IComponentEvents\r\n    {\r\n        \/\/ ...\r\n        public IList<Guid> Started { \/* ... *\/ }\r\n        public IList<Guid, int> Completed { \/* ... *\/ }\r\n\r\n        public void OperationStarted(Guid id)\r\n        {\r\n            this.Started.Add(id);\r\n        }\r\n\r\n        public void OperationCompleted(Guid id, int result)\r\n        {\r\n            this.Completed.Add(Tuple.Create(id, result));\r\n        }\r\n    }\r\n}\r\n<\/pre>\n
There are some other patterns you could use but I have not seen them much in practice. For example, you could associate each log operation with a plain .NET event handler or leverage  IObservable<\/a> from Reactive Extensions<\/a>. These could work but introduce more complexity around the registration\/subscription process.<\/p>\n
So why not step away from the statics and go from strings to structure? Your logging and overall system design could become that much more testable (read: better).<\/p>\n","protected":false},"excerpt":{"rendered":"
Everyone loves a log. A trace log can provide insight into the goings-on of a running system. An audit log gives you an important “paper trail” tracking who did what and when. An error log might be an important aid… <\/p>\n","protected":false},"author":1,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[91,71,41],"tags":[],"class_list":["post-3631","post","type-post","status-publish","format-standard","hentry","category-design","category-diagnostics","category-tdd"],"_links":{"self":[{"href":"http:\/\/writeasync.net\/index.php?rest_route=\/wp\/v2\/posts\/3631","targetHints":{"allow":["GET"]}}],"collection":[{"href":"http:\/\/writeasync.net\/index.php?rest_route=\/wp\/v2\/posts"}],"about":[{"href":"http:\/\/writeasync.net\/index.php?rest_route=\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"http:\/\/writeasync.net\/index.php?rest_route=\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"http:\/\/writeasync.net\/index.php?rest_route=%2Fwp%2Fv2%2Fcomments&post=3631"}],"version-history":[{"count":0,"href":"http:\/\/writeasync.net\/index.php?rest_route=\/wp\/v2\/posts\/3631\/revisions"}],"wp:attachment":[{"href":"http:\/\/writeasync.net\/index.php?rest_route=%2Fwp%2Fv2%2Fmedia&parent=3631"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"http:\/\/writeasync.net\/index.php?rest_route=%2Fwp%2Fv2%2Fcategories&post=3631"},{"taxonomy":"post_tag","embeddable":true,"href":"http:\/\/writeasync.net\/index.php?rest_route=%2Fwp%2Fv2%2Ftags&post=3631"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}