Re: exit signal Alarm Clock

[Bill Moseley <mo...@hank.org>]

Will this thread ever go away?

At 05:47 PM 03/03/00 -0800, Doug MacEachern wrote:

>if you call print() or read() from a mod_perl script, a hard_timeout() is
>set, that does indeed call alarm() underneath (in ap_set_callback_and_alarm)

I don't see that in the output from truss.  At least not in my tests
running a forking Apache (but not running as root).  I do see it calling
ap_set_callback_and_alarm, but not alarm().

In the entire request I only see two alarm()s set, and they are the ones I
set.  The truss output is below, if curious.

Well, I would really like to understand this.  Here's more details about
the code Doug asked about where I mess with $SIG{ALRM}.  This is the only
place I touch $SIG{ALRM}.

    eval {
        local $SIG{__DIE__};
        local $SIG{ALRM} = sub { die 'Timed out' };
        alarm 30;
        $return = read_results( $query, *SEARCH, $start_time );
        alarm 0;
    };

SEARCH is reading from a pipe with open('-|').

read_results {
    my ( $query, $fh, $start ) = @_;

    while (<$fh>) {
       [gather what's returned]
       [nothing fancy]
    }

    print LOG_FILE scalar localtime(),
                   " some message PID $$ Total time:",
                   time() - $start,
                   "\n";
}

Ok, the eval block might be better just around the while() loop.


Here are my only clues:
   1) I see the time and PID in my LOG_FILE from the above print().
      The total time for the request is between 0 and 2 seconds.

   2) Apache Timeout seconds (300) later plus a few seconds,
      exit signal Alarm Clock is written to the error_log
      for this same PID.  (the child is killed, of course)

   3) The last entry in the access_log for this PID is for the request
      BEFORE this request.  This request is not logged in access_log.

- Somehow $SIG{ALRM} is becoming undefined
- Somehow alarm(Apache Timeout) is getting set

Then something happens where this request is not logged, and sits there
for Timeout seconds until alarm fires.  I guess.  Why else would the
request not get logged.  There's five minutes between the write to the
LOG_FILE and the exit signal Alarm -- lots of time to write to the access_log.

And this all happens after this child has run any number of requests
already without a problem.  Famous last works, but looking at the truss, I
don't see the above code causing any problems.

Oh well.  Might be easiest to edit http_main.c to not print the exit signal
message for alarms....



Apache/1.3.11 (Unix) mod_perl/1.21 perl 5.005_03.
This is the only mod_perl script running, and it's running RegistryNG.

here's the truss, if really bored:

...
read(3, " G E T   / s e a r c h ?".., 4096)     = 148
sigaction(SIGUSR1, 0xEFFFD608, 0xEFFFD688)      = 0
time()                                          = 952150474

   I've got this line in ap_set_callback_and_alarm():

      fprintf(stderr,"ap_set_callback_and_alarm\n");

   And here it is in action:

write(2, " a p _ s e t _ c a l l b".., 26)      = 26
write(2, " a p _ s e t _ c a l l b".., 26)      = 26
stat("/data/test/search", 0x00548908)           = 0
sigaction(SIGALRM, 0x00000000, 0xEFFFF560)      = 0
getpid()                                        = 13133 [13130]
time()                                          = 952150474
write(16, " [ F r i   M a r     3  ".., 88)     = 88
fcntl(16, F_DUP2FD, 0x00000002)                 = 2
getcontext(0xEFFFF190)
stat("/data/test/search", 0x0018FAEC)           = 0
 
   Here's RegistryNG chdir()ing before running the script

chdir("/data/test")                             = 0
time()                                          = 952150474

   Here's my open('-|')

pipe()                                          = 6 [7]
fork()                                          = 13503
close(7)                                        = 0
fcntl(6, F_SETFD, 0x00000001)                   = 0

  local $SIG{ALRM} = sub { die 'Timed out' };
  alarm( 30 );

sigaction(SIGALRM, 0xEFFFEF50, 0xEFFFEFD0)      = 0
sigaction(SIGALRM, 0xEFFFF038, 0xEFFFF0B8)      = 0
alarm(30)                                       = 0
fstat64(6, 0xEFFFD088)                          = 0
ioctl(6, TCGETA, 0xEFFFD014)                    Err#22 EINVAL

   while( <$fh> )

read(6, "[data from child]".., 5120)            = 404
read(6, 0x0053980C, 5120)                       = 0

Get the ending time.  (I wonder why I do it twice?)

time()                                          = 952150475
time()                                          = 952150475
fstat(5, 0x0018FAEC)                            = 0

  Here's the print LOG_FILE ...
  
stat("/data/test/error.log", 0x0018FAEC)        = 0
write(5, " N o   R e s u l t s\t k".., 143)     = 143

   Reset the alarm -- still 30 seconds left ;)

alarm(0)                                        = 30

   Exiting the block, and local does its magic

sigaction(SIGALRM, 0xEFFFEF58, 0xEFFFEFD8)      = 0
llseek(6, 0, SEEK_CUR)                          Err#29 ESPIPE
close(6)                                        = 0
sigaction(SIGHUP, 0xEFFFEF88, 0xEFFFF140)       = 0
sigaction(SIGINT, 0xEFFFEF88, 0xEFFFF100)       = 0
sigaction(SIGQUIT, 0xEFFFEF88, 0xEFFFF0C0)      = 0
waitid(P_PID, 13503, 0xEFFFEF28, WEXITED|WTRAPPED) = 0
....

Bill Moseley
mailto:moseley@hank.org

Re: exit signal Alarm Clock

[Doug MacEachern <do...@pobox.com>]

> SEARCH is reading from a pipe with open('-|').
...
> fork()                                          = 13503

well, a fork in the mix could be what's triggering the problem.
you'll need to give truss the -f flag to follow syscalls into the child.