22

When thinking of agile software development and all the principles (SRP, OCP, ...) I ask myself how to treat logging.

Is logging next to an implementation a SRP violation?

I would say yes because the implementation should be also able to run without logging. So how can I implement logging in a better way? I've checked some patterns and came to a conclusion that the best way not to violate the principles in a user-defined way, but to use any pattern which is known to violate a principle is to use a decorator pattern.

Let's say we have a bunch of components completely without SRP violation and then we want to add logging.

  • component A
  • component B uses A

We want logging for A, so we create another component D decorated with A both implementing an interface I.

  • interface I
  • component L (logging component of the system)
  • component A implements I
  • component D implements I, decorates/uses A, uses L for logging
  • component B uses an I

Advantages: - I can use A without logging - testing A means I don't need any logging mocks - tests are simpler

Disadvantage: - more components and more tests

I know this seem to be another open discussion question, but I actually want to know if someone uses better logging strategies than a decorator or SRP violation. What about static singleton logger which are as default NullLogger and if syslog-logging is wanted, one change the implementation object at runtime?

Robert Harvey
  • 198,589
  • 55
  • 464
  • 673
Aitch
  • 709
  • 4
  • 13
  • possible duplicate of [Design patterns to avoiding breaking the SRP while performing heavy data logging](http://programmers.stackexchange.com/questions/179807/design-patterns-to-avoiding-breaking-the-srp-while-performing-heavy-data-logging) – gnat Mar 11 '15 at 10:32
  • I've already read it and the answer is not satisfying, sorry. – Aitch Mar 11 '15 at 10:43
  • 2
    [How do you determine how coarse or fine-grained a 'responsibility' should be when using the single responsibility principle?](http://stackoverflow.com/q/2455705/25847) – Mark Rogers Mar 11 '15 at 14:34
  • @MarkRogers thank you for sharing that interesting article. Uncle Bob says in 'Clean Code', that a nice SRP component is dealing with other components on the same level of abstraction. For me that explanation is easier to understand since the context can also be too big. But I cannot answer the question, because what is the context or abstraction leve of a logger? – Aitch Mar 11 '15 at 14:58
  • @Aitch - Long story short, I would say the abtraction level of a logger is low, so I wouldn't worry about it violating SRP. So no a logger call, doesn't necessarily violate SRP. – Mark Rogers Mar 11 '15 at 15:02
  • 3
    "is not an answer to me" or "the answer is not satisfying" is a bit dismissive. You might ponder *what* specifically is unsatisfying (what requirement do you have that wasn't met by that answer? what specifically is unique about your question?), then edit your question to make sure that this requirement/unique aspect is explained clearly. The purpose is to get you to edit your question to improve it to make it clearer and more focused, not to ask for boilerplate asserting that your question is different/shouldn't be closed without justification why. (You can also comment on the other answer.) – D.W. Mar 11 '15 at 22:21
  • How do you combine "tests are simpler" and "more tests"? If initializing a `NullLogger` is such a pain, maybe you should pursue to factor out commonalities in the setup code of your classes. – Laurent LA RIZZA Mar 12 '15 at 09:04
  • @D.W. the 'possible duplicate' talks about 'heavy data logging' which means debugging by logging to me or any fact of producing that much logging data, that it is mentioned in the question. I would expect any 'buffered/batch log' as answer, but I gave a simple and clear example. And I hope it's not too dismissive if I don't want to accept any explanation by using the MVC-Pattern. MVC was the first pattern everyone knows I think and the last pattern professionals use. If I edit my question to 'business logic logging' there might be some people complaining, that now it's something different. – Aitch Mar 12 '15 at 23:48
  • I'd like to thank everybody for your answers, but now I vote for close, because it's 'primarily opinion-based' I think. Writing low-level C++ stuff logging to `std::cerr` is ccc and fine for me, but higher level server web-apps logging events is not, for me (opinion-based). Maybe the discussion would have might been a bit shorter if I had mentioned non-ccc logging (sorry for that). – Aitch Mar 13 '15 at 02:32

6 Answers6

68

I would say you're taking SRP far too seriously. If your code is tidy enough that logging is the only "violation" of SRP then you are doing better than 99% of all other programmers, and you should pat yourself on the back.

The point of SRP is to avoid horrific spaghetti code where code that does different things is all mixed up together. Mixing logging with functional code doesn't ring any alarm bells for me.

grahamparks
  • 2,099
  • 1
  • 15
  • 14
  • having clean code and some small violations is the one hand, and on the other hand is boilerplate code in the tests. Every logger dependency means one additional ctor parameter to me. – Aitch Mar 11 '15 at 11:53
  • 21
    @Aitch: Your choices are to hard-wire the logging into your class, pass in a handle to a logger or don't log anything at all. If you're going to be ultra-strict about the SRP at the expense of everything else, I'd recommend not logging anything, ever. Whatever you need to know about what your software is doing can be noodled out with a debugger. The P in SRP stands for "principle," not "physical law of nature which must never be broken." – Blrfl Mar 11 '15 at 12:51
  • @Blrfl I agree, but how about TDD? Do you mock the logger, do you use NullLogger, do you uglify you code with `if(logger) logger.info(...);` ? As I've already mentioned, SRP violation also means ugly tests. That's why SRP is the most important principle to me. – Aitch Mar 11 '15 at 13:04
  • Lots of people would use conditional compilation to turn the logging on and off and write to a global logger when tests are not running. It is far better than injecting a logger into all of your classes. That would make a mess of a clean code base. – Mike Mar 11 '15 at 13:19
  • 4
    @Aitch: You should be able to trace logging in your class back to some requirement, otherwise you're violating YAGNI. If logging is on the table, you provide in a valid logger handle just like you would for anything else the class needs, preferably one from a class that's already passed testing. Whether it's one that produces actual log entries or dumps them into the bit bucket is the concern of what instantiated the instance of your class; the class itself shouldn't care. – Blrfl Mar 11 '15 at 13:22
  • @Mike: Conditional compilation alters the code. You don't want to put code into production that wasn't the same as what was used under test, even if it is something trivial. – Blrfl Mar 11 '15 at 13:23
  • @Blrfl I think you are talking about debugging via logging, I absolutely don't want. The aspect is about monitoring the application INFO - EMERGENCY, not DEBUG. Because of that logging is not part of the non-functional requirements, I don't want to treat it in another way. For example I want to log when customers log in. If I solve it with a 'lastLogin' field in the database, I don't expect the solution to be much different than logging to another logger which writes it via logstash to the elastic search and I can analyze the statistics with kibana. Wouldn't you also call it logging? – Aitch Mar 11 '15 at 14:10
  • 4
    @Aitch To answer your question about unit testing: `Do you mock the logger?`, that is PRECISELY what you do. You should have an `ILogger` interface that defines WHAT the logger does. The code under test gets injected with an `ILogger` that you specify. For testing, you have `class TestLogger : ILogger`. The great thing about this is the `TestLogger` can expose things like the last string or error logged. The tests can verify that the code under test is logging correctly. For example, a test could be `UserSignInTimeGetsLogged()`, where the test checks `TestLogger` for the logged. – CurtisHx Mar 11 '15 at 19:41
  • 5
    99% seems a bit low. You're probably better than 100% of all programmers. – Paul Draper Mar 11 '15 at 21:21
  • 3
    +1 for sanity. We need more of this kind of thinking: less focus on words and abstract principles and more focus on *having a maintainable code base*. – jpmc26 Mar 12 '15 at 06:42
  • "having clean code and some small violations is the one hand, and on the other hand is boilerplate code in the tests. Every logger dependency means one additional ctor parameter to me." @Aitch You're going overboard with tests and probably doing too much mocking. Stop. Your tests will become an unmaintainable mess that are actually a detriment to your project. I have seen it happen. Think more about what tests provide *real* value. Blindly testing everything with *not* improve reliability or the design. Unit tests should be *simple*; they're best suited for input/output testing. – jpmc26 Mar 12 '15 at 06:53
  • The point of SRP is abstraction and composability, separating concerns to be able to interchange them. Saying that prevents code from being spaghetti code is a bit far-fetched. You can respect SRP in every class and yet have horrendous composition code. That's why your saying "If your code is tidy enough". – Laurent LA RIZZA Mar 12 '15 at 08:58
  • 1
    @LaurentLARIZZA This answer is only discussing the reason for which SRP became a guideline in the first place. If you think this answer is claiming that following SRP blindly will magically result in wonderful code, then you have completely missed the point of the answer. – jpmc26 Mar 12 '15 at 18:15
  • @jpmc26 I'm with you and I'm not trying to enforce 100% test coverage. I sometimes skip logging tests and I skip the tests where I retrieve data from the database. Because of this it's important for me to keep those ccc code away from functional part I really want to test. – Aitch Mar 13 '15 at 00:45
  • @CurtisHx same here: a component doing something and logging means a test if it does something and if it logs. Than SRP hits you twice ;) – Aitch Mar 13 '15 at 00:50
  • I meant 'non-ccc logging code' above and can't edit it anymore, sorry. – Aitch Mar 13 '15 at 01:30
  • @jpmc26: Fair enough, then. – Laurent LA RIZZA Mar 13 '15 at 08:54
  • I'm still getting upvotes for my question and 7yr later (or earlier) I agree with this answer and making it also the accepted answer. We should not make things more complicated than they have to, not even use DI for a logger. thank you – Aitch Mar 21 '22 at 19:53
20

No, it is not a violation of SRP.

The messages you send to the log should change for the same reasons as the surrounding code.

What IS a violation of SRP is using a specific library for logging directly in the code. If you decide to change the way of logging, SRP states that it should not impact your business code.

Some kind of abstract Logger should be accessible to your implementation code, and the only thing your implementation should say is "Send this message to the log", with no concerns wrt how it's done. Deciding about the exact way of logging (even timestamping) is not your implementation's responsibility.

Your implementation then should also not know whether the logger it is sending messages to is a NullLogger.

That said.

I would not brush logging away as a cross-cutting concern too fast. Emitting logs to trace specific events occurring in your implementation code belongs to the implementation code.

What is a cross-cutting concern, OTOH, is execution tracing: logging enters and exits in each and every method. AOP is best placed to do this.

  • Let's say the logger message is 'login user xyz', which is sent to a logger which prepends a timestamp etc. Do you know what 'login' means to the implementation? Is it starting a session with a cookie or any other mechanism? I think there are many different ways to implement a login, thus change the implementation has logically nothing to do with the fact that a user logs in. That's another great example of decorating different components (say OAuthLogin, SessionLogin, BasicAuthorizationLogin) doing the same thing as a `Login`-interface decorated with the same logger. – Aitch Mar 13 '15 at 01:12
  • It depends what the message "login user xyz" means. If it marks the fact that a login is successful, the sending of the message to the log belongs in the login use case. The specific way to represent the login information as a string (OAuth, Session, LDAP, NTLM, fingerprint, hamster wheel) belongs in the specific class representing the credentials or the login strategy. There is no compelling need to remove it. This sepcific case is not a cross-cutting concern. It is specific to the login use case. – Laurent LA RIZZA Mar 13 '15 at 08:31
7

As logging is often considered a cross-cutting concern I'd suggest using AOP for separating logging from implementation.

Depending on the language you'd use an interceptor or some AOP framework (e.g. AspectJ in Java) to perform this.

The question is if this is actually worth the hassle. Note that this separation will increase the complexity of your project while providing very little benefit.

Oliver Weiler
  • 2,448
  • 19
  • 28
  • 2
    Most of the AOP code I saw was about logging every entering and exit step of every method. I only want to log some business logic parts. So maybe it's possible to log only annotated methods, but AOP at all can only exists in scripting languages and virtual machine environments, right? In e.g. C++ it's impossible. I admit that I'm not very happy with AOP approaches, but maybe there is no cleaner solution. – Aitch Mar 11 '15 at 11:39
  • 1
    @Aitch. "C++ it's impossible." : If you google for "aop c++" you will find articles about it. "...the AOP code I saw was about logging every entering and exit step of every method. I only want to log some business logic parts." Aop allows you define patterns to find the methods to modify. i.e. all methods from namespace "my.busininess.*" – k3b Mar 11 '15 at 12:13
  • 1
    Logging is often NOT a cross-cutting concern, especially when you want your log to contain interesting information, i.e. more information than is contained in an exception stack trace. – Laurent LA RIZZA Mar 12 '15 at 08:46
6

This sounds fine. You're describing a fairly standard logging decorator. You have:

component L (logging component of the system)

This has one responsibility: logging information that is passed to it.

component A implements I

This has one responsibility: providing an implementation of interface I (assuming I is properly SRP-compliant, that is).

This is the crucial part:

component D implements I, decorates/uses A, uses L for logging

When stated that way, it sounds complex, but look at it this way: Component D does one thing: bringing A and L together.

  • Component D does not log; it delegates that to L
  • Component D does not implement I itself; it delegates that to A

The only responsibility that component D has is to make sure that L is notified when A is used. The implementations of A and L are both elsewhere. This is completely SRP-compliant, as well as being a neat example of OCP and a pretty commonplace use of decorators.

An important caveat: when D uses your logging component L, it should do so in a way that lets you change how you're logging. The simplest way to do this is to have an interface IL that is implemented by L. Then:

  • Component D uses an IL to log; an instance of L is provided
  • Component D uses an I to provide functionality; an instance of A is provided
  • Component B uses an I; an instance of D is provided

That way, nothing depends directly on anything else, making it easy to swap them out. This makes it easy to adapt to change, and easy to mock parts of the system so you can unit test.

anaximander
  • 2,285
  • 3
  • 19
  • 21
  • I actually only know C# which has native delegation support. That's why I wrote `D implements I`. Thank you for your answer. – Aitch Mar 11 '15 at 17:07
0

Of course it's a violation of SRP as you have a cross cutting concern. You can however create a class that is responsible for composing the logging with execution of any action.

example:

class Logger {
   ActuallLogger logger;
   public Action ComposeLog(string msg, Action action) {
      return () => {
          logger.debug(msg);
          action();
      };
   }
}
Paul Nikonowicz
  • 445
  • 4
  • 9
  • 3
    Downvoted. Logging is a cross-cutting concern indeed. So is sequencing method calls in your code. That's not reason enough to claim a violation of SRP. Logging the occurrence of a specific event in your application is NOT a cross-cutting concern. The WAY these messages get carried to any interested user is indeed a separate concern, and describing this in the implementation code IS a violation of SRP. – Laurent LA RIZZA Mar 12 '15 at 08:53
  • "sequencing method calls" or functional composition is not a cross cutting concern but rather an implementation detail. The responsibility of the function I created is to compose a log statement, with an action. I do not need to use the word "and" to describe what this function does. – Paul Nikonowicz Mar 12 '15 at 17:45
  • It's not an implementation detail. It has a profound effect on the shape of your code. – Laurent LA RIZZA Mar 13 '15 at 08:49
  • I think that I am looking at SRP from the perspective of "WHAT does this function do" where as you are looking at SRP from the perspective of "HOW does this function do it". – Paul Nikonowicz Mar 13 '15 at 17:19
-4

Yes it is a violation of SRP as logging is a cross cutting concern.

The correct way is to delegate logging to a logger class (Interception) which sole purpose is to log - abiding by the SRP.

See this link for a good example: https://msdn.microsoft.com/en-us/library/dn178467%28v=pandp.30%29.aspx

Here is a short example:

public interface ITenantStore
{
    Tenant GetTenant(string tenant);
    void SaveTenant(Tenant tenant);
}

public class TenantStore : ITenantStore
{
    public Tenant GetTenant(string tenant)
    {....}

    public void SaveTenant(Tenant tenant)
    {....}
} 

public class TenantStoreLogger : ITenantStore
{
    private readonly ILogger _logger; //dep inj
    private readonly ITenantStore _tenantStore;

    public TenantStoreLogger(ITenantStore tenantStore)
    {
        _tenantStore = tenantStore;
    }

    public Tenant GetTenant(string tenant)
    {
        _logger.Log("reading tenant " + tenant.id);
        return _tenantStore.GetTenant(tenant);
    }

    public void SaveTenant(Tenant tenant)
    {
        _tenantStore.SaveTenant(tenant);
        _logger.Log("saving tenant " + tenant.id);
    }
}

Benefits include

  • You can test this without logging - true unit testing
  • you can easily toggle logging on / off - even at runtime
  • you can substitute logging for other forms of logging, without ever having to change the TenantStore file.
z0mbi3
  • 390
  • 2
  • 8
  • Thank you for the nice link. Figure 1 on that page is actually what I would call my favorite solution. The list of cross cutting concerns (logging, caching, etc.) and a decorator pattern is the most generic solution and I'm happy not to be completely wrong with my thoughts, although the larger community would like to drop that abstraction and inline logging. – Aitch Mar 11 '15 at 17:35
  • 2
    I don't see you assigning the _logger variable anywhere. Were you planning on using constructor injection and just forgot? If so, you'd probably get a compiler warning. – user2023861 Mar 11 '15 at 18:05
  • 31
    Instead of TenantStore being DIPed with a general purpose Logger, which requires N+1 classes (when you add a LandlordStore, a FooStore, a BarStore, etc.) you have a TenantStoreLogger being DIPed with a TenantStore, a FooStoreLogger being DIPed with a FooStore, etc... requiring 2N classes. As far as I can tell, for **zero benefit.** When you want to do no-logging unit testing, you'll need to rejigger N classes, instead of just configuring a NullLogger. IMO, this is a very poor approach. – user949300 Mar 11 '15 at 19:19
  • 7
    Doing this for every single class that needs logging drastically increases the complexity of your code base (unless so few classes have logging that you wouldn't even call it a cross cutting concern anymore). It ultimately makes the code *less* maintainable simply because of the large number of interfaces to maintain, which goes against everything the Single Responsibility Principle was created for. – jpmc26 Mar 12 '15 at 06:47
  • 12
    Downvoted. You removed the logging concern from the Tenant class, but now your `TenantStoreLogger` will change every time `TenantStore` changes. You're not separating concerns any more than in the initial solution. – Laurent LA RIZZA Mar 12 '15 at 08:14
  • @user2023861 I'm not familiar with C# but also Java EE allows DI to private attributes. just ignore it. it's the same as passing it as an ctor parameter. – Aitch Mar 12 '15 at 23:57
  • @user949300 you didn't get the idea of decorating an `ITenantStore`, see the ctor `TenantStoreLogger(ITenantStore tenantStore)`. why 2N classes? – Aitch Mar 13 '15 at 00:04
  • @jpmc26 also the question about what logging means to you. I don't want to debug my application. I want to known what happens on a business level. Not every component is interesting to me like reading from a database which happens with every server request. – Aitch Mar 13 '15 at 00:10
  • @LaurentLARIZZA that's completely wrong, since the logger does not depend on the store implementation. – Aitch Mar 13 '15 at 00:17
  • 1
    @Aitch: It does. You have the same set of methods in both classes. Add a method in le implementation class, and you have to add one in the logger, or you lose one line of log. It's not a dependency that prevents you to compile, but a dependency nonetheless. My definition of dependencies is: *A depends on B whenever a change in B induces a change in A. The first change you'll make if you want to add functionality to `TenantStore` is add a method. You then have to publish it through the `ITenantStore`, forcing an implementation in `TenantStoreLogger`. – Laurent LA RIZZA Mar 13 '15 at 08:38
  • @Aitech: Effectively, it just means that `ITenantStore` is not a stable abstraction. It effectively depends on `TenantStore`, even though you applied DIP. – Laurent LA RIZZA Mar 13 '15 at 08:43
  • This is what we call Design pattern happy. Right? ;) – Samuel Mar 17 '15 at 23:43
  • The fact it requires twice as many classes is a failure of the language, not the code given here, which is very pure and correct way to do this in OOP. If someone *seriously* wants logging for every class (And normally you'd just want it around logic that causes side effects, which shouldn't be many if you have clear and well defined boundaries) then AOP would be a better approach to solve this issue without breaking SRP if supported. Luckily it's supported by most languages either natively or with a library now. – ZombieTfk Sep 28 '21 at 23:29