Clean Code, step down rule and SRP I am currently reading Uncle Bob's Clean Code and wonder what would be the "cleaner" implementation of the following:

Let's say I want to implement a HTTPRequest class which handles the execution of (well, obviously) http requests. 

This was my initial implementation:

class HTTPRequest(object):
    def __init__(self, url, method, **kwds):
        self.logger = logging.getLogger(__name__)
        self.url = url
        self.method = method
        self.request_kwds = kwds
        self.execution_time_seconds = 0.0
        self.response = None
        self.logger.debug("Created instance %s" % self)

    def execute(self):
        self.logger.debug("%s starting request" % self)
        start_time = time.time()
        self.response = HTTPResponse(
            request=self,
            request_response=requests.request(url=self.url, method=self.method, **self.request_kwds)
        )
        self.execution_time_seconds = time.time() - start_time
        self.logger.debug(
            "%s received response %s after %.4f seconds" % (self, self.response, self.execution_time_seconds)
        )
        self.response.raise_for_status()
        return self.response


The execute method currently does two things: issuing the request and capturing the response, and measuring the execution time. 
So first of all, this would be a violation of the Single Responsibility Principle.
Furthermore, it is very detailed and on a low level of abstraction. 

Now, I could split this up in different sub methods, like this:

class HTTPRequest(object):
    def __init__(self, url, method, **kwds):
        self.logger = logging.getLogger(__name__)
        self.url = url
        self.method = method
        self.request_kwds = kwds
        self._start_time = 0
        self.execution_time_seconds = 0.0
        self.response = None
        self.logger.debug("Created instance %s" % self)

    def execute(self):
        self.logger.debug("%s starting request" % self)
        self._start_time_measurement()
        self._execute_request()
        self._stop_time_measurement()
        self.logger.debug(
            "%s received response %s after %.4f seconds" % (self, self.response, self.execution_time_seconds)
        )
        return self.response

    def _start_time_measurement(self):
        self._start_time = time.time()

    def _execute_request(self):
        self.response = HTTPResponse(
            request=self,
            request_response=requests.request(url=self.url, method=self.method, **self.request_kwds)
        )
        self.response.raise_for_status()

    def _stop_time_measurement(self):
        self.execution_time_seconds = time.time() - self._start_time


Besides having separated the logic of time measurement and request execution, from what I've read so far this version should be considered "cleaner". 

But I have two concerns about it:


This class is still extremely simple. This refactoring made it significantly longer (replacing two single line statements with a call to a function which takes up two lines (+1 for spacing). Doing this kind of refactoring to a "real" class with a lot of business logic could blow it up indefinitely (which is then again considered "unclean")
The original version was - in my eyes - already readable enough, as it used intention-revealing names for the variables, making it clear that there is some kind of time measurement going on during the request.


So the question is:
which version do you prefer, and why? How much extraction of logic into sub methods is too much?



For the sake of completeness, here is a (stripped down version of) the HTTPResponse class and necessary imports to make the code executable:

import time
import logging

import requests

class HTTPResponse(object):
    def __init__(self, request, request_response):
        self.request = request
        self._response = request_response

    def raise_for_status(self):
        self._response.raise_for_status()


class HTTPRequest(object):
    # one of the two versions from above
Whether it makes sense to break this up is somewhat contextually dependent on whether you anticipate reusing this pattern elsewhere, IMO.  If it's a one-off it might be cleaner to simply do it in-place as in your first example; I don't think the second example is particularly easier to follow, since your execute method still contains a lot of logging-related code either way, and it has the undesirable side effect of adding more state to your object that could otherwise be locally scoped.

However, if you do plan on reusing this logging logic, a neat way to separate its implementation details from the function that you're trying to log is putting it in a decorator:

import functools


def logged(logger_name):
    logger = logging.getLogger(logger_name)

    def decorator(func):
        @functools.wraps(func)
        def wrapped_func(self, *args, **kwargs):
            start_time = time.time()
            logger.debug("%s starting execution" % self)
            ret = func(self, *args, **kwargs)
            exec_time = time.time() - start_time
            logger.debug(
                "%s returned %s after %.4f seconds" % (self, ret, exec_time)
            )
            return ret
        return wrapped_func
    return decorator


class HTTPRequest(object):
    def __init__(self, url, method, **kwds):
        self.logger = logging.getLogger(__name__)
        self.url = url
        self.method = method
        self.request_kwds = kwds
        self.logger.debug("Created instance %s" % self)

    @logged(__name__)
    def execute(self):
        response = HTTPResponse(
            request=self,
            request_response=requests.request(
                url=self.url,
                method=self.method,
                **self.request_kwds
            )
        )
        response.raise_for_status()
        return response


Now all of the logging logic is completely removed from the body of execute, and it lives in that one little @logged decoration, which you can reuse with any other method on any other object (note that the decorator is written to assume it's being applied to an instance method, because it uses a self parameter in its logging).  Note that it always measures the overall execution time of the decorated function starting before it's called and ending after it returns (I'm not sure if raise_for_status() blocks long enough for it to make a meaningful difference that the stopwatch ends after you return the response rather than after you create it).

There are a lot of potential further directions to take this -- for example, you could create a logging superclass/mixin that also encapsulates the logging in __init__, or that handles logging-related state that needs to persist in between method calls (e.g. if you want to do any sort of aggregation), and thereby have the ability to make your logging significantly more sophisticated without exposing any of that complexity in the rest of your code.  So this approach scales in lots of interesting ways, but again, whether it's worthwhile depends on whether you actually need that scaling.

Making all these things work in a thoroughly typesafe way is also doable but adds a decent amount of complexity that I won't even go into here.

A simpler approach that's less extensible but sticks a lot closer to your original implementation while still getting most of the code out of execute would be to use a higher order function within the class (similar to the decorator approach but with less magic):

class HTTPRequest(object):
    def __init__(self, url, method, **kwds):
        self.logger = logging.getLogger(__name__)
        self.url = url
        self.method = method
        self.request_kwds = kwds
        self.logger.debug("Created instance %s" % self)

    def measure_request_time(self, func, *args, **kwargs):
        self.logger.debug("%s starting request" % self)
        start_time = time.time()
        ret = func(*args, **kwargs)
        self.execution_time_seconds = time.time() - start_time
        self.logger.debug(
            "%s received response %s after %.4f seconds"
            % (self, ret, self.execution_time_seconds)
        )
        return ret

    def execute(self):
        self.response = measure_request_time(
            HTTPResponse,
            request=self,
            request_response=requests.request(
                url=self.url,
                method=self.method,
                **self.request_kwds
            )
        )
        self.response.raise_for_status()
        return self.response