[rt-users] Timestamps when logging to a file

Tue Dec 13 00:13:05 EST 2005

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On Mon, 12 Dec 2005 at 20:38 (-0800), Jim Meyer wrote:

> Have you added any Contribs? ;]

No, and the only mods I've made are to the page logo and the default order 
in which QuickSearch displays the tickets in a queue.

> Hmmm. Any discernible pattern? What type of events are logging with 
> wrong dates?

Here's an extract of contiguous lines from my log file.  The transition 
between those using local time and those using GMT seems quite 'smooth'; 
in other words, the type of message doesn't seem to correlate with the 
time zone being used:

   [Mon Dec 12 08:50:19 2005] [debug]: About to think about scrips for transaction #30363 (/usr/local/rt3/lib/RT/Transaction_Overlay.pm:154)
   [Mon Dec 12 08:50:19 2005] [info]: <rt-3.4.2-63131-30362-15.3.44651226019174 at SNS> sent To: postcards at postcards1001.com Cc:  Bcc:  (/usr/local/rt3/lib/RT/Action/SendEmail.pm:295)
   [Mon Dec 12 08:50:19 2005] [info]: Ticket 63131 created in queue 'security' by postcards at postcards1001.com (/usr/local/rt3/lib/RT/Ticket_Overlay.pm:730)
   [Mon Dec 12 17:01:01 2005] [debug]: About to think about scrips for transaction #30364 (/usr/local/rt3/lib/RT/Transaction_Overlay.pm:154)
   [Mon Dec 12 17:01:01 2005] [debug]: About to think about scrips for transaction #30365 (/usr/local/rt3/lib/RT/Transaction_Overlay.pm:154)
   [Mon Dec 12 17:01:01 2005] [debug]: About to think about scrips for transaction #30366 (/usr/local/rt3/lib/RT/Transaction_Overlay.pm:154)
   [Mon Dec 12 17:01:01 2005] [debug]: About to think about scrips for transaction #30367 (/usr/local/rt3/lib/RT/Transaction_Overlay.pm:154)
   [Mon Dec 12 17:01:01 2005] [debug]: About to think about scrips for transaction #30368 (/usr/local/rt3/lib/RT/Transaction_Overlay.pm:154)
   [Mon Dec 12 17:01:01 2005] [debug]: About to prepare scrips for transaction #30368 (/usr/local/rt3/lib/RT/Transaction_Overlay.pm:158)
   [Mon Dec 12 17:01:01 2005] [debug]: Found 0 scrips (/usr/local/rt3/lib/RT/Scrips_Overlay.pm:354)
   [Mon Dec 12 17:01:01 2005] [debug]: About to commit scrips for transaction #30368 (/usr/local/rt3/lib/RT/Transaction_Overlay.pm:167)
   [Mon Dec 12 17:01:01 2005] [info]: Ticket 63132 created in queue 'SECN-STAGING' by RT_System (/usr/local/rt3/lib/RT/Ticket_Overlay.pm:730)
   [Mon Dec 12 17:01:01 2005] [debug]: About to think about scrips for transaction #30369 (/usr/local/rt3/lib/RT/Transaction_Overlay.pm:154)
   [Mon Dec 12 17:01:01 2005] [debug]: About to prepare scrips for transaction #30369 (/usr/local/rt3/lib/RT/Transaction_Overlay.pm:158)
   [Mon Dec 12 17:01:01 2005] [debug]: Found 0 scrips (/usr/local/rt3/lib/RT/Scrips_Overlay.pm:354)
   [Mon Dec 12 17:01:01 2005] [debug]: About to commit scrips for transaction #30369 (/usr/local/rt3/lib/RT/Transaction_Overlay.pm:167)
   [Mon Dec 12 17:01:01 2005] [debug]: About to think about scrips for transaction #30370 (/usr/local/rt3/lib/RT/Transaction_Overlay.pm:154)
   [Mon Dec 12 17:01:01 2005] [debug]: About to think about scrips for transaction #30371 (/usr/local/rt3/lib/RT/Transaction_Overlay.pm:154)
   [Mon Dec 12 17:01:01 2005] [debug]: About to think about scrips for transaction #30372 (/usr/local/rt3/lib/RT/Transaction_Overlay.pm:154)
   [Mon Dec 12 17:01:01 2005] [debug]: About to prepare scrips for transaction #30372 (/usr/local/rt3/lib/RT/Transaction_Overlay.pm:158)
   [Mon Dec 12 17:01:01 2005] [debug]: Found 0 scrips (/usr/local/rt3/lib/RT/Scrips_Overlay.pm:354)
   [Mon Dec 12 17:01:01 2005] [debug]: About to commit scrips for transaction #30372 (/usr/local/rt3/lib/RT/Transaction_Overlay.pm:167)
   [Mon Dec 12 09:01:08 2005] [debug]: Guessed encoding: ascii (/usr/local/rt3/lib/RT/I18N.pm:395)
   [Mon Dec 12 09:01:08 2005] [debug]: Guessed encoding: ascii (/usr/local/rt3/lib/RT/I18N.pm:395)
   [Mon Dec 12 09:01:08 2005] [debug]: Converting 'ascii' to 'utf-8' for text/plain - [SNS #63132] Worm/Virus Infected System (Modem user irenel)
    (/usr/local/rt3/lib/RT/I18N.pm:225)
   [Mon Dec 12 09:32:18 2005] [debug]: Converting 'ISO-8859-1' to 'utf-8' for text/plain - Re: [SNS #62933] 128.32.181.110 (march-365-357a-001-d.SPH) Bot-Infected Host (MAY BE BLOCKED) (/usr/local/rt3/lib/RT/I18N.pm:225)
   [Mon Dec 12 09:32:18 2005] [debug]: Found a ticket ID. It's 62933 (/usr/local/rt3/lib/RT/Interface/Email.pm:449)
   [Mon Dec 12 09:32:18 2005] [debug]: About to think about scrips for transaction #30374 (/usr/local/rt3/lib/RT/Transaction_Overlay.pm:154)
   [Mon Dec 12 09:32:18 2005] [debug]: About to think about scrips for transaction #30375 (/usr/local/rt3/lib/RT/Transaction_Overlay.pm:154)
   [Mon Dec 12 09:32:18 2005] [debug]: About to think about scrips for transaction #30376 (/usr/local/rt3/lib/RT/Transaction_Overlay.pm:154)
   [Mon Dec 12 09:32:18 2005] [debug]: About to prepare scrips for transaction #30376 (/usr/local/rt3/lib/RT/Transaction_Overlay.pm:158)
   [Mon Dec 12 09:32:18 2005] [debug]: Found 0 scrips (/usr/local/rt3/lib/RT/Scrips_Overlay.pm:354)
   [Mon Dec 12 09:32:18 2005] [debug]: About to commit scrips for transaction #30376 (/usr/local/rt3/lib/RT/Transaction_Overlay.pm:167)
   [Mon Dec 12 09:32:27 2005] [debug]: Guessed encoding: ascii (/usr/local/rt3/lib/RT/I18N.pm:395)
   [Mon Dec 12 09:32:27 2005] [debug]: Guessed encoding: ascii (/usr/local/rt3/lib/RT/I18N.pm:395)
   [Mon Dec 12 09:32:27 2005] [debug]: Converting 'ascii' to 'utf-8' for text/plain - Re: [SNS #60990] Worm/Virus Infected System (Modem user tapeworm)
    (/usr/local/rt3/lib/RT/I18N.pm:225)
   [Mon Dec 12 09:32:27 2005] [debug]: Found a ticket ID. It's 60990 (/usr/local/rt3/lib/RT/Interface/Email.pm:449)
   [Mon Dec 12 09:32:27 2005] [debug]: About to think about scrips for transaction #30377 (/usr/local/rt3/lib/RT/Transaction_Overlay.pm:154)
   [Mon Dec 12 09:32:27 2005] [debug]: About to prepare scrips for transaction #30377 (/usr/local/rt3/lib/RT/Transaction_Overlay.pm:158)
   [Mon Dec 12 09:32:27 2005] [debug]: Found 0 scrips (/usr/local/rt3/lib/RT/Scrips_Overlay.pm:354)
   [Mon Dec 12 09:32:27 2005] [debug]: About to commit scrips for transaction #30377 (/usr/local/rt3/lib/RT/Transaction_Overlay.pm:167)
   [Mon Dec 12 17:33:29 2005] [debug]: About to think about scrips for transaction #30378 (/usr/local/rt3/lib/RT/Transaction_Overlay.pm:154)
   [Mon Dec 12 17:33:29 2005] [debug]: About to think about scrips for transaction #30379 (/usr/local/rt3/lib/RT/Transaction_Overlay.pm:154)

> Meanwhile, looking at the code, I see that the gmtime() calls are in 
> anonymous coderefs used as callbacks by the Log::Dispatch object. This 
> gives me two questions, both about bases I'm sure you've already touched 
> but I have to ask:
>
> 1. You've stopped and started your RT instance? (not restart, but
>   stop then start)

Yes, I always completely stop (using '/usr/local/etc/rc.d/apache2.sh stop'),
then start (using '/usr/local/etc/rc.d/apache2.sh start').

> 2. Did you change both instances of the gmtime call in that file?
>   If not, you might frob that to see if the problem disappears.

Yes, I did.  Even though one of them just refers to LogToScreen, which I 
don't have configured, I figured I'd cover all bases.

> Finally, the only other snippet of code which might relate is in 
> RT::Date, where there's a selector according to source of the time 
> string:
>
>    #Dateamnip strings aren't in GMT.
>    if ( $args{'Format'} =~ /^datemanip$/i ) {
>        $self->Unix(
>            timelocal( $sec, $min, $hours, $mday, $mon, $year )
>        );
>    }
>    #ISO and SQL dates are in GMT
>    else {
>        $self->Unix(
>            timegm( $sec, $min, $hours, $mday, $mon, $year )
>        );
>    }
>
> Is it possible that some time string is being de-stringified according 
> to these rules when you've changed the way the string was composed? 
> Seems like wild goose chase, but that's the only other moderately 
> obvious place.

The interesting thing is that I see no GMT in any other place where time 
is displayed, e.g., the web interface.  This problem is occurring only in 
my log file.

I'm tempted to try modifying Date.pm, but I don't want to mess up time 
representations in places other than my logs.  So I'd need to be sure I 
understood where that module is used.

Incidentally, my RT_SiteConfig.pm has this:

    Set($LogToSyslog    , '');
    Set($LogToScreen    , '');
    Set($LogToFile      , 'debug');
    Set($LogDir, '/hold/k-9/logs');
    Set($LogToFileNamed , "rt.log");    #log to rt.log

I specifically want all my log messages going to the file and nowhere 
else.

Mike

_____________________________________________________________________
Mike Friedman                   System and Network Security
mikef at ack.Berkeley.EDU          2484 Shattuck Avenue
1-510-642-1410                  University of California at Berkeley
http://ack.Berkeley.EDU/~mikef  http://security.berkeley.edu
_____________________________________________________________________

-----BEGIN PGP SIGNATURE-----
Version: PGP 6.5.8

iQA/AwUBQ55YZK0bf1iNr4mCEQKBgACggEMUKKXWYQJ0IMkVMZJDDI3pmjoAnRQ7
qhm/4Dlp27WbeUOSgb0kcxM3
=VZMo
-----END PGP SIGNATURE-----