How to make logging decorator log the filename where it's used and not where it is defined?












2















I use the logging module with the filename format to capture the log output of my code. This works fine, since now I always know from which file the message was sent. However, I have an indent logging decorator for which I would like to actually log the filename where it is used and not the module where the decorator is defined. Is this possible?



Here is a short example of what it is doing now:



test.py



import logging
from log import logger
from log import indented

@indented('Here I start my method...', 'And here it ends')
def my_func():
logger.info('Look, a message!')


if __name__ == '__main__':
logging.basicConfig(
filename='LOG',
level=logging.DEBUG,
format='%(asctime)s.%(msecs)03d [ %(levelname)-8s] %(filename)s: %(message)s',
datefmt="%Y-%m-%d %H:%M:%S")
my_func()


Log output



2018-07-27 13:27:15.541 [ INFO    ] log.py: Here I start my method...
2018-07-27 13:27:15.541 [ INFO ] test.py: ---- Look, a message!
2018-07-27 13:27:15.541 [ INFO ] log.py: And here it ends


Now I would like all three messages to contain test.py like so:



Desired output



2018-07-27 13:27:15.541 [ INFO    ] test.py: Here I start my method...
2018-07-27 13:27:15.541 [ INFO ] test.py: ---- Look, a message!
2018-07-27 13:27:15.541 [ INFO ] test.py: And here it ends


log.py



import logging
from contextlib import contextmanager
from functools import wraps


class IndentationAdapter(logging.LoggerAdapter):
def __init__(self, logger, extra):
super().__init__(logger, extra)
self._indent = 0

def indent(self):
self._indent += 4

def dedent(self):
self._indent -= 4

def process(self, msg, kwargs):
if self._indent > 0:
return '{i} {m}'.format(i='-'*self._indent, m=msg), kwargs
else:
return msg, kwargs

logger = IndentationAdapter(logging.getLogger(), {})

@contextmanager
def indent_logging():
logger.indent()
try:
yield
finally:
logger.dedent()


def indented(begin_message, end_message):
def indent_decorator(func):
@wraps(func)
def func_wrapper(*args, **kwargs):
logger.info(begin_message)
with indent_logging():
output = func(*args, **kwargs)
logger.info(end_message)

return output

return func_wrapper
return indent_decorator









share|improve this question

























  • I noticed that in c:Python36Liblogging_init_.py it gets the filename from directly inspecting the stack in "findCaller" and it finds the first thing not in that file. Changing the logging module itself is right out, so I'm stuck there at the moment, and about to go to bed. The call through the adaptor happens in log.py but it finds test.py anyway. There might be a work-around defining your own format variable and pass it in extra.

    – Kenny Ostrom
    Dec 31 '18 at 5:27











  • incidentally, I found it easier to use stream=sys.stdout while debugging

    – Kenny Ostrom
    Dec 31 '18 at 5:29
















2















I use the logging module with the filename format to capture the log output of my code. This works fine, since now I always know from which file the message was sent. However, I have an indent logging decorator for which I would like to actually log the filename where it is used and not the module where the decorator is defined. Is this possible?



Here is a short example of what it is doing now:



test.py



import logging
from log import logger
from log import indented

@indented('Here I start my method...', 'And here it ends')
def my_func():
logger.info('Look, a message!')


if __name__ == '__main__':
logging.basicConfig(
filename='LOG',
level=logging.DEBUG,
format='%(asctime)s.%(msecs)03d [ %(levelname)-8s] %(filename)s: %(message)s',
datefmt="%Y-%m-%d %H:%M:%S")
my_func()


Log output



2018-07-27 13:27:15.541 [ INFO    ] log.py: Here I start my method...
2018-07-27 13:27:15.541 [ INFO ] test.py: ---- Look, a message!
2018-07-27 13:27:15.541 [ INFO ] log.py: And here it ends


Now I would like all three messages to contain test.py like so:



Desired output



2018-07-27 13:27:15.541 [ INFO    ] test.py: Here I start my method...
2018-07-27 13:27:15.541 [ INFO ] test.py: ---- Look, a message!
2018-07-27 13:27:15.541 [ INFO ] test.py: And here it ends


log.py



import logging
from contextlib import contextmanager
from functools import wraps


class IndentationAdapter(logging.LoggerAdapter):
def __init__(self, logger, extra):
super().__init__(logger, extra)
self._indent = 0

def indent(self):
self._indent += 4

def dedent(self):
self._indent -= 4

def process(self, msg, kwargs):
if self._indent > 0:
return '{i} {m}'.format(i='-'*self._indent, m=msg), kwargs
else:
return msg, kwargs

logger = IndentationAdapter(logging.getLogger(), {})

@contextmanager
def indent_logging():
logger.indent()
try:
yield
finally:
logger.dedent()


def indented(begin_message, end_message):
def indent_decorator(func):
@wraps(func)
def func_wrapper(*args, **kwargs):
logger.info(begin_message)
with indent_logging():
output = func(*args, **kwargs)
logger.info(end_message)

return output

return func_wrapper
return indent_decorator









share|improve this question

























  • I noticed that in c:Python36Liblogging_init_.py it gets the filename from directly inspecting the stack in "findCaller" and it finds the first thing not in that file. Changing the logging module itself is right out, so I'm stuck there at the moment, and about to go to bed. The call through the adaptor happens in log.py but it finds test.py anyway. There might be a work-around defining your own format variable and pass it in extra.

    – Kenny Ostrom
    Dec 31 '18 at 5:27











  • incidentally, I found it easier to use stream=sys.stdout while debugging

    – Kenny Ostrom
    Dec 31 '18 at 5:29














2












2








2


2






I use the logging module with the filename format to capture the log output of my code. This works fine, since now I always know from which file the message was sent. However, I have an indent logging decorator for which I would like to actually log the filename where it is used and not the module where the decorator is defined. Is this possible?



Here is a short example of what it is doing now:



test.py



import logging
from log import logger
from log import indented

@indented('Here I start my method...', 'And here it ends')
def my_func():
logger.info('Look, a message!')


if __name__ == '__main__':
logging.basicConfig(
filename='LOG',
level=logging.DEBUG,
format='%(asctime)s.%(msecs)03d [ %(levelname)-8s] %(filename)s: %(message)s',
datefmt="%Y-%m-%d %H:%M:%S")
my_func()


Log output



2018-07-27 13:27:15.541 [ INFO    ] log.py: Here I start my method...
2018-07-27 13:27:15.541 [ INFO ] test.py: ---- Look, a message!
2018-07-27 13:27:15.541 [ INFO ] log.py: And here it ends


Now I would like all three messages to contain test.py like so:



Desired output



2018-07-27 13:27:15.541 [ INFO    ] test.py: Here I start my method...
2018-07-27 13:27:15.541 [ INFO ] test.py: ---- Look, a message!
2018-07-27 13:27:15.541 [ INFO ] test.py: And here it ends


log.py



import logging
from contextlib import contextmanager
from functools import wraps


class IndentationAdapter(logging.LoggerAdapter):
def __init__(self, logger, extra):
super().__init__(logger, extra)
self._indent = 0

def indent(self):
self._indent += 4

def dedent(self):
self._indent -= 4

def process(self, msg, kwargs):
if self._indent > 0:
return '{i} {m}'.format(i='-'*self._indent, m=msg), kwargs
else:
return msg, kwargs

logger = IndentationAdapter(logging.getLogger(), {})

@contextmanager
def indent_logging():
logger.indent()
try:
yield
finally:
logger.dedent()


def indented(begin_message, end_message):
def indent_decorator(func):
@wraps(func)
def func_wrapper(*args, **kwargs):
logger.info(begin_message)
with indent_logging():
output = func(*args, **kwargs)
logger.info(end_message)

return output

return func_wrapper
return indent_decorator









share|improve this question
















I use the logging module with the filename format to capture the log output of my code. This works fine, since now I always know from which file the message was sent. However, I have an indent logging decorator for which I would like to actually log the filename where it is used and not the module where the decorator is defined. Is this possible?



Here is a short example of what it is doing now:



test.py



import logging
from log import logger
from log import indented

@indented('Here I start my method...', 'And here it ends')
def my_func():
logger.info('Look, a message!')


if __name__ == '__main__':
logging.basicConfig(
filename='LOG',
level=logging.DEBUG,
format='%(asctime)s.%(msecs)03d [ %(levelname)-8s] %(filename)s: %(message)s',
datefmt="%Y-%m-%d %H:%M:%S")
my_func()


Log output



2018-07-27 13:27:15.541 [ INFO    ] log.py: Here I start my method...
2018-07-27 13:27:15.541 [ INFO ] test.py: ---- Look, a message!
2018-07-27 13:27:15.541 [ INFO ] log.py: And here it ends


Now I would like all three messages to contain test.py like so:



Desired output



2018-07-27 13:27:15.541 [ INFO    ] test.py: Here I start my method...
2018-07-27 13:27:15.541 [ INFO ] test.py: ---- Look, a message!
2018-07-27 13:27:15.541 [ INFO ] test.py: And here it ends


log.py



import logging
from contextlib import contextmanager
from functools import wraps


class IndentationAdapter(logging.LoggerAdapter):
def __init__(self, logger, extra):
super().__init__(logger, extra)
self._indent = 0

def indent(self):
self._indent += 4

def dedent(self):
self._indent -= 4

def process(self, msg, kwargs):
if self._indent > 0:
return '{i} {m}'.format(i='-'*self._indent, m=msg), kwargs
else:
return msg, kwargs

logger = IndentationAdapter(logging.getLogger(), {})

@contextmanager
def indent_logging():
logger.indent()
try:
yield
finally:
logger.dedent()


def indented(begin_message, end_message):
def indent_decorator(func):
@wraps(func)
def func_wrapper(*args, **kwargs):
logger.info(begin_message)
with indent_logging():
output = func(*args, **kwargs)
logger.info(end_message)

return output

return func_wrapper
return indent_decorator






python logging






share|improve this question















share|improve this question













share|improve this question




share|improve this question








edited Dec 30 '18 at 23:28







NOhs

















asked Jul 27 '18 at 11:45









NOhsNOhs

1,16511137




1,16511137













  • I noticed that in c:Python36Liblogging_init_.py it gets the filename from directly inspecting the stack in "findCaller" and it finds the first thing not in that file. Changing the logging module itself is right out, so I'm stuck there at the moment, and about to go to bed. The call through the adaptor happens in log.py but it finds test.py anyway. There might be a work-around defining your own format variable and pass it in extra.

    – Kenny Ostrom
    Dec 31 '18 at 5:27











  • incidentally, I found it easier to use stream=sys.stdout while debugging

    – Kenny Ostrom
    Dec 31 '18 at 5:29



















  • I noticed that in c:Python36Liblogging_init_.py it gets the filename from directly inspecting the stack in "findCaller" and it finds the first thing not in that file. Changing the logging module itself is right out, so I'm stuck there at the moment, and about to go to bed. The call through the adaptor happens in log.py but it finds test.py anyway. There might be a work-around defining your own format variable and pass it in extra.

    – Kenny Ostrom
    Dec 31 '18 at 5:27











  • incidentally, I found it easier to use stream=sys.stdout while debugging

    – Kenny Ostrom
    Dec 31 '18 at 5:29

















I noticed that in c:Python36Liblogging_init_.py it gets the filename from directly inspecting the stack in "findCaller" and it finds the first thing not in that file. Changing the logging module itself is right out, so I'm stuck there at the moment, and about to go to bed. The call through the adaptor happens in log.py but it finds test.py anyway. There might be a work-around defining your own format variable and pass it in extra.

– Kenny Ostrom
Dec 31 '18 at 5:27





I noticed that in c:Python36Liblogging_init_.py it gets the filename from directly inspecting the stack in "findCaller" and it finds the first thing not in that file. Changing the logging module itself is right out, so I'm stuck there at the moment, and about to go to bed. The call through the adaptor happens in log.py but it finds test.py anyway. There might be a work-around defining your own format variable and pass it in extra.

– Kenny Ostrom
Dec 31 '18 at 5:27













incidentally, I found it easier to use stream=sys.stdout while debugging

– Kenny Ostrom
Dec 31 '18 at 5:29





incidentally, I found it easier to use stream=sys.stdout while debugging

– Kenny Ostrom
Dec 31 '18 at 5:29












1 Answer
1






active

oldest

votes


















1














I was able to automate the filename and begin/end messages by copying some of the code inspection used by the standard library's logging module. I removed the manual begin and end messages, thinking this was more your intent. I also removed filename from the log format, and added it in the text logged by the indent_decorator.



    def indented():
def indent_decorator(func):
@wraps(func)
def func_wrapper(*args, **kwargs):
filename = os.path.basename(func.__code__.co_filename)
logger.info(filename + ': begin ' + func.__name__)
with indent_logging():
output = func(*args, **kwargs)
logger.info(filename + ': end ' + func.__name__)

return output

return func_wrapper
return indent_decorator


Here is the log output



2018-12-31 08:14:25.536 [ INFO    ] test.py: begin my_func
2018-12-31 08:14:25.536 [ INFO ] ---- Look, a message!
2018-12-31 08:14:25.536 [ INFO ] test.py: end my_func


I don't know how much we can rely on code staying the same in future versions of python, but this works for me in 3.6.5



I suspect that it should be further simplified so you don't have to put parens on the decorator, so that might be a later edit.






share|improve this answer























    Your Answer






    StackExchange.ifUsing("editor", function () {
    StackExchange.using("externalEditor", function () {
    StackExchange.using("snippets", function () {
    StackExchange.snippets.init();
    });
    });
    }, "code-snippets");

    StackExchange.ready(function() {
    var channelOptions = {
    tags: "".split(" "),
    id: "1"
    };
    initTagRenderer("".split(" "), "".split(" "), channelOptions);

    StackExchange.using("externalEditor", function() {
    // Have to fire editor after snippets, if snippets enabled
    if (StackExchange.settings.snippets.snippetsEnabled) {
    StackExchange.using("snippets", function() {
    createEditor();
    });
    }
    else {
    createEditor();
    }
    });

    function createEditor() {
    StackExchange.prepareEditor({
    heartbeatType: 'answer',
    autoActivateHeartbeat: false,
    convertImagesToLinks: true,
    noModals: true,
    showLowRepImageUploadWarning: true,
    reputationToPostImages: 10,
    bindNavPrevention: true,
    postfix: "",
    imageUploader: {
    brandingHtml: "Powered by u003ca class="icon-imgur-white" href="https://imgur.com/"u003eu003c/au003e",
    contentPolicyHtml: "User contributions licensed under u003ca href="https://creativecommons.org/licenses/by-sa/3.0/"u003ecc by-sa 3.0 with attribution requiredu003c/au003e u003ca href="https://stackoverflow.com/legal/content-policy"u003e(content policy)u003c/au003e",
    allowUrls: true
    },
    onDemand: true,
    discardSelector: ".discard-answer"
    ,immediatelyShowMarkdownHelp:true
    });


    }
    });














    draft saved

    draft discarded


















    StackExchange.ready(
    function () {
    StackExchange.openid.initPostLogin('.new-post-login', 'https%3a%2f%2fstackoverflow.com%2fquestions%2f51557273%2fhow-to-make-logging-decorator-log-the-filename-where-its-used-and-not-where-it%23new-answer', 'question_page');
    }
    );

    Post as a guest















    Required, but never shown

























    1 Answer
    1






    active

    oldest

    votes








    1 Answer
    1






    active

    oldest

    votes









    active

    oldest

    votes






    active

    oldest

    votes









    1














    I was able to automate the filename and begin/end messages by copying some of the code inspection used by the standard library's logging module. I removed the manual begin and end messages, thinking this was more your intent. I also removed filename from the log format, and added it in the text logged by the indent_decorator.



        def indented():
    def indent_decorator(func):
    @wraps(func)
    def func_wrapper(*args, **kwargs):
    filename = os.path.basename(func.__code__.co_filename)
    logger.info(filename + ': begin ' + func.__name__)
    with indent_logging():
    output = func(*args, **kwargs)
    logger.info(filename + ': end ' + func.__name__)

    return output

    return func_wrapper
    return indent_decorator


    Here is the log output



    2018-12-31 08:14:25.536 [ INFO    ] test.py: begin my_func
    2018-12-31 08:14:25.536 [ INFO ] ---- Look, a message!
    2018-12-31 08:14:25.536 [ INFO ] test.py: end my_func


    I don't know how much we can rely on code staying the same in future versions of python, but this works for me in 3.6.5



    I suspect that it should be further simplified so you don't have to put parens on the decorator, so that might be a later edit.






    share|improve this answer




























      1














      I was able to automate the filename and begin/end messages by copying some of the code inspection used by the standard library's logging module. I removed the manual begin and end messages, thinking this was more your intent. I also removed filename from the log format, and added it in the text logged by the indent_decorator.



          def indented():
      def indent_decorator(func):
      @wraps(func)
      def func_wrapper(*args, **kwargs):
      filename = os.path.basename(func.__code__.co_filename)
      logger.info(filename + ': begin ' + func.__name__)
      with indent_logging():
      output = func(*args, **kwargs)
      logger.info(filename + ': end ' + func.__name__)

      return output

      return func_wrapper
      return indent_decorator


      Here is the log output



      2018-12-31 08:14:25.536 [ INFO    ] test.py: begin my_func
      2018-12-31 08:14:25.536 [ INFO ] ---- Look, a message!
      2018-12-31 08:14:25.536 [ INFO ] test.py: end my_func


      I don't know how much we can rely on code staying the same in future versions of python, but this works for me in 3.6.5



      I suspect that it should be further simplified so you don't have to put parens on the decorator, so that might be a later edit.






      share|improve this answer


























        1












        1








        1







        I was able to automate the filename and begin/end messages by copying some of the code inspection used by the standard library's logging module. I removed the manual begin and end messages, thinking this was more your intent. I also removed filename from the log format, and added it in the text logged by the indent_decorator.



            def indented():
        def indent_decorator(func):
        @wraps(func)
        def func_wrapper(*args, **kwargs):
        filename = os.path.basename(func.__code__.co_filename)
        logger.info(filename + ': begin ' + func.__name__)
        with indent_logging():
        output = func(*args, **kwargs)
        logger.info(filename + ': end ' + func.__name__)

        return output

        return func_wrapper
        return indent_decorator


        Here is the log output



        2018-12-31 08:14:25.536 [ INFO    ] test.py: begin my_func
        2018-12-31 08:14:25.536 [ INFO ] ---- Look, a message!
        2018-12-31 08:14:25.536 [ INFO ] test.py: end my_func


        I don't know how much we can rely on code staying the same in future versions of python, but this works for me in 3.6.5



        I suspect that it should be further simplified so you don't have to put parens on the decorator, so that might be a later edit.






        share|improve this answer













        I was able to automate the filename and begin/end messages by copying some of the code inspection used by the standard library's logging module. I removed the manual begin and end messages, thinking this was more your intent. I also removed filename from the log format, and added it in the text logged by the indent_decorator.



            def indented():
        def indent_decorator(func):
        @wraps(func)
        def func_wrapper(*args, **kwargs):
        filename = os.path.basename(func.__code__.co_filename)
        logger.info(filename + ': begin ' + func.__name__)
        with indent_logging():
        output = func(*args, **kwargs)
        logger.info(filename + ': end ' + func.__name__)

        return output

        return func_wrapper
        return indent_decorator


        Here is the log output



        2018-12-31 08:14:25.536 [ INFO    ] test.py: begin my_func
        2018-12-31 08:14:25.536 [ INFO ] ---- Look, a message!
        2018-12-31 08:14:25.536 [ INFO ] test.py: end my_func


        I don't know how much we can rely on code staying the same in future versions of python, but this works for me in 3.6.5



        I suspect that it should be further simplified so you don't have to put parens on the decorator, so that might be a later edit.







        share|improve this answer












        share|improve this answer



        share|improve this answer










        answered Dec 31 '18 at 14:26









        Kenny OstromKenny Ostrom

        2,9251119




        2,9251119






























            draft saved

            draft discarded




















































            Thanks for contributing an answer to Stack Overflow!


            • Please be sure to answer the question. Provide details and share your research!

            But avoid



            • Asking for help, clarification, or responding to other answers.

            • Making statements based on opinion; back them up with references or personal experience.


            To learn more, see our tips on writing great answers.




            draft saved


            draft discarded














            StackExchange.ready(
            function () {
            StackExchange.openid.initPostLogin('.new-post-login', 'https%3a%2f%2fstackoverflow.com%2fquestions%2f51557273%2fhow-to-make-logging-decorator-log-the-filename-where-its-used-and-not-where-it%23new-answer', 'question_page');
            }
            );

            Post as a guest















            Required, but never shown





















































            Required, but never shown














            Required, but never shown












            Required, but never shown







            Required, but never shown

































            Required, but never shown














            Required, but never shown












            Required, but never shown







            Required, but never shown







            Popular posts from this blog

            Monofisismo

            Angular Downloading a file using contenturl with Basic Authentication

            Olmecas