Error logging only works when not inside of a function

[cpoetter]

Environment & Versions

• Operating system: Ubuntu 14.04.4 in Docker
• Python: 2.7
• Django: 1.10
• django-crontab: 0.7.1

Settings

• My django-crontab settings:

CRONJOBS = [
  ('*/1 * * * *', 'app.cron.run')
]

Details

I have the following 2 cron.py files:

import logging

logging.basicConfig()
logger = logging.getLogger(__name__)

def run():
    pass

raise ValueError('This error is reported.')

and

import logging

logging.basicConfig()
logger = logging.getLogger(__name__)

def run():
    raise ValueError('This error is NOT reported.')

The first snippet reports the error, the second one does not. I use Sentry for error logging. Do you have any idea, why that happens?

Thank you very much for your help!

[kraiz]

Hey, just a guess based on what i saw before in #31. When run() is executed triggered from cron the current working dir is maybe not set correctly. This can confuse the logging.

[cpoetter]

Hi @kraiz ,
thank you so much for this fast response. It's still confusing that it works in the first case then. So you think something like this

import os;
os.chdir('/path/to/working/dir');

should fix it? What do you think the directory should be? The directory of the app? I will try it directly tomorrow morning.

Best,
Chris

[kraiz]

Ah, just saw the logging config and thought there's a problem with it. rereaded it and you didnt see the raised error...try adding a suffix param to capture the output into a (absolutely referenced) file like in #61. This should provide further information and guide you.

[cpoetter]

I modified my settings.py to look like this now:

CRONJOBS = [
    ('*/1 * * * *', 'app.cron.run', '>> /tmp/stdout.log 2>> /tmp/stderr.log')
]

For the case that did NOT report any error, with the raise inside of the run function, the stderr.log contained the following:

ERROR:django_crontab.crontab:Failed to complete cronjob at ('*/1 * * * *', 'app.cron.run', '>> /tmp/stdout.log 2>> /tmp/stderr.log')
Traceback (most recent call last):
  File "/usr/local/lib/python2.7/dist-packages/django_crontab/crontab.py", line 145, in run_job
    func(*job_args, **job_kwargs)
  File "/code/ddp/app/cron.py", line 43, in run
    raise ValueError('This error is NOT reported.')
ValueError: This error is NOT reported.

For the other case, where the raise command is outside of the run function, which reports the error successfully, the stderr.log looks like this:

Traceback (most recent call last):
  File "/code/ddp/manage.py", line 10, in <module>
    execute_from_command_line(sys.argv)
  File "/usr/local/lib/python2.7/dist-packages/django/core/management/__init__.py", line 367, in execute_from_command_line
    utility.execute()
  File "/usr/local/lib/python2.7/dist-packages/django/core/management/__init__.py", line 359, in execute
    self.fetch_command(subcommand).run_from_argv(self.argv)
  File "/usr/local/lib/python2.7/dist-packages/django/core/management/base.py", line 294, in run_from_argv
    self.execute(*args, **cmd_options)
  File "/usr/local/lib/python2.7/dist-packages/django/core/management/base.py", line 345, in execute
    output = self.handle(*args, **options)
  File "/usr/local/lib/python2.7/dist-packages/django_crontab/management/commands/crontab.py", line 29, in handle
    Crontab().run_job(options['jobhash'])
  File "/usr/local/lib/python2.7/dist-packages/django_crontab/crontab.py", line 142, in run_job
    module = import_module(module_path)
  File "/usr/lib/python2.7/importlib/__init__.py", line 37, in import_module
    __import__(name)
  File "/code/ddp/app/cron.py", line 55, in <module>
    raise ValueError('This error is reported.')
ValueError: This error is reported.

I am not quite sure what to learn from this, but it might look like the reporting in the second case runs through Django, in the first case, however, the reporting does not run through Django?

What do you think, @kraiz ?

[cpoetter]

A temporary solution for me is this cron.py file:

def run():
    # Do nothing, no errors reported.
    pass

def actual_run():
    # Do all that needs to be done.
    raise ValueError('This error is reported.')

actual_run()

[kraiz]

I would call this expected. The first (raise-inside) log shows the logging output of django-crontabs logging event. It just captures the error that happened within the method that it called (here.
The second (raise-outside) log is longer as it isn't captured by logging. django-crontab fails even before executing the method....during import of the module where the method to execute is located (here.

[cpoetter]

Hm okay. So it looks like my django-crontab logger is not setup correctly. Do you have any ideas what I need to change/add? I tried to add this code

import os;
os.chdir('/absolute/path/to/django/folder');

at the beginning to my cron.py. Changing the working dir clearly worked, but it unfortunately did not help the error reporting.

Thank you very much for your help!

[kraiz]

For CWD problem i suggest setting CRONTAB_COMMAND_PREFIX to cd /absolute/path/to/django/folder &&.

django-crontab's logger just captures any error wrapping it into logging. If you want to handle the error logging yourself in special ways I see 2 options:

• overwrite django-crontab's logger within your logging config
• wrap your code into a try catch statement like django-crontab does.

[robertour]

So, after hours of wonder where my Exceptions were going (I still don't know btw), I manage to redirect them putting the general try catch around the method:

import logging
import traceback

logging.basicConfig()
logger = logging.getLogger(__name__)

def run():
    try:
        raise ValueError('This error is NOT reported.')
    except:
        logger.error(traceback.format_exc())

I finally capture the silent bug. This is just obvious once you see it, but not when you are wondering what is happening: is it crontabs? is it django-cron? is it cron sending my exceptions to the mail? maybe syslog? is 2>> /tmp/error.log working at all? at least it is definetily running because I manage to create a file...

Until I did the above, I managed to see the exception and fix my code. Is there any possible way to avoid that these exceptions dissapper in limbo. I am still wondering where do they actually go when I don't use the try/catch?