Debugging: Console Output and Upstart Scripts

Question

How do you send the output of an upstart script to a terminal so to find tracebacks in python code? It's taking me for ever to do things without trace-backs that used to take just a second. I'm having to place several file write calls to track down errors. What took second to find before with a traceback is turning in to several minutes minutes. This is miserable. This has been going on for a few weeks now and I'm sick of it. would some speak up on this please. I feel like I'm using assembly without a debugger again.

Solution 1

If you use Upstart 1.4 or newer, put console log into your Upstart job and all the output to stdout/stderr will end up to /var/log/upstart/<job>.log. Then you can do tail -f /var/log/upstart/<job>.log & to have the output appear in terminal.

Solution 2

When I write a python daemon I catch all the exceptions and throw then to the log file. I not only use for debug, but in production too. I have a a small script that I run every morning that looks for something upsetting in the logs.

It also helps in keeping the daemon running, of course.

Some sample code (I remove the not interesting parts):

import logging

if __name__ == "__main__":
    logging.basicConfig(level=logging.INFO,
                    format='%(asctime)s %(levelname)s %(message)s',
                    filename=LOG_FILE,
                    filemode='w')
    logging.info("Sincrod inicializado")
    if not DEBUG:
        daemonize()
    while True:
        try:
            actua()
        except:
            logging.error(sys.exc_info())
        if (datetime.datetime.now().hour > NOITE_EMPEZA\
         and datetime.datetime.now().hour < NOITE_REMATA):
            time.sleep(INTERVALO_NOITE)
        else:
            time.sleep(INTERVALO_DIA)

Where actua() is the real daemon (it writes to log too). Note that I also have a DEBUG variable in a settings file, when it's True, I don't fork the daemon so it's executes on the console.

Daemons

Daemons are the unix equivalent to windows services. They are processes that run in the background independent from other processes. That means that their father is usually init, and that they are detached from any tty. As they are independent, there is no predefined place to put their output.

There are lots of python libraries and snippets to make a daemon, in the above example I use my own function, that combines some ideas from Steinar Knutsens and Jeff Kunces versions. It's as simple as possible, note that I fork twice.

def daemonize():
    """Forks this process creating a daemon and killing the original one"""
    if (not os.fork()):
        # get our own session and fixup std[in,out,err]
        os.setsid()
        sys.stdin.close()
        sys.stdout = NullDevice()
        sys.stderr = NullDevice()
        if (not os.fork()):
            # hang around till adopted by init
            ppid = os.getppid()
            while (ppid != 1):
                time.sleep(0.5)
                ppid = os.getppid()
        else:
            # time for child to die
            os._exit(0)
    else:
        # wait for child to die and then bail
        os.wait()
        sys.exit()

Solution 3

There's a whole section on debugging techniques in the Upstart Cookbook. The easiest thing you could do is add --debug to your kernel arguments, which will increase upstart's verbosity and dump everything to syslog. Yes, debugging is complex, it's a reflection of the net complexity required to create a parallelized init system. I'm sure there's room for improvement.

Comments

[ppetraki]

Well, OK. since you're already logging to syslog, then just filter out your daemon messages and dump them to the console. I don't see why this is specific to upstart? SysV init would have the same problem.

[Javier Rivera]

You are right, it's not specific to upstart, to tell the truth most of my servers run 8.04, no upstart. But it's valid for upstart too. OP was asking how to debug python scripts with upstart, not for a method that only works with upstart. I'm not logging to syslog but to a specific file, and the 'trick' here is catching all exceptions and dumping the stack trace to that file.

[ppetraki]

well, that's just managing stdout based on the context right? I know plenty of unix daemons that have equivalent logging verbosity regardless of whether it's attached to a tty or functioning as a daemon. If this were Ruby, I would over-ride or decorate the base class method that exceptions use to output. I'm sure something similar can be done in Python. You might be better served asking this question on stack exchange proper. This is more of a basic unix daemon coding/design problem, and as you stated, it has nothing specific to do with init scripts.

[bambuntu]

I'm still getting familiar with the lingo. I assume by daemon, you mean a specific script that runs in the background. In your code, I just put my script in place of actua() to get the callbacks for that script call? Is there anyway to channel it to a console instead of a file?

[Javier Rivera]

You can print the errors instead of logging them. Note that this code expects lot's of things, mainly constants and a daemonize() function.

[bambuntu]

the cook book doesn't properly explain a debugging environment to a new comer. I've seen similar explanations before. There are either lacking or make guru assumptions. It's very frustrating to people who want to add to the community and just starting out. I've never ran into a programming environment that didn't provide the line of code where the error occurs except in assembly, where you are reinventing the wheel, so that can be forgiven.

[bambuntu]

Is there anyway it could be written so when we add os.system("python myScript.py") inside a loggin function, than myScript.py would be logged, or any other call to a script? Is it possible to make it that simple? It is already an unbelievable amount of frustration that no output exists already, I won't know if this works or not if there is an error. That's why it is so important to have something that works and is simple.

[ppetraki]

Well, what would you suggest then? It's an open document. If you've got a debugging technique that's leaps and bounds above what's presented there then please add it. The OP's problems are more a result of not understanding how to manage basic unix paradigms inside his additional runtime of choice vs the context it's being deployed in. Just because you're using python or [insert fancy runtime language here] doesn't mean you get to ignore the fundamental runtime, UNIX.

[ppetraki]

daemons in the stand alone sense are usually detached from the tty they were started on, have closed their original file handles to stdin, stdout, and stdin, and are a child of init. So if you want to print exceptions to someplace specific, find out how they are outputed, and direct them from there. linfo.org/daemon.html. Again, this doesn't have anything to do with upstart, or even init for that matter. Get your program functioning correctly in true daemon mode and then move it upstart.

[bambuntu]

So, does this mean that python does not make exceptions that show the error and the line of code it occurred on when when the process the script runs in is owned by init?

[Javier Rivera]

It is more complex, but as a simplification unless you log it to some other file, it doesn't. Daemons, in unix, shouldn't print anything.

[ppetraki]

I meant to say "stdin, stdout, and stderr" before. To answer your question... Once you're owned by init, you should have no ready way of interacting with the screen anymore, you must explicitly set this up. Think about it, if I daemonize something from say gnome-console, and then close that console, where does stdout actually go? Nowhere, because the file descriptor originally designated to that tty is now defunct. A tty is a medium, file descriptors are channels in that medium. This is why daemons usually log to a socket or to a file, it's a fixed point independent of the tty.

[bambuntu]

First, thanks for being patient. This is new to me. Have I got this right: (1) A process started by init() (runlevel scripts and upstart scripts) do not send standard output anywhere. (2) Processes which are forked (The parent process is killed and child process is adopted by init()) send no standard output anywhere. The make this process send output, a tty, file or socket must be assigned to this process. The output will then be sent there for viewing.

[ppetraki]

That's about right, here's what your daemonize call is doing behind the scenes. www-theorie.physik.unizh.ch/~dpotter/howto/daemonize . You can verify this by examining the python source. Runtime languages are great for getting something up and running quickly, but once you start interacting with the operating system at the process level, which in your case is when you called daemonize; whether you realize it or not, you crossed the boundary into the UNIX runtime and process management. Pick up a reference on UNIX/Linux system programming, or just google.

[Javier Rivera]

That daemonize is my own function, not a python standard one ;). I need to edit the answer to try to consolidate all this comments.

[ppetraki]

Well, that would do it :), see pypi.python.org/pypi/python-daemon

[rslite]

Kind of late to the party, but this answer saved me :) Also looks like this works for me without any special setting in the upstart conf file. For my part this should be the accepted answer.

[Francisco]

Didn't know upstart managed service logs were in /var/log/upstart. Really useful, thank.