On Oct 16, 2013, at 10:44 AM, Christopher Armstrong <radix@twistedmatrix.com> wrote:

On Wed, Oct 16, 2013 at 12:33 PM, Conor Sayres <sayresc@gmail.com> wrote: Hi All,

I'm working for an astro observatory and we are upgrading our telescope control software. We are swapping to twisted under the hood, and I have run into an issue regarding logging.

I have set up twisted logging to record all communication between our devices. When we simulate our system with a high frequency log rollover rate (~5 seconds), many of the logs contain only garbage. Here is an example of a few lines in a given bad log file:

3230 3133 2d31 302d 3136 2031 303a 3131 3a34 352d 3037 3030 205b 2d5d 2044 6576 436d 6428 5354 4154 5553 290a 3230 3133 2d31 302d 3136 2031 303a 3131 3a34 352d 3037 3030 205b 2d5d 2044 6576 436d 6428 5354 4154 5553 290a 3230 3133 2d31 302d

Here is an example of a few lines from a good log file:

2013-10-16 10:11:39-0700 [_SocketProtocol,client] Galil Reply(XQ#STATUS) 2013-10-16 10:11:39-0700 [-] Galil Reply(: 1, 1, 1, 1, 1 axis homed) 2013-10-16 10:11:39-0700 [-] To All Users(1 1 i axisHomed=1, 1, 1, 1, 1) 2013-10-16 10:11:39-0700 [-] Galil Reply(000000000, 000000000, 000000000, 000000000, 000000000 commanded position) 2013-10-16 10:11:39-0700 [-] To All Users(1 1 i cmdMount=0, 0, 0, 0, 0) 2013-10-16 10:11:39-0700 [_SocketProtocol,client] MirrorCtrl Reply(1 1 i axisHomed=1, 1, 1, 1, 1) 2013-10-16 10:11:39-0700 [_SocketProtocol,client] Galil Reply(XQ#STATUS)

I haven't been able to reproduce the problem in a simpler framework than our simulation. I am triggering the rollover by directly calling LogFile.rollover on a timer. The problem also exists if I define a small file size limit for automatic rollover and let twisted do it automatically.

I don't think there's any method named "rollover" anywhere in Twisted (in fact, I just confirmed this with grep).

I'm sorry, the method is rotate my mistake

Your message is pretty vague and context-free; could you try to add more necessary detail? Is the problem with the output you're seeing the *content* of the numbers/letters, or just the fact that they're appearing at all? Maybe there's relevant output before or after that block of numbers/letters? Did you leave out the timestamp prefixes when pasting to this email, or is there really no timestamp prefixing the lines of that output?

The bad log files are 100% full of non-relevant output. They contain no time stamps, solely lines of 4 character blocks (hex?). They should contain information like the example of a good log I showed above. The good log files are 100% full of relevant output, no corruption. They contain the timestamps (as they should). It seems somewhat random whether or not a given log file will be good or bad.

I don't know where those numbers/letters could be coming from. Does your code (or any libraries you use) ever print to stdout? By default, Twisted redirects all prints (and any writing to sys.stdout) to the log file.

The log was configured to NOT capture print statements to stdout.

-- Christopher Armstrong http://radix.twistedmatrix.com/ http://planet-if.com/

_______________________________________________ Twisted-Python mailing list Twisted-Python@twistedmatrix.com http://twistedmatrix.com/cgi-bin/mailman/listinfo/twisted-python

On Oct 16, 2013, at 11:19 AM, Christopher Armstrong <radix@twistedmatrix.com> wrote:

The only other thing I can think of (without having a reproducible example of the problem in a self-contained executable example) is that some other program or code is opening the same file and writing garbage to it. Maybe you accidentally pass the location of the log file somewhere that wants a file to write to. It's unlikely that twisted's logging code itself would write unprefixed lines without a custom observer doing so.

Whenever I've seen truly garbage stuff like this, it's always been some code that opens a file descriptor, has it closed out from under it, and then the log file gets (re-?)opened with the same file descriptor number. Then write() calls start going to the logfile's FD. This is almost certainly a bug in your code or some other library that it's using, not Twisted itself. -g

Hi Guys, Tom nailed it. It seems to be a bug in my text editor from which I was viewing the files (Sublime Text 2). The logging was correct all along. Thanks All! Conor On Oct 16, 2013, at 3:07 PM, Tom Prince <tom.prince@ualberta.net> wrote:

Conor Sayres <sayresc@gmail.com> writes:

...

I have set up twisted logging to record all communication between our devices. When we simulate our system with a high frequency log rollover rate (~5 seconds), many of the logs contain only garbage. Here is an example of a few lines in a given bad log file:

3230 3133 2d31 302d 3136 2031 303a 3131 3a34 352d 3037 3030 205b 2d5d 2044 6576 436d 6428 5354 4154 5553 290a 3230 3133 2d31 302d 3136 2031 303a 3131 3a34 352d 3037 3030 205b 2d5d 2044 6576 436d 6428 5354 4154 5553 290a 3230 3133 2d31 302d

How are you viewing the log file? I suspect you are using less, and that the file contains some control characters, and less is automatically showing you a hex dump. Try using `less -A`.

The above lines when coverted from hex are:

2013-10-16 10:11:45-0700 [-] DevCmd(STATUS) 2013-10-16 10:11:45-0700 [-] DevCmd(STATUS) 2013-10

which looks like part of a log file.

Tom