Now let's use the knowledge we have acquired to trace the execution of the code and watch all the events as they happen. Let's take a simple Apache::Registryscript that purposely hangs the server process, like the one in Example 6-28.

Example 6-28. stopping_detector.pl

my $r = shift;
$r->send_http_header('text/plain');

print "PID = $$\n";
$r->rflush;

while (1) {
    sleep 1;
}

The script gets a request object $r by shift( ) ing it from the @_ argument list (passed by the handler( )subroutine that was created on the fly by Apache::Registry). Then the script sends a Content-Type header telling the client that we are going to send a plain-text response.

Next, the script prints out a single line telling us the ID of the process that handled the request, which we need to know in order to run the tracing utility. Then we flush Apache's STDOUT buffer. If we don't flush the buffer, we will never see this information printed (our output is shorter than the buffer size used for print( ), and the script intentionally hangs, so the buffer won't be auto-flushed).[31]

[31]Buffering is used to reduce the number of system calls (which do the actual writing) and therefore improve performance. When the buffer (usually a few kilobytes in size) is getting full, it's flushed and the data is written.

Then we enter an infinite while loop that does nothing but sleep( ), emulating code that doesn't generate any output. For example, it might be a long-running mathematical calculation, a database query, or a search for extraterrestrial life.

Running strace -p PID, where PID is the process ID as printed on the browser, we see the following output printed every second:

rt_sigprocmask(SIG_BLOCK, [CHLD], [  ], 8)  = 0
rt_sigaction(SIGCHLD, NULL, {SIG_DFL}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [  ], NULL, 8)  = 0
nanosleep({1, 0}, {1, 0})                 = 0
time([978969822])                         = 978969822
time([978969822])                         = 978969822

Alternatively, we can run the server in single-server mode. In single-server mode, we don't need to print the process ID, since the PID is the process of the single mod_perl process that we're running. When the process is started in the background, the shell program usually prints the PID of the process, as shown here:

panic% httpd -X &
 [1] 20107

Now we know what process we have to attach to with strace (or a similar utility):

panic% strace -p 20107
rt_sigprocmask(SIG_BLOCK, [CHLD], [  ], 8)  = 0
rt_sigaction(SIGCHLD, NULL, {SIG_DFL}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [  ], NULL, 8)  = 0
nanosleep({1, 0}, {1, 0})                 = 0
time([978969822])                         = 978969822
time([978969822])                         = 978969822

We see the same output as before.

Let's leave strace running and press the Stop button. Did anything change? No, the same system calls trace is printed every second, which means that Apache didn't detect the broken connection.

Now we are going to write \0 (NULL) characters to the client in an attempt to detect the broken connection as soon as possible after the Stop button is pressed. Since these are NULL characters, they won't be seen in the output. Therefore, we modify the loop code in the following way:

while (1) {
    $r->print("\0");
    last if $r->connection->aborted;
    sleep 1;
}

We add a print( )statement to print a NULL character, then we check whether the connection was aborted, with the help of the $r->connection->aborted method. If the connection is broken, we break out of the loop.

We run this script and run strace on it as before, but we see that it still doesn't work—the script doesn't stop when the Stop button is pressed.

The problem is that we aren't flushing the buffer. The NULL characters won't be printed until the buffer is full and is autoflushed. Since we want to try writing to the connection pipe all the time, we add an $r->rflush( ) call. Example 6-29 is a new version of the code.

Example 6-29. stopping_detector2.pl

my $r = shift;
$r->send_http_header('text/plain');

print "PID = $$\n";
$r->rflush;

while (1) {
    $r->print("\0");
    $r->rflush;
    last if $r->connection->aborted;
    sleep 1;
}

After starting the strace utility on the running process and pressing the Stop button, we see the following output:

rt_sigprocmask(SIG_BLOCK, [CHLD], [  ], 8)  = 0
rt_sigaction(SIGCHLD, NULL, {SIG_DFL}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [  ], NULL, 8)  = 0
nanosleep({1, 0}, {1, 0})               = 0
time([978970895])                       = 978970895
alarm(300)                              = 0
alarm(0)                                = 300
write(3, "\0", 1)                       = -1 EPIPE (Broken pipe)
--- SIGPIPE (Broken pipe) ---
chdir("/usr/src/httpd_perl")            = 0
select(4, [3], NULL, NULL, {0, 0})      = 1 (in [3], left {0, 0})
time(NULL)                              = 978970895
write(17, "127.0.0.1 - - [08/Jan/2001:19:21"..., 92) = 92
gettimeofday({978970895, 554755}, NULL) = 0
times({tms_utime=46, tms_stime=5, tms_cutime=0, 
  tms_cstime=0}) = 8425400
close(3)                                = 0
rt_sigaction(SIGUSR1, {0x8099524, [  ], SA_INTERRUPT|0x4000000}, 
  {SIG_IGN}, 8) = 0alarm(0)                                = 0
rt_sigprocmask(SIG_BLOCK, NULL, [  ], 8)  = 0
rt_sigaction(SIGALRM, {0x8098168, [  ], SA_RESTART|0x4000000}, 
  {0x8098168, [  ], SA_INTERRUPT|0x4000000}, 8) = 0
fcntl(18, F_SETLKW, {type=F_WRLCK, whence=SEEK_SET, 
  start=0, len=0}) = 0

Apache detects the broken pipe, as you can see from this snippet:

write(3, "\0", 1)                       = -1 EPIPE (Broken pipe)
--- SIGPIPE (Broken pipe) ---

Then it stops the script and does all the cleanup work, such as access logging:

write(17, "127.0.0.1 - - [08/Jan/2001:19:21"..., 92) = 92

where 17 is a file descriptor of the opened access_log file.