[LON-CAPA-admin] Only One Access Server Serving Maps?

Wed Aug 19 03:37:34 EDT 2009

Paul

> repcopy_userfile LWP result: 404 Not Found
> repcopy_userfile LWP result: 500 Cannot write to
> '/home/httpd/html/userfiles/ndsu/3H21488e15c894a96ndsul1/default.sequence.in.transfer':

> Tue Aug 18 10:15:23 2009 (27523): Userfile repcopy failed for
> uploaded/ndsu/3H214842a5d894a96ndsul1/default.sequence.meta

The 404 Not Found matches the lonnet.log entry, and is expected (there
is no .meta file for a default.sequence).

The "500 Cannot write to ... Permission denied" for the userfile  
repcopy of default.sequence sounds line an SELinux error.  Is SELinux  
enabled?  If so set, it to permissive or disabled.  You might also  
verify that the Apache web child processes are running as the www user.

Stuart Raeburn
MSU LON-CAPA group

Quoting Paul Omernik <paul.omernik at ndsu.edu>:

> Stuart,
>
> These are after the modification to lonnet.pm
>
> tail --lines=20 /etc/httpd/logs/error_log
> [Tue Aug 18 05:10:24 2009] [notice] Digest: generating secret for digest
> authentication ...
> [Tue Aug 18 05:10:24 2009] [notice] Digest: done
> [Tue Aug 18 05:10:24 2009] [notice] mod_python: Creating 4 session mutexes
> based on 150 max processes and 0 max threads.
> [Tue Aug 18 05:10:24 2009] [notice] Apache/2.2.3 (Red Hat) configured --
> resuming normal operations
> [Tue Aug 18 10:14:45 2009] [notice] SIGHUP received.  Attempting to restart
> [Tue Aug 18 10:14:46 2009] [warn] module perl_module is already loaded,
> skipping
> [Tue Aug 18 10:14:48 2009] [notice] Digest: generating secret for digest
> authentication ...
> [Tue Aug 18 10:14:48 2009] [notice] Digest: done
> [Tue Aug 18 10:14:48 2009] [notice] mod_python: Creating 4 session mutexes
> based on 150 max processes and 0 max threads.
> [Tue Aug 18 10:14:48 2009] [notice] Apache/2.2.3 (Red Hat) configured --
> resuming normal operations
> repcopy_userfile LWP result: 404 Not Found
> repcopy_userfile LWP result: 500 Cannot write to
> '/home/httpd/html/userfiles/ndsu/3H214842a5d894a96ndsul1/default.sequence.in.transfer':
> Permission denied
> repcopy_userfile LWP result: 404 Not Found
> repcopy_userfile LWP result: 500 Cannot write to
> '/home/httpd/html/userfiles/ndsu/3H21488e15c894a96ndsul1/default.sequence.in.transfer':
> Permission denied
> repcopy_userfile LWP result: 404 Not Found
> repcopy_userfile LWP result: 500 Cannot write to
> '/home/httpd/html/userfiles/ndsu/3H21482865c894a96ndsul1/default.sequence.in.transfer':
> Permission denied
> repcopy_userfile LWP result: 404 Not Found
> repcopy_userfile LWP result: 500 Cannot write to
> '/home/httpd/html/userfiles/ndsu/1H214826f5d894a41ndsul1/default.sequence.in.transfer':
> Permission denied
> repcopy_userfile LWP result: 404 Not Found
> repcopy_userfile LWP result: 500 Cannot write to
> '/home/httpd/html/userfiles/ndsu/3H21486c85d894a96ndsul1/default.sequence.in.transfer':
> Permission denied
>
>
> tail /home/httpd/perl/logs/lonnet.log
> Tue Aug 18 10:15:23 2009 (27523): Userfile repcopy failed for
> uploaded/ndsu/3H214842a5d894a96ndsul1/default.sequence.meta
> Tue Aug 18 10:15:23 2009 (27523): Userfile repcopy failed for
> uploaded/ndsu/3H214842a5d894a96ndsul1/default.sequence
> Tue Aug 18 10:16:50 2009 (27526): Userfile repcopy failed for
> uploaded/ndsu/3H21488e15c894a96ndsul1/default.sequence.meta
> Tue Aug 18 10:16:50 2009 (27526): Userfile repcopy failed for
> uploaded/ndsu/3H21488e15c894a96ndsul1/default.sequence
> Tue Aug 18 10:16:55 2009 (27520): Userfile repcopy failed for
> uploaded/ndsu/3H21482865c894a96ndsul1/default.sequence.meta
> Tue Aug 18 10:16:55 2009 (27520): Userfile repcopy failed for
> uploaded/ndsu/3H21482865c894a96ndsul1/default.sequence
> Tue Aug 18 10:17:00 2009 (27522): Userfile repcopy failed for
> uploaded/ndsu/1H214826f5d894a41ndsul1/default.sequence.meta
> Tue Aug 18 10:17:00 2009 (27522): Userfile repcopy failed for
> uploaded/ndsu/1H214826f5d894a41ndsul1/default.sequence
> Tue Aug 18 10:17:04 2009 (27524): Userfile repcopy failed for
> uploaded/ndsu/3H21486c85d894a96ndsul1/default.sequence.meta
> Tue Aug 18 10:17:04 2009 (27524): Userfile repcopy failed for
> uploaded/ndsu/3H21486c85d894a96ndsul1/default.sequence
>
>
> ls -la /home/httpd/html/userfiles/ndsu/ | grep H214
> drwxr-x---  4 www  www  4096 Aug 17 09:36 1H214826f5d894a41ndsul1
>
> Which is the one I copied from yesterday.
>
> I also see this in lonnet.log:
>
> Tue Aug 18 10:41:30 2009 (2906): caching of id ->
> dns%3a%2fadm%2fdns%2fhosts  failed
> Tue Aug 18 10:41:31 2009 (2906): caching of id ->
> dns%3a%2fadm%2fdns%2fdomain  failed
> Tue Aug 18 10:41:31 2009 (2906): Name iedulib.ipc.kanazawa-u.ac.jp no IP
> found
> Tue Aug 18 10:41:31 2009 (2906): Name lon-capa.colorado.edu no IP found
> Tue Aug 18 10:41:31 2009 (2906): Name nyul1.physics.nyu.edu no IP found
> Tue Aug 18 10:41:31 2009 (2906): Name shs-dunk-lin.shs.sarasota.k12.fl.us no
> IP found
> Tue Aug 18 10:41:31 2009 (2906): caching of id -> iphost%3aiphost  failed
>
> I have been trying to remember what changed, but since I can't pinpoint a
> date that this issue actually started, it will be tough to nail down.  Our
> summer courses used triton (ndsua2), which was updated to CentOS 5.3 in the
> same way and at the same time as proteus (ndsua1), and triton is behaving
> just fine.
>
> Paul
>
> On Mon, Aug 17, 2009 at 10:08 PM, Stuart Raeburn <raeburn at msu.edu> wrote:
>
>> Paul,
>>
>> I'm seeing the same thing when I log-into a LON-CAPA session on ndsua1 and
>> select an old course of mine, for which the home server is msul1, so I don't
>> think this issue is related to cloning or recent creation of courses.  This
>> seems more of a general issue to do with file replication on ndsua1.
>>
>> I suspect there may be a network issue of some sort which prevents the
>> response to outgoing web requests from ndsua1 being received  again by the
>> server.  It seems that it's not a disk space, as these files are very small,
>> or a permissions issue as you tested that.
>>
>> As nsdua1 allows me to start a session on nsdua1 (which will authenticate
>> my log-in against the msu library server), connectivity via the LON-CAPA
>> port (5663) is evidently available.  Furthermore, nmap run against port 5663
>> reports that it is open.
>>
>> The missing file issue seems to be related to inbound traffic from remote
>> web servers, as what nsdua1 will do in the case of a default.sequence file
>> (which is an "uploaded" file) is to make an LWP request for the file to the
>> course's home server (the msu library server), which it will then store
>> locally.
>>
>> I see the request from ndsua1 for the file in my MSU course in the server
>> logs on the MSU library server:
>>
>> 134.129.87.63 - - [17/Aug/2009:21:59:01 -0400] "GET
>> /raw/uploaded/msu/33803011027874598msul1/default.sequence HTTP/1.1" 200 4781
>> "-" "libwww-perl
>>
>> and the logs suggest that the file was served successfully.
>>
>> The question is then:
>>
>> 1. Were the requested data ever received on ndsua1?
>> 2. If so, what did ndsua1 do with the data?
>>
>> You may find some clues in /home/httpd/perl/logs/lonnet.log
>>
>> The fact that you found that the problem persisted after copying the
>> missing file via the command line suggests that the LWP request for the HEAD
>> to check if the file exists also resulted in an error.
>>
>> This is the relevant code from lonnet.pm for that check.  I'm assuming
>> that the file you copied was not deleted, but that instead, $lwpresp was not
>> "ok" but the return code was something other than a 404.
>>
>> my $lwpresp = &getuploaded('HEAD',$uri,$cdom,$cnum,\$info,\$rtncode);
>> if ($lwpresp ne 'ok') {
>> # there is no such file anymore, even though we had a local copy
>> if ($rtncode eq '404') {
>>    unlink($file);
>> }
>> return -1;
>>
>>
>> In the case where the file has yet to be replicated, this is the relevant
>> chunk of code (from lonnet.pm which fetches the file
>>
>> my $transferfile=$file.'.in.transfer';
>>
>> $request=new
>> HTTP::Request('GET',$protocol.'://'.&hostname($homeserver).'/raw/'.$uri);
>> my $response=$ua->request($request,$transferfile);
>> # did it work?
>> if ($response->is_error()) {
>>    unlink($transferfile);
>>    &logthis("Userfile repcopy failed for $uri");
>>    return -1;
>> }
>> # worked, rename the transfer file
>> rename($transferfile,$file);
>>
>> You could put some debugging lines in there to print out the status of the
>> LWP request, and also the result of the rename()   unfortunately LON-CAPA
>> doesn't check this presently.
>>
>> For example add this before the line:  unlink($transferfile);
>>
>> print STDERR "repcopy_userfile LWP result: ".$response->status_line."\n";
>>
>>
>> and maybe change the rename to do:
>>
>> if (!rename($transferfile,$file)) {
>>    print STDERR "repcopy_userfile rename failed: ".$!."\n";
>> }
>>
>> Then reload Apache and look in /etc/httpd/logs/error_log after attempting
>> to select a course, and retrieve the default.sequence file.
>>
>> Stuart Raeburn
>> MSU LON-CAPA group
>>
>>
>>
>> Quoting Paul Omernik <paul.omernik at ndsu.edu>:
>>
>>  Of our two access servers, only one appears to be allowing mapping to the
>>> library server.  The one with issues (ndsua1) returns:
>>>
>>> The following problems occurred:
>>> Map not loaded: The file
>>>
>>> /home/httpd/html/userfiles/ndsu/1H214826f5d894a41ndsul1/default.sequencedoes
>>> not exist.
>>>
>>> Much like Lars, I clone the courses from the previous semester, and I can
>>> find the previous hash on ndsua2, in fact, it's listed in the Course
>>> Environment:
>>>
>>> /ndsu/2B66911d60f49493bndsul1
>>>
>>> and
>>>
>>> drwxr-x---  6 www  www  4096 Jun 24 09:32 2B66911d60f49493bndsul1
>>>
>>> (on ndsua2).
>>>
>>> The hash that ndsua1 can't find is located on ndsua2, so I attempted
>>> scp'ing
>>> the information over to ndsua1, matched the www:www ownership, and still
>>> nothing.
>>>
>>> This 'inaccessibility' exists for all courses I've created recently.
>>> Courses were created by logging in to the library server and cloning a
>>> previous course.
>>>
>>> Thank you,
>>>
>>> Paul