Bug 40513 - Seeding PRNG with 0 bytes of entropy
Summary: Seeding PRNG with 0 bytes of entropy
Status: REOPENED
Alias: None
Product: Apache httpd-2
Classification: Unclassified
Component: mod_ssl (show other bugs)
Version: 2.2.12
Hardware: All Linux
: P2 major (vote)
Target Milestone: ---
Assignee: Apache HTTPD Bugs Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2006-09-14 20:45 UTC by Patrick Rutkowski
Modified: 2013-04-22 20:08 UTC (History)
0 users



Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Patrick Rutkowski 2006-09-14 20:45:44 UTC
I installed apache 2.2 with mod_ssl today on a local computer for development
purposes and decided to have a peek at the logs just for fun. When I saw
"Seeding PRNG with 0 bytes of entropy" I was amused and at the same time
somewhat frightened.

Below is a copy of my config file and what follows after that are the relevant
log entries for a single fetch of "http://localhost/" via Safari.

===============================================================
===============
ServerRoot "/opt/apache2"

Listen 80
Listen 443

User  opt-www
Group opt-www

LoadModule perl_module  modules/mod_perl.so
LoadModule logio_module modules/mod_logio.so

<Directory />
    Options None
    AllowOverride None
</Directory>

<FilesMatch "^\.ht">
    Order allow,deny
    Deny from all
    Satisfy All
</FilesMatch>

SSLRandomSeed           startup file:/dev/random  512
SSLRandomSeed           connect file:/dev/random  512
SSLSessionCache         shmcb:/opt/apache2/ssl/ssl_scache(512000)
SSLSessionCacheTimeout  300
SSLMutex                file:/opt/apache2/ssl/ssl_mutex

LogLevel  info
LogFormat "%t %h %{SSL_PROTOCOL}x %{SSL_CIPHER}x \"%r\" %b" ssl_log_format
LogFormat "%h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\" %I %O"

NameVirtualHost *:80

<VirtualHost *:80>
    ServerAdmin  rutski89@gmail.com
    DocumentRoot /opt/var/www/localhost/htdocs
    ServerName   localhost
    ServerAlias  mini

    Loglevel     debug
    ErrorLog     /opt/var/www/localhost/logs/error_log
    TransferLog  /opt/var/www/localhost/logs/access_log

    ScriptAlias /cgi-bin/ "/opt/var/www/localhost/cgi-bin/"
</VirtualHost>

<VirtualHost *:443>
    SSLEngine             on
    SSLCertificateFile    /opt/var/www/localhost-ssl/ssl/server.crt
    SSLCertificateKeyFile /opt/var/www/localhost-ssl/ssl/server.key

    ServerAdmin  rutski89@gmail.com
    DocumentRoot /opt/var/www/localhost-ssl/htdocs
    ServerName   localhost
    ServerAlias  mini

    Loglevel     info
    ErrorLog     /opt/var/www/localhost-ssl/logs/error_log
    TransferLog  /opt/var/www/localhost-ssl/logs/access_log
    CustomLog    /opt/var/www/localhost-ssl/logs/ssl_log ssl_log_format
    
    <Directory /opt/var/www/localhost-ssl/htdocs>
        Options Indexes
    </Directory>

    BrowserMatch ".*MSIE.*" \
        nokeepalive ssl-unclean-shutdown \
        downgrade-1.0 force-response-1.0
</VirtualHost>
===============================================================
===============

There's no imminent danger since this is just a local dev box but I  
would like to get to the bottom of this 0 PRNG seed weirdness anyway;  
just blame human curiosity.

(Note: The offending log entry is on the 2nd line of error_log)

===============================================================
===============
==access_log==

::1 - - [14/Sep/2006:12:52:11 -0400] "GET / HTTP/1.1" 200 209 "-"  
"Mozilla/5.0 (Macintosh; U; PPC Mac OS X; en) AppleWebKit/418.8  
(KHTML, like Gecko) Safari/419.3" 569 1359
::1 - - [14/Sep/2006:12:52:11 -0400] "GET /favicon.ico HTTP/1.1" 200  
- "-" "Mozilla/5.0 (Macintosh; U; PPC Mac OS X; en) AppleWebKit/418.8  
(KHTML, like Gecko) Safari/419.3" 320 362

==error_log==

[Thu Sep 14 12:52:11 2006] [info] [client ::1] Connection to child 5  
established (server localhost:443)
[Thu Sep 14 12:52:11 2006] [info] Seeding PRNG with 0 bytes of entropy
[Thu Sep 14 12:52:11 2006] [info] Client requested a 'session-resume'  
but we have no such session.
[Thu Sep 14 12:52:11 2006] [info] Initial (No.1) HTTPS request  
received for child 5 (server localhost:443)
[Thu Sep 14 12:52:11 2006] [info] Subsequent (No.2) HTTPS request  
received for child 5 (server localhost:443)
[Thu Sep 14 12:52:16 2006] [info] [client ::1] (70007)The timeout  
specified has expired: SSL input filter read failed.
[Thu Sep 14 12:52:16 2006] [info] [client ::1] Connection closed to  
child 5 with standard shutdown (server localhost:443)

==ssl_log==

[14/Sep/2006:12:52:11 -0400] ::1 TLSv1 RC4-SHA "GET / HTTP/1.1" 209
[14/Sep/2006:12:52:11 -0400] ::1 TLSv1 RC4-SHA "GET /favicon.ico HTTP/1.1" -
===============================================================
===============
Comment 1 Joe Orton 2006-10-10 11:59:01 UTC
Can you get a truss output from the child process doing this?  It should only
happen AFAICT if a read() from /dev/random fails.
Comment 2 Stefan Fritsch 2011-08-27 19:05:34 UTC
This PR has been in state NEEDINFO for > 4 years. Closing.
Comment 3 Arkadiusz Miskiewicz 2013-04-09 20:35:12 UTC
I have the same message on Linux x86_64 platform, httpd 2.2.24:

strace for single child process:

# grep random log
22:22:12 open("/dev/urandom", O_RDONLY) = 14 <0.002871>
22:22:12 open("/dev/urandom", O_RDONLY) = 14 <0.000039>
22:22:12 open("/dev/urandom", O_RDONLY) = 14 <0.000028>
22:22:12 open("/dev/urandom", O_RDONLY) = 14 <0.000035>
22:22:12 open("/dev/urandom", O_RDONLY) = 14 <0.000030>
22:22:12 open("/dev/urandom", O_RDONLY) = 14 <0.000030>

so it opens /dev/urandom fine and later:

22:22:42 write(2, "[Tue Apr 09 22:22:42 2013] [debug] mod_headers.c(756): headers: ap_headers_output_filter()\n", 91) = 91 <0.000035>
22:22:42 setsockopt(13, SOL_TCP, TCP_CORK, [1], 4) = 0 <0.000018>
22:22:42 writev(13, [{"HTTP/1.1 200 OK\r\nDate: Tue, 09 Apr 2013 20:22:42 GMT\r\nServer: Apache\r\nLast-Modified: Wed, 27 Mar 2013 10:32:25 GMT\r\nETag: \"92d1bb54-13252-4d8e58dcfc4d5\"\r\nAccept-Ranges: bytes\r\nContent-Length: 78418\r\nK"..., 284}], 1) = 284 <0.000021>
22:22:42 sendfile(13, 14, [0], 78418)   = 23076 <0.000045>
22:22:42 setsockopt(13, SOL_TCP, TCP_CORK, [0], 4) = 0 <0.000015>
22:22:42 poll([{fd=13, events=POLLOUT}], 1, 300000) = 1 ([{fd=13, revents=POLLOUT}]) <0.010243>
22:22:42 sendfile(13, 14, [23076], 55342) = 30660 <0.000036>
22:22:42 poll([{fd=13, events=POLLOUT}], 1, 300000) = 1 ([{fd=13, revents=POLLOUT}]) <0.029560>
22:22:42 sendfile(13, 14, [53736], 24682) = 24682 <0.000026>
22:22:42 read(13, 0x8838ef8, 8000)      = -1 EAGAIN (Resource temporarily unavailable) <0.000017>
22:22:42 write(9, "some.host xx.xx.170.48 - - [09/Apr/2013:22:22:42 +0200] \"GET /pages_low/51_low.jpg HTTP/1.1\" 200 78702 \"http://some.host/?utm_source=glowna&utm_medium=middle&utm_campaign=abc"..., 297) = 297 <0.000027>
22:22:42 write(11, "some.host xx.xx.170.48 - - [09/Apr/2013:22:22:42 +0200] \"GET /pages_low/51_low.jpg HTTP/1.1\" 200 78702 \"http://some.host/?utm_source=glowna&utm_medium=middle&utm_campaign=abc"..., 280) = 280 <0.000020>
22:22:42 gettid()                       = 29778 <0.000023>
22:22:42 open("/proc/29778/attr/current", O_WRONLY) = 15 <0.000027>
22:22:42 write(15, "changehat 000000001f74f58e^", 27) = 27 <0.000021>
22:22:42 close(15)                      = 0 <0.000017>
22:22:42 gettid()                       = 29778 <0.000014>
22:22:42 open("/proc/29778/attr/current", O_WRONLY) = 15 <0.000020>
22:22:42 write(15, "changehat 000000001f74f58e^HANDLING_UNTRUSTED_INPUT", 51) = 51 <0.000052>
22:22:42 close(15)                      = 0 <0.000015>

(change hat due to apache-mod_apparmor usage)

22:22:42 times({tms_utime=156, tms_stime=41, tms_cutime=0, tms_cstime=0}) = 1444949832 <0.000015>
22:22:42 close(14)                      = 0 <0.000017>
22:22:42 poll([{fd=13, events=POLLIN}], 1, 2000) = 0 (Timeout) <2.007569>
22:22:44 times({tms_utime=156, tms_stime=41, tms_cutime=0, tms_cstime=0}) = 1444950033 <0.000016>
22:22:44 shutdown(13, SHUT_WR)          = 0 <0.000039>
22:22:44 poll([{fd=13, events=POLLIN}], 1, 2000) = 1 ([{fd=13, revents=POLLIN|POLLHUP}]) <0.023552>
22:22:44 read(13, "", 512)              = 0 <0.000029>
22:22:44 close(13)                      = 0 <0.000033>
22:22:44 read(7, 0x7fff40e8c897, 1)     = -1 EAGAIN (Resource temporarily unavailable) <0.000021>
22:22:44 semop(5931027, {{0, -1, SEM_UNDO}}, 1) = 0 <1.202430>
22:22:46 epoll_wait(10, {?} 0x881c4a8, 4, 10000) = 1 <0.058998>
22:22:46 accept(6, {sa_family=AF_INET, sin_port=htons(39947), sin_addr=inet_addr("89.69.21.174")}, [16]) = 13 <0.000023>
22:22:46 fcntl(13, F_GETFD)             = 0 <0.000018>
22:22:46 fcntl(13, F_SETFD, FD_CLOEXEC) = 0 <0.000018>
22:22:46 semop(5931027, {{0, 1, SEM_UNDO}}, 1) = 0 <0.000031>
22:22:46 write(2, "[Tue Apr 09 22:22:46 2013] [info] [client 89.69.21.174] Connection to child 54 established (server localhost:443)\n", 114) = 114 <0.000039>
22:22:46 write(2, "[Tue Apr 09 22:22:46 2013] [info] Seeding PRNG with 0 bytes of entropy\n", 71) = 71 <0.000032>
22:22:46 fcntl(13, F_GETFL)             = 0x2 (flags O_RDWR) <0.000023>
22:22:46 fcntl(13, F_SETFL, O_RDWR|O_NONBLOCK) = 0 <0.000016>
22:22:46 write(2, "[Tue Apr 09 22:22:46 2013] [debug] ssl_engine_kernel.c(1872): OpenSSL: Handshake: start\n", 88) = 88 <0.000023>
22:22:46 write(2, "[Tue Apr 09 22:22:46 2013] [debug] ssl_engine_kernel.c(1880): OpenSSL: Loop: before/accept initialization\n", 106) = 106 <0.000022>


# grep "Seeding PRNG with 0 bytes of entropy" /var/log/httpd/error_log  | wc -l
4395
# grep "Seeding PRNG" /var/log/httpd/error_log | grep -v "Seeding PRNG with 0 bytes of entropy"
#

so every message had 0 bytes in it.


Updated bug fields to match this case since original reporter is not responding.
Comment 4 Arkadiusz Miskiewicz 2013-04-10 07:43:04 UTC
In ssl_rand_seed apRandSeed->nelts is 0 so it does nothing.

Turns out that I was missing some configuration like

SSLRandomSeed startup file:/dev/urandom  256
SSLRandomSeed connect builtin

but on the other hand I would expect defaults to be sane and using entropy source without requiring manual configuration.
Comment 5 Stefan Fritsch 2013-04-10 20:26:19 UTC
I think this is not a problem on common platforms. According to the openssl RAND_seed man page, 'On systems that provide "/dev/urandom", the randomness device is used to seed the PRNG transparently'. So, SSLRandomSeed is really only needed on platforms that do not have /dev/urandom.

But this should be updated in the docs, and maybe we want to reduce the loglevel of the message to debug if SSLRandomSeed is not set.
Comment 6 vegard.nospam 2013-04-22 20:08:33 UTC
I can confirm this issue on a clean SLES 11SP2 64-bit, with apache2-2.2.12-1.28.1.

Without the lines:

SSLRandomSeed startup file:/dev/urandom  256
SSLRandomSeed connect builtin

in the apache config, the error log reports the following: 
[info] Init: Seeding PRNG with 0 bytes of entropy

System info: 
uname -a:
Linux test-host-name 3.0.13-0.27-default #1 SMP Wed Feb 15 13:33:49 UTC 2012 (d73692b) x86_64 x86_64 x86_64 GNU/Linux

cat /etc/SuSE-release:
SUSE Linux Enterprise Server 11 (x86_64)
VERSION = 11
PATCHLEVEL = 2

modssl-version from Apache error_log:
mod_ssl/2.2.12 compiled against Server: Apache/2.2.12, Library: OpenSSL/0.9.8h

/dev/urandom is present on this host:
crw-rw-rw- 1 root root 1, 9 Apr 10 11:44 /dev/urandom

(When the two lines first mentioned are present in the config, PRNG is behaving as one should expect, with entropy =! 0)

Regards,
Vegard Fremstad