Running Python script as upstart service shows different time output

Question

I have a python script that is essentially a small socket server that does some simple network tasks for me, and I started running it as an upstart service to keep track of it and manage whether or not it was running. To log information, I am using Python's built in logging module. When running as an Upstart service, I noticed a small problem: All of the time calls come out in GMT. When running it on its own(either ./scriptname.py or python scriptname.py) it uses local time, and Python is aware of the local time. The system time is set correctly, and I only see this behavior when running as an upstart service. Does anyone know why this would happen and how I could fix it?

EDIT: Relevant code: I have a helper class, conveniently called helper, that contains some oft used functions (I know it needs to be better organized, but it was thrown together fairly quickly). Most notably this function that I use to set up my logger:

class helper:
    log_format = '%(asctime)-25s %(name)-25s %(levelname)-12s %(message)s'

    @staticmethod
    def createLogger(name):
        rotatingFile = logging.handlers.RotatingFileHandler('/var/log/myLog.log', maxBytes=1048576, backupCount=5)
        rotatingFile.setLevel(logging.DEBUG)
        formatter = logging.Formatter(helper.log_format)
        formatter.time = localtime()
        rotatingFile.setFormatter(formatter)
        log = logging.getLogger(name)
        log.setLevel(logging.DEBUG)
        logging.basicConfig(format=helper.log_format, level=logging.DEBUG)
        if not log.handlers:
            log.addHandler(rotatingFile)
        return log

And it gets used like this in one of my classes:

class MyClass:

    def __init__(self):
        self._log = helper.createLogger('LogName')
        self._log.info('Some relevant info')

    _log = None

It's all pretty straightforward use of the python internal logging tools. I added the formatter.time = localtime() after I started noticing this problem, but before I realized that it only happened when run as a service. It didn't help.

Here is my (very basic) upstart config that I got from a tutorial:

description "Blah blah"
author  "My Name <My Email>"

start on runlevel [234]
stop on runlevel [0156]

exec /path/to/script.py

respawn

In your upstart config, is the TZ environment variable being set? — Mark, Jun 28 '12 at 16:37
I actually added it to the upstart config to see if that would work but it didn't do anything. I'm new to upstart but I tried `exec TZ=/usr/share/zoneinfo/US/Central` and `exec export TZ=/usr/share/zoneinfo/US/Central` but it still has time in GMT when I restart the service. — Annath, Jun 28 '12 at 17:40
Maybe post your sample code so we can experiment with it? I assume if you run it while logged into a guest session that it also works properly with local time? — bryce, Jul 02 '12 at 20:29
I added the basic python I'm using as well as the upstart config. — Annath, Jul 02 '12 at 21:04
You should be using GMT for logging anyway, this makes easier to compare logs from servers at distinct timezones. — Paulo Scardine, Jul 09 '12 at 02:55
@Paulo Scardine, I hadn't even thought about that, but you're definitely right. This becomes less important with that in mind, but just for sanity's sake I'd sitll like to solve this. I will be logging in GMT intentionally from now on though. — Annath, Jul 09 '12 at 15:02
@Annath: try `os.environ["TZ"]="US/Central"` inside `/path/to/script.py` (before the logging stuff) — Paulo Scardine, Jul 09 '12 at 19:41

ivan_pozdeev · Answer 1 · 2012-07-09T02:38:53.107

1

Inspect your script's environment under upstart. localtime() takes timezone information from TZ/TZDIR//etc/localtime, 'GMT' being the hard-coded default (see time/tzset.c in glibc sources) . The environment may be chrooted or otherwise restricted and your TZ specification might not work.

As a quick check, you can use strace -o <outfile> -ff start <jobname> to see whether python reads the correct timezone file at startup.

edited Jul 09 '12 at 02:38

answered Jul 09 '12 at 02:31

ivan_pozdeev

33,874
19
107
152

Unfortunately, I couldn't find any references in the strace output to a timezone. – Annath Jul 09 '12 at 16:55

score 1 · Accepted Answer · answered Jul 09 '12 at 20:10

1

So, I think I finally discovered the issue. I needed to set the TZ env var but I wasn't doing it right before. Adding env TZ=/usr/share/zoneinfo/US/Central to my upstart config corrected it. Thanks for the help everyone!

answered Jul 09 '12 at 20:10

Annath

1,262
10
20

Running Python script as upstart service shows different time output

2 Answers2