in reply to Re^6: apache/perl caching problem
in thread apache/perl caching problem

If you have stopped and restarted your apache server and are still receiving responses from old versions of your script, then the problem is not a simple case of mod_perl holding old versions in memory.

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.

For "quick and dirty" logging (i.e. to be removed when debugging is done, as opposed to logging that is to become a permanent part of the scripts) I usually print to STDERR. Output to STDERR should show up in your sites error log. This allows you to see information that is not available in the access logs.

You could use CGI::Log or CGI::LogCarp.How you get information into the logs is less important than what information is recorded there.

You are correct that adding logging to new versions of your script will not change older versions. None the less, it would be good to add some logging. Your current versions will soon become old versions. You might produce a few versions that differ only in the version numbers they log, just to make some versions with enhanced logging into old versions.

The HTTP protocol is one of request and response. The browser sends a request and the server sends a response. While the requests and responses can be complex, the relationship between them is usually very simple: one request receives one response.

You have "bad" responses being received at the browser. The challenge is to determine where these "bad" responses are coming from and why they are being produced. The first step is to determine where they are coming from. Keep focused on this simple aspect of the situation and avoid being distracted by the complexities.

When your browser sends a request, where does it go? Does it get to your server? You may find that some of the requests are not going to the server you think they are going to: some other server may be responding.

Server logs and network sniffers can be very helpful, along with your understanding of the HTTP protocol and careful attention to the details of what is happening. It can be painstaking work but ultimately isn't very difficult if you have access to the systems and understand the fundamentals.

If there is someone there more familiar with the infrastructure (network, proxy servers, web servers, etc.) I would review the symptoms with them.

It is possible that your infrastructure includes a "transparent" proxy server. This is a proxy server that intercepts and potentially modifies communications that aren't explicitly directed to it. In some cases, they provide a response to the client that appears to have been sent by the server when in fact the proxy server has blocked the communication with the server and produced the response itself. They can include caches, so the response they provide might be from an old version of your script. But they would typically be dealing only with the HTTP requests and responses and would not be able to execute an old version of your script with new query parameters (if such is relevant to your script).

If there is a transparent proxy server in your environment, your infrastructure folks should be able to tell you about it, but sometimes such devices are installed without being well understood or the person who knew what it was doing leaves while it carries on. You can detect a transparent proxy by careful comparison of what happens at the browser with what happens at the server. In the absence of proxy servers (transparent or otherwise) there should be a one-to-one correspondence of requests and responses at both ends and neither requests not responses should be modified in transit.

Replies are listed 'Best First'.
Re^8: apache/perl caching problem
by ksublondie (Friar) on May 04, 2010 at 18:37 UTC
    "...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"?

      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.

        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.