[Twisted-Python] Twisted-Python Digest, Vol 115, Issue 19

Wed Oct 16 14:41:40 MDT 2013

Don't know if this helps:

>>> chr(0x32) + chr(0x30) + chr(0x31) + chr(0x33) + chr(0x2d) + chr(0x31) +
chr(0x30) + chr(0x2d) + chr(0x31) + chr(0x36) + chr(0x20) + chr(0x31) +
chr(0x30) + chr(0x3a) + chr(0x31) + chr(0x31)
'2013-10-16 10:11'
>>>

On Wed, Oct 16, 2013 at 1:14 PM,
<twisted-python-request at twistedmatrix.com>wrote:

> Send Twisted-Python mailing list submissions to
>         twisted-python at twistedmatrix.com
>
> To subscribe or unsubscribe via the World Wide Web, visit
>         http://twistedmatrix.com/cgi-bin/mailman/listinfo/twisted-python
> or, via email, send a message with subject or body 'help' to
>         twisted-python-request at twistedmatrix.com
>
> You can reach the person managing the list at
>         twisted-python-owner at twistedmatrix.com
>
> When replying, please edit your Subject line so it is more specific
> than "Re: Contents of Twisted-Python digest..."
>
>
> Today's Topics:
>
>    1. Re: Garbage in logfiles? (Conor Sayres)
>    2. Re: Garbage in logfiles? (Christopher Armstrong)
>    3. Re: Garbage in logfiles? (Glyph)
>
>
> ----------------------------------------------------------------------
>
> Message: 1
> Date: Wed, 16 Oct 2013 11:12:12 -0700
> From: Conor Sayres <sayresc at gmail.com>
> To: Twisted general discussion <twisted-python at twistedmatrix.com>
> Subject: Re: [Twisted-Python] Garbage in logfiles?
> Message-ID: <81DD4767-8F1E-4A55-857E-A7A61BE9E3D4 at gmail.com>
> Content-Type: text/plain; charset="us-ascii"
>
>
> On Oct 16, 2013, at 10:44 AM, Christopher Armstrong <
> radix at twistedmatrix.com> wrote:
>
> > On Wed, Oct 16, 2013 at 12:33 PM, Conor Sayres <sayresc at 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 at twistedmatrix.com
> > http://twistedmatrix.com/cgi-bin/mailman/listinfo/twisted-python
>
> -------------- next part --------------
> An HTML attachment was scrubbed...
> URL: <
> http://twistedmatrix.com/pipermail/twisted-python/attachments/20131016/26ac98d0/attachment-0001.html
> >
>
> ------------------------------
>
> Message: 2
> Date: Wed, 16 Oct 2013 13:19:07 -0500
> From: Christopher Armstrong <radix at twistedmatrix.com>
> To: Twisted general discussion <twisted-python at twistedmatrix.com>
> Subject: Re: [Twisted-Python] Garbage in logfiles?
> Message-ID:
>         <CAPkRfURUVATCZr2-e2nLKaUpN4U3GK-kgHoLnP-a_1EUAcG=
> Mg at mail.gmail.com>
> Content-Type: text/plain; charset="utf-8"
>
> On Wed, Oct 16, 2013 at 1:12 PM, Conor Sayres <sayresc at gmail.com> wrote:
>
> >
> > On Oct 16, 2013, at 10:44 AM, Christopher Armstrong <
> > radix at twistedmatrix.com> wrote:
> >
> > On Wed, Oct 16, 2013 at 12:33 PM, Conor Sayres <sayresc at 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.
> >
>
>
>
> 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.
>
>
> >
> > --
> > Christopher Armstrong
> > http://radix.twistedmatrix.com/
> > http://planet-if.com/
> >
> >  _______________________________________________
> > Twisted-Python mailing list
> > Twisted-Python at twistedmatrix.com
> > http://twistedmatrix.com/cgi-bin/mailman/listinfo/twisted-python
> >
> >
> >
> > _______________________________________________
> > Twisted-Python mailing list
> > Twisted-Python at twistedmatrix.com
> > http://twistedmatrix.com/cgi-bin/mailman/listinfo/twisted-python
> >
> >
>
>
> --
> Christopher Armstrong
> http://radix.twistedmatrix.com/
> http://planet-if.com/
> -------------- next part --------------
> An HTML attachment was scrubbed...
> URL: <
> http://twistedmatrix.com/pipermail/twisted-python/attachments/20131016/bb3b76ae/attachment-0001.html
> >
>
> ------------------------------
>
> Message: 3
> Date: Wed, 16 Oct 2013 13:14:00 -0700
> From: Glyph <glyph at twistedmatrix.com>
> To: Twisted general discussion <twisted-python at twistedmatrix.com>
> Subject: Re: [Twisted-Python] Garbage in logfiles?
> Message-ID: <0B91CDE1-5DED-4521-95DE-84EC0C246C4E at twistedmatrix.com>
> Content-Type: text/plain; charset="us-ascii"
>
>
> On Oct 16, 2013, at 11:19 AM, Christopher Armstrong <
> radix at 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
> -------------- next part --------------
> An HTML attachment was scrubbed...
> URL: <
> http://twistedmatrix.com/pipermail/twisted-python/attachments/20131016/48c706a3/attachment.html
> >
>
> ------------------------------
>
> _______________________________________________
> Twisted-Python mailing list
> Twisted-Python at twistedmatrix.com
> http://twistedmatrix.com/cgi-bin/mailman/listinfo/twisted-python
>
>
> End of Twisted-Python Digest, Vol 115, Issue 19
> ***********************************************
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://twistedmatrix.com/pipermail/twisted-python/attachments/20131016/805fae8f/attachment-0001.html>