--- loncom/loncnew 2004/02/17 15:09:08 1.43 +++ loncom/loncnew 2005/01/19 21:38:25 1.57.2.1 @@ -2,7 +2,7 @@ # The LearningOnline Network with CAPA # lonc maintains the connections to remote computers # -# $Id: loncnew,v 1.43 2004/02/17 15:09:08 albertel Exp $ +# $Id: loncnew,v 1.57.2.1 2005/01/19 21:38:25 albertel Exp $ # # Copyright Michigan State University Board of Trustees # @@ -61,6 +61,7 @@ use LONCAPA::LondConnection; use LONCAPA::LondTransaction; use LONCAPA::Configuration; use LONCAPA::HashIterator; +use Fcntl qw(:flock); # Read the httpd configuration file to get perl variables @@ -82,7 +83,7 @@ my $ClientConnection = 0; # Uniquifier f my $DebugLevel = 0; my $NextDebugLevel= 2; # So Sigint can toggle this. -my $IdleTimeout= 3600; # Wait an hour before pruning connections. +my $IdleTimeout= 600; # Wait 10 minutes before pruning connections. my $LogTransactions = 0; # When True, all transactions/replies get logged. @@ -103,6 +104,10 @@ my $RecentLogEntry = ""; my $ConnectionRetries=2; # Number of connection retries allowed. my $ConnectionRetriesLeft=2; # Number of connection retries remaining. my $LondVersion = "unknown"; # Version of lond we talk with. +my $KeyMode = ""; # e.g. ssl, local, insecure from last connect. +my $LondConnecting = 0; # True when a connection is being built. + +my $DieWhenIdle = 0; # When true children die when trimmed -> 0. # # The hash below gives the HTML format for log messages @@ -110,13 +115,27 @@ my $LondVersion = "unknown"; # Versi # my %LogFormats; -$LogFormats{"CRITICAL"} = "CRITICAL: %s"; -$LogFormats{"SUCCESS"} = "SUCCESS: %s"; -$LogFormats{"INFO"} = "INFO: %s"; -$LogFormats{"WARNING"} = "WARNING: %s"; +$LogFormats{"CRITICAL"} = "CRITICAL: %s"; +$LogFormats{"SUCCESS"} = "SUCCESS: %s"; +$LogFormats{"INFO"} = "INFO: %s"; +$LogFormats{"WARNING"} = "WARNING: %s"; $LogFormats{"DEFAULT"} = " %s "; +# UpdateStatus; +# Update the idle status display to show how many connections +# are left, retries and other stuff. +# +sub UpdateStatus { + if ($ConnectionRetriesLeft > 0) { + ShowStatus(GetServerHost()." Connection count: ".$ConnectionCount + ." Retries remaining: ".$ConnectionRetriesLeft + ." ($KeyMode)"); + } else { + ShowStatus(GetServerHost()." >> DEAD <<"); + } +} + =pod @@ -156,9 +175,9 @@ host and the time will be formatted into =cut sub Log { - my $severity = shift; - my $message = shift; - + + my ($severity, $message) = @_; + if(!$LogFormats{$severity}) { $severity = "DEFAULT"; } @@ -193,8 +212,10 @@ Returns the name of the host that a sock =cut sub GetPeername { - my $connection = shift; - my $AdrFamily = shift; + + + my ($connection, $AdrFamily) = @_; + my $peer = $connection->peername(); my $peerport; my $peerip; @@ -217,18 +238,20 @@ Invoked to issue a debug message. =cut sub Debug { - my $level = shift; - my $message = shift; + + my ($level, $message) = @_; + if ($level <= $DebugLevel) { Log("INFO", "-Debug- $message host = $RemoteHost"); } } sub SocketDump { - my $level = shift; - my $socket= shift; + + my ($level, $socket) = @_; + if($level <= $DebugLevel) { - $socket->Dump(); + $socket->Dump(-1); # Ensure it will get dumped. } } @@ -260,8 +283,8 @@ sub ShowStatus { sub SocketTimeout { my $Socket = shift; Log("WARNING", "A socket timeout was detected"); - Debug(0, " SocketTimeout called: "); - $Socket->Dump(); + Debug(5, " SocketTimeout called: "); + $Socket->Dump(0); if(exists($ActiveTransactions{$Socket})) { FailTransaction($ActiveTransactions{$Socket}); } @@ -269,7 +292,8 @@ sub SocketTimeout { # a connection failure: $ConnectionRetriesLeft--; if($ConnectionRetriesLeft <= 0) { - Log("CRITICAL", "Host marked dead: ".GetServerHost()); + Log("CRITICAL", "Host marked DEAD: ".GetServerHost()); + $LondConnecting = 0; } } @@ -285,13 +309,12 @@ Invoked each timer tick. sub Tick { + my ($Event) = @_; + my $clock_watcher = $Event->w; + my $client; - if($ConnectionRetriesLeft > 0) { - ShowStatus(GetServerHost()." Connection count: ".$ConnectionCount - ." Retries remaining: ".$ConnectionRetriesLeft); - } else { - ShowStatus(GetServerHost()." >> DEAD <<"); - } + UpdateStatus(); + # Is it time to prune connection count: @@ -301,6 +324,22 @@ sub Tick { if($IdleSeconds > $IdleTimeout) { # Prune a connection... my $Socket = $IdleConnections->pop(); KillSocket($Socket); + $IdleSeconds = 0; # Otherwise all connections get trimmed to fast. + UpdateStatus(); + if(($ConnectionCount == 0) && $DieWhenIdle) { + # + # Create a lock file since there will be a time window + # between our exit and the parent's picking up the listen + # during which no listens will be done on the + # lonnet client socket. + # + my $lock_file = GetLoncSocketPath().".lock"; + open(LOCK,">$lock_file"); + print LOCK "Contents not important"; + close(LOCK); + + exit(0); + } } } else { $IdleSeconds = 0; # Reset idle count if not idle. @@ -319,23 +358,21 @@ sub Tick { # Do we have work in the queue, but no connections to service them? # If so, try to make some new connections to get things going again. # - + # Note this code is dead now... + # my $Requests = $WorkQueue->Count(); - if (($ConnectionCount == 0) && ($Requests > 0)) { + if (($ConnectionCount == 0) && ($Requests > 0) && (!$LondConnecting)) { if ($ConnectionRetriesLeft > 0) { - my $Connections = ($Requests <= $MaxConnectionCount) ? - $Requests : $MaxConnectionCount; - Debug(5,"Work but no connections, start ".$Connections." of them"); - my $successCount = 0; - for (my $i =0; $i < $Connections; $i++) { - $successCount += MakeLondConnection(); - } - if($successCount == 0) { # All connections failed: + Debug(5,"Work but no connections, Make a new one"); + my $success; + $success = &MakeLondConnection; + if($success == 0) { # All connections failed: Debug(5,"Work in queue failed to make any connectiouns\n"); EmptyQueue(); # Fail pending transactions with con_lost. CloseAllLondConnections(); # Should all be closed but.... } } else { + $LondConnecting = 0; ShowStatus(GetServerHost()." >>> DEAD!!! <<<"); Debug(5,"Work in queue, but gave up on connections..flushing\n"); EmptyQueue(); # Connections can't be established. @@ -343,6 +380,11 @@ sub Tick { } } + if ($ConnectionCount == 0) { + $KeyMode = ""; + $clock_watcher->cancel(); + } + &UpdateStatus(); } =pod @@ -383,6 +425,7 @@ long enough, it will be shut down and re sub ServerToIdle { my $Socket = shift; # Get the socket. + $KeyMode = $Socket->{AuthenticationMode}; delete($ActiveTransactions{$Socket}); # Server has no transaction &Debug(5, "Server to idle"); @@ -462,7 +505,7 @@ sub ClientWritable { } else { # Partial string sent. $Watcher->data(substr($Data, $result)); if($result == 0) { # client hung up on us!! - Log("INFO", "lonc pipe client hung up on us!"); + # Log("INFO", "lonc pipe client hung up on us!"); $Watcher->cancel; $Socket->shutdown(2); $Socket->close(); @@ -515,8 +558,8 @@ The transaction that is being completed. sub CompleteTransaction { &Debug(5,"Complete transaction"); - my $Socket = shift; - my $Transaction = shift; + + my ($Socket, $Transaction) = @_; if (!$Transaction->isDeferred()) { # Normal transaction my $data = $Socket->GetReply(); # Data to send. @@ -550,9 +593,8 @@ sub CompleteTransaction { =cut sub StartClientReply { - my $Transaction = shift; - my $data = shift; + my ($Transaction, $data) = @_; my $Client = $Transaction->getClient(); @@ -591,7 +633,13 @@ Parameters: sub FailTransaction { my $transaction = shift; - Log("WARNING", "Failing transaction ".$transaction->getRequest()); + + # If the socket is dead, that's already logged. + + if ($ConnectionRetriesLeft > 0) { + Log("WARNING", "Failing transaction " + .$transaction->getRequest()); + } Debug(1, "Failing transaction: ".$transaction->getRequest()); if (!$transaction->isDeferred()) { # If the transaction is deferred we'll get to it. my $client = $transaction->getClient(); @@ -778,6 +826,11 @@ sub LondReadable { "Lond connection lost."); if(exists($ActiveTransactions{$Socket})) { FailTransaction($ActiveTransactions{$Socket}); + } else { + # Socket is connecting and failed... need to mark + # no longer connecting. + + $LondConnecting = 0; } $Watcher->cancel(); KillSocket($Socket); @@ -852,6 +905,10 @@ sub LondReadable { .$RemoteHost." now ready for action"); } ServerToIdle($Socket); # Next work unit or idle. + + # + $LondConnecting = 0; # Best spot I can think of for this. + # } elsif ($State eq "SendingRequest") { # We need to be writable for this and probably don't belong @@ -965,6 +1022,10 @@ sub LondWritable { " has been disconnected"); if(exists($ActiveTransactions{$Socket})) { FailTransaction($ActiveTransactions{$Socket}); + } else { + # In the process of conneting, so need to turn that off. + + $LondConnecting = 0; } $Watcher->cancel(); KillSocket($Socket); @@ -1125,7 +1186,9 @@ sub MakeLondConnection { data => $Connection, desc => 'Connection to lond server'); $ActiveConnections{$Connection} = $event; - + if ($ConnectionCount == 0) { + &SetupTimer; # Need to handle timeouts with connections... + } $ConnectionCount++; Debug(4, "Connection count = ".$ConnectionCount); if($ConnectionCount == 1) { # First Connection: @@ -1133,6 +1196,7 @@ sub MakeLondConnection { } Log("SUCESS", "Created connection ".$ConnectionCount ." to host ".GetServerHost()); + $LondConnecting = 1; # Connection in progress. return 1; # Return success. } @@ -1164,8 +1228,8 @@ The text of the request to send. =cut sub StartRequest { - my $Lond = shift; - my $Request = shift; # This is a LondTransaction. + + my ($Lond, $Request) = @_; Debug(6, "StartRequest: ".$Request->getRequest()); @@ -1216,15 +1280,18 @@ sub QueueTransaction { if(!defined $LondSocket) { # Need to queue request. Debug(5,"Must queue..."); $WorkQueue->enqueue($requestData); - if($ConnectionCount < $MaxConnectionCount) { + Debug(5, "Queue Transaction startnew $ConnectionCount $LondConnecting"); + if(($ConnectionCount < $MaxConnectionCount) && (! $LondConnecting)) { + if($ConnectionRetriesLeft > 0) { Debug(5,"Starting additional lond connection"); - if(MakeLondConnection() == 0) { + if(&MakeLondConnection() == 0) { EmptyQueue(); # Fail transactions, can't make connection. CloseAllLondConnections; # Should all be closed but... } } else { ShowStatus(GetServerHost()." >>> DEAD !!!! <<<"); + $LondConnecting = 0; EmptyQueue(); # It's worse than that ... he's dead Jim. CloseAllLondConnections; # Should all be closed but.. } @@ -1269,7 +1336,7 @@ sub ClientRequest { Debug(8,"Data: ".$data." this read: ".$thisread); $data = $data.$thisread; # Append new data. $watcher->data($data); - if($data =~ /(.*\n)/) { # Request entirely read. + if($data =~ /\n$/) { # Request entirely read. if($data eq "close_connection_exit\n") { Log("CRITICAL", "Request Close Connection ... exiting"); @@ -1378,7 +1445,7 @@ sub SetupLoncListener { my $SocketName = GetLoncSocketPath(); unlink($SocketName); unless ($socket =IO::Socket::UNIX->new(Local => $SocketName, - Listen => 10, + Listen => 250, Type => SOCK_STREAM)) { die "Failed to create a lonc listner socket"; } @@ -1416,29 +1483,36 @@ into the status file. We also use this to reset the retries count in order to allow the client to retry connections with a previously dead server. =cut + sub ChildStatus { my $event = shift; my $watcher = $event->w; Debug(2, "Reporting child status because : ".$watcher->data); my $docdir = $perlvar{'lonDocRoot'}; - my $fh = IO::File->new(">>$docdir/lon-status/loncstatus.txt"); - print $fh $$."\t".$RemoteHost."\t".$Status."\t". + + open(LOG,">>$docdir/lon-status/loncstatus.txt"); + flock(LOG,LOCK_EX); + print LOG $$."\t".$RemoteHost."\t".$Status."\t". $RecentLogEntry."\n"; # # Write out information about each of the connections: # - print $fh "Active connection statuses: \n"; - my $i = 1; - print STDERR "================================= Socket Status Dump:\n"; - foreach my $item (keys %ActiveConnections) { - my $Socket = $ActiveConnections{$item}->data; - my $state = $Socket->GetState(); - print $fh "Connection $i State: $state\n"; - print STDERR "---------------------- Connection $i \n"; - $Socket->Dump(); - $i++; + if ($DebugLevel > 2) { + print LOG "Active connection statuses: \n"; + my $i = 1; + print STDERR "================================= Socket Status Dump:\n"; + foreach my $item (keys %ActiveConnections) { + my $Socket = $ActiveConnections{$item}->data; + my $state = $Socket->GetState(); + print LOG "Connection $i State: $state\n"; + print STDERR "---------------------- Connection $i \n"; + $Socket->Dump(-1); # Ensure it gets dumped.. + $i++; + } } + flock(LOG,LOCK_UN); + close(LOG); $ConnectionRetriesLeft = $ConnectionRetries; } @@ -1509,7 +1583,6 @@ sub ChildProcess { cb => \&ToggleDebug, data => "INT"); - SetupTimer(); SetupLoncListener(); @@ -1532,9 +1605,10 @@ sub ChildProcess { # Create a new child for host passed in: sub CreateChild { + my $host = shift; + my $sigset = POSIX::SigSet->new(SIGINT); sigprocmask(SIG_BLOCK, $sigset); - my $host = shift; $RemoteHost = $host; Log("CRITICAL", "Forking server for ".$host); my $pid = fork; @@ -1661,7 +1735,6 @@ sub CheckKids { foreach my $pid (keys %ChildHash) { Debug(2, "Sending USR1 -> $pid"); kill 'USR1' => $pid; # Tell Child to report status. - sleep 1; # Wait so file doesn't intermix. } } @@ -1805,17 +1878,33 @@ sub KillThemAll { local($SIG{CHLD}) = 'IGNORE'; # Our children >will< die. foreach my $pid (keys %ChildHash) { my $serving = $ChildHash{$pid}; - Debug(2, "Killing lonc for $serving pid = $pid"); - ShowStatus("Killing lonc for $serving pid = $pid"); - Log("CRITICAL", "Killing lonc for $serving pid = $pid"); + ShowStatus("Nicely Killing lonc for $serving pid = $pid"); + Log("CRITICAL", "Nicely Killing lonc for $serving pid = $pid"); kill 'QUIT' => $pid; - delete($ChildHash{$pid}); } - my $execdir = $perlvar{'lonDaemons'}; - unlink("$execdir/logs/lonc.pid"); + } + +# +# Kill all children via KILL. Just in case the +# first shot didn't get them. + +sub really_kill_them_all_dammit +{ + Debug(2, "Kill them all Dammit"); + local($SIG{CHLD} = 'IGNORE'); # In case some purist reenabled them. + foreach my $pid (keys %ChildHash) { + my $serving = $ChildHash{$pid}; + &ShowStatus("Nastily killing lonc for $serving pid = $pid"); + Log("CRITICAL", "Nastily killing lonc for $serving pid = $pid"); + kill 'KILL' => $pid; + delete($ChildHash{$pid}); + my $execdir = $perlvar{'lonDaemons'}; + unlink("$execdir/logs/lonc.pid"); + } +} =pod =head1 Terminate @@ -1825,7 +1914,15 @@ Terminate the system. =cut sub Terminate { - KillThemAll; + &Log("CRITICAL", "Asked to kill children.. first be nice..."); + &KillThemAll; + # + # By now they really should all be dead.. but just in case + # send them all SIGKILL's after a bit of waiting: + + sleep(4); + &Log("CRITICAL", "Now kill children nasty"); + &really_kill_them_all_dammit; Log("CRITICAL","Master process exiting"); exit 0;