Logging Custom Script Output to Files

[nordicmachine]

I've been trying to figure out how to log the log messages from custom scripts to a file and not having much success. Hoping someone can point me in the right direction.

I have a really simple custom script (wrote for testing this functionality):

""" Netbox Scripts - Example Script - exscript.py """
from extras.scripts import Script  # pylint: disable=import-error

class ExampleScript(Script):
   def run(self, data, commit):
       self.log_info("Hello World")

I then edited my configuration.py as follows:

# Enable custom logging. Please see the Django documentation for detailed guidance on configuring custom logs:
#   https://docs.djangoproject.com/en/stable/topics/logging/
#LOGGING = {}
LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'normal': {
            'format': '%(asctime)s %(name)s %(levelname)s: %(message)s'
        },
    },
    'handlers': {
        'file': {
            'level': 'DEBUG',
            'class': 'logging.FileHandler',
            'filename': '/opt/netbox/netbox.log',
            'formatter': 'normal',
        },
    },
    'loggers': {
        'netbox.scripts.exscript': {
            'handlers': ['file'],
            'level': 'DEBUG',
        },
    },
}

When I run my custom script from the UI, I see INFO level log message in the UI, but nothing ever gets written to the file. The file does get created and gunicorn restarts cleanly. I've tried many variations for the name to put in the loggers configuration, but nothing works. To verify that this logging setup works at all, I did try logging the logger netbox and djanjgo and those work, so it seems to be something around the script logging itself.

Any help would be greatly appreciated!

[mtinberg]

I may be way off base and I didn't search through the source code to check, but I don't think Script logging/messages have anything to do with Python/Django logging, they are messages stored with the job and organized as log types so audit scripts can report success/failure/warning/info data in a familiar way. You can pull the data from previous jobs using the REST API in /api/extras/job-results/${jobid}/ if you want to log it or integrate it elsewhere. — Mark Tinberg ***@***.***> Division of Information Technology-Network Services University of Wisconsin-Madison

…

________________________________ From: Adam Baker ***@***.***> Sent: Thursday, June 15, 2023 7:07 AM To: netbox-community/netbox ***@***.***> Cc: Subscribed ***@***.***> Subject: [netbox-community/netbox] Logging Custom Script Output to Files (Discussion #12913) I've been trying to figure out how to log the log messages from custom scripts to a file and not having much success. Hoping someone can point me in the right direction. I have a really simple custom script (wrote for testing this functionality): """ Netbox Scripts - Example Script - exscript.py """ from extras.scripts import Script # pylint: disable=import-error class ExampleScript(Script): def run(self, data, commit): self.log_info("Hello World") I then edited my configuration.py as follows: # Enable custom logging. Please see the Django documentation for detailed guidance on configuring custom logs: # https://docs.djangoproject.com/en/stable/topics/logging/ #LOGGING = {} LOGGING = { 'version': 1, 'disable_existing_loggers': False, 'formatters': { 'normal': { 'format': '%(asctime)s %(name)s %(levelname)s: %(message)s' }, }, 'handlers': { 'file': { 'level': 'DEBUG', 'class': 'logging.FileHandler', 'filename': '/opt/netbox/netbox.log', 'formatter': 'normal', }, }, 'loggers': { 'netbox.scripts.exscript': { 'handlers': ['file'], 'level': 'DEBUG', }, }, } When I run my custom script from the UI, I see INFO level log message in the UI, but nothing ever gets written to the file. The file does get created and gunicorn restarts cleanly. I've tried many variations for the name to put in the loggers configuration, but nothing works. To verify that this logging setup works at all, I did try logging the logger netbox and djanjgo and those work, so it seems to be something around the script logging itself. Any help would be greatly appreciated! — Reply to this email directly, view it on GitHub<#12913>, or unsubscribe<https://github.com/notifications/unsubscribe-auth/AAS7UM5TNS3OFKVEW3IZQT3XLL3JLANCNFSM6AAAAAAZHX4LGY>. You are receiving this because you are subscribed to this thread.Message ID: ***@***.***>

[nordicmachine]

You could be completely correct here. I didn't dig into the code either. I was basing my assumption on the list of available loggers detailed on the LOGGING Configuration

[mtinberg]

Well this is run by python logging and is available to be logged to any destination that the logging module supports, you learn something new every day. I set this up in my test lab with a test report and it does work I have a test report something like this (lightly edited) ```python # test_report.py from extras.report import Report class TestReport(Report): description = "A test" def test_a_thing(self): self.log("just a message") self.log_success(self, "yay") self.log_failure(self, "oh no") ``` And my logging config (which is in JSON from my config management system) ```json { "version": 1, "disable_existing_loggers": false, "handlers": { "syslog": { "class": "logging.handlers.SysLogHandler", "level": "DEBUG", "address": "/dev/log" }, "console": { "class": "logging.StreamHandler" } }, "loggers": { "django": { "handlers": [ "syslog" ], "level": "WARN" }, "netbox.reports.test_report.TestReport": { "handlers": [ "syslog" ], "level": "DEBUG" } } } ``` Which logged the following sudo journalctl -f -u netbox -u netbox-rqworker​ ``` Jun 16 09:52:06 testweb1 python[29030]: Running report Jun 16 09:52:06 testweb1 python[29030]: just a message Jun 16 09:52:06 testweb1 python[29030]: Success | <test_report.TestReport object at 0x7f2c3ec93820>: yay Jun 16 09:52:06 testweb1 python[29030]: Failure | <test_report.TestReport object at 0x7f2c3ec93820>: oh no Jun 16 09:52:06 testweb1 python[29030]: Report failed ``` — Mark Tinberg ***@***.***> Division of Information Technology-Network Services University of Wisconsin-Madison

…

________________________________ From: Adam Baker ***@***.***> Sent: Friday, June 16, 2023 7:40 AM To: netbox-community/netbox ***@***.***> Cc: Mark Tinberg ***@***.***>; Comment ***@***.***> Subject: Re: [netbox-community/netbox] Logging Custom Script Output to Files (Discussion #12913) You could be completely correct here. I didn't dig into the code either. I was basing my assumption on the list of available loggers detailed on the LOGGING Configuration<https://demo.netbox.dev/static/docs/configuration/optional-settings/#logging> — Reply to this email directly, view it on GitHub<#12913 (reply in thread)>, or unsubscribe<https://github.com/notifications/unsubscribe-auth/AAS7UM4AKO4KTCQIQQKFZJTXLRH45ANCNFSM6AAAAAAZHX4LGY>. You are receiving this because you commented.Message ID: ***@***.***>

[mtinberg]

I think this is what you probably need

    'loggers': {
        'netbox.scripts.exscript.ExampleScript': {
            'handlers': ['file'],
            'level': 'DEBUG',
        },
    },

[nordicmachine]

@mtinberg thank you so much for your example and the correction on my logger. I finally got back to looking at this and it was your journalctl command that finally tipped me off to my mistake. I was restarting the main gunicorn process that runs netbox after making the config change.... I should have restarted rq-worker since it's what actually executes the scripts/reports. Once I did that things started working. Funny the little things ones misses.

Thanks again for your help!