Actions
Bug #1461
closedSSL bad write retry with several concurrent connections
ASK QUESTIONS IN Forums:
Description
With both 1.4 and 1.5 (I am now running on the latest trunk), i've had issues with SSL connections occasionally failing and leaving the message 'bad write retry' - which indicates that SSL_write gave a WANT_WRITE and was not retried with the same parameters. This seems to happen especially during long uploads, but i've seen it happen during downloads and such as well. It may be related to having multiple SSL connections transferring data simultaneously, as seen below.
Here is a bit of information from some debug I added. Each line starts with 'debug fd' - pay attention to the FDs to separate each connection. 'Prior write result' and 'Prior read result' show the error value (from SSL_get_error) given by the previous call. Note how there are 4 connections here that all fail at the same time.
network_openssl.c.180: (trace) debug 15: SSL_write MEM_CHUNK ptr=81b1480 sz=211 re=211 network_openssl.c.289: (trace) debug 15: SSL_write FILE_CHUNK ptr=810b508 sz=40679 re=0 network_openssl.c.296: (trace) debug 15: Prior write result WANT_WRITE network_openssl.c.289: (trace) debug 13: SSL_write FILE_CHUNK ptr=810b508 sz=40679 re=0 network_openssl.c.296: (trace) debug 13: Prior write result WANT_WRITE network_openssl.c.289: (trace) debug 15: SSL_write FILE_CHUNK ptr=810b508 sz=40679 re=0 network_openssl.c.334: (trace) debug 15: Prior write result 1 network_openssl.c.338: (error) SSL_write(): ssl-error: 1 (ret = -1), error:1409F07F:SSL routines:SSL3_WRITE_PENDING:bad write retry network_openssl.c.338: (error) SSL_write(): ssl-error: 1 (ret = -1), error:1409F07F:SSL routines:SSL3_WRITE_PENDING:bad write retry connections.c.1370: (trace) (network-subsys sent us a fatal-error) network_openssl.c.289: (trace) debug 10: SSL_write FILE_CHUNK ptr=810b508 sz=42321 re=0 network_openssl.c.334: (trace) debug 10: Prior write result 1 network_openssl.c.338: (error) SSL_write(): ssl-error: 1 (ret = -1), error:1409F07F:SSL routines:SSL3_WRITE_PENDING:bad write retry network_openssl.c.338: (error) SSL_write(): ssl-error: 1 (ret = -1), error:1409F07F:SSL routines:SSL3_WRITE_PENDING:bad write retry connections.c.1370: (trace) (network-subsys sent us a fatal-error) network_openssl.c.289: (trace) debug 12: SSL_write FILE_CHUNK ptr=810b508 sz=51615 re=0 network_openssl.c.334: (trace) debug 12: Prior write result 1 network_openssl.c.338: (error) SSL_write(): ssl-error: 1 (ret = -1), error:1409F07F:SSL routines:SSL3_WRITE_PENDING:bad write retry network_openssl.c.338: (error) SSL_write(): ssl-error: 1 (ret = -1), error:1409F07F:SSL routines:SSL3_WRITE_PENDING:bad write retry connections.c.1370: (trace) (network-subsys sent us a fatal-error) network_openssl.c.48: (trace) debug 11: SSL_read ptr=81845f0 sz=8255 re=609 network_openssl.c.48: (trace) debug 11: SSL_read ptr=81b15d0 sz=8255 re=-1 network_openssl.c.94: (trace) debug 11: Prior read result 1 network_openssl.c.97: (error) ssl-errors: error:1409F07F:SSL routines:SSL3_WRITE_PENDING:bad write retry network_openssl.c.97: (error) ssl-errors: error:1409F07F:SSL routines:SSL3_WRITE_PENDING:bad write retry connections.c.603: (error) ++ oops, something went wrong while reading connections.c.1033: (trace) (error)
Updated by stbuehler almost 17 years ago
- Status changed from New to Fixed
- Resolution set to duplicate
Duplicate of #285
Updated by francisco over 10 years ago
- Status changed from Fixed to Reopened
Hi there! Does someone have any idea why lighttpd is freezing?
FreeBSD - 9.2-PRERELEASE FreeBSD - amd64
lighttpd-1.4.35
php5-5.4.26
Apr 7 11:22:40 new kernel: pid 13344 (lighttpd), uid 80: exited on signal 11 Apr 7 14:44:37 new kernel: pid 34798 (lighttpd), uid 80: exited on signal 11 Apr 7 15:58:37 new kernel: pid 36132 (lighttpd), uid 80: exited on signal 11 Apr 7 16:31:49 new kernel: pid 36886 (lighttpd), uid 80: exited on signal 11 Apr 7 17:18:15 new kernel: pid 37546 (lighttpd), uid 80: exited on signal 11
fastcgi.server = ( ".php" =>
( "localhost" =>
(
"socket" => "/var/run/lighttpd/php-fastcgi.socket",
"bin-path" => "/usr/local/bin/php-cgi",
"max-procs" => 1,
"idle-timeout" => 20,
"bin-environment" => (
"PHP_FCGI_CHILDREN" => "10",
"PHP_FCGI_MAX_REQUESTS" => "5000"
),
"bin-copy-environment" => (""),
"broken-scriptfilename" => "enable"
)
)
)
# top last pid: 39741; load averages: 1.17, 1.17, 1.24 up 12+16:46:12 18:04:08 101 processes: 2 running, 97 sleeping, 1 stopped, 1 zombie CPU: 5.1% user, 0.0% nice, 1.3% system, 0.0% interrupt, 93.5% idle Mem: 955M Active, 18G Inact, 3054M Wired, 543M Cache, 2601M Buf, 371M Free Swap: 4096M Total, 888K Used, 4095M Free PID USERNAME THR PRI NICE SIZE RES STATE C TIME WCPU COMMAND 30636 mysql 37 21 0 1359M 849M uwait 5 281:51 67.14% mysqld 37795 www 1 29 0 272M 52936K accept 6 4:56 6.88% php-cgi 37921 www 1 27 0 268M 48616K accept 2 4:24 6.88% php-cgi 37751 www 1 25 0 276M 55996K CPU22 22 4:48 6.69% php-cgi 37884 www 1 27 0 272M 49416K accept 2 4:30 6.59% php-cgi 37832 www 1 24 0 272M 52844K accept 4 5:28 6.40% php-cgi 38006 www 1 22 0 264M 44480K lockf 6 3:37 3.86% php-cgi 37956 www 1 22 0 264M 44772K select 14 4:30 2.39% php-cgi 37920 www 1 20 0 268M 48648K select 15 4:44 0.98% php-cgi 38485 www 1 21 0 62216K 19956K kqread 14 0:44 0.88% lighttpd 37922 www 1 41 0 260M 40624K accept 0 4:51 0.00% php-cgi 38005 www 1 40 0 280M 59176K accept 7 4:34 0.00% php-cgi # ps -aux USER PID %CPU %MEM VSZ RSS TT STAT STARTED TIME COMMAND root 11 2372.7 0.0 0 384 ?? RL 26Mar14 436982:49.33 [idle] mysql 30636 21.4 3.4 1388016 855480 ?? S 11:18AM 278:56.62 /usr/local/libexec/mysqld --defaults-extra-file=/usr/db/mysql/m www 37832 8.1 0.2 278640 51124 ?? S 4:49PM 5:03.84 /usr/local/bin/php-cgi www 37751 6.8 0.2 270576 44912 ?? S 4:44PM 4:30.46 /usr/local/bin/php-cgi www 38005 6.7 0.2 282864 56984 ?? S 4:56PM 4:16.19 /usr/local/bin/php-cgi www 37795 6.4 0.2 278768 50660 ?? S 4:47PM 4:38.62 /usr/local/bin/php-cgi www 38006 6.3 0.2 270448 43364 ?? S 4:57PM 3:19.98 /usr/local/bin/php-cgi www 37884 5.4 0.2 270876 44968 ?? R 4:51PM 4:10.03 /usr/local/bin/php-cgi www 37922 5.3 0.2 266480 40852 ?? S 4:53PM 4:29.73 /usr/local/bin/php-cgi root 1229 1.1 0.0 43640 7360 ?? S 26Mar14 300:06.65 /usr/local/sbin/snmpd -p /var/run/net_snmpd.pid www 38485 0.9 0.1 62776 20484 ?? S 5:19PM 0:38.23 /usr/local/sbin/lighttpd -f /usr/local/etc/lighttpd/lighttpd.co www 37956 0.6 0.2 270576 44768 ?? S 4:54PM 4:07.55 /usr/local/bin/php-cgi root 0 0.1 0.0 0 224 ?? DLs 26Mar14 57:52.96 [kernel] root 1 0.0 0.0 6276 432 ?? ILs 26Mar14 0:00.11 /sbin/init -- root 2 0.0 0.0 0 16 ?? DL 26Mar14 0:00.00 [ctl_thrd] root 3 0.0 0.0 0 16 ?? DL 26Mar14 0:00.00 [sctp_iterator] root 4 0.0 0.0 0 16 ?? DL 26Mar14 0:00.00 [xpt_thrd] root 5 0.0 0.0 0 16 ?? DL 26Mar14 0:13.59 [pagedaemon] root 6 0.0 0.0 0 16 ?? DL 26Mar14 0:00.00 [vmdaemon] root 7 0.0 0.0 0 16 ?? DL 26Mar14 0:00.02 [pagezero] root 8 0.0 0.0 0 16 ?? DL 26Mar14 0:06.47 [bufdaemon] root 9 0.0 0.0 0 16 ?? DL 26Mar14 0:07.96 [vnlru] root 10 0.0 0.0 0 16 ?? DL 26Mar14 0:00.00 [audit] root 12 0.0 0.0 0 560 ?? WL 26Mar14 53:57.26 [intr] root 13 0.0 0.0 0 48 ?? DL 26Mar14 3:05.60 [geom] root 14 0.0 0.0 0 16 ?? DL 26Mar14 1:01.60 [yarrow] root 15 0.0 0.0 0 128 ?? DL 26Mar14 1:56.27 [usb] root 16 0.0 0.0 0 16 ?? DL 26Mar14 96:23.22 [syncer] root 17 0.0 0.0 0 16 ?? DL 26Mar14 0:49.30 [softdepflush] root 310 0.0 0.0 22380 5092 ?? Ss Sun12PM 1:09.70 /usr/local/sbin/openvpn --cd /usr/local/etc/openvpn --daemon op root 867 0.0 0.0 14264 1580 ?? Is 26Mar14 0:00.00 /usr/sbin/moused -p /dev/ums0 -t auto -I /var/run/moused.ums0.p root 888 0.0 0.0 14264 1580 ?? Is 26Mar14 0:00.00 /usr/sbin/moused -p /dev/ums1 -t auto -I /var/run/moused.ums1.p root 905 0.0 0.0 10376 3508 ?? Is 26Mar14 0:00.50 /sbin/devd root 1137 0.0 0.0 12076 1668 ?? Ss 26Mar14 0:16.41 /usr/sbin/syslogd -s root 1173 0.0 0.0 14164 1872 ?? Ss 26Mar14 0:01.24 /usr/sbin/rpcbind root 1187 0.0 0.0 12044 8024 ?? Is 26Mar14 0:00.17 /usr/sbin/amd -p -a /.amd_mnt -l syslog /host /etc/amd.map /net root 1370 0.0 0.0 14600 2160 ?? Ss 26Mar14 0:48.23 /usr/local/libexec/postfix/master -w root 1529 0.0 0.0 46876 4184 ?? Is 26Mar14 0:00.04 /usr/sbin/sshd root 1533 0.0 0.0 14176 1932 ?? Ss 26Mar14 0:16.43 /usr/sbin/cron -s mysql 30152 0.0 0.0 14536 2300 ?? Is 11:18AM 0:00.05 /bin/sh /usr/local/bin/mysqld_safe --defaults-extra-file=/usr/d www 36134 0.0 0.1 249968 19468 ?? Is 3:26PM 0:00.22 /usr/local/bin/php-cgi www 37920 0.0 0.2 274544 48788 ?? S 4:53PM 4:23.58 /usr/local/bin/php-cgi www 37921 0.0 0.2 274672 48616 ?? I 4:53PM 4:06.79 /usr/local/bin/php-cgi www 38486 0.0 0.0 0 0 ?? Z 5:19PM 0:00.00 <defunct> www 38487 0.0 0.0 10072 1684 ?? S 5:19PM 0:01.00 /usr/local/sbin/cronolog /var/log/light/log1.log www 38488 0.0 0.0 3956 1596 ?? I 5:19PM 0:00.00 /usr/local/sbin/cronolog /var/log/light/log2.log www 38489 0.0 0.0 10072 1684 ?? I 5:19PM 0:00.01 /usr/local/sbin/cronolog /var/log/light/log3.log www 38490 0.0 0.0 3956 1596 ?? I 5:19PM 0:00.00 /usr/local/sbin/cronolog /var/log/light/log4.log www 38491 0.0 0.0 3956 1596 ?? I 5:19PM 0:00.00 /usr/local/sbin/cronolog /var/log/light/log5.log www 38492 0.0 0.0 3956 1596 ?? I 5:19PM 0:00.00 /usr/local/sbin/cronolog /var/log/light/log6.log www 38493 0.0 0.0 3956 1596 ?? I 5:19PM 0:00.00 /usr/local/sbin/cronolog /var/log/light/log7.log www 38494 0.0 0.0 10072 1684 ?? I 5:19PM 0:00.00 /usr/local/sbin/cronolog /var/log/light/log8.log www 38495 0.0 0.0 10072 1684 ?? I 5:19PM 0:00.00 /usr/local/sbin/cronolog /var/log/light/log9.log www 38496 0.0 0.0 10072 1684 ?? S 5:19PM 0:00.00 /usr/local/sbin/cronolog /var/log/light/logA.log www 38497 0.0 0.0 10072 1684 ?? I 5:19PM 0:00.00 /usr/local/sbin/cronolog /var/log/light/logB.log www 38498 0.0 0.0 10072 1684 ?? I 5:19PM 0:00.00 /usr/local/sbin/cronolog /var/log/light/logC.log www 38499 0.0 0.0 10072 1684 ?? I 5:19PM 0:00.00 /usr/local/sbin/cronolog /var/log/light/logD.log www 38500 0.0 0.0 10072 1684 ?? I 5:19PM 0:00.00 /usr/local/sbin/cronolog /var/log/light/logE.log www 38501 0.0 0.0 10072 1684 ?? I 5:19PM 0:00.01 /usr/local/sbin/cronolog /var/log/light/logF.log www 38502 0.0 0.0 10072 1684 ?? S 5:19PM 0:00.01 /usr/local/sbin/cronolog /var/log/light/logG.log root 1569 0.0 0.0 12084 1748 v0 Is+ 26Mar14 0:00.00 /usr/libexec/getty Pc ttyv0 root 1570 0.0 0.0 12084 1744 v1 Is+ 26Mar14 0:00.00 /usr/libexec/getty Pc ttyv1 root 1571 0.0 0.0 12084 1744 v2 Is+ 26Mar14 0:00.00 /usr/libexec/getty Pc ttyv2 root 1572 0.0 0.0 12084 1744 v3 Is+ 26Mar14 0:00.00 /usr/libexec/getty Pc ttyv3 root 1573 0.0 0.0 12084 1744 v4 Is+ 26Mar14 0:00.00 /usr/libexec/getty Pc ttyv4 root 1574 0.0 0.0 12084 1744 v5 Is+ 26Mar14 0:00.00 /usr/libexec/getty Pc ttyv5 root 1575 0.0 0.0 12084 1744 v6 Is+ 26Mar14 0:00.00 /usr/libexec/getty Pc ttyv6 root 1576 0.0 0.0 12084 1744 v7 Is+ 26Mar14 0:00.00 /usr/libexec/getty Pc ttyv7
2014-04-07 16:34:13: (log.c.164) server started 2014-04-07 16:34:15: (network_openssl.c.139) SSL: 1 -1 error:1409F07F:SSL routines:SSL3_WRITE_PENDING:bad write retry 2014-04-07 16:34:15: (connections.c.619) connection closed: write failed on fd 42 2014-04-07 16:34:18: (network_openssl.c.139) SSL: 1 -1 error:1409F07F:SSL routines:SSL3_WRITE_PENDING:bad write retry 2014-04-07 16:34:18: (connections.c.619) connection closed: write failed on fd 91 2014-04-07 16:34:27: (network_openssl.c.139) SSL: 1 -1 error:1409F07F:SSL routines:SSL3_WRITE_PENDING:bad write retry 2014-04-07 16:34:27: (connections.c.619) connection closed: write failed on fd 67 2014-04-07 16:35:15: (network_openssl.c.139) SSL: 1 -1 error:1409F07F:SSL routines:SSL3_WRITE_PENDING:bad write retry 2014-04-07 16:35:15: (connections.c.619) connection closed: write failed on fd 24 2014-04-07 16:37:00: (connections.c.137) (warning) close: 135 Connection reset by peer 2014-04-07 16:40:20: (network_openssl.c.256) SSL: 1 -1 error:1409F07F:SSL routines:SSL3_WRITE_PENDING:bad write retry 2014-04-07 16:40:20: (connections.c.619) connection closed: write failed on fd 96 2014-04-07 16:40:24: (network_openssl.c.139) SSL: 1 -1 error:1409F07F:SSL routines:SSL3_WRITE_PENDING:bad write retry 2014-04-07 16:40:24: (connections.c.619) connection closed: write failed on fd 79 2014-04-07 16:40:24: (connections.c.1692) SSL (error): 5 -1 35 Resource temporarily unavailable 2014-04-07 16:40:28: (network_openssl.c.139) SSL: 1 -1 error:1409F07F:SSL routines:SSL3_WRITE_PENDING:bad write retry 2014-04-07 16:40:28: (connections.c.619) connection closed: write failed on fd 35 2014-04-07 16:40:28: (connections.c.1692) SSL (error): 5 -1 35 Resource temporarily unavailable 2014-04-07 16:43:09: (network_openssl.c.139) SSL: 1 -1 error:1409F07F:SSL routines:SSL3_WRITE_PENDING:bad write retry 2014-04-07 16:43:09: (connections.c.619) connection closed: write failed on fd 77 2014-04-07 16:43:10: (network_openssl.c.139) SSL: 1 -1 error:1409F07F:SSL routines:SSL3_WRITE_PENDING:bad write retry 2014-04-07 16:43:10: (connections.c.619) connection closed: write failed on fd 90 2014-04-07 16:43:10: (connections.c.1692) SSL (error): 5 -1 35 Resource temporarily unavailable 2014-04-07 16:44:08: (network_openssl.c.139) SSL: 1 -1 error:1409F07F:SSL routines:SSL3_WRITE_PENDING:bad write retry 2014-04-07 16:44:08: (connections.c.619) connection closed: write failed on fd 92 2014-04-07 16:46:44: (network_openssl.c.139) SSL: 1 -1 error:1409F07F:SSL routines:SSL3_WRITE_PENDING:bad write retry 2014-04-07 16:46:44: (connections.c.619) connection closed: write failed on fd 40 2014-04-07 16:51:15: (connections.c.137) (warning) close: 67 Connection reset by peer 2014-04-07 16:51:29: (network_openssl.c.139) SSL: 1 -1 error:1409F07F:SSL routines:SSL3_WRITE_PENDING:bad write retry 2014-04-07 16:51:29: (connections.c.619) connection closed: write failed on fd 28 2014-04-07 16:51:33: (network_openssl.c.139) SSL: 1 -1 error:1409F07F:SSL routines:SSL3_WRITE_PENDING:bad write retry 2014-04-07 16:51:33: (connections.c.619) connection closed: write failed on fd 58 2014-04-07 16:55:24: (network_openssl.c.139) SSL: 1 -1 error:1409F07F:SSL routines:SSL3_WRITE_PENDING:bad write retry 2014-04-07 16:55:24: (connections.c.619) connection closed: write failed on fd 144 2014-04-07 16:56:34: (network_openssl.c.256) SSL: 1 -1 error:1409F07F:SSL routines:SSL3_WRITE_PENDING:bad write retry 2014-04-07 16:56:34: (connections.c.619) connection closed: write failed on fd 112 2014-04-07 17:01:35: (connections.c.137) (warning) close: 103 Connection reset by peer 2014-04-07 17:07:16: (network_openssl.c.139) SSL: 1 -1 error:1409F07F:SSL routines:SSL3_WRITE_PENDING:bad write retry 2014-04-07 17:07:16: (connections.c.619) connection closed: write failed on fd 38 2014-04-07 17:10:31: (connections.c.277) SSL: -1 5 54 Connection reset by peer 2014-04-07 17:18:05: (network_openssl.c.139) SSL: 1 -1 error:1409F07F:SSL routines:SSL3_WRITE_PENDING:bad write retry 2014-04-07 17:18:05: (connections.c.619) connection closed: write failed on fd 99 2014-04-07 17:19:00: (log.c.164) server started 2014-04-07 17:20:06: (network_openssl.c.256) SSL: 1 -1 error:1409F07F:SSL routines:SSL3_WRITE_PENDING:bad write retry 2014-04-07 17:20:06: (connections.c.619) connection closed: write failed on fd 94 2014-04-07 17:23:03: (network_openssl.c.256) SSL: 1 -1 error:1409F07F:SSL routines:SSL3_WRITE_PENDING:bad write retry 2014-04-07 17:23:03: (connections.c.619) connection closed: write failed on fd 52 2014-04-07 17:28:04: (network_openssl.c.139) SSL: 1 -1 error:1409F07F:SSL routines:SSL3_WRITE_PENDING:bad write retry 2014-04-07 17:28:04: (connections.c.619) connection closed: write failed on fd 104 2014-04-07 17:28:04: (connections.c.1692) SSL (error): 5 -1 35 Resource temporarily unavailable 2014-04-07 17:31:20: (network_openssl.c.256) SSL: 1 -1 error:1409F07F:SSL routines:SSL3_WRITE_PENDING:bad write retry 2014-04-07 17:31:20: (connections.c.619) connection closed: write failed on fd 44 2014-04-07 17:32:33: (network_openssl.c.139) SSL: 1 -1 error:1409F07F:SSL routines:SSL3_WRITE_PENDING:bad write retry 2014-04-07 17:32:33: (connections.c.619) connection closed: write failed on fd 112 2014-04-07 17:34:38: (connections.c.277) SSL: -1 5 54 Connection reset by peer 2014-04-07 17:41:41: (connections.c.137) (warning) close: 43 Connection reset by peer 2014-04-07 17:42:03: (network_openssl.c.139) SSL: 1 -1 error:1409F07F:SSL routines:SSL3_WRITE_PENDING:bad write retry 2014-04-07 17:42:03: (connections.c.619) connection closed: write failed on fd 123 2014-04-07 17:49:13: (connections.c.137) (warning) close: 28 Connection reset by peer 2014-04-07 17:49:58: (connections.c.137) (warning) close: 28 Connection reset by peer
Updated by gstrauss over 8 years ago
- Description updated (diff)
- Missing in 1.5.x set to Yes
Updated by gstrauss over 8 years ago
- Status changed from Reopened to Fixed
- Target version changed from 1.5.0 to 1.4.40
- Missing in 1.5.x deleted (
Yes)
lighttpd 1.4.40 provides additional flags to openssl to allow for buffers to move as long as the data is resubmitted without modification.
Please reopen this ticket if problem is still occurring in lighttpd 1.4.40.
Actions
Also available in: Atom