Too many CLOSE_WAIT connections

[yonas]

Hi,

I'm seeing over 2,200 CLOSE_WAIT connections on my server (a VPS running under KVM). After killing all the relayd processes and starting it, I'm seeing the number of CLOSE_WAIT connections slowly climbing again.

I'm running OpenBSD 5.6-stable with the latest 5.6-stable patch branch fetched and compiled today.

Here's some info:

$ uname -a
OpenBSD 5.6 GENERIC.MP#1 amd64

$ relayctl show summary
Id      Type            Name                            Avlblty Status
1       relay           www                                     active
1       table           webhosts:80                             active (1 hosts)
1       host            10.8.0.2                        98.69%  up
2       relay           wwwssl                                  active
2       table           webhosts:80                             active (1 hosts)
2       host            10.8.0.2                        98.59%  up

$ ps aux|grep relay
_relayd  16788  0.0  0.3  1624  3156 ??  S      3:02AM    0:15.65 relayd: pfe (relayd)
_relayd  12960  0.0  0.9  6620  9356 ??  S      3:02AM    0:19.04 relayd: relay (relayd)
_relayd   9157  0.0  0.3  1556  3188 ??  I      3:02AM    0:00.02 relayd: ca (relayd)
_relayd  26941  0.0  0.3  1560  3184 ??  I      3:02AM    0:00.03 relayd: ca (relayd)
_relayd   1633  0.0  0.3  1548  3164 ??  I      3:02AM    0:00.02 relayd: ca (relayd)
_relayd  10017  0.0  0.3  1548  3088 ??  I      3:02AM    0:00.01 relayd: ca (relayd)
_relayd  23462  0.0  0.3  1552  3152 ??  I      3:02AM    0:00.02 relayd: ca (relayd)
_relayd  21549  0.0  0.3  1268  2820 ??  S      3:02AM    0:30.23 relayd: hce (relayd)
_relayd  30665  0.0  0.9  6572  9384 ??  S      3:02AM    0:18.71 relayd: relay (relayd)
_relayd   5491  0.0  0.9  6676  9500 ??  S      3:02AM    0:18.86 relayd: relay (relayd)
_relayd  20565  0.0  0.9  6648  9452 ??  S      3:02AM    0:19.12 relayd: relay (relayd)
_relayd  29017  0.0  0.9  6664  9492 ??  S      3:02AM    0:19.40 relayd: relay (relayd)

$ tail /var/log/daemon
Mar 23 23:23:41 obsd relayd[20565]: relay www, session 1329 (501 active), 0,xxx.xxx.xxx.xxx -> 10.8.0.2:80, last write (done), GET
Mar 23 23:23:41 obsd relayd[20565]: relay www, session 1330 (501 active), 0, xxx.xxx.xxx.xxx -> 10.8.0.2:80, last write (done), GET
Mar 23 23:24:39 obsd relayd[12960]: relay www, session 1351 (501 active), 0,xxx.xxx.xxx.xxx -> :0, hard timeout
Mar 23 23:26:38 obsd relayd[5491]: relay www, session 1335 (501 active), 0,xxx.xxx.xxx.xxx -> :0, hard timeout
Mar 23 23:30:39 obsd relayd[30665]: relay www, session 1320 (501 active), 0,xxx.xxx.xxx.xxx -> :0, hard timeout
Mar 23 23:31:39 obsd relayd[29017]: relay www, session 1340 (501 active), 0,xxx.xxx.xxx.xxx -> :0, hard timeout
Mar 23 23:31:40 obsd relayd[29017]: relay www, session 1341 (501 active), 0, xxx.xxx.xxx.xxx -> 10.8.0.2:80, last write (done), GET
Mar 23 23:31:40 obsd relayd[29017]: relay www, session 1342 (501 active), 0,xxx.xxx.xxx.xxx -> 10.8.0.2:80, last write (done), GET
Mar 23 23:34:39 obsd relayd[20565]: relay www, session 1331 (501 active), 0,xxx.xxx.xxx.xxx -> :0, hard timeout
Mar 23 23:34:40 obsd relayd[12960]: relay www, session 1352 (501 active), 0,xxx.xxx.xxx.xxx -> :0, hard timeout
Mar 23 23:34:40 obsd relayd[20565]: relay www, session 1332 (501 active), 0,xxx.xxx.xxx.xxx -> 10.8.0.2:80, last write (done), GET
Mar 23 23:34:40 obsd relayd[12960]: relay www, session 1353 (501 active), 0,xxx.xxx.xxx.xxx -> 10.8.0.2:80, last write (done), GET
Mar 23 23:37:38 obsd relayd[5491]: relay www, session 1336 (501 active), 0,xxx.xxx.xxx.xxx -> :0, hard timeout
Mar 23 23:37:39 obsd relayd[5491]: relay www, session 1337 (501 active), 0,xxx.xxx.xxx.xxx -> 10.8.0.2:80, last write (done), GET

$ cat /etc/relayd.conf
#
#  Relayd
#

interval 10
timeout 1000
prefork 5
log updates

ext_addr="xxx.xxx.xxx.xxx"
server1="10.8.0.2"

table <webhosts> { $server1 }

http protocol "www" {
        match header append "X-Forwarded-For" value "$REMOTE_ADDR"
        match header append "X-Forwarded-By" value "$SERVER_ADDR:$SERVER_PORT"
}

relay "www" {
        listen on $ext_addr port http
        protocol "www"

        #forward to <webhosts> check http "/" code 200
        forward to <webhosts> check tcp
}

http protocol "httpssl" {
        match header append "X-Forwarded-For" value "$REMOTE_ADDR"
        match header append "X-Forwarded-By" value "$SERVER_ADDR:$SERVER_PORT"
        match header set "Connection" value "close"

        # Various TCP performance options
        tcp { nodelay, sack, socket buffer 65536, backlog 128 }

        ssl { no sslv2, sslv3, tlsv1, ciphers HIGH }
        ssl session cache disable
}

relay "wwwssl" {
        # Provide SSL termination
        listen on $ext_addr port 443 ssl
        protocol "httpssl"

        # Forward to hosts in the webhosts table
        forward to <webhosts> port http check tcp
}

$ top
load averages:  0.80,  0.90,  0.58
50 processes: 49 idle, 1 on processor
CPU0 states:  0.0% user,  0.0% nice,  0.2% system,  0.0% interrupt, 99.8% idle
CPU1 states:  0.2% user,  0.0% nice,  0.0% system,  0.0% interrupt, 99.8% idle
Memory: Real: 70M/331M act/tot Free: 650M Cache: 196M Swap: 0K/1264M 

[erickonradmiller]

I have seen similar behavior while testing, where the number of active sessions (HTTPS) exceeds 500 (once it hits 501) causes the service to stop responding to requests. Waiting a little while will hard timeout some of the sessions, and the service becomes responsive again, but additional page loads will bring the active session count back to 501 and it becomes non-responsive again.

The session expiration appears to be broken from what I can tell - where sessions are expired extremely slow (1 per minute or more?) regardless of what the "session timeout" option is set to (I have it set to 15 seconds for testing).

My test configuration is pretty simple, with a single site running on httpd on the same server as relayd. Browsing a single test page (HTTPS page) with the word "Testing" copied a bunch of times appears to work fine. Holding down the F5 key to repeat load the page will cause the active session count to rise, up to 501, and then relayd stops responding to requests.

Note that relayctl works while this is happening, This is an example after it becomes non-responsive to additional HTTPS requests:

# relayctl show relay
Id      Type            Name                            Avlblty Status
1       relay           httpsproxy                              active
                        total: 4344 sessions
                        last: 0/60s 4344/h 4344/d sessions
                        average: 0/60s 0/h 0/d sessions

I'd love to get this resolved since I would love to use relayd for all of our Layer 7 balancing, but we're stuck. Reyk - if you need any help testing, let me know. I'll be happy to help.

Eric

[erickonradmiller]

I forgot to mention that my testing was done with OpenBSD 5.7 (fresh install from ISO).

Also, it looks like relayd hung last night, causing 100% CPU utilization on all 4 processors.

Eric