Page MenuHomeFreeBSD

Print more detail as part of the sonewconn() overflow message
ClosedPublic

Authored by jtl on Apr 3 2020, 8:14 PM.

Details

Summary

When a socket's listen queue overflows, sonewconn() emits a debug-level log message. These messages are sometimes useful to systems administrators in highlighting a process which is not keeping up with its listen queue.

This commit attempts to enhance the usefulness of this message by printing more details about the socket's address. If all else fails, it will at least print the domain name of the socket.

Test Plan

Tested with this Python script (with different values of the 'test' variable):

import socket
import os

test = 'unix'

if test == 'IPv4':
    HOST = '127.0.0.1'
    AF = socket.AF_INET
if test == 'IPv6':
    HOST = '::1'
    AF = socket.AF_INET6
if test in ('IPv4', 'IPv6'):
    PORT = 65432
    ADDR = (HOST, PORT)

if test == 'unix':
    ADDR = "/tmp/testsock"
    AF = socket.AF_UNIX

TYPE = socket.SOCK_STREAM
ls = socket.socket(AF, TYPE)
ls.bind(ADDR)
ls.listen(2)

sockets = []
for i in range(0, 5):
    try:
        s = socket.socket(AF, TYPE)
        s.connect(ADDR)
    except:
        continue
    sockets.append(s)

for s in sockets:
    s.close()

ls.close()

if test == 'unix':
    os.remove(ADDR)

Diff Detail

Repository
rS FreeBSD src repository
Lint
Automatic diff as part of commit; lint not applicable.
Unit
Automatic diff as part of commit; unit tests not applicable.

Event Timeline

jtl created this revision.Apr 3 2020, 8:14 PM
jtl added a comment.Apr 3 2020, 8:16 PM

FWIW, these are examples of the messages this produces:

Apr  3 19:58:34 c006 kernel: sonewconn: pcb 0xfffff805a566a200 (127.0.0.1:65432 (proto 6)): Listen queue overflow: 4 already in queue awaiting acceptance (1 occurrences)
Apr  3 19:59:44 c006 kernel: sonewconn: pcb 0xfffff80611de4000 ([::1]:65432 (proto 6)): Listen queue overflow: 4 already in queue awaiting acceptance (2 occurrences)
Apr  3 20:16:12 c006 kernel: sonewconn: pcb 0xfffff80170cde100 (local:/tmp/testsock): Listen queue overflow: 4 already in queue awaiting acceptance (1 occurrences)
chs added a subscriber: chs.Apr 3 2020, 8:41 PM
chs added inline comments.
sys/kern/uipc_socket.c
595 ↗(On Diff #70158)

This doesn't leave space for the colon. You can also use

static char localprefix[] = "local:";
char descr[SUNPATHLEN + sizeof(localprefix)];

(and then use localprefix later instead of repeating the string literal) rather than strlen(), to make sure that the size is calculated at compile time and to make sure that the size allocated matches what is actually used.

jhb added a comment.Apr 3 2020, 8:52 PM

I think this looks fine. It would be nice to use a string builder instead of memcpy/strcat, etc. like sbuf(9) to make it more robust to future changes. ip6_sprintf is the only bit that I think isn't easily adaptable to sbuf(9) as-is, though you could use a temporary stack buffer for that as well, something like:

struct sbuf sb;
char ip6buf[INET6_ADDRSTRLEN];
....

sbuf_new(&sb, descr, sizeof(descr), SBUF_FIXEDLEN);
...

    sbuf_printf(&sb, "[%s]", ip6_sprintf(ip6buf, ...);

I guess inet_ntoa_r would need similar treatment, though you could just reuse ip6buf for that (maybe call it addrbuf or some such instead). Would also remove the magic 6 when null-terminating sun_path, etc.

jtl added a comment.Apr 3 2020, 11:39 PM
In D24272#534063, @jhb wrote:

I think this looks fine. It would be nice to use a string builder instead of memcpy/strcat, etc. like sbuf(9) to make it more robust to future changes.

Good idea! I'll do that.

sys/kern/uipc_socket.c
595 ↗(On Diff #70158)

Good catch! I'll fix this.

bz added a comment.Apr 5 2020, 3:02 PM

I like the idea; I'll wait for the sbuf conversion.

sys/sys/un.h
54 ↗(On Diff #70158)

I'd almost say this could be an independent change. I am slightly confused as to why this is 104 (and has been for 25-ish years) and I assume more people will wonder over time.

wollman added a subscriber: wollman.Apr 5 2020, 8:31 PM

I have been begging for this for years and strongly support.

sys/sys/un.h
54 ↗(On Diff #70158)

Because back in the mists of ancient time, sockaddrs had to fit in an mbuf and mbufs were only 128 bytes. There's no reason it has to be that way now except binary compatibility

jtl updated this revision to Diff 70266.Apr 6 2020, 6:16 PM

Switch to using sbuf(9) for string creation. Also, use a constant string for "local:".

bz accepted this revision.Apr 7 2020, 8:10 AM
bz added inline comments.
sys/sys/un.h
54 ↗(On Diff #70158)

Can we document this with a comment? That would be awesome as otherwise the knowledge one day will be lost.

This revision is now accepted and ready to land.Apr 7 2020, 8:10 AM
jhb accepted this revision.Apr 7 2020, 11:02 PM
jhb added inline comments.
sys/kern/uipc_socket.c
662 ↗(On Diff #70266)

This is even nicer than the sbuf_printf(..., "%.*s", ...) approach I had thought of in my head for this case.

669 ↗(On Diff #70266)

style nit: blank line before comment.

673 ↗(On Diff #70266)

I would perhaps do 'sbuf_finish(&descrsb) != 0 ||' as we tend to prefer explicit '== 0' and '!= 0' style-wise.

kbowling accepted this revision.Apr 13 2020, 12:21 AM
kbowling added a subscriber: kbowling.

This will be super useful for users, these overflow messages currently require a lot of system expertise to diagnose.

jtl marked 3 inline comments as done.Apr 13 2020, 2:24 PM

I'm going to do a tinderbox build of this + D24316 (mostly, to make sure I didn't mess up the various INET/INET6 combinations) and then commit them.

sys/kern/uipc_socket.c
669 ↗(On Diff #70266)

ACK, I will change this when I commit it.

673 ↗(On Diff #70266)

ACK, I will change this when I commit it.

jtl updated this revision to Diff 70504.Apr 13 2020, 5:03 PM
jtl marked 2 inline comments as done.
  • Address @jhb's comments.
  • Add the comment requested by @bz on the reason UNIX domain sockets are restricted to 104 bytes.
This revision now requires review to proceed.Apr 13 2020, 5:03 PM
This revision was not accepted when it landed; it landed in state Needs Review.Apr 14 2020, 3:27 PM
This revision was automatically updated to reflect the committed changes.