Logging problem

Fri Aug 8 21:14:50 EST 2003

On Fri, Aug 08, 2003 at 12:27:00PM +0200, René van der Kroft wrote:
> At 11:36 5-8-2003 -0700, you wrote:
> >> Today I received the error again:
> >>
> >>         Received disconnect from IP: 2: fork failed: Resource temporarily
> >> unavailable
> >>
> >>         rsync: connection unexpectedly closed (0 bytes read so far)
> >>         rsync error: error in rsync protocol data stream (code 12) at
> >> io.c(150)
> >>         rsync error: partial transfer (code 23) at main.c(578)
> >>
> >> I've checked the system logs to check if the system was out of resouces 
> >but
> >> I can't find anything.
> >> Is there's something else what it could be?
> >
> >That message is not coming from anywhere in rsync.  This
> >must be coming from a library.  I notice a "^M" on the end
> >of it.  Either the other end is windows or this message has
> >been cooked (stty).
> >
> >I cannot say what resource is temporarily unavailable.  It
> >might have run out of pids or, more likely, memory.  In
> >either case if fork failed rsync will quickly exit freeing
> >up resources.  If you feel daring you could run a fork bomb
> >to confirm that it is fork hitting a limit.
> 
> 
> 
> I've add verbose logging to the SSH deamon, and I notice something strange. 
> I'am using a public key create a SSH connection, this is working correct. 
> The connection is created successfully like the logs shows. As you can see 
> the connection disconnections after a few seconds and a new connection is 
> started. This repeats itself for almost an hour!!! This is probaly is 
> creating a fork limit...

There isn't a fork limit.  There are limits on the total
number of processes and some systems have per-user limits on
the number of processes.  But those limits are for
simultaneous processes so if a process exits you can start a
new one.  More common is running out of memory that the
kernel can use for the process/task/thread structure and
memory maps.

Ssh itself won't attempt to reconnect if a connection is
closed.

The log looks pretty normal to me except for the pid numbers
"sshd[###]" and that the connection closure seems to be
initiated by the client.  The client initiating closure
looks as though it caught a signal, and normally it would be
the server doing the closure due to the shell exiting.  But
then i don't normally pour over sshd logs at this level of
verbosity.

The pid numbers though, they are bouncing around quite
wildly.  Most *ix systems allocate pids sequentially
skipping numbers already in use and when they hit the
maximum number loop back to a low number.  That kind of
bouncing around is usually a product of running out of pids
but could be an OS's attempt at randomisation for security
purposes.

Looking back at your earlier message i see you are running
OpenBSD 4.3.  I've not used that particular flavour but i'd
look to see what the maximum number of processes are and how
many you have running; and also check on the system-wide
limit on open file descriptors.  You may want to get some help
tracking this down from that community.  This certainly does
not look like an rsync problem.

> 
> Do you know what could be wrong?
> 
> Logfile:
> 
> Aug  8 04:00:23 doos sshd[22581]: Connection from 123.456.789.123 port 21408
> Aug  8 04:00:25 doos sshd[4488]: Failed none for user from 123.456.789.123 
> port 21408 ssh2
> Aug  8 04:00:25 doos sshd[22581]: Failed none for user from 123.456.789.123 
> port 21408 ssh2
> Aug  8 04:00:25 doos sshd[22581]: Found matching DSA key: 
> bc:f9:00:ed:29:78:f4:4b:d3:9c:e2:99:f9:31:16:00
> Aug  8 04:00:25 doos sshd[4488]: Accepted publickey for user from 
> 123.456.789.123 port 21408 ssh2
> Aug  8 04:00:25 doos sshd[22581]: Accepted publickey for user from 
> 123.456.789.123 port 21408 ssh2
> Aug  8 04:00:43 doos sshd[2772]: Connection closed by 123.456.789.123
> Aug  8 04:00:43 doos sshd[2772]: Closing connection to 123.456.789.123
> 
> Aug  8 04:00:43 doos sshd[30621]: Connection from 123.456.789.123 port 42870
> Aug  8 04:00:44 doos sshd[30621]: Failed none for user from 123.456.789.123 
> port 42870 ssh2
> Aug  8 04:00:44 doos sshd[28720]: Failed none for user from 123.456.789.123 
> port 42870 ssh2
> Aug  8 04:00:45 doos sshd[30621]: Found matching DSA key: 
> bc:f9:00:ed:29:78:f4:4b:d3:9c:e2:99:f9:31:16:00
> Aug  8 04:00:45 doos sshd[28720]: Accepted publickey for user from 
> 123.456.789.123 port 42870 ssh2
> Aug  8 04:00:45 doos sshd[30621]: Accepted publickey for user from 
> 123.456.789.123 port 42870 ssh2
> Aug  8 04:00:47 doos sshd[20405]: Connection closed by 123.456.789.123
> Aug  8 04:00:47 doos sshd[20405]: Closing connection to 123.456.789.123
> 
> Aug  8 04:01:23 doos sshd[31597]: Connection from 123.456.789.123 port 27324
> Aug  8 04:01:24 doos sshd[31597]: Failed none for user from 123.456.789.123 
> port 27324 ssh2
> Aug  8 04:01:24 doos sshd[10248]: Failed none for user from 123.456.789.123 
> port 27324 ssh2
> Aug  8 04:01:24 doos sshd[31597]: Found matching DSA key: 
> bc:f9:00:ed:29:78:f4:4b:d3:9c:e2:99:f9:31:16:00
> Aug  8 04:01:24 doos sshd[10248]: Accepted publickey for user from 
> 123.456.789.123 port 27324 ssh2
> Aug  8 04:01:24 doos sshd[31597]: Accepted publickey for user from 
> 123.456.789.123 port 27324 ssh2
> Aug  8 04:01:32 doos sshd[1537]: Connection closed by 123.456.789.123
> Aug  8 04:01:32 doos sshd[1537]: Closing connection to 123.456.789.123
> 
> -- 
> To unsubscribe or change options: 
> http://lists.samba.org/mailman/listinfo/rsync
> Before posting, read: http://www.catb.org/~esr/faqs/smart-questions.html
> 

-- 
________________________________________________________________
	J.W. Schultz            Pegasystems Technologies
	email address:		jw at pegasys.ws

		Remember Cernan and Schmitt