Debian Bug report logs - #115767
openssh: Couldn't obtain random bytes (error 604389476)

Toggle useless messages

Message #5 received at submit@bugs.debian.org (full text, mbox, reply):

From: Ryan Murray <rmurray@cyberhqz.com>

To: submit@bugs.debian.org

Subject: openssh: Couldn't obtain random bytes (error 604389476)

Date: Tue, 16 Oct 2001 00:24:40 -0700

Package: openssh
Version: 2.9p2-6
Severity: important

On mips and mipsel, the above error message is frequently seen when calling
ssh with a command, usually several times in rapid succession, although that
is not always the case.  The error appears to come from the OpenBSD compat code
for arc4random, even if arc4 is not the cipher in use!

What the error number means I am not sure of, as it comes from inside
SSL, and I can't tell what it means from a quick glance at the code. 
A call to one of the more descriptive error calls at this point may be
a good idea.

So I can see two possible things to help the problem:
1. report a more verbose error message so that one might understand why it
   is failing so it might be fixed.
2. don't initialize the arc4 random routines if arc4 is not used.

I will attempt to do #1, but as the problem is intermittent, it may take
awhile to collect the information.  I think a more descriptive error message
in this failure case would be a good idea either way.

Message #16 received at 115767@bugs.debian.org (full text, mbox, reply):

From: Colin Watson <cjwatson@debian.org>

To: Ryan Murray <rmurray@cyberhqz.com>

Cc: 115767@bugs.debian.org

Subject: Re: openssh: Couldn't obtain random bytes (error 604389476)

Date: Mon, 30 Dec 2002 02:36:30 +0000

On Tue, Oct 16, 2001 at 12:24:40AM -0700, Ryan Murray wrote:
> Package: openssh
> Version: 2.9p2-6
> Severity: important

Sorry it took so long to reply to this. Are you still seeing this bug?

> On mips and mipsel, the above error message is frequently seen when calling
> ssh with a command, usually several times in rapid succession, although that
> is not always the case.  The error appears to come from the OpenBSD compat code
> for arc4random, even if arc4 is not the cipher in use!

arc4random() is used for all kinds of routine things within OpenSSH,
such as session keys. It can't be disabled.

> What the error number means I am not sure of, as it comes from inside
> SSL, and I can't tell what it means from a quick glance at the code. 
> A call to one of the more descriptive error calls at this point may be
> a good idea.
> 
> So I can see two possible things to help the problem:
> 1. report a more verbose error message so that one might understand why it
>    is failing so it might be fixed.
> 2. don't initialize the arc4 random routines if arc4 is not used.
> 
> I will attempt to do #1, but as the problem is intermittent, it may take
> awhile to collect the information.  I think a more descriptive error message
> in this failure case would be a good idea either way.

I agree that that would have helped. In this case, it's possible to find
the place where the error is generated just from the OpenSSL error code.
It decodes to:

  ERR_LIB_RAND (unsurprisingly)
  RAND_F_SSLEAY_RAND_BYTES
  RAND_R_PRNG_NOT_SEEDED

... which will come with the following error data:

  You need to read the OpenSSL FAQ, http://www.openssl.org/support/faq.html

This is generated in ssleay_rand_bytes, crypto/rand/md_rand.c, in the
case where less than 20 bytes of entropy are available.

Now, Debian's ssh is configured not to call RAND_add(), because we
expect to have a working /dev/urandom. Is there perhaps some problem
with this on mips and mipsel?

Regards,

-- 
Colin Watson                                  [cjwatson@flatline.org.uk]

Message #21 received at 115767@bugs.debian.org (full text, mbox, reply):

From: Colin Watson <cjwatson@debian.org>

To: debian-mips@lists.debian.org

Cc: 115767@bugs.debian.org

Subject: OpenSSH bug #115767

Date: Sun, 27 Apr 2003 18:49:51 +0100

Hi,

Is anyone still seeing bug #115767 on mips or mipsel, or indeed any
architecture? The bug reporter hasn't responded to my reply and request
for more information (perhaps not surprisingly since it took over a year
for us to get back to him in the first place).

Alternatively, are there any known problems with /dev/urandom on mips or
mipsel?

I'm afraid I'm not subscribed to debian-mips, so please continue to cc
either me or (preferably) 115767@bugs.debian.org on replies.

Thanks,

-- 
Colin Watson                                  [cjwatson@flatline.org.uk]

Message #26 received at 115767-quiet@bugs.debian.org (full text, mbox, reply):

From: Colin Watson <cjwatson@debian.org>

To: Anand Kumria <wildfire@progsoc.uts.edu.au>

Cc: 155467@bugs.debian.org, Jedd Rashbrooke <jedd@progsoc.uts.edu.au>, 115767-quiet@bugs.debian.org

Subject: Re: Bug#155467: ssh dies when it has run out of random bits

Date: Sun, 27 Apr 2003 19:33:28 +0100

severity 115767 important
merge 115767 155467
thanks

On Tue, Aug 06, 2002 at 12:19:55PM +1000, Anand Kumria wrote:
> On Mon, Aug 05, 2002 at 06:29:12PM +0100, Matthew Vernon wrote:
> > Anand Kumria writes:
> >  > Aug  5 07:45:16 ftoomsh sshd[6025]: fatal: Couldn't obtain random bytes
> >  > (error 604389476)
> > 
> > This seems correct to me - if sshd cannot obtain any more random
> > bytes, then it's completely stuffed - It can't do any more crypto
> > operations at all, not just for that connection.
> 
> Well if sshd couldn't really obtain more random data I'd expect the
> already existent connections to (eventually) die due to the same cause.
> 
> This doesn't happen -- as far as I've seen.
> 
> Also the fact that I can restart sshd immediately after it has died
> tends to indicate that what has actually happened is that it didn't get
> enough random data; sshd could simply try again and all should be well.
> 
> After all, the world is full of randomness.

Hi,

I analysed #115767 a while back, but I didn't notice that they were the
same bug until now.

Since the Debian OpenSSL package is configured to use /dev/urandom, I
would expect never to see this error, since /dev/urandom always returns
as much data as was requested even if the system runs out of entropy.
Would you agree with this? If so, I'm inclined to think that this is an
OpenSSL bug.

Cheers,

-- 
Colin Watson                                  [cjwatson@flatline.org.uk]

Message #31 received at 115767@bugs.debian.org (full text, mbox, reply):

From: Thiemo Seufer <ica2_ts@csv.ica.uni-stuttgart.de>

To: debian-mips@lists.debian.org

Cc: 115767@bugs.debian.org

Subject: Re: OpenSSH bug #115767

Date: Sun, 27 Apr 2003 21:58:34 +0200

Colin Watson wrote:
> Hi,
> 
> Is anyone still seeing bug #115767 on mips or mipsel, or indeed any
> architecture? The bug reporter hasn't responded to my reply and request
> for more information (perhaps not surprisingly since it took over a year
> for us to get back to him in the first place).

I never saw it.

> Alternatively, are there any known problems with /dev/urandom on mips or
> mipsel?

None I know of.


Thiemo

Message #36 received at 115767@bugs.debian.org (full text, mbox, reply):

From: Andy Smith <andy@lug.org.uk>

To: 115767@bugs.debian.org

Subject: I see this too on x86-xen running etch

Date: Thu, 9 Mar 2006 17:13:34 +0000

[Message part 1 (text/plain, inline)]

Hi,

I get this error message and sshd dying intermittently since I
upgraded one of my sarge xen domains to etch.  It always happens in
the middle of a prolonged dictionary attack on my sshd.  My other
sarge domains on the same hardware get the dictionary attacks and
weather them fine though.

I don't understand how it can be running out of random bytes when
/dev/urandom is there and appears to be working.

Last time this happened I ran sshd from the console like so:

/usr/sbin/sshd -eD -o 'LogLevel VERBOSE'

and got this:

(snip thousands of similar lines)
Failed password for invalid user random from 219.238.174.73 port 47185 ssh2
Received disconnect from 219.238.174.73: 11: Bye Bye
Connection from 219.238.174.73 port 47333
Invalid user cacilia from 219.238.174.73
input_userauth_request: invalid user cacilia
Failed password for invalid user cacilia from 219.238.174.73 port 47333 ssh2
Received disconnect from 219.238.174.73: 11: Bye Bye
Connection from 219.238.174.73 port 47476
Couldn't obtain random bytes (error 604389476)
ruminant:~#

Any ideas?

-- 
http://strugglers.net/wiki/Xen_hosting -- A Xen VPS hosting hobby
Encrypted mail welcome - keyid 0x604DE5DB

[signature.asc (application/pgp-signature, inline)]

Message #41 received at 115767@bugs.debian.org (full text, mbox, reply):

From: Justin Pryzby <justinpryzby@users.sourceforge.net>

To: Andy Smith <andy@lug.org.uk>, 115767@bugs.debian.org

Subject: Re: Bug#115767: I see this too on x86-xen running etch

Date: Thu, 9 Mar 2006 12:37:06 -0500

On Thu, Mar 09, 2006 at 05:13:34PM +0000, Andy Smith wrote:
> Hi,
> 
> I get this error message and sshd dying intermittently since I
> upgraded one of my sarge xen domains to etch.  It always happens in
> the middle of a prolonged dictionary attack on my sshd.  My other
> sarge domains on the same hardware get the dictionary attacks and
> weather them fine though.
> 
> I don't understand how it can be running out of random bytes when
> /dev/urandom is there and appears to be working.
> 
> Last time this happened I ran sshd from the console like so:
> 
> /usr/sbin/sshd -eD -o 'LogLevel VERBOSE'
This doesn't actually help much; the same error code was reported
before.  Would you consider trying to strace the processes?  This was
recommended for the other similar bug (assigned to "openssl"; there
are #115767, #155467).

Something like strace -f -o /var/log/ssh-strace/ssh-strace.log, where
you should be able to set the directory permissions to be sufficiently
tight.

This might also be a kernel bug, if read() returns short when it
shouldn't.  How reproducible is this for you?  What if you

  while :; do ssh otherhost true; done;

(with rsa or other noninteractive authentication mechanism enabled)

Justin

Message #46 received at 115767@bugs.debian.org (full text, mbox, reply):

From: Andy Smith <andy@lug.org.uk>

To: Justin Pryzby <justinpryzby@users.sourceforge.net>

Cc: 115767@bugs.debian.org

Subject: Re: Bug#115767: I see this too on x86-xen running etch

Date: Thu, 9 Mar 2006 17:49:21 +0000

[Message part 1 (text/plain, inline)]

On Thu, Mar 09, 2006 at 12:37:06PM -0500, Justin Pryzby wrote:
> On Thu, Mar 09, 2006 at 05:13:34PM +0000, Andy Smith wrote:
> > Hi,
> > 
> > I get this error message and sshd dying intermittently since I
> > upgraded one of my sarge xen domains to etch.  It always happens in
> > the middle of a prolonged dictionary attack on my sshd.  My other
> > sarge domains on the same hardware get the dictionary attacks and
> > weather them fine though.
> > 
> > I don't understand how it can be running out of random bytes when
> > /dev/urandom is there and appears to be working.
> > 
> > Last time this happened I ran sshd from the console like so:
> > 
> > /usr/sbin/sshd -eD -o 'LogLevel VERBOSE'
> This doesn't actually help much; the same error code was reported
> before.

Fair point, just wanted to show it really is the same thing as
previously reported.

> Would you consider trying to strace the processes?  This was
> recommended for the other similar bug (assigned to "openssl"; there
> are #115767, #155467).

I would but I'm concerned that this will use large amounts of disk
space.  This problem only manifests itself perhaps once every month
or two and depends on me getting a big SSH dictionary attack it
seems.

> Something like strace -f -o /var/log/ssh-strace/ssh-strace.log, where
> you should be able to set the directory permissions to be sufficiently
> tight.

What if I ran strace without the -f and ran ssh with -eD again so it
doesn't detach or fork?  Then I'd only have strace logs from the
parent sshd right?  Which wouldn't be too much of a logging burden
yet would still show the problem, I'm guessing.

> This might also be a kernel bug, if read() returns short when it
> shouldn't.  How reproducible is this for you?  What if you
> 
>   while :; do ssh otherhost true; done;
> 
> (with rsa or other noninteractive authentication mechanism enabled)

I've had this running for a few minutes now and can't reproduce..
indeed the ssh dictionary attacks were connecting constantly for
hours at a time and still not triggering it, so I think it will be
hard to reproduce.  I'll leave it running and update if there's
anything to report.

Thanks for looking into this,
Andy

-- 
http://strugglers.net/wiki/Xen_hosting -- A Xen VPS hosting hobby
Encrypted mail welcome - keyid 0x604DE5DB

[signature.asc (application/pgp-signature, inline)]

Message #51 received at 115767@bugs.debian.org (full text, mbox, reply):

From: Justin Pryzby <justinpryzby@users.sourceforge.net>

To: Andy Smith <andy@lug.org.uk>, 115767@bugs.debian.org

Subject: Re: Bug#115767: I see this too on x86-xen running etch

Date: Thu, 9 Mar 2006 13:34:19 -0500

On Thu, Mar 09, 2006 at 05:49:21PM +0000, Andy Smith wrote:
> On Thu, Mar 09, 2006 at 12:37:06PM -0500, Justin Pryzby wrote:
> 
> > Would you consider trying to strace the processes?  This was
> > recommended for the other similar bug (assigned to "openssl"; there
> > are #115767, #155467).
> 
> I would but I'm concerned that this will use large amounts of disk
> space.  This problem only manifests itself perhaps once every month
> or two and depends on me getting a big SSH dictionary attack it
> seems.

> > Something like strace -f -o /var/log/ssh-strace/ssh-strace.log, where
> > you should be able to set the directory permissions to be sufficiently
> > tight.
> 
> What if I ran strace without the -f and ran ssh with -eD again so it
> doesn't detach or fork?  Then I'd only have strace logs from the
> parent sshd right?  Which wouldn't be too much of a logging burden
> yet would still show the problem, I'm guessing.
I guess you meant sshd:

     -e      When this option is specified, sshd will send the output
     to the standard error instead of the system log.

I don't see how this helps.

     -D      When this option is specified, sshd will not detach and
     does not become a daemon.  This allows easy monitoring of sshd.

or this either; "forking" doesn't refer to creating child sshd
processes to handle the individual connection, but rather forking a
couple times to get a process independent of your shell; this would
simply cause the sshd process to not return until you kill it (or it
crashes due to lack of random data, of course).

Why don't you just logrotate the files?

I thought there was a logrotate dataloss bug (which might be
completely irrelevant to this discussion, but couldn't find it).  And,
since the "data" is just strace output, you wont lose anything you
wouldn't have had anyway, so just nevermind me...

BTW strace has -e to cut down on the types of output to create, but I
would suggest to not use it, otherwise the relevant context will be
lost.

Also, you should probably use strace -ff instead.

Thanks for testing
Justin

Message #56 received at 115767@bugs.debian.org (full text, mbox, reply):

From: Andy Smith <andy@lug.org.uk>

To: Justin Pryzby <justinpryzby@users.sourceforge.net>

Cc: 115767@bugs.debian.org

Subject: Re: Bug#115767: I see this too on x86-xen running etch

Date: Fri, 14 Apr 2006 15:58:09 +0000

[Message part 1 (text/plain, inline)]

On Thu, Mar 09, 2006 at 12:37:06PM -0500, Justin Pryzby wrote:
> Something like strace -f -o /var/log/ssh-strace/ssh-strace.log, where
> you should be able to set the directory permissions to be sufficiently
> tight.

Okay, I'm now running:

$ sudo strace -ff -o /var/log/ssh-strace/ssh-strace.log /usr/sbin/sshd

But after only a couple of minutes all these files have been
created:

$ sudo ls -lah /var/log/ssh-strace/
total 3.2M
drwx------  2 root root 3.0K Apr 14 15:54 .
drwxr-xr-x 10 root root 2.0K Apr 14 06:30 ..
-rw-r--r--  1 root root  87K Apr 14 15:54 ssh-strace.log
-rw-r--r--  1 root root  56K Apr 14 15:51 ssh-strace.log.15527
-rw-r--r--  1 root root 5.2K Apr 14 15:51 ssh-strace.log.15528
-rw-r--r--  1 root root  56K Apr 14 15:51 ssh-strace.log.15529
-rw-r--r--  1 root root 5.2K Apr 14 15:51 ssh-strace.log.15530
-rw-r--r--  1 root root  56K Apr 14 15:51 ssh-strace.log.15531
-rw-r--r--  1 root root 5.2K Apr 14 15:51 ssh-strace.log.15532
-rw-r--r--  1 root root  56K Apr 14 15:51 ssh-strace.log.15533
-rw-r--r--  1 root root 5.2K Apr 14 15:51 ssh-strace.log.15534
-rw-r--r--  1 root root  75K Apr 14 15:52 ssh-strace.log.15535
-rw-r--r--  1 root root 6.0K Apr 14 15:51 ssh-strace.log.15536
-rw-r--r--  1 root root 2.2K Apr 14 15:51 ssh-strace.log.15537
-rw-r--r--  1 root root  56K Apr 14 15:51 ssh-strace.log.15538
-rw-r--r--  1 root root 5.3K Apr 14 15:51 ssh-strace.log.15539
-rw-r--r--  1 root root  57K Apr 14 15:52 ssh-strace.log.15540
-rw-r--r--  1 root root  76K Apr 14 15:52 ssh-strace.log.15541
-rw-r--r--  1 root root 2.4K Apr 14 15:51 ssh-strace.log.15542
-rw-r--r--  1 root root  17K Apr 14 15:51 ssh-strace.log.15543
-rw-r--r--  1 root root 2.4K Apr 14 15:51 ssh-strace.log.15544
-rw-r--r--  1 root root 2.3K Apr 14 15:51 ssh-strace.log.15545
-rw-r--r--  1 root root  56K Apr 14 15:51 ssh-strace.log.15546
-rw-r--r--  1 root root 5.2K Apr 14 15:51 ssh-strace.log.15547
-rw-r--r--  1 root root  56K Apr 14 15:51 ssh-strace.log.15548
-rw-r--r--  1 root root 5.2K Apr 14 15:51 ssh-strace.log.15549
-rw-r--r--  1 root root 3.4K Apr 14 15:51 ssh-strace.log.15550
-rw-r--r--  1 root root  56K Apr 14 15:51 ssh-strace.log.15551
-rw-r--r--  1 root root 5.2K Apr 14 15:51 ssh-strace.log.15552
-rw-r--r--  1 root root  56K Apr 14 15:51 ssh-strace.log.15553
-rw-r--r--  1 root root 5.2K Apr 14 15:51 ssh-strace.log.15554
-rw-r--r--  1 root root  56K Apr 14 15:51 ssh-strace.log.15555
-rw-r--r--  1 root root 5.2K Apr 14 15:51 ssh-strace.log.15556
-rw-r--r--  1 root root  56K Apr 14 15:51 ssh-strace.log.15557
-rw-r--r--  1 root root 5.2K Apr 14 15:51 ssh-strace.log.15558
-rw-r--r--  1 root root  39K Apr 14 15:52 ssh-strace.log.15559
-rw-r--r--  1 root root  56K Apr 14 15:52 ssh-strace.log.15560
-rw-r--r--  1 root root 5.2K Apr 14 15:52 ssh-strace.log.15561
-rw-r--r--  1 root root  94K Apr 14 15:52 ssh-strace.log.15562
-rw-r--r--  1 root root  56K Apr 14 15:52 ssh-strace.log.15563
-rw-r--r--  1 root root 5.2K Apr 14 15:52 ssh-strace.log.15564
-rw-r--r--  1 root root  56K Apr 14 15:52 ssh-strace.log.15565
-rw-r--r--  1 root root 5.2K Apr 14 15:52 ssh-strace.log.15566
-rw-r--r--  1 root root  56K Apr 14 15:52 ssh-strace.log.15567
-rw-r--r--  1 root root 5.2K Apr 14 15:52 ssh-strace.log.15568
-rw-r--r--  1 root root  56K Apr 14 15:52 ssh-strace.log.15569
-rw-r--r--  1 root root 5.2K Apr 14 15:52 ssh-strace.log.15570
-rw-r--r--  1 root root  56K Apr 14 15:52 ssh-strace.log.15573
-rw-r--r--  1 root root 5.2K Apr 14 15:52 ssh-strace.log.15575
-rw-r--r--  1 root root  56K Apr 14 15:52 ssh-strace.log.15576
-rw-r--r--  1 root root 5.2K Apr 14 15:52 ssh-strace.log.15577
-rw-r--r--  1 root root  56K Apr 14 15:52 ssh-strace.log.15578
-rw-r--r--  1 root root 5.2K Apr 14 15:52 ssh-strace.log.15579
-rw-r--r--  1 root root  56K Apr 14 15:52 ssh-strace.log.15581
-rw-r--r--  1 root root 5.2K Apr 14 15:52 ssh-strace.log.15582
-rw-r--r--  1 root root  56K Apr 14 15:52 ssh-strace.log.15583
-rw-r--r--  1 root root 5.3K Apr 14 15:52 ssh-strace.log.15584
-rw-r--r--  1 root root  56K Apr 14 15:52 ssh-strace.log.15585
-rw-r--r--  1 root root 5.2K Apr 14 15:52 ssh-strace.log.15586
-rw-r--r--  1 root root  56K Apr 14 15:52 ssh-strace.log.15587
-rw-r--r--  1 root root 5.2K Apr 14 15:52 ssh-strace.log.15588
-rw-r--r--  1 root root  56K Apr 14 15:53 ssh-strace.log.15589
-rw-r--r--  1 root root 5.2K Apr 14 15:53 ssh-strace.log.15590
-rw-r--r--  1 root root  56K Apr 14 15:53 ssh-strace.log.15591
-rw-r--r--  1 root root 5.2K Apr 14 15:53 ssh-strace.log.15592
-rw-r--r--  1 root root  56K Apr 14 15:53 ssh-strace.log.15593
-rw-r--r--  1 root root 5.3K Apr 14 15:53 ssh-strace.log.15594
-rw-r--r--  1 root root  44K Apr 14 15:53 ssh-strace.log.15595
-rw-r--r--  1 root root 2.5K Apr 14 15:53 ssh-strace.log.15596
-rw-r--r--  1 root root  56K Apr 14 15:53 ssh-strace.log.15597
-rw-r--r--  1 root root 5.2K Apr 14 15:53 ssh-strace.log.15598
-rw-r--r--  1 root root  56K Apr 14 15:53 ssh-strace.log.15599
-rw-r--r--  1 root root 5.2K Apr 14 15:53 ssh-strace.log.15600
-rw-r--r--  1 root root  56K Apr 14 15:53 ssh-strace.log.15601
-rw-r--r--  1 root root 5.3K Apr 14 15:53 ssh-strace.log.15602
-rw-r--r--  1 root root  56K Apr 14 15:53 ssh-strace.log.15603
-rw-r--r--  1 root root 5.3K Apr 14 15:53 ssh-strace.log.15604
-rw-r--r--  1 root root  56K Apr 14 15:53 ssh-strace.log.15605
-rw-r--r--  1 root root 5.2K Apr 14 15:53 ssh-strace.log.15606
-rw-r--r--  1 root root  56K Apr 14 15:53 ssh-strace.log.15608
-rw-r--r--  1 root root 5.2K Apr 14 15:53 ssh-strace.log.15609
-rw-r--r--  1 root root  56K Apr 14 15:53 ssh-strace.log.15611
-rw-r--r--  1 root root 5.2K Apr 14 15:53 ssh-strace.log.15612
-rw-r--r--  1 root root  56K Apr 14 15:53 ssh-strace.log.15613
-rw-r--r--  1 root root 5.2K Apr 14 15:53 ssh-strace.log.15614
-rw-r--r--  1 root root  56K Apr 14 15:53 ssh-strace.log.15615
-rw-r--r--  1 root root 5.2K Apr 14 15:53 ssh-strace.log.15616
-rw-r--r--  1 root root  56K Apr 14 15:54 ssh-strace.log.15617
-rw-r--r--  1 root root 5.2K Apr 14 15:54 ssh-strace.log.15618
-rw-r--r--  1 root root  56K Apr 14 15:54 ssh-strace.log.15619
-rw-r--r--  1 root root 5.2K Apr 14 15:54 ssh-strace.log.15623
-rw-r--r--  1 root root  56K Apr 14 15:54 ssh-strace.log.15625
-rw-r--r--  1 root root 5.2K Apr 14 15:54 ssh-strace.log.15626
-rw-r--r--  1 root root  56K Apr 14 15:54 ssh-strace.log.15627
-rw-r--r--  1 root root 5.2K Apr 14 15:54 ssh-strace.log.15628
-rw-r--r--  1 root root  56K Apr 14 15:54 ssh-strace.log.15629
-rw-r--r--  1 root root 5.2K Apr 14 15:54 ssh-strace.log.15630
-rw-r--r--  1 root root  56K Apr 14 15:54 ssh-strace.log.15631
-rw-r--r--  1 root root 5.2K Apr 14 15:54 ssh-strace.log.15632
-rw-r--r--  1 root root  56K Apr 14 15:54 ssh-strace.log.15633
-rw-r--r--  1 root root 5.2K Apr 14 15:54 ssh-strace.log.15634
-rw-r--r--  1 root root  44K Apr 14 15:54 ssh-strace.log.15636
-rw-r--r--  1 root root 2.0K Apr 14 15:54 ssh-strace.log.15637

so I'm a bit concerned I'm going to run out of disk space.  Can I
delete files older than a day, daily, if I have not had a
reoccurance of the problem?

And yes I am also aware I need to adjust my umask to stop them being
world readable.

Cheers,
Andy

[signature.asc (application/pgp-signature, inline)]

Message #61 received at 115767@bugs.debian.org (full text, mbox, reply):

From: Justin Pryzby <justinpryzby@users.sourceforge.net>

To: Andy Smith <andy@lug.org.uk>, 115767@bugs.debian.org

Subject: Re: Bug#115767: I see this too on x86-xen running etch

Date: Fri, 14 Apr 2006 12:37:07 -0400

On Fri, Apr 14, 2006 at 03:58:09PM +0000, Andy Smith wrote:
> On Thu, Mar 09, 2006 at 12:37:06PM -0500, Justin Pryzby wrote:
> > Something like strace -f -o /var/log/ssh-strace/ssh-strace.log, where
> > you should be able to set the directory permissions to be sufficiently
> > tight.
> 
> Okay, I'm now running:
> 
> $ sudo strace -ff -o /var/log/ssh-strace/ssh-strace.log /usr/sbin/sshd
Arg, in a different bug (firefox, another one of the top-50-bug
packages to which i'm subscribed), I discovered that strace -ff -o -p
caused corrupted strace output and memory corruption (in strace only).
Please make sure that your strace output is sane (no overlapping
calls).  I think all three of those options are necessary to trigger
that bug, though.

> But after only a couple of minutes all these files have been
> created:

> so I'm a bit concerned I'm going to run out of disk space.
Heh, indeed.

> Can I delete files older than a day, daily, if I have not had a
> reoccurance of the problem?
Yes.  I suggested logrotate, though I'm not familiar with it at all,
it is the standard too for this, and the config file syntax seems
pretty easy.  You'll have to run a special cronjob, though, if you
want it to happen more than once a day.

You can also tar rzf the files; since they are small, there's lots of
overhead, tar will overcome that, (and compress it to boot).  If you
can come up with some way of testing for this (such as if sshd dies;
does it?!) then you can just remove all the files every few minutes in
a root cronjob (and restart sshd, while you're at it):

* * * * * pidof /usr/sbin/sshd || { rm /var/log/ssh-strace/ssh-strace.log.*; /etc/init.d/ssh start; }

> And yes I am also aware I need to adjust my umask to stop them being
> world readable.
Actually, since the directory is 0700, that isn't strictly necessary.
Other users will neither be able to see the files nor even use that
directory as a component of a pathname.

> $ sudo ls -lah /var/log/ssh-strace/
> total 3.2M
> drwx------  2 root root 3.0K Apr 14 15:54 .

Justin

Message #68 received at 115767@bugs.debian.org (full text, mbox, reply):

From: Andy Smith <andy@lug.org.uk>

To: Justin Pryzby <justinpryzby@users.sourceforge.net>

Cc: 115767@bugs.debian.org

Subject: Re: Bug#115767: I see this too on x86-xen running etch

Date: Sat, 15 Apr 2006 22:27:32 +0000

[Message part 1 (text/plain, inline)]

> On Fri, Apr 14, 2006 at 03:58:09PM +0000, Andy Smith wrote:
> > Okay, I'm now running:
> > 
> > $ sudo strace -ff -o /var/log/ssh-strace/ssh-strace.log /usr/sbin/sshd

Unfortunately now whenever I log in via an sshd that is running
under strace, none of my setuid binaries work.  For sudo this is a
showstopper: all I get is "sudo: must be setuid root".  Since I
still need to use this machine I've had to stop running sshd under
strace. :(

If anyone is interested in debugging this I can set you up a 64M
etch xen domain that you have root access to and you can do what you
like to it to try and get to the bottom of this.

Failing that, I guess I will have to do the same, but I will be
slower..

Cheers,
Andy

[signature.asc (application/pgp-signature, inline)]

Message #73 received at 115767@bugs.debian.org (full text, mbox, reply):

From: Justin Pryzby <justinpryzby@users.sourceforge.net>

To: Andy Smith <andy@lug.org.uk>, 115767@bugs.debian.org

Subject: Re: Bug#115767: I see this too on x86-xen running etch

Date: Sun, 16 Apr 2006 11:42:00 -0400

On Sat, Apr 15, 2006 at 10:27:32PM +0000, Andy Smith wrote:
> > On Fri, Apr 14, 2006 at 03:58:09PM +0000, Andy Smith wrote:
> > > Okay, I'm now running:
> > > 
> > > $ sudo strace -ff -o /var/log/ssh-strace/ssh-strace.log /usr/sbin/sshd
> 
> Unfortunately now whenever I log in via an sshd that is running
> under strace, none of my setuid binaries work.
Um, yea, that would break .. its mentioned in the strace manpage BUGS section.

> For sudo this is a
> showstopper: all I get is "sudo: must be setuid root".  Since I
> still need to use this machine I've had to stop running sshd under
> strace. :(
What about strace without -f?  I just tested with strace -o /dev/null sh, and I
am still able to run sudo.  It isn't clear to me whether this will catch the
problem; it depends on the server crashing (you said it did, no?) and sshd not
forking before it tries to read urandom. 

> If anyone is interested in debugging this I can set you up a 64M
> etch xen domain that you have root access to and you can do what you
> like to it to try and get to the bottom of this.
I'm not sure I would know what to try ..

Thanks
Justin

Message #78 received at 115767@bugs.debian.org (full text, mbox, reply):

From: Andy Smith <andy@lug.org.uk>

To: Justin Pryzby <justinpryzby@users.sourceforge.net>

Cc: 115767@bugs.debian.org

Subject: Re: Bug#115767: I see this too on x86-xen running etch

Date: Mon, 24 Apr 2006 20:04:27 +0000

On Sun, Apr 16, 2006 at 11:42:00AM -0400, Justin Pryzby wrote:
> What about strace without -f?  I just tested with strace -o /dev/null sh, and I
> am still able to run sudo.  It isn't clear to me whether this will catch the
> problem; it depends on the server crashing (you said it did, no?) and sshd not
> forking before it tries to read urandom. 

I restarted it without -f, and sshd stayed up for about 6 days.
Unfortunately when I look at the log file its mtime is about 6 days
ago.. so I doubt very much it has anything useful in it.

I'll look into running another sshd on a higher port for my own
needs and strace one on port 22.  The dictionary attacks should
still trigger this eventually.

Cheers,
Andy

Message #83 received at 115767@bugs.debian.org (full text, mbox, reply):

From: Justin Pryzby <justinpryzby@users.sourceforge.net>

To: Andy Smith <andy@lug.org.uk>, 115767@bugs.debian.org

Subject: Re: Bug#115767: I see this too on x86-xen running etch

Date: Mon, 24 Apr 2006 16:22:39 -0400

On Mon, Apr 24, 2006 at 08:04:27PM +0000, Andy Smith wrote:
> On Sun, Apr 16, 2006 at 11:42:00AM -0400, Justin Pryzby wrote:
> > What about strace without -f?  I just tested with strace -o /dev/null sh, and I
> > am still able to run sudo.  It isn't clear to me whether this will catch the
> > problem; it depends on the server crashing (you said it did, no?) and sshd not
> > forking before it tries to read urandom. 
> 
> I restarted it without -f, and sshd stayed up for about 6 days.
> Unfortunately when I look at the log file its mtime is about 6 days
> ago.. so I doubt very much it has anything useful in it.
Strange; for me, strace -f -p `pidof /usr/sbin/sshd` has about 1 page
of output.  Disabling privledge separation causes it to output many
times more.  I don't really know what the implications of this are,
especially with strace, but sudo does work. 

Justin

Message #88 received at 115767@bugs.debian.org (full text, mbox, reply):

From: Andy Smith <andy@lug.org.uk>

To: Justin Pryzby <justinpryzby@users.sourceforge.net>

Cc: 115767@bugs.debian.org

Subject: Re: Bug#115767: I see this too on x86-xen running etch

Date: Sat, 29 Apr 2006 15:11:55 +0000

On Mon, Apr 24, 2006 at 08:04:27PM +0000, Andy Smith wrote:
> I'll look into running another sshd on a higher port for my own
> needs and strace one on port 22.  The dictionary attacks should
> still trigger this eventually.

Okay, I did this, and ~5 days later a massive dictionary attack
triggered the problem:

# grep -c 'sshd.*Invalid user.*from 62.193.245.215' /var/log/auth.log
1902
# grep -B 4 6372 /var/log/auth.log
Apr 29 13:57:06 ruminant sshd[443]: Invalid user qmailr from 62.193.245.215
Apr 29 13:57:06 ruminant sshd[445]: Invalid user qmails from 62.193.245.215
Apr 29 13:57:07 ruminant sshd[447]: Invalid user r00t from 62.193.245.215
Apr 29 13:57:07 ruminant sshd[449]: Invalid user r00t from 62.193.245.215
Apr 29 13:57:07 ruminant sshd[6372]: fatal: Couldn't obtain random bytes (error 604389476)
# ls -lh /var/log/ssh-strace/ssh-strace.log.6372
-rw-r--r-- 1 root root 23M Apr 29 13:57 /var/log/ssh-strace/ssh-strace.log.6372
# tail -40 /var/log/ssh-strace/ssh-strace.log.6372
13:57:07 write(7, "\0\0\2Y\n\n\n\nPort 22\n\n\n\nProtocol 2\n\nH"..., 609) = 609
13:57:07 close(7)                       = 0
13:57:07 close(8)                       = 0
13:57:07 getpid()                       = 6372
13:57:07 getpid()                       = 6372
13:57:07 close(4)                       = 0
13:57:07 select(8, [3 5], NULL, NULL, NULL) = 1 (in [5])
13:57:07 --- SIGCHLD (Child exited) @ 0 (0) ---
13:57:07 waitpid(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 255}], WNOHANG) = 449
13:57:07 waitpid(-1, 0xbfffeb5c, WNOHANG) = -1 ECHILD (No child processes)
13:57:07 rt_sigaction(SIGCHLD, NULL, {0x804d470, [], 0}, 8) = 0
13:57:07 sigreturn()                    = ? (mask now [])
13:57:07 close(5)                       = 0
13:57:07 select(8, [3], NULL, NULL, NULL) = 1 (in [3])
13:57:07 accept(3, {sa_family=AF_INET6, sin6_port=htons(40492), inet_pton(AF_INET6, "::ffff:62.193.245.215", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28]) = 4
13:57:07 fcntl64(4, F_GETFL)            = 0x2 (flags O_RDWR)
13:57:07 pipe([5, 6])                   = 0
13:57:07 socketpair(PF_FILE, SOCK_STREAM, 0, [7, 8]) = 0
13:57:07 fork()                         = 451
13:57:07 close(6)                       = 0
13:57:07 write(7, "\0\0\2b\0", 5)       = 5
13:57:07 write(7, "\0\0\2Y\n\n\n\nPort 22\n\n\n\nProtocol 2\n\nH"..., 609) = 609
13:57:07 close(7)                       = 0
13:57:07 close(8)                       = 0
13:57:07 getpid()                       = 6372
13:57:07 getpid()                       = 6372
13:57:07 getpid()                       = 6372
13:57:07 getpid()                       = 6372
13:57:07 getpid()                       = 6372
13:57:07 time([1146319027])             = 1146319027
13:57:07 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=56, ...}) = 0
13:57:07 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=56, ...}) = 0
13:57:07 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=56, ...}) = 0
13:57:07 getpid()                       = 6372
13:57:07 socket(PF_FILE, SOCK_DGRAM, 0) = 6
13:57:07 fcntl64(6, F_SETFD, FD_CLOEXEC) = 0
13:57:07 connect(6, {sa_family=AF_FILE, path="/dev/log"}, 16) = 0
13:57:07 send(6, "<34>Apr 29 13:57:07 sshd[6372]: "..., 85, MSG_NOSIGNAL) = 85
13:57:07 close(6)                       = 0
13:57:07 exit_group(255)                = ?

I can't see anything that jumps out as being wrong in any of the
strace logs for the forked children 451, 449, 447, 445 etc..  Any
ideas?

Cheers,
Andy

Message #93 received at 115767@bugs.debian.org (full text, mbox, reply):

From: Justin Pryzby <justinpryzby@users.sourceforge.net>

To: Andy Smith <andy@lug.org.uk>, 115767@bugs.debian.org

Subject: Re: Bug#115767: I see this too on x86-xen running etch

Date: Fri, 5 May 2006 14:58:53 -0400

On Sat, Apr 29, 2006 at 03:11:55PM +0000, Andy Smith wrote:
> On Mon, Apr 24, 2006 at 08:04:27PM +0000, Andy Smith wrote:
> > I'll look into running another sshd on a higher port for my own
> > needs and strace one on port 22.  The dictionary attacks should
> > still trigger this eventually.
> 
> Okay, I did this, and ~5 days later a massive dictionary attack
> triggered the problem:
> 
> # grep -c 'sshd.*Invalid user.*from 62.193.245.215' /var/log/auth.log
> 1902
> # grep -B 4 6372 /var/log/auth.log
> Apr 29 13:57:06 ruminant sshd[443]: Invalid user qmailr from 62.193.245.215
> Apr 29 13:57:06 ruminant sshd[445]: Invalid user qmails from 62.193.245.215
> Apr 29 13:57:07 ruminant sshd[447]: Invalid user r00t from 62.193.245.215
> Apr 29 13:57:07 ruminant sshd[449]: Invalid user r00t from 62.193.245.215
> Apr 29 13:57:07 ruminant sshd[6372]: fatal: Couldn't obtain random bytes (error 604389476)
> # ls -lh /var/log/ssh-strace/ssh-strace.log.6372
> -rw-r--r-- 1 root root 23M Apr 29 13:57 /var/log/ssh-strace/ssh-strace.log.6372
> # tail -40 /var/log/ssh-strace/ssh-strace.log.6372
> 13:57:07 write(7, "\0\0\2Y\n\n\n\nPort 22\n\n\n\nProtocol 2\n\nH"..., 609) = 609
> 13:57:07 close(7)                       = 0
> 13:57:07 close(8)                       = 0
> 13:57:07 getpid()                       = 6372
> 13:57:07 getpid()                       = 6372
> 13:57:07 close(4)                       = 0
> 13:57:07 select(8, [3 5], NULL, NULL, NULL) = 1 (in [5])
> 13:57:07 --- SIGCHLD (Child exited) @ 0 (0) ---
> 13:57:07 waitpid(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 255}], WNOHANG) = 449
> 13:57:07 waitpid(-1, 0xbfffeb5c, WNOHANG) = -1 ECHILD (No child processes)
> 13:57:07 rt_sigaction(SIGCHLD, NULL, {0x804d470, [], 0}, 8) = 0
> 13:57:07 sigreturn()                    = ? (mask now [])
> 13:57:07 close(5)                       = 0
> 13:57:07 select(8, [3], NULL, NULL, NULL) = 1 (in [3])
> 13:57:07 accept(3, {sa_family=AF_INET6, sin6_port=htons(40492), inet_pton(AF_INET6, "::ffff:62.193.245.215", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28]) = 4
> 13:57:07 fcntl64(4, F_GETFL)            = 0x2 (flags O_RDWR)
> 13:57:07 pipe([5, 6])                   = 0
> 13:57:07 socketpair(PF_FILE, SOCK_STREAM, 0, [7, 8]) = 0
> 13:57:07 fork()                         = 451
> 13:57:07 close(6)                       = 0
> 13:57:07 write(7, "\0\0\2b\0", 5)       = 5
> 13:57:07 write(7, "\0\0\2Y\n\n\n\nPort 22\n\n\n\nProtocol 2\n\nH"..., 609) = 609
> 13:57:07 close(7)                       = 0
> 13:57:07 close(8)                       = 0
> 13:57:07 getpid()                       = 6372
> 13:57:07 getpid()                       = 6372
> 13:57:07 getpid()                       = 6372
> 13:57:07 getpid()                       = 6372
> 13:57:07 getpid()                       = 6372
> 13:57:07 time([1146319027])             = 1146319027
> 13:57:07 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=56, ...}) = 0
> 13:57:07 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=56, ...}) = 0
> 13:57:07 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=56, ...}) = 0
> 13:57:07 getpid()                       = 6372
> 13:57:07 socket(PF_FILE, SOCK_DGRAM, 0) = 6
> 13:57:07 fcntl64(6, F_SETFD, FD_CLOEXEC) = 0
> 13:57:07 connect(6, {sa_family=AF_FILE, path="/dev/log"}, 16) = 0
> 13:57:07 send(6, "<34>Apr 29 13:57:07 sshd[6372]: "..., 85, MSG_NOSIGNAL) = 85
> 13:57:07 close(6)                       = 0
> 13:57:07 exit_group(255)                = ?
> 
> I can't see anything that jumps out as being wrong in any of the
> strace logs for the forked children 451, 449, 447, 445 etc..  Any
> ideas?
Nothing that I can see..  You might change your strace to use -s200 to
get longer strings.  Could you send more complete strace logs from
sshd and the relevant client?  I guess it was another process (451?)
which experienced the actual problem, and communicated that to the
master daemon process.

Justin

Message #102 received at 115767@bugs.debian.org (full text, mbox, reply):

From: "Bernhard M. Wiedemann" <debianbmw1@lsmod.de>

To: 115767@bugs.debian.org

Subject: Re: Bug#115767: I see this too on x86 user-mode-linux on etch

Date: Tue, 25 Mar 2008 11:02:39 +0100

Hi,

I am running several virtual machines (currently using 2.6.24.2) with user-mode-linux (UML) and am seeing the very same problem repeatedly.
Mar 25 06:00:05 uml12d sshd[28619]: fatal: Couldn't obtain random bytes (error 604389476)
after a dictionary attack with 5 tries per second.
I straced the normal connection procedure with strace -o sshd.strace -f -p 11541 and found:

11736 open("/dev/urandom", O_RDONLY|O_NOCTTY|O_NONBLOCK) = 3
11736 fstat64(3, {st_mode=S_IFCHR|0644, st_rdev=makedev(1, 9), ...}) = 0
11736 poll([{fd=3, events=POLLIN, revents=POLLIN}], 1, 10) = 1
11736 read(3, "\342\224\2443\314cVK\325\331I\322?=zEa\324u\276\2\f\361\2618p\3217\n\201x\210", 32) = 32
11736 close(3)

The "poll" is probably there to prevent blocking of /dev/random but maybe there are conditions that cause it to return something other than "1" here?

I am seeing a common pattern here: mips, xen, uml... are all platforms that have few real entropy sources like HDDs and thus are more prone to running out of entropy.


On a related note:
I saw openvpn failing on openSUSE-10.3 this morning and it looks very similar:
Tue Mar 25 09:05:24 2008 key/87.185.50.159:1194 ERROR: Random number generator cannot obtain entropy for key generation [SSL]
Tue Mar 25 09:05:24 2008 key/87.185.50.159:1194 Exiting

So maybe it is a kernel bug? Or do those programs fail to check for some normal return value?
I guess, you could speed up triggering this bug by manually emptying the entropy pool with cat /dev/random > /dev/null


Ciao
Bernhard M.

Message #107 received at 115767@bugs.debian.org (full text, mbox, reply):

From: Sebastian Andrzej Siewior <sebastian@breakpoint.cc>

To: "Bernhard M. Wiedemann" <debianbmw1@lsmod.de>

Cc: 115767@bugs.debian.org, Ryan Murray <rmurray@cyberhqz.com>, Andy Smith <andy@lug.org.uk>

Subject: Re: Bug#115767: I see this too on x86 user-mode-linux on etch

Date: Mon, 29 Feb 2016 15:12:13 +0100

On 2008-03-25 11:02:39 [+0100], Bernhard M. Wiedemann wrote:
> Hi,
Hi,

> I am running several virtual machines (currently using 2.6.24.2) with user-mode-linux (UML) and am seeing the very same problem repeatedly.

the year 2016 arrived and with it new kernel, openssl among other packages.
Can anyone of the reporters here reproduce the bug on current unstable or
atleast stable distro?
If not, we could probably close the bug if nobody complains about it anymore
and the problem might have vanished.

> Ciao
> Bernhard M.

Sebastian

Message #112 received at 115767@bugs.debian.org (full text, mbox, reply):

From: "Bernhard M. Wiedemann" <bernhardout2@lsmod.de>

To: Sebastian Andrzej Siewior <sebastian@breakpoint.cc>, "Bernhard M. Wiedemann" <debianbmw1@lsmod.de>

Cc: 115767@bugs.debian.org, Ryan Murray <rmurray@cyberhqz.com>, Andy Smith <andy@lug.org.uk>

Subject: Re: Bug#115767: I see this too on x86 user-mode-linux on etch

Date: Mon, 29 Feb 2016 17:33:32 +0100

On 2016-02-29 15:12, Sebastian Andrzej Siewior wrote:
> the year 2016 arrived and with it new kernel, openssl among other packages.
> Can anyone of the reporters here reproduce the bug on current unstable or
> atleast stable distro?

I have switched from UML to KVM and have not seen this bug anymore since
years.

Ciao
Bernhard M.

Message #117 received at 115767-close@bugs.debian.org (full text, mbox, reply):

From: Sebastian Andrzej Siewior <sebastian@breakpoint.cc>

To: "Bernhard M. Wiedemann" <bernhardout2@lsmod.de>

Cc: "Bernhard M. Wiedemann" <debianbmw1@lsmod.de>, 115767-close@bugs.debian.org, Ryan Murray <rmurray@cyberhqz.com>, Andy Smith <andy@lug.org.uk>

Subject: Re: Bug#115767: I see this too on x86 user-mode-linux on etch

Date: Fri, 4 Mar 2016 23:10:25 +0100

On 2016-02-29 17:33:32 [+0100], Bernhard M. Wiedemann wrote:
> I have switched from UML to KVM and have not seen this bug anymore since
> years.

I hereby close the bug. Nobody seem to be able to reproduce anymore. The
current linux UML maintainer (Richard Weinberger) can not recall to have
ever seen such a bug (but then he wasn't around 2001).
Feel free to reopen the bug with more info once someone is able to
trigger it again.

> Ciao
> Bernhard M.

Sebastian

Send a report that this bug log contains spam.