HTTP error response code 500 using LWP::UserAgent on one site, but not on any other

[ted.byers]

This is a real puzzle. I am trying to determine why a script works on my workstation (Windows 7), but not on either of two servers running Windows Server 2008. We're using Activestate perl, and the behaviour is identical regardless of whether we use 5.12, 5.14 or 5.16, with the latest release of LWP.

I have a basic script that I used to teach a colleague about Perl web programming. It reproduces the problem exactly. Here it is:

use strict;
use Log::Log4perl qw(:easy get_logger);
use LWP::UserAgent;
use HTTP::Request;
use HTTP::Request::Common;
use HTTP::Response;
use HTTP::Status;

$| = 1;

my $ua = LWP::UserAgent->new;

$ua->add_handler("request_send",  sub { log_it("Request: ".shift->dump
+); return });
$ua->add_handler("response_done", sub { my $rsp = shift; my @red = $rs
+p->redirects; my $r; foreach $r (@red) {log_it("Response redirect: ".
+$r)}; log_it("Response last request: ".$rsp->request->uri); log_it("R
+esponse headers: ".$rsp->headers_as_string); log_it("Response code: "
+.$rsp->code); my $msg = status_message($rsp->code); log_it("Response 
+status: ".$msg) if defined $msg; log_it("Response status: ".$rsp->sta
+tus_line); return });

# Define configuration
my $conf = q(
        log4perl.logger                    = TRACE, FileApp, ScreenApp
        log4perl.appender.FileApp          = Log::Log4perl::Appender::
+File
        log4perl.appender.FileApp.filename = lwp.log
        log4perl.appender.FileApp.layout   = PatternLayout
        log4perl.appender.FileApp.layout.ConversionPattern = %d> %m%n
        log4perl.appender.ScreenApp          = Log::Log4perl::Appender
+::Screen
        log4perl.appender.ScreenApp.stderr   = 0
        log4perl.appender.ScreenApp.layout   = PatternLayout
        log4perl.appender.ScreenApp.layout.ConversionPattern = %d> %m%
+n
);

# Initialize logging behaviour
Log::Log4perl->init( \$conf );
Log::Log4perl->infiltrate_lwp();

my $logger = get_logger();

my $req_url = $ARGV[0];
if ($req_url =~ m/http/) {
  $req_url = "$req_url";
} else {
  $req_url = "http://$req_url";
}


# whether you use GET or POST, both shown below, depends on what the
# server accepts.  try both, preferring POST
my $response = $ua->request(POST "$req_url");
my $code = $response->code;
if ($code == 405) {
  $response = $ua->request(GET "$req_url");
}
#
#my $response = $ua->request(POST "$req_url",/%parms);
#    print "\n===================================================\n";
#    print "The response, as a string, is:\n";
#    print $response->as_string;
#    print "\n===================================================\n";

#if ( $response->is_redirect  ) {
if (($code > 299) && ($code < 400)) {
    print $response->previous . " redirected to location " .  $respons
+e->header('Location') .  "\n";
    print "The content is: ",$response->content,"\n";
    print "\n===================================================\n";
    print "The response, as a string, is:\n";
    print $response->as_string;
    print "\n===================================================\n";
    $logger->info($response->previous . " redirected to location " .  
+$response->header('Location'));
} else {
  if ($response->is_success) {
    print "The content is: ",$response->content,"\n";
    $logger->info("The URL $req_url was successfully retrieved.");
    if (lc($response->content)=~m/'error_response'/){
      $logger->warn("Response problematic content: ".$response->conten
+t);
    }
  } else {
    $logger->warn("The URL $req_url was not successfully retrieved.");
  }
}


sub log_it {
  my $tmp = shift;
  $tmp =~ s/\n+/,\t/g;
  $tmp =~ s/,\t$//;
  $logger->info($tmp);
  return;
}

Now, if I use the above code, and pass, as the argument either 'www.google.ca' or 'https://www.google.ca', All works fine. If, instead, I pass the URL for the querying API I need to use, I get a server error, response code #500. The really bizarre aspect of this is that submitting the same request using MS IE or Firefox works as expected. That suggests that LWP is producing something different from what, or failing to produce something that, the two most common web browsers produce.

The senior tech guy at the company providing the service says that that is happening before the request even gets to his PHP script. He asked that I provide him with all the HTTP headers, along with the complete request, so that he and his team can figure out why only those requests from this script on the two servers fail at his end, and yet the precisely the same code, running on my Windows 7 workstation, succeeds. I can not imagine why the same code would generate different headers depending on which machine it is running on (in all cases, the machines running the script live behind good firewalls).

I guess there are three questions here. First, how do I modify the above script so that instead of actually sending the request to the server in question, it simply writes everything it would normally send to a file instead? This is critical, so that the tech guys at the company providing the API can begin their investigations more thoroughly, with better information. The man was truly baffled as to why a 500 error would be produced by his system. Second, how do I debug this? I did see LWP::Debug, but it's documentation says it is deprecated. I would expect, therefore, that there would be some recent alternative. Is there a directive or variable I can use that would tell LWP to produce debug info, but not actually send the data to the server? And is there a directive to use or a variable that can be set that would result in LWP sending output to standard out representing everything that happens between the client and server, from the point where the two set up an SSL session to the point where the server sends the final response? (I'd really like to be able to do this without manually stepping through the code with a debugger - and I'd like to be able to send such a trace to the folk responsible for the API I am using - knowing at what stage in that dialog the error happens would likely be priceless to them.) Third, does anyone have an thoughts on why precisely the same code would work fine on one machine but fail on another?

It is important to emphasize that this code worked fine on another server since 2007, and only failed once we tried to deploy it to a new machine (in the cloud, if that matters). It is also important to emphasize that making the request seconds after the failed attempt with the script, but using MS IE or Firefox, succeeds; so there is no issue related to connectivity.

Any ideas?

Thanks

Ted

[Old_Gray_Bear]

An HTTP 500 error is a general error message issued by the server when no more specific 5xx message is appropriate. You will need to get the log(s) from the failing server to determine what exactly is going sour.

As a work around, you can have LWP send a user agent string identifying your 'browser' and one of the browsers that the remote server accepts. Note: this may lead to other "compatibility" issues.

[ted.byers]

Thanks OGB.

That is actually being done by the technical staff at the company that is providing the service. I have used such logs for my own web servers countless times to diagnose problems:usualy related to my own cgi programs, but sometimes to diagnose why my users encounter troubles.

That said, I doubt that he'd let me examine his logs, any more than I would let an outside developer examine my logs.

Do you have any thoughts on how to tell LWP to write the headers and request to a file instead of sending them to a server; or perhaps how to have it send to the logger suitable output for every step of the process of hand-shaking between the client and server, from the moment the connection is initiated to the moment the response is sent?

Thanks again.

Ted>

[Old_Gray_Bear]

They should be able to give you and extract of their logs if you provide them with a start and end time and the source host name/address. It's no big thing to filter a log for the time stamps in your range and then filter for your particular address. ISPs and their ilk have to do that to comply with a court-ordered "wiretap". (Or, how did they get the Generals email?)

[afoken]

An HTTP 500 error is a general error message issued by the server when no more specific 5xx message is appropriate.

Correct. But LWP may also generate 500 errors, as a way to communicate fatal errors to the caller:

#!/usr/bin/perl

use 5.010;
use strict;
use warnings;
use LWP::UserAgent;
use Data::Dumper;

my $ua=LWP::UserAgent->new();
my $resp=$ua->get("http://no.such.server.in.my.lan/no-such-page");

say $resp->status_line;
say Dumper $resp;

500 Can't connect to no.such.server.in.my.lan:80 (Bad hostname)
$VAR1 = bless( {
                 '_content' => 'Can\'t connect to no.such.server.in.my
+.lan:80 (Bad hostname)

LWP::Protocol::http::Socket: Bad hostname \'no.such.server.in.my.lan\'
+ at /usr/lib64/perl5/site_perl/5.12.3/LWP/Protocol/http.pm line 51.
',
                 '_rc' => 500,
                 '_headers' => bless( {
                                        'client-warning' => 'Internal 
+response',
                                        'client-date' => 'Sat, 17 Nov 
+2012 19:32:13 GMT',
                                        'content-type' => 'text/plain'
                                      }, 'HTTP::Headers' ),
                 '_msg' => 'Can\'t connect to no.such.server.in.my.lan
+:80 (Bad hostname)',
                 '_request' => bless( {
                                        '_content' => '',
                                        '_uri' => bless( do{\(my $o = 
+'http://no.such.server.in.my.lan/no-such-page')}, 'URI::http' ),
                                        '_headers' => bless( {
                                                               'user-a
+gent' => 'libwww-perl/6.02'
                                                             }, 'HTTP:
+:Headers' ),
                                        '_method' => 'GET'
                                      }, 'HTTP::Request' )
               }, 'HTTP::Response' );

Alexander

[aitap]

You can try running Wireshark to catch all packets your machine sends to the server.

[ted.byers]

Thanks

Yes, I have tried using Wireshark in the past. I am sure some find it useful, but I had some trouble getting it's user interface to do anything that was useful for me. Part of the problem is it gets everything; most of which is irrelevant to the problem at hand. It would be more useful if it could be told to get the traffic only between my client script and the server it is trying to connect to.

Thanks again

Ted

[aitap]

You need to write a filter expression. In your case it should look like http && ip.addr == <server's IP address> (see example).

[ted.byers]

I just heard from the head tech guy at the company responsible for the service I am using. He is wondering if my "CA Store does/can not support EV1 (Extended Validation) SSL Certificates." He is asking if I can "try and update your(my) CA store?" How would I do that? Further, might it be a question of configuration, as I would expect that the CA stores on the servers, which are much newer than my workstation, would be much more current than that on my workstation.

Any thoughts on how I ought to proceed on this?

Thanks

Ted