[RPKI] routinator on NetBSD exiting unexpectedly

[Havard Eidnes]

Hi,

I have recently spun up a new routinator instance (using
version 0.13.0) on NetBSD 10.0_RC1.

For some reason this one decides to exit after running a relatively
short while, printing the single rather uninformative line

Logging to syslog failed: Format. Exiting.

For this one, I had to resort to system call tracing to find out
what's actually going on, and this appears to be the smoking gun:

 20317  22356 routinator GIO   fd 3 wrote 201 bytes
       "<28>Nov 30 12:03:51 routinator[11891]: rsync://rpki.afrinic.net/reposi\
        tory/: default_perms_for_dir: sys_acl_get_file(member_repository, ACL_\
        TYPE_DEFAULT): Operation not supported, falling back on umask"
 20317  22356 routinator RET   write 201/0xc9
 20317  22356 routinator CALL  __clock_gettime50(0,0x75a1e23f7280)
 20317  22356 routinator RET   __clock_gettime50 0
 20317  22356 routinator CALL  write(3,0x75a1e6b5c000,0xd2)
 20317  22356 routinator GIO   fd 3 wrote 210 bytes
       "<28>Nov 30 12:03:51 routinator[11891]: rsync://rpki.afrinic.net/reposi\
        tory/: default_perms_for_dir: sys_acl_get_file(member_repository/F3688\
        6B3, ACL_TYPE_DEFAULT): Operation not supported, falling back on umask"
 20317  22356 routinator RET   write 210/0xd2
 20317  22356 routinator CALL  __clock_gettime50(0,0x75a1e23f7280)
 20317  22356 routinator RET   __clock_gettime50 0
 20317  22356 routinator CALL  write(3,0x75a1e6baa000,0xf3)
 20317  22356 routinator RET   write -1 errno 55 No buffer space available
 20317  22356 routinator CALL  write(2,0xe397a28,0x1a)
 20317  22356 routinator GIO   fd 2 wrote 26 bytes
       "Logging to syslog failed: "
 20317  22356 routinator RET   write 26/0x1a
 20317  22356 routinator CALL  write(2,0x75a1e91a5018,6)
 20317  22356 routinator GIO   fd 2 wrote 6 bytes
       "Format"
 20317  22356 routinator RET   write 6
 20317  22356 routinator CALL  write(2,0xe397a42,0xb)
 20317  22356 routinator GIO   fd 2 wrote 11 bytes
       ". Exiting.\n"

So...  The actual error is that the rust-based syslog function
gets an ENOBUFS return from write(2), and that is apparently
unexpected.  This is related to handling of unix-domain sockets
in NetBSD, and I have a separate thread going there whether that
error return is appropriate or not.

However, the reason for this is apparently that routinator spews
so many of those preceding "default_perms_for_dir: ... Operation
not supported, falling back on umask" messages in quick
succession, in fact so many that syslogd() doesn't manage to
empty its end of /var/run/log quickly enough, and routinator gets
the "ENOBUFS" error return.

I've tried to grep the routinator source for either "falling back
on" or "default_perms_for_dir", but have come up empty so far.  Has
someone gone to great lengths to make the source un-grep'able?  I
thought rust programs compiled together all the sources with no
dynamic linking of libraries, so the entire source code should be
available in the build tree?

It seems to me that once one such "error" about unsupported
operation (related to file system ACLs?) is detected, it is most
probably counter-productive to try again for each and every
subsequent file, if the underlying file system is not configured to
support ACLs, and the number of files routinator apparently wants to
do this for (a huge number) contributes to the flooding of the
syslog unix domain socket, which again leads to routinator
unexpectedly exiting as per the above.

Hm, yes...  Come to think of it, I have turned up the logging level
to "debug", that obviously also doesn't help.  However, dialing that
back to "info" or "warn" does not improve matters, setting it to
"error" seems to have worked around this particular issue, but the
"heartbeat" from routinator is now absent from the logs.

Is there any way this can be improved on the routinator side?  I
purposely avoid logging to a file, since I get log file rotation
"for free" ("already configured") with syslog, and I've not checked
whether routinator has any mechanism to do that rotation itself when
logging directly to a file (doesn't look like it does from the
supplied example config).

Regards,

- Håvard