[LON-CAPA-admin] Published resources not showing up on access servers

Thu Sep 17 17:23:54 EDT 2015

Hi Bob,

Looking at lonc.log on the MSU LON-CAPA library server s10 I see that  
the run of /home/httpd/perl/loncron used to update connections and  
retrieve updated cluster membership information failed to connect to  
binghamtona2 at 5:11 am today.

On the MSU library server ...

Thu Sep 17 05:11:14 2015 (2148) [loncapa2.chem.binghamton.edu] [Thu  
Sep 17 05:11:14 2015: Parent keeping the flock] <font  
color='red'>CRITICAL: Forking server for  
loncapa2.chem.binghamton.edu</font>
Thu Sep 17 05:11:18 2015 (13722) [loncapa2.chem.binghamton.edu] [Thu  
Sep 17 05:11:14 2015: Connected to loncapa2.chem.binghamton.edu] <font  
color='red'>CRITICAL: Failed to make a connection with lond.</font>
Thu Sep 17 05:11:18 2015 (13722) [loncapa2.chem.binghamton.edu] [Thu  
Sep 17 05:11:14 2015: Connected to loncapa2.chem.binghamton.edu] <font  
color='blue'>WARNING: Failing transaction sethost</font>

As a result the lonc status reported on s10 for  
loncapa2.chem.binghamton.edu was:

www      13722  2148  0 05:11 ?        00:00:00 lonc:  
loncapa2.chem.binghamton.edu Connection count: 0 Retries remaining: 5  
() Thu Sep 17 13:29:08 2015

However, when I attempted to connect to binghamtona2 a few hours ago  
the connection was successfully created:

www      13722  2148  0 05:11 ?        00:00:00 lonc:  
loncapa2.chem.binghamton.edu Connection count: 1 Retries remaining: 5  
(insecure) Thu Sep 17 13:34:39 2015

and I was able to transfer my user session there.

 From the lonc.log information on your library server ...

>    Thu Sep 17 11:05:19 2015 (3279) [loncapa2.chem.binghamton.edu] [Thu Sep
> 17 10:53:24 2015: loncapa2.chem.binghamton.edu Connection count: 0 Retries
> remaining: 5 ()] <font color='green'>SUCCESS: Connection 1 to
> loncapa2.chem.binghamton.edu now ready for action</font>
>    Thu Sep 17 11:10:20 2015 (3279) [loncapa2.chem.binghamton.edu] [Thu Sep
> 17 11:10:20 2015: loncapa2.chem.binghamton.edu Connection count: 1 Retries
> remaining: 5 (insecure)] <font color='blue'>WARNING: Shutting down a
> socket</font>

This indicates successful creation of a connection, and then shutdown  
5 minutes later, as a result of pruning of idle connections (this is  
all as expected).  The IdleTimeout hard-coded in  
/home/httpd/perl/loncnew is 5 minutes.

>    Thu Sep 17 10:53:24 2015 (3279) [loncapa2.chem.binghamton.edu] [Thu Sep
> 17 10:42:10 2015: loncapa2.chem.binghamton.edu Connection count: 0 Retries
> remaining: 5 ()] <font color='yellow'>INFO: Resetting Connection
> Retries.</font>

This occurs when &Apache::lonnet::reconlonc() sends "reset_retries".   
&reconlonc($clientname) is called in lond when lond is connected by a  
known client (excluding connections from itself).

>       Cleanup phase: Notifications
>
>      Notifying host binghamtona7:not_found
>      Notifying host binghamtona2:not_found

The logged "not_found" messages originate from  
lond::update_resource_handler() on the library server, and will be  
sent if the old copy of the file which has just been republished is no  
longer present on the access server.

That can happen if the Linux OS on the access server was updated  
without preserving the contents of /home/httpd/html/res/.  This is not  
an issue, including the case where the access server had a  
subscription to the file before the access server was updated/rebuilt.  
  When the file is requested in a user session hosted on the access  
server it should be replicated to the access server from the library  
server, as usual.

However this:

>    Thu Sep 17 11:00:30 2015 (3908): <font color="blue">WARNING: LWP get:
> 403 Forbidden: /home/httpd/html/res/binghamton/gonzales/Testing
> Area/foobar.problem</font>
>

indicates that the replication failed.  You might check in the  
corresponding Apache error_log file for the request for:

GET /raw/binghamton/gonzales/TestingArea/foobar.problem

from 128.226.130.9.

See:

http://mail.lon-capa.org/pipermail/lon-capa-admin/2013-November/002773.html

for a discussion of things to check.  In that particular instance the  
"Forbidden" error was caused by an incorrect IP address in /etc/hosts

Stuart Raeburn
LON-CAPA Academic Consortium

Quoting Bob Gonzales <rgonzal at binghamton.edu>:

> Hi,
>
> I'm running 2.11.1 and centos 7.1 on all my servers.
>
> When I publish a resource and then try to access it on any of my access
> servers I get the message 'unable to find' and then the name of the problem
> just published.
>
> The subscription file for the problem shows the access server has
> subscribed.
>
> When I republished a file the log file for the problem I got the following
> information from the log file for the problem:
>
>       Cleanup phase: Notifications
>
>      Notifying host binghamtona7:not_found
>      Notifying host binghamtona2:not_found
>      Notifying course binghamton_71215825fc2344762binghamtonl1:ok
>
> I see a lot of these messages for binghamtona2 (loncapa2) in the library
> server lonnet.log
>
> Thu Sep 17 10:53:24 2015 (8257): Trying to reconnect lonc for binghamtona2 (
> loncapa2.chem.binghamton.edu)
>
> And these in the library servers lonc.log
>
>     Thu Sep 17 10:42:10 2015 (3279) [loncapa2.chem.binghamton.edu] [Thu Sep
> 17 10:42:10 2015: loncapa2.chem.binghamton.edu Connection count: 0 Retries
> remaining: 5 ()] <font color='yellow'>INFO: Resetting Connection
> Retries.</font>
>    Thu Sep 17 10:53:24 2015 (3279) [loncapa2.chem.binghamton.edu] [Thu Sep
> 17 10:42:10 2015: loncapa2.chem.binghamton.edu Connection count: 0 Retries
> remaining: 5 ()] <font color='yellow'>INFO: Resetting Connection
> Retries.</font>
>    Thu Sep 17 10:53:24 2015 (3279) [loncapa2.chem.binghamton.edu] [Thu Sep
> 17 10:53:24 2015: loncapa2.chem.binghamton.edu Connection count: 0 Retries
> remaining: 5 ()] <font color='yellow'>INFO: Resetting Connection
> Retries.</font>
>    Thu Sep 17 10:53:24 2015 (3279) [loncapa2.chem.binghamton.edu] [Thu Sep
> 17 10:53:24 2015: loncapa2.chem.binghamton.edu  Connection count: 0 Retries
> remaining: 5 ()] <font color='yellow'>INFO: Resetting Connection
> Retries.</font>
>    Thu Sep 17 11:05:19 2015 (3279) [loncapa2.chem.binghamton.edu] [Thu Sep
> 17 10:53:24 2015: loncapa2.chem.binghamton.edu Connection count: 0 Retries
> remaining: 5 ()] <font color='green'>SUCCESS: Created connection 1 to host
> loncapa2.chem.binghamton.edu</font>
>    Thu Sep 17 11:05:19 2015 (3279) [loncapa2.chem.binghamton.edu] [Thu Sep
> 17 10:53:24 2015: loncapa2.chem.binghamton.edu Connection count: 0 Retries
> remaining: 5 ()] <font color='yellow'>INFO: Connected to lond version:
> 489</font>
>    Thu Sep 17 11:05:19 2015 (3279) [loncapa2.chem.binghamton.edu] [Thu Sep
> 17 10:53:24 2015: loncapa2.chem.binghamton.edu Connection count: 0 Retries
> remaining: 5 ()] <font color='green'>SUCCESS: Connection 1 to
> loncapa2.chem.binghamton.edu now ready for action</font>
>    Thu Sep 17 11:10:20 2015 (3279) [loncapa2.chem.binghamton.edu] [Thu Sep
> 17 11:10:20 2015: loncapa2.chem.binghamton.edu Connection count: 1 Retries
> remaining: 5 (insecure)] <font color='blue'>WARNING: Shutting down a
> socket</font>
>
> I also see this in the access servers lonnet.log:
>
>    Thu Sep 17 11:00:30 2015 (3908): <font color="blue">WARNING: LWP get:
> 403 Forbidden: /home/httpd/html/res/binghamton/gonzales/Testing
> Area/foobar.problem</font>
>
> I don't really know what all of this means.  Any help would be appreciated.
>
> Thanks,
> Bob Gonzales
> Binghamton University
> Chemistry Dept