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

[jtl]

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)

[jtl]

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]

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]

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]

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]

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]

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]

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

[bz]

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.

[jhb]

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]

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

[jtl]

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]

• Address @jhb's comments.
• Add the comment requested by @bz on the reason UNIX domain sockets are restricted to 104 bytes.