Re: [systemd-devel] systemd-journald doesn't follow max datagram length when forwarding messages to syslog
On Sun, 10.08.14 21:07, Umut Tezduyar Lindskog (u...@tezduyar.com) wrote: The problem is due to sending socket's SO_SNDBUF limit. My guess at this point is the amount of messages you can queue to syslog socket is determined by 3 factors. a) Sending socket's SO_SNDBUF b) Receiving socket's SO_RCVBUF c) Global variable /proc/sys/net/unix/max_dgram_qlen. My workaround is adding SendBuffer=8M to systemd-journald-dev-log.socket but I am not sure if the way we account things is intuitive. My propose is passing systemd-journald-dev-log.socket to systemd-journald so that systemd-journald can forward messages to rsyslog through it. Or not deal with this since newer rsyslog fetches logs. References https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/tree/net/unix/af_unix.c#n1445 http://vger.kernel.org/~davem/skb_sk.html I have now changed git to also set SendBuffer=8M for the .socket unit. I must agree though, it's a bit surprising that we use the same socket here for recieving syslog and forwarding it. I was tempted to just add a second socket for the forwarding, that is internal to journald, and never seen outside. While this appears cleaner on one hand, it also would require us to either hardcode the buffer size or come up with a new config setting for it. Neither of these options are particularly attractive, in particular given that we can currently just set SendBuffer=8M and be done with it. Hence that's what I did. Does that make sense? Lennart -- Lennart Poettering, Red Hat ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] systemd-journald doesn't follow max datagram length when forwarding messages to syslog
On Wed, Aug 13, 2014 at 6:59 PM, Lennart Poettering lenn...@poettering.net wrote: On Sun, 10.08.14 21:07, Umut Tezduyar Lindskog (u...@tezduyar.com) wrote: The problem is due to sending socket's SO_SNDBUF limit. My guess at this point is the amount of messages you can queue to syslog socket is determined by 3 factors. a) Sending socket's SO_SNDBUF b) Receiving socket's SO_RCVBUF c) Global variable /proc/sys/net/unix/max_dgram_qlen. My workaround is adding SendBuffer=8M to systemd-journald-dev-log.socket but I am not sure if the way we account things is intuitive. My propose is passing systemd-journald-dev-log.socket to systemd-journald so that systemd-journald can forward messages to rsyslog through it. Or not deal with this since newer rsyslog fetches logs. References https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/tree/net/unix/af_unix.c#n1445 http://vger.kernel.org/~davem/skb_sk.html I have now changed git to also set SendBuffer=8M for the .socket unit. I must agree though, it's a bit surprising that we use the same socket here for recieving syslog and forwarding it. I was tempted to just add a second socket for the forwarding, that is internal to journald, and never seen outside. While this appears cleaner on one hand, it also would require us to either hardcode the buffer size or come up with a new config setting for it. Neither of these options are particularly attractive, in particular given that we can currently just set SendBuffer=8M and be done with it. Hence that's what I did. Does that make sense? Thanks. I think it is good enough. Lennart -- Lennart Poettering, Red Hat ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] systemd-journald doesn't follow max datagram length when forwarding messages to syslog
On Wed, Aug 6, 2014 at 9:08 PM, Umut Tezduyar Lindskog u...@tezduyar.com wrote: 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 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 1 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. The problem is due to sending socket's SO_SNDBUF limit. My guess at this point is the amount of messages you can queue to syslog socket is determined by 3 factors. a) Sending socket's SO_SNDBUF b) Receiving socket's SO_RCVBUF c) Global variable /proc/sys/net/unix/max_dgram_qlen. My workaround is adding SendBuffer=8M to systemd-journald-dev-log.socket but I am not sure if the way we account things is intuitive. My propose is passing systemd-journald-dev-log.socket to systemd-journald so that systemd-journald can forward messages to rsyslog through it. Or not deal with this since newer rsyslog fetches logs. References https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/tree/net/unix/af_unix.c#n1445 http://vger.kernel.org/~davem/skb_sk.html Umut 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. ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
[systemd-devel] systemd-journald doesn't follow max datagram length when forwarding messages to syslog
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
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
1 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.
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);
