[systemd-devel] systemd-journald doesn't follow max datagram length when forwarding messages to syslog

[Umut Tezduyar Lindskog]

Hi,

journald fails to forward messages to syslog when it is using
Server->syslog_fd even before the limit of
/proc/sys/net/unix/max_dgram_qlen is reached.

For this experiment,

1) I have made sure /proc/sys/net/unix/max_dgram_qlen is set to 9999
before syslog.socket is created.
2) Replaced rsyslog.service's ExecStart with /bin/sleep
3) Booted system and observed following messages:

systemd-journal[434]: Forwarding to syslog missed 2 messages. (succeed
274 messages) [*]
systemd-journal[434]: Forwarding to syslog missed 183 messages.
(succeed 274 messages)
systemd-journal[434]: Forwarding to syslog missed 41 messages.
(succeed 274 messages)

This got me interested since we are loosing messages and after further
debugging I have come up with attached patch [**]. After booting up
the system and filling up the journal with "systemd-cat echo hello",
following correct behavior is observed.

systemd-journal[449]: Forwarding to syslog missed 1 messages. (succeed
10000 messages)

It is same hardware and clearly I have enough memory to store 1000
messages. I can't explain why it would make a difference to use
Server->syslog_fd vs a new socket fd but something is not right and
hopefully someone can explain. Further, we can fix journal so we won't
miss messages.

Thank you
Umut


[*] The number 274 fluctuates a bit between boots and I patched
journald to display how many messages have been sent to syslog.
[**] Patch is only to show proof of concept and not optimized.
-------------- next part --------------
diff --git a/systemd/src/journal/journald-server.h b/systemd/src/journal/journald-server.h
index 42a2235..b4117f7 100644
--- a/systemd/src/journal/journald-server.h
+++ b/systemd/src/journal/journald-server.h
@@ -100,6 +100,7 @@ typedef struct Server {
         bool forward_to_wall;
 
         unsigned n_forward_syslog_missed;
+        unsigned n_forward_syslog_success;
         usec_t last_warn_forward_syslog_missed;
 
         uint64_t cached_available_space;
diff --git a/systemd/src/journal/journald-syslog.c b/systemd/src/journal/journald-syslog.c
index b826e23..537386f 100644
--- a/systemd/src/journal/journald-syslog.c
+++ b/systemd/src/journal/journald-syslog.c
@@ -37,6 +37,7 @@
 
 static void forward_syslog_iovec(Server *s, const struct iovec *iovec, unsigned n_iovec, struct ucred *ucred, struct timeval *tv) {
 
+        int fd = -1;
         union sockaddr_union sa = {
                 .un.sun_family = AF_UNIX,
                 .un.sun_path = "/run/systemd/journal/syslog",
@@ -71,12 +72,22 @@ static void forward_syslog_iovec(Server *s, const struct iovec *iovec, unsigned
                 msghdr.msg_controllen = cmsg->cmsg_len;
         }
 
+        fd = socket(AF_UNIX, SOCK_DGRAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0);
+        if (fd < 0) {
+                log_debug("Failed to create a socket");
+                return;
+        }
+
+
         /* Forward the syslog message we received via /dev/log to
          * /run/systemd/syslog. Unfortunately we currently can't set
          * the SO_TIMESTAMP auxiliary data, and hence we don't. */
 
-        if (sendmsg(s->syslog_fd, &msghdr, MSG_NOSIGNAL) >= 0)
+        if (sendmsg(fd, &msghdr, MSG_NOSIGNAL) >= 0) {
+                s->n_forward_syslog_success++;
+                close(fd);
                 return;
+	}
 
         /* The socket is full? I guess the syslog implementation is
          * too slow, and we shouldn't wait for that... */
@@ -96,17 +107,22 @@ static void forward_syslog_iovec(Server *s, const struct iovec *iovec, unsigned
                 u.pid = getpid();
                 memcpy(CMSG_DATA(cmsg), &u, sizeof(struct ucred));
 
-                if (sendmsg(s->syslog_fd, &msghdr, MSG_NOSIGNAL) >= 0)
+                if (sendmsg(fd, &msghdr, MSG_NOSIGNAL) >= 0) {
+                        s->n_forward_syslog_success++;
+                        close(fd);
                         return;
+		}
 
                 if (errno == EAGAIN) {
                         s->n_forward_syslog_missed++;
+                        close(fd);
                         return;
                 }
         }
 
         if (errno != ENOENT)
                 log_debug("Failed to forward syslog message: %m");
+        close(fd);
 }
 
 static void forward_syslog_raw(Server *s, int priority, const char *buffer, struct ucred *ucred, struct timeval *tv) {
@@ -492,7 +508,8 @@ void server_maybe_warn_forward_syslog_missed(Server *s) {
         if (s->last_warn_forward_syslog_missed + WARN_FORWARD_SYSLOG_MISSED_USEC > n)
                 return;
 
-        server_driver_message(s, SD_MESSAGE_FORWARD_SYSLOG_MISSED, "Forwarding to syslog missed %u messages.", s->n_forward_syslog_missed);
+        server_driver_message(s, SD_MESSAGE_FORWARD_SYSLOG_MISSED, "Forwarding to syslog missed %u messages. (succeed %u messages)", s->n_forward_syslog_missed,
+                                                                                                                                     s->n_forward_syslog_success);
 
         s->n_forward_syslog_missed = 0;
         s->last_warn_forward_syslog_missed = n;