You are viewing a plain text version of this content. The canonical link for it is here.
Posted to modperl@perl.apache.org by Carl Lipo <ca...@internap.com> on 2000/07/06 01:23:24 UTC
Apache::ASP and clock times
We are having a problem with our Apache::ASP scripts and the clock time
they are reporting. It seems that when an ASP script is run, the internal
clock is sometimes set to GMT. An example from our error log is shown
below. The problem is that our scripts expect localtime (PDT). The other
odd (and particularly frustrating) thing is that this problem is *not*
consistent. Sometimes we get GMT while other times we get localtime (PDT).
Its very odd. We have narrowed the problem down to mod_perl and/or
Apache::ASP. Has anyone seen this behavior before? Is there a
configuration problem?
The problem seems to start with the ScriptOnStart (not before that...) --
and lasts until the end of the ASP processing.
>>>> This is PDT, the correct local time <<<<<<<<<<<<<<<<<<<<<<<<<<<<
[Wed Jul 5 16:10:56 2000] [error] [asp] [29715] [debug] ASP object
created -
Application: Apache::ASP::Application=HASH(0x83532a8); GlobalASA: Apache::ASP::GlobalASA=HASH(0x81df93c); Internal: Apache::ASP::State=HASH(0x81eab5c); Request: Apache::ASP::Request=HASH(0x87ed180); Response: Apache::ASP::Response=HASH(0x87ed198); Server: Apache::ASP::Server=HASH(0x848891c); Session: Apache::ASP::Session=HASH(0x81e97a8); app_state: 1; basename: index.htm; buffering_on: 1; cgi_headers: 0; clean: 0; compile_includes: 0; cookie_path: /; dbg: 2; debugs_output: ARRAY(0x81a6990); errs: 0; filehandle: GLOB(0x8353284); filename: /office/common/infosource-wally/index.htm; filter: 1; global: /etc/apache/state-asp; global_package: ; group_refresh: 120; id: _office_common_infosource_wally_index_htmxINL; includes_dir: .; init_packages: ARRAY(0x8488964); mail_alert_to: ; mail_errors_to: infosource@internap.com; mtime: 962475992; no_cache: ; no_session: ; no_state: ; package: Apache::ASP::Compiles::_etc_apache_state_asp_global_asa; paranoid_session: 0; pod_comments: 1; r: Apache=SCALAR(0x81e9610); remote_ip: 216.223.5.149; secure_session: ; session_serialize: ; session_timeout: 1200; stat_inc: ; stat_inc_match: ; state_cache: ; state_db: DB_File; state_dir: /etc/apache/state-asp/.state; state_manager: 10; ua: Mozilla/4.72
[en] (X11; U; Linux 2.2.13 i686); unique_packages: 0;
[Wed Jul 5 16:10:56 2000] [error] [asp] [29715] [debug] inlining include home-go.include
[Wed Jul 5 16:10:56 2000] [error] [asp] [29715] [debug] inlining include links/internap.links
[Wed Jul 5 16:10:56 2000] [error] [asp] [29715] [debug] active undefing
sub Apache::ASP::Compiles::_etc_apache_state_asp_global_asa::_office_common_infosource_wally_index_htmxINL
code CODE(0x87ef78c) before compiling
[Wed Jul 5 16:10:56 2000] [error] [asp] [29715] [debug] compiling into
package Apache::ASP::Compiles::_etc_apache_state_asp_global_asa subid
Apache::ASP::Compiles::_etc_apache_state_asp_global_asa::_office_common_infosource_wally_index_htmxINL
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
-->>> note here is the Script_OnStart. Notice how the time changes!
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
[Wed Jul 5 23:10:56 2000] [error] [asp] [29715] [debug] Script_OnStart
[Wed Jul 5 23:10:56 2000] [error] [asp] [29715] [debug] executing
Script_OnStart
[Wed Jul 5 23:10:56 2000] [error] [asp] [29715] Time is now (localtime(time()):
[Wed Jul 5 23:10:56 2000] [error] [asp] [29715] 56 10 23 5 6 100 3 186
>>>> printing localtime(time()) [above] shows that perl really thinks it
>>>> is this later [GMT time] <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
[Wed Jul 5 23:10:56 2000] [error] [asp] [29715] [debug] executing
_office_common_infosource_wally_index_htmxINL
[Wed Jul 5 23:10:58 2000] [error] [asp] [29715] ************ INDEX.HTM*************
[Wed Jul 5 23:10:58 2000] [error] [asp] [29715] ***** INDEX USER: carl*****
[Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] active undefing sub
Apache::ASP::Compiles::_etc_apache_state_asp_global_asa::_etc_apache_state_asp_footer
code CODE(0x88cce9c) before compiling
[Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] executing
Apache::ASP::Compiles::_etc_apache_state_asp_global_asa::_etc_apache_state_asp_footer
[Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] Script_OnEnd
[Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] executing Script_OnEnd
[Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] building cgi headers
[Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] status 200
[Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] destroying - asp: Apache::ASP=HASH(0x856293c);
[Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] testing internal time for cleanup groups
[Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] state application locks: 1, unlocks: 1
[Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] state application locks: 0, unlocks: 0
[Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] state internal locks: 4, unlocks: 4
[Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] state internal locks: 0, unlocks: 0
[Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] state 08a41d19d762fbf748c15fe02b8c76ce locks: 35, unlocks: 35
[Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] END ASP DESTROY
----------------------------------------------------------------------------
Carl Lipo EMAIL: carl@internap.com
IT Systems Architect PAGER: 888.393.5620
InterNAP Network Services OFFICE: 206.504.5442
601 Union Street, Suite 1000 FAX: 206.264.1833
Seattle, WA 98101 CELL: 206.579.0163
Unauthorized use, disclosure or distribution of information within
this message is prohibited.
Re: Apache::ASP and clock times
Posted by Carl Lipo <ca...@internap.com>.
We are not sure why but it appears that the time problem may end up being
specific to a DSO enabled, debian distribution of apache. When we
recompiled a static version, the time that the ASP processes reported
remained the same as the system clock (no changes from PDT to GMT). It
looks like this is a bad-compilation problem or an effect of DSO.
On Fri, 7 Jul 2000, Vivek Khera wrote:
> >>>>> "JC" == Joshua Chamas <jo...@chamas.com> writes:
>
> JC> It may be possible that the time calculation is based
> JC> on some TZ* environment variable that is not consistent,
>
> It has been my experience that the first time any of the system
> date/time routines are called and TZ is set, that becomes the
> permanent time zone until the process goes away. So it could be
> something totally other than ASP setting the time zone for the
> process.
>
>
Re: Apache::ASP and clock times
Posted by Vivek Khera <kh...@kciLink.com>.
>>>>> "JC" == Joshua Chamas <jo...@chamas.com> writes:
JC> It may be possible that the time calculation is based
JC> on some TZ* environment variable that is not consistent,
It has been my experience that the first time any of the system
date/time routines are called and TZ is set, that becomes the
permanent time zone until the process goes away. So it could be
something totally other than ASP setting the time zone for the
process.
Re: Apache::ASP and clock times
Posted by Joshua Chamas <jo...@chamas.com>.
In a situation like this, I would make sure that
you compiled your Apache/modperl from scratch, and
maybe do it again just to make sure. Maybe you
are using some stock RedHat build, that has odd
quirks to it, and your own static build would
just make this disappear.
Its a terrible was to deal with this kind of problem
buts its so utterly bizarre.
Maybe someone else has a better idea for you? Not me.
--Joshua
Carl Lipo wrote:
>
> > That the error_log date itself is changing seems
> > to me that Apache also thinks its the wrong time.
> > If this were consistent, I would think that your box
> > just has the wrong timezone set, but that this is
> > inconsistent is bizarre.
>
> Yes, this is the problem. If it was just a matter of being one time or the
> other, we could deal. But since its inconsistent --> its a serious
> problem.
> >
> > It may be possible that the time calculation is based
> > on some TZ* environment variable that is not consistent,
> > perhaps being set by some scripts & something? Still
> > bizarre but seems plausible to me. I would log the
> > data from %ENV in Script_OnStart , and see how it differs
> > between these time changes.
>
> Thats what we thought. However, if we print out the TZ variable in the
> Script_OnStart it consistently comes out PDT regardless of the time that
> the server reports. Argh.
>
> >
> > Anyone else have any ideas here ?
> >
> > Looking at your Apache::ASP settings I would recommend
> > that you set StateDir to some /tmp or /var area, instead
> > of the default in Global/.state for better housekeeping.
> > Global is really good for includes, global.asa, and
> > perl modules, and I would keep the state files out of
> > there which are dynamic bits.
> >
>
> Good point. We need to clean that up.
>
> > --Joshua
> >
> > Carl Lipo wrote:
> > >
> > > We are having a problem with our Apache::ASP scripts and the clock time
> > > they are reporting. It seems that when an ASP script is run, the internal
> > > clock is sometimes set to GMT. An example from our error log is shown
> > > below. The problem is that our scripts expect localtime (PDT). The other
> > > odd (and particularly frustrating) thing is that this problem is *not*
> > > consistent. Sometimes we get GMT while other times we get localtime (PDT).
> > > Its very odd. We have narrowed the problem down to mod_perl and/or
> > > Apache::ASP. Has anyone seen this behavior before? Is there a
> > > configuration problem?
> > >
> > > The problem seems to start with the ScriptOnStart (not before that...) --
> > > and lasts until the end of the ASP processing.
> > >
> > > >>>> This is PDT, the correct local time <<<<<<<<<<<<<<<<<<<<<<<<<<<<
> > > [Wed Jul 5 16:10:56 2000] [error] [asp] [29715] [debug] ASP object
> > > created -
> > > Application: Apache::ASP::Application=HASH(0x83532a8); GlobalASA: Apache::ASP::GlobalASA=HASH(0x81df93c); Internal: Apache::ASP::State=HASH(0x81eab5c); Request: Apache::ASP::Request=HASH(0x87ed180); Response: Apache::ASP::Response=HASH(0x87ed198); Server: Apache::ASP::Server=HASH(0x848891c); Session: Apache::ASP::Session=HASH(0x81e97a8); app_state: 1; basename: index.htm; buffering_on: 1; cgi_headers: 0; clean: 0; compile_includes: 0; cookie_path: /; dbg: 2; debugs_output: ARRAY(0x81a6990); errs: 0; filehandle: GLOB(0x8353284); filename: /office/common/infosource-wally/index.htm; filter: 1; global: /etc/apache/state-asp; global_package: ; group_refresh: 120; id: _office_common_infosource_wally_index_htmxINL; includes_dir: .; init_packages: ARRAY(0x8488964); mail_alert_to: ; mail_errors_to: infosource@internap.com; mtime: 962475992; no_cache: ; no_session: ; no_state: ; package: Apache::ASP::Compiles::_etc_apache_state_asp_global_asa; paranoid_session: 0; pod_comments: 1;!
r!
> !
> :
> > > Apache=SCALAR(0x81e9610); remote_ip: 216.223.5.149; secure_session: ; session_serialize: ; session_timeout: 1200; stat_inc: ; stat_inc_match: ; state_cache: ; state_db: DB_File; state_dir: /etc/apache/state-asp/.state; state_manager: 10; ua: Mozilla/4.72
> > > [en] (X11; U; Linux 2.2.13 i686); unique_packages: 0;
> > > [Wed Jul 5 16:10:56 2000] [error] [asp] [29715] [debug] inlining include home-go.include
> > > [Wed Jul 5 16:10:56 2000] [error] [asp] [29715] [debug] inlining include links/internap.links
> > > [Wed Jul 5 16:10:56 2000] [error] [asp] [29715] [debug] active undefing
> > > sub Apache::ASP::Compiles::_etc_apache_state_asp_global_asa::_office_common_infosource_wally_index_htmxINL
> > > code CODE(0x87ef78c) before compiling
> > > [Wed Jul 5 16:10:56 2000] [error] [asp] [29715] [debug] compiling into
> > > package Apache::ASP::Compiles::_etc_apache_state_asp_global_asa subid
> > > Apache::ASP::Compiles::_etc_apache_state_asp_global_asa::_office_common_infosource_wally_index_htmxINL
> > >
> > > >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
> > > -->>> note here is the Script_OnStart. Notice how the time changes!
> > > >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
> > > [Wed Jul 5 23:10:56 2000] [error] [asp] [29715] [debug] Script_OnStart
> > > [Wed Jul 5 23:10:56 2000] [error] [asp] [29715] [debug] executing
> > > Script_OnStart
> > > [Wed Jul 5 23:10:56 2000] [error] [asp] [29715] Time is now (localtime(time()):
> > > [Wed Jul 5 23:10:56 2000] [error] [asp] [29715] 56 10 23 5 6 100 3 186
> > > >>>> printing localtime(time()) [above] shows that perl really thinks it
> > > >>>> is this later [GMT time] <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
> > >
> > > [Wed Jul 5 23:10:56 2000] [error] [asp] [29715] [debug] executing
> > > _office_common_infosource_wally_index_htmxINL
> > > [Wed Jul 5 23:10:58 2000] [error] [asp] [29715] ************ INDEX.HTM*************
> > > [Wed Jul 5 23:10:58 2000] [error] [asp] [29715] ***** INDEX USER: carl*****
> > > [Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] active undefing sub
> > > Apache::ASP::Compiles::_etc_apache_state_asp_global_asa::_etc_apache_state_asp_footer
> > > code CODE(0x88cce9c) before compiling
> > > [Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] executing
> > > Apache::ASP::Compiles::_etc_apache_state_asp_global_asa::_etc_apache_state_asp_footer
> > > [Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] Script_OnEnd
> > > [Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] executing Script_OnEnd
> > > [Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] building cgi headers
> > > [Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] status 200
> > > [Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] destroying - asp: Apache::ASP=HASH(0x856293c);
> > > [Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] testing internal time for cleanup groups
> > > [Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] state application locks: 1, unlocks: 1
> > > [Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] state application locks: 0, unlocks: 0
> > > [Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] state internal locks: 4, unlocks: 4
> > > [Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] state internal locks: 0, unlocks: 0
> > > [Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] state 08a41d19d762fbf748c15fe02b8c76ce locks: 35, unlocks: 35
> > > [Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] END ASP DESTROY
> > >
> > >
> > > ----------------------------------------------------------------------------
> > > Carl Lipo EMAIL: carl@internap.com
> > > IT Systems Architect PAGER: 888.393.5620
> > > InterNAP Network Services OFFICE: 206.504.5442
> > > 601 Union Street, Suite 1000 FAX: 206.264.1833
> > > Seattle, WA 98101 CELL: 206.579.0163
> > >
> > > Unauthorized use, disclosure or distribution of information within
> > > this message is prohibited.
> >
> >
Re: Apache::ASP and clock times
Posted by Carl Lipo <ca...@internap.com>.
> That the error_log date itself is changing seems
> to me that Apache also thinks its the wrong time.
> If this were consistent, I would think that your box
> just has the wrong timezone set, but that this is
> inconsistent is bizarre.
Yes, this is the problem. If it was just a matter of being one time or the
other, we could deal. But since its inconsistent --> its a serious
problem.
>
> It may be possible that the time calculation is based
> on some TZ* environment variable that is not consistent,
> perhaps being set by some scripts & something? Still
> bizarre but seems plausible to me. I would log the
> data from %ENV in Script_OnStart , and see how it differs
> between these time changes.
Thats what we thought. However, if we print out the TZ variable in the
Script_OnStart it consistently comes out PDT regardless of the time that
the server reports. Argh.
>
> Anyone else have any ideas here ?
>
> Looking at your Apache::ASP settings I would recommend
> that you set StateDir to some /tmp or /var area, instead
> of the default in Global/.state for better housekeeping.
> Global is really good for includes, global.asa, and
> perl modules, and I would keep the state files out of
> there which are dynamic bits.
>
Good point. We need to clean that up.
> --Joshua
>
> Carl Lipo wrote:
> >
> > We are having a problem with our Apache::ASP scripts and the clock time
> > they are reporting. It seems that when an ASP script is run, the internal
> > clock is sometimes set to GMT. An example from our error log is shown
> > below. The problem is that our scripts expect localtime (PDT). The other
> > odd (and particularly frustrating) thing is that this problem is *not*
> > consistent. Sometimes we get GMT while other times we get localtime (PDT).
> > Its very odd. We have narrowed the problem down to mod_perl and/or
> > Apache::ASP. Has anyone seen this behavior before? Is there a
> > configuration problem?
> >
> > The problem seems to start with the ScriptOnStart (not before that...) --
> > and lasts until the end of the ASP processing.
> >
> > >>>> This is PDT, the correct local time <<<<<<<<<<<<<<<<<<<<<<<<<<<<
> > [Wed Jul 5 16:10:56 2000] [error] [asp] [29715] [debug] ASP object
> > created -
> > Application: Apache::ASP::Application=HASH(0x83532a8); GlobalASA: Apache::ASP::GlobalASA=HASH(0x81df93c); Internal: Apache::ASP::State=HASH(0x81eab5c); Request: Apache::ASP::Request=HASH(0x87ed180); Response: Apache::ASP::Response=HASH(0x87ed198); Server: Apache::ASP::Server=HASH(0x848891c); Session: Apache::ASP::Session=HASH(0x81e97a8); app_state: 1; basename: index.htm; buffering_on: 1; cgi_headers: 0; clean: 0; compile_includes: 0; cookie_path: /; dbg: 2; debugs_output: ARRAY(0x81a6990); errs: 0; filehandle: GLOB(0x8353284); filename: /office/common/infosource-wally/index.htm; filter: 1; global: /etc/apache/state-asp; global_package: ; group_refresh: 120; id: _office_common_infosource_wally_index_htmxINL; includes_dir: .; init_packages: ARRAY(0x8488964); mail_alert_to: ; mail_errors_to: infosource@internap.com; mtime: 962475992; no_cache: ; no_session: ; no_state: ; package: Apache::ASP::Compiles::_etc_apache_state_asp_global_asa; paranoid_session: 0; pod_comments: 1; r!
:
> > Apache=SCALAR(0x81e9610); remote_ip: 216.223.5.149; secure_session: ; session_serialize: ; session_timeout: 1200; stat_inc: ; stat_inc_match: ; state_cache: ; state_db: DB_File; state_dir: /etc/apache/state-asp/.state; state_manager: 10; ua: Mozilla/4.72
> > [en] (X11; U; Linux 2.2.13 i686); unique_packages: 0;
> > [Wed Jul 5 16:10:56 2000] [error] [asp] [29715] [debug] inlining include home-go.include
> > [Wed Jul 5 16:10:56 2000] [error] [asp] [29715] [debug] inlining include links/internap.links
> > [Wed Jul 5 16:10:56 2000] [error] [asp] [29715] [debug] active undefing
> > sub Apache::ASP::Compiles::_etc_apache_state_asp_global_asa::_office_common_infosource_wally_index_htmxINL
> > code CODE(0x87ef78c) before compiling
> > [Wed Jul 5 16:10:56 2000] [error] [asp] [29715] [debug] compiling into
> > package Apache::ASP::Compiles::_etc_apache_state_asp_global_asa subid
> > Apache::ASP::Compiles::_etc_apache_state_asp_global_asa::_office_common_infosource_wally_index_htmxINL
> >
> > >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
> > -->>> note here is the Script_OnStart. Notice how the time changes!
> > >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
> > [Wed Jul 5 23:10:56 2000] [error] [asp] [29715] [debug] Script_OnStart
> > [Wed Jul 5 23:10:56 2000] [error] [asp] [29715] [debug] executing
> > Script_OnStart
> > [Wed Jul 5 23:10:56 2000] [error] [asp] [29715] Time is now (localtime(time()):
> > [Wed Jul 5 23:10:56 2000] [error] [asp] [29715] 56 10 23 5 6 100 3 186
> > >>>> printing localtime(time()) [above] shows that perl really thinks it
> > >>>> is this later [GMT time] <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
> >
> > [Wed Jul 5 23:10:56 2000] [error] [asp] [29715] [debug] executing
> > _office_common_infosource_wally_index_htmxINL
> > [Wed Jul 5 23:10:58 2000] [error] [asp] [29715] ************ INDEX.HTM*************
> > [Wed Jul 5 23:10:58 2000] [error] [asp] [29715] ***** INDEX USER: carl*****
> > [Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] active undefing sub
> > Apache::ASP::Compiles::_etc_apache_state_asp_global_asa::_etc_apache_state_asp_footer
> > code CODE(0x88cce9c) before compiling
> > [Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] executing
> > Apache::ASP::Compiles::_etc_apache_state_asp_global_asa::_etc_apache_state_asp_footer
> > [Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] Script_OnEnd
> > [Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] executing Script_OnEnd
> > [Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] building cgi headers
> > [Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] status 200
> > [Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] destroying - asp: Apache::ASP=HASH(0x856293c);
> > [Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] testing internal time for cleanup groups
> > [Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] state application locks: 1, unlocks: 1
> > [Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] state application locks: 0, unlocks: 0
> > [Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] state internal locks: 4, unlocks: 4
> > [Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] state internal locks: 0, unlocks: 0
> > [Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] state 08a41d19d762fbf748c15fe02b8c76ce locks: 35, unlocks: 35
> > [Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] END ASP DESTROY
> >
> >
> > ----------------------------------------------------------------------------
> > Carl Lipo EMAIL: carl@internap.com
> > IT Systems Architect PAGER: 888.393.5620
> > InterNAP Network Services OFFICE: 206.504.5442
> > 601 Union Street, Suite 1000 FAX: 206.264.1833
> > Seattle, WA 98101 CELL: 206.579.0163
> >
> > Unauthorized use, disclosure or distribution of information within
> > this message is prohibited.
>
>
Re: Apache::ASP and clock times
Posted by Joshua Chamas <jo...@chamas.com>.
That the error_log date itself is changing seems
to me that Apache also thinks its the wrong time.
If this were consistent, I would think that your box
just has the wrong timezone set, but that this is
inconsistent is bizarre.
It may be possible that the time calculation is based
on some TZ* environment variable that is not consistent,
perhaps being set by some scripts & something? Still
bizarre but seems plausible to me. I would log the
data from %ENV in Script_OnStart , and see how it differs
between these time changes.
Anyone else have any ideas here ?
Looking at your Apache::ASP settings I would recommend
that you set StateDir to some /tmp or /var area, instead
of the default in Global/.state for better housekeeping.
Global is really good for includes, global.asa, and
perl modules, and I would keep the state files out of
there which are dynamic bits.
--Joshua
Carl Lipo wrote:
>
> We are having a problem with our Apache::ASP scripts and the clock time
> they are reporting. It seems that when an ASP script is run, the internal
> clock is sometimes set to GMT. An example from our error log is shown
> below. The problem is that our scripts expect localtime (PDT). The other
> odd (and particularly frustrating) thing is that this problem is *not*
> consistent. Sometimes we get GMT while other times we get localtime (PDT).
> Its very odd. We have narrowed the problem down to mod_perl and/or
> Apache::ASP. Has anyone seen this behavior before? Is there a
> configuration problem?
>
> The problem seems to start with the ScriptOnStart (not before that...) --
> and lasts until the end of the ASP processing.
>
> >>>> This is PDT, the correct local time <<<<<<<<<<<<<<<<<<<<<<<<<<<<
> [Wed Jul 5 16:10:56 2000] [error] [asp] [29715] [debug] ASP object
> created -
> Application: Apache::ASP::Application=HASH(0x83532a8); GlobalASA: Apache::ASP::GlobalASA=HASH(0x81df93c); Internal: Apache::ASP::State=HASH(0x81eab5c); Request: Apache::ASP::Request=HASH(0x87ed180); Response: Apache::ASP::Response=HASH(0x87ed198); Server: Apache::ASP::Server=HASH(0x848891c); Session: Apache::ASP::Session=HASH(0x81e97a8); app_state: 1; basename: index.htm; buffering_on: 1; cgi_headers: 0; clean: 0; compile_includes: 0; cookie_path: /; dbg: 2; debugs_output: ARRAY(0x81a6990); errs: 0; filehandle: GLOB(0x8353284); filename: /office/common/infosource-wally/index.htm; filter: 1; global: /etc/apache/state-asp; global_package: ; group_refresh: 120; id: _office_common_infosource_wally_index_htmxINL; includes_dir: .; init_packages: ARRAY(0x8488964); mail_alert_to: ; mail_errors_to: infosource@internap.com; mtime: 962475992; no_cache: ; no_session: ; no_state: ; package: Apache::ASP::Compiles::_etc_apache_state_asp_global_asa; paranoid_session: 0; pod_comments: 1; r:
> Apache=SCALAR(0x81e9610); remote_ip: 216.223.5.149; secure_session: ; session_serialize: ; session_timeout: 1200; stat_inc: ; stat_inc_match: ; state_cache: ; state_db: DB_File; state_dir: /etc/apache/state-asp/.state; state_manager: 10; ua: Mozilla/4.72
> [en] (X11; U; Linux 2.2.13 i686); unique_packages: 0;
> [Wed Jul 5 16:10:56 2000] [error] [asp] [29715] [debug] inlining include home-go.include
> [Wed Jul 5 16:10:56 2000] [error] [asp] [29715] [debug] inlining include links/internap.links
> [Wed Jul 5 16:10:56 2000] [error] [asp] [29715] [debug] active undefing
> sub Apache::ASP::Compiles::_etc_apache_state_asp_global_asa::_office_common_infosource_wally_index_htmxINL
> code CODE(0x87ef78c) before compiling
> [Wed Jul 5 16:10:56 2000] [error] [asp] [29715] [debug] compiling into
> package Apache::ASP::Compiles::_etc_apache_state_asp_global_asa subid
> Apache::ASP::Compiles::_etc_apache_state_asp_global_asa::_office_common_infosource_wally_index_htmxINL
>
> >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
> -->>> note here is the Script_OnStart. Notice how the time changes!
> >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
> [Wed Jul 5 23:10:56 2000] [error] [asp] [29715] [debug] Script_OnStart
> [Wed Jul 5 23:10:56 2000] [error] [asp] [29715] [debug] executing
> Script_OnStart
> [Wed Jul 5 23:10:56 2000] [error] [asp] [29715] Time is now (localtime(time()):
> [Wed Jul 5 23:10:56 2000] [error] [asp] [29715] 56 10 23 5 6 100 3 186
> >>>> printing localtime(time()) [above] shows that perl really thinks it
> >>>> is this later [GMT time] <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
>
> [Wed Jul 5 23:10:56 2000] [error] [asp] [29715] [debug] executing
> _office_common_infosource_wally_index_htmxINL
> [Wed Jul 5 23:10:58 2000] [error] [asp] [29715] ************ INDEX.HTM*************
> [Wed Jul 5 23:10:58 2000] [error] [asp] [29715] ***** INDEX USER: carl*****
> [Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] active undefing sub
> Apache::ASP::Compiles::_etc_apache_state_asp_global_asa::_etc_apache_state_asp_footer
> code CODE(0x88cce9c) before compiling
> [Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] executing
> Apache::ASP::Compiles::_etc_apache_state_asp_global_asa::_etc_apache_state_asp_footer
> [Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] Script_OnEnd
> [Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] executing Script_OnEnd
> [Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] building cgi headers
> [Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] status 200
> [Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] destroying - asp: Apache::ASP=HASH(0x856293c);
> [Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] testing internal time for cleanup groups
> [Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] state application locks: 1, unlocks: 1
> [Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] state application locks: 0, unlocks: 0
> [Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] state internal locks: 4, unlocks: 4
> [Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] state internal locks: 0, unlocks: 0
> [Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] state 08a41d19d762fbf748c15fe02b8c76ce locks: 35, unlocks: 35
> [Wed Jul 5 23:10:59 2000] [error] [asp] [29715] [debug] END ASP DESTROY
>
>
> ----------------------------------------------------------------------------
> Carl Lipo EMAIL: carl@internap.com
> IT Systems Architect PAGER: 888.393.5620
> InterNAP Network Services OFFICE: 206.504.5442
> 601 Union Street, Suite 1000 FAX: 206.264.1833
> Seattle, WA 98101 CELL: 206.579.0163
>
> Unauthorized use, disclosure or distribution of information within
> this message is prohibited.