Re^8: apache/perl caching problem

[ksublondie]

"...verify this by having your script log its start time, process ID, version and the full path and modification time of the file loaded..."

I've implemented logging to view the pid's and yes, I'm seeing duplicate numbers. I can figure out how to view the version, full path & modification time of a different file, but how would you view the current file that is being executed? It looks like there are entries in the log for each execution. Would it be a safe assumption that each request is being handled by the server in question and not a problem with the network infrastructure?

"...By "standard CGI script" I mean a script that is read from disk and executed once for each request. An implication (or perhaps I should say assumption of mine) is that a perl interpreter is started for each request. This is in distinction to a script running in the context of mod_perl, FastCGI or some other context which transforms or encapsulates it in a persistent process that handles several requests before terminating..."

I *THINK* it's a "standard CGI script", but honestly, I'm not positive... This started out as a basic site someone else designed using login sessions. Since I've taken it over, I've added modules and additional sections to the site that are all blanketed under the session. I DO have "use CGI ':standard';" in my code. Does that make it a "standard CGI script"?

[ig]

The following is not a CGI script (it doesn't produce headers or any useful output) but it does show how you can log the name of the script, the directory it is located in, the process id it is running as and a version. You could incorporate something similar into your script.

#!/usr/bin/perl
use strict;
use warnings;
use FindBin;

my $VERSION = "1.0";

print STDERR "This is $0 version $VERSION located in $FindBin::Bin run
+ning as process $$\n";

Output from a few executions is as follows:

ian@laptop2:~$ ./test.pl
This is ./test.pl version 1.0 located in /home/ian running as process 
+6119
ian@laptop2:~$ ./test.pl
This is ./test.pl version 1.0 located in /home/ian running as process 
+6120
ian@laptop2:~$ ./test.pl
This is ./test.pl version 1.0 located in /home/ian running as process 
+6121

Note that the process id is different every time I run the script.

If you add similar logging to your CGI script, you should be able to find the output in your website error log. Then, if you change the version number every time you change the script, you will have a record of what version was running and what process number was running it. You could change only the version number, just to make a change, then restart your server and check the logs for entries with the old version number appearing after the restart. If you find one, use the ps command to find out what the process is. This will help to isolate the problem.

If you see a log entry on your server every time you submit a request from your browser, then it is reasonable to conclude the requests are making it to the server. There is still the possibility that the requests and/or responses are being modified between the server and browser. This is unusual, but it can happen. Don't worry about that yet. First, confirm that the server is running your script once for each request from the browser. Then confirm that each time your server runs your script it runs the "current" version. You might include the scripts version number in both the log and the response to the browser: you can put it in an HTML comment if you don't want it to be visible in the browser. Then you can check that the response received at the browser is from the current version of your script, or at least the same as the version that ran on the server.

[ksublondie]

Interesting...

Tue May  4 17:29:33 2010 process id=28886 version=1.0/usr/sbin
Tue May  4 17:29:36 2010 process id=29076 version=1.0/usr/sbin
Tue May  4 17:29:38 2010 process id=29076 version=1.0/usr/sbin
Tue May  4 17:29:39 2010 process id=29076 version=1.0/usr/sbin
Tue May  4 17:29:41 2010 process id=28075 version=1.0/usr/sbin
Tue May  4 17:29:43 2010 process id=28075 version=1.0/usr/sbin
Tue May  4 17:29:45 2010 process id=28886 version=1.0/usr/sbin
Tue May  4 17:31:11 2010 process id=28651 version=1.0 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 17:31:14 2010 process id=28651 version=1.0 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 17:31:15 2010 process id=29230 version=1.0 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 17:31:17 2010 process id=28651 version=1.0 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 17:31:19 2010 process id=29230 version=1.0 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 17:31:21 2010 process id=28651 version=1.0 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 17:31:22 2010 process id=29230 version=1.0 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 17:31:24 2010 process id=28651 version=1.0 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 17:31:25 2010 process id=29230 version=1.0 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 17:31:26 2010 process id=28651 version=1.0 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 17:31:28 2010 process id=29230 version=1.0 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 17:31:30 2010 process id=29230 version=1.0 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 17:31:33 2010 process id=29230 version=1.0 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 17:31:41 2010 process id=28651 version=1.0 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 17:31:42 2010 process id=29230 version=1.0 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 17:32:49 2010 process id=27224 modtime=
Tue May  4 17:32:51 2010 process id=28390 version=1.1 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 17:32:53 2010 process id=29076 version=1.0/usr/sbin
Tue May  4 17:32:54 2010 process id=29076 version=1.0/usr/sbin
Tue May  4 17:32:56 2010 process id=27224 modtime=
Tue May  4 17:32:58 2010 process id=28390 version=1.1 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 17:33:00 2010 process id=27224 modtime=
Tue May  4 17:33:01 2010 process id=27224 modtime=
Tue May  4 17:33:03 2010 process id=27224 modtime=
Tue May  4 17:33:05 2010 process id=28390 version=1.1 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 17:33:06 2010 process id=27224 modtime=
Tue May  4 17:35:42 2010 process id=28293 version=1.1 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 17:35:44 2010 process id=28651 version=1.0 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 17:35:45 2010 process id=28293 version=1.1 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 17:35:46 2010 process id=29230 version=1.0 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 17:44:22 2010 process id=28292 version=1.1 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.plTue May  4 17:44:24 2
+010 process id=28390 version=1.1 location=/usr/sbin file=/var/www/per
+l/intranet/user/firstfarm.pl
Tue May  4 17:44:31 2010 process id=28292 version=1.1 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 17:44:32 2010 process id=29076 version=1.0/usr/sbin
Tue May  4 17:44:35 2010 process id=28292 version=1.1 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 17:44:36 2010 process id=28390 version=1.1 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 17:44:37 2010 process id=29076 version=1.0/usr/sbin
Tue May  4 17:44:40 2010 process id=28390 version=1.1 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 17:44:41 2010 process id=28292 version=1.1 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 17:44:42 2010 process id=29076 version=1.0/usr/sbin
Tue May  4 17:44:45 2010 process id=28292 version=1.1 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 17:45:03 2010 process id=28886 version=1.0/usr/sbin
Tue May  4 17:45:05 2010 process id=27224 modtime=
Tue May  4 17:45:07 2010 process id=28886 version=1.0/usr/sbin
Tue May  4 17:45:09 2010 process id=28075 version=1.0/usr/sbin
Tue May  4 17:45:10 2010 process id=28886 version=1.0/usr/sbin
Tue May  4 17:45:36 2010 process id=27224 modtime=
Tue May  4 17:45:43 2010 process id=29654 version=1.2 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 17:45:45 2010 process id=28651 version=1.0 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 17:45:47 2010 process id=27224 modtime=
Tue May  4 17:45:50 2010 process id=28651 version=1.0 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 17:45:53 2010 process id=28651 version=1.0 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 17:45:54 2010 process id=29654 version=1.2 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 17:45:55 2010 process id=27224 modtime=
**restarted apache here**
Tue May  4 18:04:13 2010 process id=30058 version=1.2 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 18:04:15 2010 process id=30059 version=1.2 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 18:04:16 2010 process id=30058 version=1.2 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 18:04:18 2010 process id=30060 version=1.2 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 18:04:19 2010 process id=30059 version=1.2 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 18:04:20 2010 process id=30060 version=1.2 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 18:04:21 2010 process id=30058 version=1.2 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 18:04:22 2010 process id=30059 version=1.2 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 18:04:25 2010 process id=30060 version=1.2 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 18:04:27 2010 process id=30060 version=1.2 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 18:04:29 2010 process id=30060 version=1.2 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 18:04:31 2010 process id=30058 version=1.2 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 18:04:32 2010 process id=30060 version=1.2 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 18:05:18 2010 process id=30073 version=1.2 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 18:05:21 2010 process id=30074 version=1.2 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 18:05:30 2010 process id=30075 version=1.3 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 18:05:31 2010 process id=30073 version=1.2 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 18:05:32 2010 process id=30074 version=1.2 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 18:05:33 2010 process id=30075 version=1.3 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 18:05:34 2010 process id=30073 version=1.2 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 18:05:35 2010 process id=30075 version=1.3 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 18:05:36 2010 process id=30074 version=1.2 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 18:05:38 2010 process id=30073 version=1.2 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 18:05:39 2010 process id=30074 version=1.2 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 18:05:40 2010 process id=30075 version=1.3 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 18:06:31 2010 process id=30060 version=1.2 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 18:06:55 2010 process id=30097 version=1.3 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 18:07:16 2010 process id=30073 version=1.2 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 18:07:18 2010 process id=30057 version=1.3 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 18:07:39 2010 process id=30075 version=1.3 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 18:07:51 2010 process id=30059 version=1.2 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 18:08:03 2010 process id=30095 version=1.4 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 18:08:24 2010 process id=30060 version=1.2 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 18:08:28 2010 process id=30098 version=1.4 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 18:08:31 2010 process id=30056 version=1.4 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 18:09:28 2010 process id=30057 version=1.3 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 18:09:40 2010 process id=30073 version=1.2 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 18:10:01 2010 process id=30059 version=1.2 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 18:10:08 2010 process id=30095 version=1.4 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl
Tue May  4 18:10:10 2010 process id=30060 version=1.2 location=/usr/sb
+in file=/var/www/perl/intranet/user/firstfarm.pl

Note that the lines with "modtime" are a pre-version 1.0. I performed a ps on the pid, however, I don't really know what I'm looking for. Here's the related output of "ps -ef":

UID        PID  PPID  C STIME TTY          TIME CMD
www-data 30056 30050  0 18:03 ?        00:00:00 /usr/sbin/apache2 -k s
+tart
www-data 30057 30050  0 18:03 ?        00:00:00 /usr/sbin/apache2 -k s
+tart
www-data 30059 30050  0 18:03 ?        00:00:00 /usr/sbin/apache2 -k s
+tart
www-data 30060 30050  0 18:03 ?        00:00:00 /usr/sbin/apache2 -k s
+tart
www-data 30073 30050  0 18:04 ?        00:00:00 /usr/sbin/apache2 -k s
+tart
www-data 30074 30050  0 18:04 ?        00:00:00 /usr/sbin/apache2 -k s
+tart
www-data 30075 30050  0 18:04 ?        00:00:00 /usr/sbin/apache2 -k s
+tart
www-data 30095 30050  0 18:05 ?        00:00:00 /usr/sbin/apache2 -k s
+tart
www-data 30097 30050  0 18:05 ?        00:00:01 /usr/sbin/apache2 -k s
+tart
www-data 30098 30050  0 18:05 ?        00:00:00 /usr/sbin/apache2 -k s
+tart

I was not able to detect any requests that were not logged on the server.

[ig]

That looks very much like your server is running mod_perl or something with similar characteristics.

For comparison, here are some logs from a couple of CGI scripts running on my system: one under mod_perl and the other not. Note that with mod_perl the same process id appears over and over while without mod_perl each request causes a new process to be started.

cgi under mod_perl process id 3632
cgi under mod_perl process id 3632
cgi under mod_perl process id 3632
cgi under mod_perl process id 3632
cgi under mod_perl process id 3660
cgi under mod_perl process id 3660
cgi under mod_perl process id 3660
cgi under mod_perl process id 3660
cgi under mod_perl process id 3660
cgi under mod_perl process id 3632
cgi under mod_perl process id 3660
cgi under mod_perl process id 3660
cgi under mod_perl process id 3632
cgi under mod_perl process id 3632
cgi under mod_perl process id 3660
cgi under mod_perl process id 3660
cgi under mod_perl process id 3660
cgi under mod_perl process id 3632
cgi under mod_perl process id 3632
cgi under mod_perl process id 3632
cgi under mod_perl process id 3632
cgi under mod_perl process id 3632
standard cgi process id: 3926
standard cgi process id: 3928
standard cgi process id: 3929
standard cgi process id: 3930
standard cgi process id: 3931
standard cgi process id: 3933
standard cgi process id: 3934
standard cgi process id: 3935
standard cgi process id: 3936
standard cgi process id: 3938
standard cgi process id: 3939
standard cgi process id: 3940
standard cgi process id: 3941
standard cgi process id: 3942
standard cgi process id: 3944
standard cgi process id: 3945
standard cgi process id: 3984
standard cgi process id: 3986
standard cgi process id: 3987

As all your requests are making it to the server and you can see the server running a mixture of versions of your script, you can forget about proxy servers.

Previously you said that you sometimes saw responses from old versions of your script even after you restarted the server. I expect you will find you were mistaken (no offense intended) and that after you restart the server you no longer receive responses from versions from before the restart.

When you restart your apache server, you should see entires similar to the following in your web server error log:

[Wed May 05 19:29:50 2010] [notice] caught SIGTERM, shutting down
[Wed May 05 19:30:19 2010] [notice] Apache/2.2.12 (Ubuntu) mod_perl/2.
+0.4 Perl/v5.10.0 configured -- resuming normal operations

As for the ps output, the PID column shows the process ID, the STIME column shows when the process was started. In the sample you posted, all the processes are apache2 server processes. This confirms that it is apache2 that is running your CGI script and that it is doing so within the server process, as mod_perl does.

Assuming you are running mod_perl (fairly certain at this point) then after each restart you should only see the latest version in the logs (and responses) and any new versions introduced since restarting the server.

You can confirm your server is running mod_perl by checking the configuration for your website. You might find the mod_perl configuration manual helpful for understanding what to look for in your apache configuration file.