Timestamps when logging to a file

Mike_Friedman · December 8, 2005, 8:45pm

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

I’ve configured my RT (3.4.2) to log to a file. When I first set this up,
I noticed that the timestamps were in GMT, unlike syslog logging (which I
was using before), that uses local time.

To cause local time to be used in my file logs, I decided to modify RT.pm,
where the $RT::Logger method is called, to return ‘[localtime(time)]’
instead of ‘[gmtime(time)]’. I made a copy of RT.pm in local/lib and
restarted RT.

Now I find that most of the entries in my log file are, indeed, in local
time, but interspersed are messages still using GMT. Is there some other
place besides RT.pm that I must change to get consistent local time in my
log file?

Thanks.

Mike

Mike Friedman System and Network Security
mikef@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/AwUBQ5ibaa0bf1iNr4mCEQLXmQCfZdxXRWhTVfxwnwn+nbuPpJRKZ0YAn3Lu
YZRsuIgDFBWnyfR6RrZML4lb
=8GNM
-----END PGP SIGNATURE-----

Mike_Friedman · December 13, 2005, 12:35am

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

I posted this question last week and haven’t received any responses, so I
figured I’d ask again. It’s not the sort of question that tends to be
answered in an FAQ or in the RT Essentials book, nor even on the wiki
(though I’d like to be proven wrong about that).

Here it is again:

I’ve configured my RT (3.4.2) to log to a file. When I first set this up,
I noticed that the timestamps were in GMT, unlike syslog logging (which I
was using before), that uses local time.

To cause local time to be used in my file logs, I decided to modify RT.pm,
where the $RT::Logger module is used, to return ‘[localtime(time)]’
instead of ‘[gmtime(time)]’. I made a copy of RT.pm in local/lib and
restarted RT.

Now most of the entries in my log file are, indeed, in local time, but
they are interspersed with messages that are still using GMT. Is there
some other place besides RT.pm that I must change in order to get
consistent local time in my log file?

Thanks.

Mike

Mike Friedman System and Network Security
mikef@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/AwUBQ54XYq0bf1iNr4mCEQLSNQCfdFzA7diD4C4jekaDWM8OxiFnsOkAn00p
5sDPIH6gWuZAMLmtYObUCMer
=CYDC
-----END PGP SIGNATURE-----

Jim_Meyer1 · December 13, 2005, 2:29am

Hello!

Now most of the entries in my log file are, indeed, in local time, but
they are interspersed with messages that are still using GMT. Is there
some other place besides RT.pm that I must change in order to get
consistent local time in my log file?

YMMV, but here’s how I go hunting such things:

cd /path/to/rt
grep -rl gmtime lib
lib/RT/Date.pm
lib/RT/Tickets_Overlay.pm
lib/RT.pm
lib/RT.pm.in

Good luck!

–j
Jim Meyer, Geek at Large purp@acm.org

Schultz_Eric · December 13, 2005, 3:35am

Also a handy one:

find /path/to/rt -type f | xargs grep “thing you are looking for”

sometimes you will also want to remove some noise with some more pipes on the end:

| grep -v I18N | grep -v rt.logFrom: rt-users-bounces@lists.bestpractical.com on behalf of Jim Meyer
Sent: Mon 12/12/2005 6:29 PM
To: Mike Friedman
Cc: rt-users
Subject: Re: [rt-users] Timestamps when logging to a file

Hello!

Now most of the entries in my log file are, indeed, in local time, but
they are interspersed with messages that are still using GMT. Is there
some other place besides RT.pm that I must change in order to get
consistent local time in my log file?

YMMV, but here’s how I go hunting such things:

cd /path/to/rt
grep -rl gmtime lib
lib/RT/Date.pm
lib/RT/Tickets_Overlay.pm
lib/RT.pm
lib/RT.pm.in

Good luck!

–j
Jim Meyer, Geek at Large purp@acm.org

http://lists.bestpractical.com/cgi-bin/mailman/listinfo/rt-users

Be sure to check out the RT Wiki at http://wiki.bestpractical.com

Download a free sample chapter of RT Essentials from O’Reilly Media at http://rtbook.bestpractical.com

WE’RE COMING TO YOUR TOWN SOON - RT Training in Amsterdam, Boston and
San Francisco - Find out more at http://bestpractical.com/services/training.html

Mike_Friedman · December 13, 2005, 4:08am

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1On Mon, 12 Dec 2005 at 18:29 (-0800), Jim Meyer wrote:

On Mon, 2005-12-12 at 16:35, Mike Friedman wrote:

Now most of the entries in my log file are, indeed, in local time, but
they are interspersed with messages that are still using GMT. Is there
some other place besides RT.pm that I must change in order to get
consistent local time in my log file?

YMMV, but here’s how I go hunting such things:

cd /path/to/rt
grep -rl gmtime lib
lib/RT/Date.pm
lib/RT/Tickets_Overlay.pm
lib/RT.pm
lib/RT.pm.in

Jim,

I had already done that. But when I looked at the code in those two
modules, it appeared that they just manipulate dates, but don’t actually
do their own logging.

My problem is specifically with the writing to a log file. (In fact, if I
configure to write to syslog instead, I get local time with no mods, and
this makes sense from the code because syslogging is treated differently).

I was hoping that there is some other module that is influencing the date
in the logs in a more subtle way, perhaps not calling gmtime directly.

Or, maybe RT.pm is the only responsible module, but I need to do more than
just copy it to local/lib. (Unlike mason components, there doesn’t seem to
be a cache that needs to be deleted. Besides, I am getting localtime in
most of my log messages, it’s just that about 1/3 of them are still using
GMT).

Mike

Mike Friedman System and Network Security
mikef@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/AwUBQ55JQK0bf1iNr4mCEQJOzgCfZWubG24nUjsmpwsqe0cxzIdxEzcAni2Z
g+M1xllcbgkaN77XlJkZoE1W
=5FwP
-----END PGP SIGNATURE-----

Jim_Meyer1 · December 13, 2005, 4:38am

Hello!

I was hoping that there is some other module that is influencing the date
in the logs in a more subtle way, perhaps not calling gmtime directly.

Seems unlikely if the format is precisely the same. That or someone went
to great lengths to match the format and write to the same file without
calling the Logger object.

Have you added any Contribs? ;]

Or, maybe RT.pm is the only responsible module, but I need to do more than
just copy it to local/lib. (Unlike mason components, there doesn’t seem to
be a cache that needs to be deleted. Besides, I am getting localtime in
most of my log messages, it’s just that about 1/3 of them are still using
GMT).

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

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:

You’ve stopped and started your RT instance? (not restart, but
stop then start)
Did you change both instances of the gmtime call in that file?
If not, you might frob that to see if the problem disappears.

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.

Late-at-workily yours,

–j
Jim Meyer, Geek at Large purp@acm.org

Mike_Friedman · December 13, 2005, 5:13am

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

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@SNS sent To: postcards@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@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:

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’).

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@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-----

Jim_Meyer1 · December 13, 2005, 5:45am

Hello!

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:

[…]

In the log you sent, I’m assuming that localtime was 8:50-9:33a, yes? If
so, my test assertion is that your email-based transactions are
correctly timed while your web-based transactions are +8 hrs.

True?

Not that I know what it means or anything … =\

–j, stumped.

[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@SNS sent To: postcards@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@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)

Jim Meyer, Geek at Large purp@acm.org

Mike_Friedman · December 13, 2005, 6:43am

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1On Mon, 12 Dec 2005 at 21:45 (-0800), Jim Meyer wrote:

In the log you sent, I’m assuming that localtime was 8:50-9:33a, yes? If
so, my test assertion is that your email-based transactions are
correctly timed while your web-based transactions are +8 hrs.

True?

No, all timestamps I see in the web interface are local time, which
corresponds to my configuration in RT_SiteConfig.pm:

Set($Timezone , 'Pacific');

Most of our tickets are created by email. However, I just created a
ticket via the web and the creation time shows in local time.

As I have said, it’s only in the log file that I ever see GMT at all. This
was NOT the case when I was logging to syslog (where I got local time
consistently).

However, I had to switch to LogToFile because there’s apparently a bug in
Log::Dispatch::Syslog, that causes disruptive behavior (with error
messages spewing out at unpredictable times – on the terminal when
running external perl scripts, as well as via the web interface).
Logging to a file (which I assume uses Log::Dispatch::File) fixes all
these problems.

As I’m essentially the only one who looks at the logs, I can live with the
current behavior, whereas the problems when logging to syslog were not
tolerable.

Mike

Mike Friedman System and Network Security
mikef@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/AwUBQ55tfK0bf1iNr4mCEQJjmwCeI7NAGokS6hYVUHrrxiUx0xNGkyAAn3rY
eWUxhktLjOWR6y0oA/+sqLbc
=yrxF
-----END PGP SIGNATURE-----

Jim_Meyer1 · December 13, 2005, 7:20am

Hello!On Mon, 2005-12-12 at 22:43, Mike Friedman wrote:

On Mon, 12 Dec 2005 at 21:45 (-0800), Jim Meyer wrote:

In the log you sent, I’m assuming that localtime was 8:50-9:33a, yes? If
so, my test assertion is that your email-based transactions are
correctly timed while your web-based transactions are +8 hrs.

True?

No, all timestamps I see in the web interface are local time, which
corresponds to my configuration in RT_SiteConfig.pm:

Sorry, to be more clear: all the timestamps you’re seeing in the
logfile which are in localtime seem to be from email transactions; the
transactions in the log snippet you sent which gave the time as
16:50-17:33 were reflecting GMT and were not email transactions.

Make sense?

–j
Jim Meyer, Geek at Large purp@acm.org

Mike_Friedman · December 13, 2005, 4:47pm

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1On Mon, 12 Dec 2005 at 23:20 (-0800), Jim Meyer wrote:

Sorry, to be more clear: all the timestamps you’re seeing in the
logfile which are in localtime seem to be from email transactions; the
transactions in the log snippet you sent which gave the time as
16:50-17:33 were reflecting GMT and were not email transactions.

Jim,

Well, I don’t think so. I see the same kinds of transactions for both
local time and GMT entries. Here’s another excerpt, from this morning’s
logs. Local time is about 1am (GMT about 9am):

[Tue Dec 13 01:02:27 2005] [debug]: About to think about scrips for transaction #30794 (/usr/local/rt3/lib/RT/Transaction_Overlay.pm:154)
[Tue Dec 13 01:02:27 2005] [debug]: About to think about scrips for transaction #30795 (/usr/local/rt3/lib/RT/Transaction_Overlay.pm:154)
[Tue Dec 13 01:02:27 2005] [debug]: About to think about scrips for transaction #30796 (/usr/local/rt3/lib/RT/Transaction_Overlay.pm:154)
[Tue Dec 13 01:02:27 2005] [debug]: About to prepare scrips for transaction #30796 (/usr/local/rt3/lib/RT/Transaction_Overlay.pm:158)
[Tue Dec 13 01:02:27 2005] [debug]: Found 1 scrips (/usr/local/rt3/lib/RT/Scrips_Overlay.pm:354)
[Tue Dec 13 01:02:27 2005] [debug]: About to commit scrips for transaction #30796 (/usr/local/rt3/lib/RT/Transaction_Overlay.pm:167)
[Tue Dec 13 01:02:27 2005] [info]: rt-3.4.2-63174-30796-15.5.73348494846677@SNS #63174/30796 - Scrip 15 (/usr/local/rt3/lib/RT/Action/SendEmail.pm:235)
[Tue Dec 13 01:02:27 2005] [debug]: About to think about scrips for transaction #30797 (/usr/local/rt3/lib/RT/Transaction_Overlay.pm:154)
[Tue Dec 13 01:02:27 2005] [info]: rt-3.4.2-63174-30796-15.5.73348494846677@SNS sent To: everyone@3marbles.com Cc: Bcc: (/usr/local/rt3/lib/RT/Action/SendEmail.pm
:295)
[Tue Dec 13 01:02:27 2005] [info]: Ticket 63174 created in queue ‘security’ by everyone@3marbles.com (/usr/local/rt3/lib/RT/Ticket_Overlay.pm:730)
[Tue Dec 13 09:05:24 2005] [debug]: About to think about scrips for transaction #30798 (/usr/local/rt3/lib/RT/Transaction_Overlay.pm:154)
[Tue Dec 13 09:05:24 2005] [debug]: About to think about scrips for transaction #30799 (/usr/local/rt3/lib/RT/Transaction_Overlay.pm:154)
[Tue Dec 13 09:05:24 2005] [debug]: About to think about scrips for transaction #30800 (/usr/local/rt3/lib/RT/Transaction_Overlay.pm:154)
[Tue Dec 13 09:05:24 2005] [debug]: About to think about scrips for transaction #30801 (/usr/local/rt3/lib/RT/Transaction_Overlay.pm:154)
[Tue Dec 13 09:05:24 2005] [debug]: About to think about scrips for transaction #30802 (/usr/local/rt3/lib/RT/Transaction_Overlay.pm:154)

Mike

Mike Friedman System and Network Security
mikef@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/AwUBQ577E60bf1iNr4mCEQKMRACgu+WWjacf7vYLpOQhC6mB8n6Iq2YAoOz9
692/0mnePxY60t3yAa4nvx9r
=9c+x
-----END PGP SIGNATURE-----

Mike_Friedman · December 13, 2005, 5:35pm

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

I think I’ve found a correlation for transactions that get logged with
GMT, as opposed to local time. I have several perl scripts that use the
RT API. It seems that transactions resulting from those scripts get
logged with GMT, whereas transactions initiated from within RT (usually,
but not necessarily, triggered by email) get logged in local time.

I still don’t understand why this is, or how I can get all transactions to
be logged in local time. Maybe someone else has some ideas.

Thanks.

MikeOn Tue, 13 Dec 2005 at 08:47 (-0800), Mike Friedman wrote:

Well, I don’t think so. I see the same kinds of transactions for both local
time and GMT entries.

Mike Friedman System and Network Security
mikef@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/AwUBQ58GUq0bf1iNr4mCEQJEdwCggNeKaZvUSqr+OY0hyBejiWkHtmAAoOhN
zUuCl629mWPTT3Qpuj354di0
=kzQj
-----END PGP SIGNATURE-----

Mike_Friedman · December 14, 2005, 12:26am

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

I believe I’ve figured out what my problem was. It’s really quite simple,
now that I know what it is (!)

In order for my own scripts to pick up modules (i.e., RT.pm) from
local/lib, I need to include that library explicitly in my perl code.
Presumably, RT itself already does this, so it knows to honor overrides in
local/lib.

So, I changed

use lib qw (/usr/local/rt3/lib);

to

use lib qw (/usr/local/rt3/local/lib /usr/local/rt3/lib);

And now my perl scripts are using my modified RT.pm (in which I had
changed ‘gmtime’ to ‘localtime’), so logging from my scripts also uses
local time.

(Fortunately, there’s only one occurrence of the above ‘use’ statement
that I need to change for all my scripts. The statement appears only in
my own perl module where I keep all my functions that use the RT API).

MikeOn Tue, 13 Dec 2005 at 09:35 (-0800), Mike Friedman wrote:

I think I’ve found a correlation for transactions that get logged with
GMT, as opposed to local time. I have several perl scripts that use the
RT API. It seems that transactions resulting from those scripts get
logged with GMT, whereas transactions initiated from within RT (usually,
but not necessarily, triggered by email) get logged in local time.

I still don’t understand why this is, or how I can get all transactions
to be logged in local time. Maybe someone else has some ideas.

Mike Friedman System and Network Security
mikef@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/AwUBQ59mtq0bf1iNr4mCEQKV1wCgrpNQjiikR2zRIncG3X4NyVCCu5cAoLXt
IJp03mgZGhmZRBJ9Gxg9hDj8
=yFcN
-----END PGP SIGNATURE-----

Jim_Meyer1 · December 14, 2005, 3:14am

Hello!

I believe I’ve figured out what my problem was. It’s really quite simple,
now that I know what it is (!)

It always is, isn’t it? ;]

In order for my own scripts to pick up modules (i.e., RT.pm) from
local/lib, I need to include that library explicitly in my perl code.
Presumably, RT itself already does this, so it knows to honor overrides in
local/lib.

Sorta. I should have realized that you were using a whole copy of RT.pm
rather than putting only the function you need to override into
local/lib/RT_Local.pm, which is included by lib/RT.pm (using a require
statement at the end) and which will then cause your version of the
function to prevail.

I just kinda assumed that you knew the whole *_Local.pm trick (which
works for pretty much every major perl module in RT) … but since I
only learned it in the last three months, though, you’d think I’d
remember to mention it.

Cheers!

–j
Jim Meyer, Geek at Large purp@acm.org

Mike_Friedman · December 14, 2005, 11:12pm

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1On Tue, 13 Dec 2005 at 19:14 (-0800), Jim Meyer wrote:

Sorta. I should have realized that you were using a whole copy of RT.pm
rather than putting only the function you need to override into
local/lib/RT_Local.pm, which is included by lib/RT.pm (using a require
statement at the end) and which will then cause your version of the
function to prevail.

I just kinda assumed that you knew the whole *_Local.pm trick (which
works for pretty much every major perl module in RT) … but since I
only learned it in the last three months, though, you’d think I’d
remember to mention it.

Jim,

No, I didn’t know about the ‘*_Local.pm trick’. Where is this documented?

And even as I look in RT.pm and see the ‘eval require …’ statement, it’s
not obvious to me in which paths RT_Local.pm will be searched for, though
I assume from what you say that it will search local/lib first.

If you can point me to more information about this particular override
facility, I’d appreciate it.

Thanks.

Mike

Mike Friedman System and Network Security
mikef@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/AwUBQ6Cm060bf1iNr4mCEQIArgCfcAsi4JdndiRYnAgJ5a4oH8V10BkAniFf
NiikRu1EerjSnGwV+zl2NffA
=RWZw
-----END PGP SIGNATURE-----

Jim_Meyer1 · December 14, 2005, 11:47pm

Hello!On Wed, 2005-12-14 at 15:12, Mike Friedman wrote:

No, I didn’t know about the ‘*_Local.pm trick’. Where is this documented?

http://wiki.bestpractical.com/index.cgi?page_name=CleanlyCustomizeRT

Cheers!

–j
Jim Meyer, Geek at Large purp@acm.org

Mike_Friedman · January 28, 2006, 2:54am

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

Hi,

Is there a straightforward way for me to see who is currently logged in to
RT, assuming I have all the necessary privileges?

If it must be done by a direct database query (mysql in my case), then
what would the query look like? But I’d prefer doing it through RT
itself.

Thanks.

Mike

Mike Friedman System and Network Security
mikef@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+AwUBQ9rc4a0bf1iNr4mCEQK4HACYtFCsg75MyEGtbd3EF18w83EmnwCfexcM
iPudSIaZbRNaw8JxM3SJLkE=
=/VMG
-----END PGP SIGNATURE-----

Todd_Chapman1 · January 28, 2006, 7:17pm

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

Hi,

Is there a straightforward way for me to see who is currently logged in to
RT, assuming I have all the necessary privileges?

If it must be done by a direct database query (mysql in my case), then
what would the query look like? But I’d prefer doing it through RT
itself.

Thanks.

Mike

Mike,

I might be wrong, but I don’t think there is a way currently.
The sessions table in the database has open sessions, but that
just means someone is logged in. It doesn’t seem to record
who is logged in, but you could probably change the code
to track user name/id.

-Todd