Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Command line option -T is not restricted to messages from remote hosts #93

Open
opty77 opened this issue Jan 7, 2025 · 19 comments
Open
Labels
bug Something isn't working documentation Documentation
Milestone

Comments

@opty77
Copy link

opty77 commented Jan 7, 2025

With RFC 3164 (the default) syslogd can use messages' timestamp but it doesn't provide enough information/precision (year, TZ and subseconds). You can't reliably sort messages taken from several files, you would have to log them to a single file too.

RFC 5424 helps a bit but you still have to fake the subsecond part of glibc's syslog(3) messages which may lead to wrong order in sorted list. (Consider the edge of the consecutive seconds.)

But... you can run syslogd -T (undocumented for local messages), let it always generate consistent timestamps (although different) and reliably sort messages from several files. IIRC rsyslog uses this approach by default and I wonder whether syslogd should behave the same. It would fix #92 which led me to these thoughts.

@troglobit
Copy link
Owner

Interesting observation about the effect of -T on local messages, I was not aware of that! 😮

I've tried real hard to bring sysklogd in-line with the FreeBSD and NetBSD implementations of syslogd, from which old sysklogd is derived from. So I've spent the better part of this morning trying to figure out how they limit the RemoteAddDate (-T) option from just biting on remote messages in their code bases -- doesn't seem they do, and their man-pages (1, 2) document -T similarly to sysklogd.

So at the very least we should update our documentation of -T to match the reality. However, I'm not keen on changing the default behavior of syslogd -- maybe for the next major bump (3.x). By opening up the description of -T instead it would be clearer to an administrator how to control the behavior to suit their needs.

@opty77
Copy link
Author

opty77 commented Jan 9, 2025

Yeah, it surprised me too.

I definitely agree with documentation update, something like

Always use the local time and date for messages received from the network as well as for local non-kernel ones, instead of the timestamp field supplied in the message. This is useful if some of the originating hosts cannot keep time properly, are unable to generate a correct timestamp or you need more information/precision (year, TZ or subseconds; assuming RFC 5424).

I rather meant changing the default behavior just in RFC 5424 case but that again leads to the last paragraph in #92 (comment).

@troglobit
Copy link
Owner

I definitely agree with documentation update, something like

Always use the local time and date for messages received from the network as well as for local non-kernel ones, instead of the timestamp field supplied in the message. This is useful if some of the originating hosts cannot keep time properly, are unable to generate a correct timestamp or you need more information/precision (year, TZ or subseconds; assuming RFC 5424).

Mmm, we'll see. Must be succinct and easy to read. Adding this to the next milestone.

I rather meant changing the default behavior just in RFC 5424 case but that again leads to the last paragraph in #92 (comment).

No, the output formats only control the RFC style in the output, not how to interpret the input. It would also be very confusing/inconsistent.

The only thing we should change is the documentation.

@troglobit troglobit changed the title Timestamps: RFC 3164 vs. RFC 5424 Command line option -T is not restricted to messages from remote hosts Jan 9, 2025
@troglobit troglobit added bug Something isn't working documentation Documentation labels Jan 9, 2025
@troglobit troglobit added this to the v2.8.0 milestone Jan 9, 2025
@opty77
Copy link
Author

opty77 commented Jan 9, 2025

Think of a message always containing two types of timestamps: original and syslogd-received. Then you could choose which one to use in the output.

But I guess I should rather finally decide which one to choose instead of trying to make syslogd rsyslog-ish?

@troglobit
Copy link
Owner

Think of a message always containing two types of timestamps: original and syslogd-received. Then you could choose which one to use in the output.

Sure, but that should not be implicitly changed by the RFCXXXX output format options. For that another action option should be used instead, e.g., ;datetime=replace or similar.

But I guess I should rather finally decide which one to choose instead of trying to make syslogd rsyslog-ish?

The direction of the sysklogd project is quite clear, as I've stated previously, we aim to track our upstream brethren in FreeBSD and NetBSD land and we are not aiming to become an rsyslogd replacement.

@opty77
Copy link
Author

opty77 commented Jan 9, 2025

I guess that I finally understand.

@opty77
Copy link
Author

opty77 commented Jan 16, 2025

Worth a mention?

@troglobit
Copy link
Owner

Worth a mention?

I've held off responding to this, but I really do not understand this comment. The link references a long thread, the link anchor points to a post from the rsyslogd maintainer. What in particular do you, @opty77, think is "worth a mention" here? Or do you mean this particular comment should be taken into consideration for this particular bug report? I honestly cannot guess what people mean, so please try to be more clear in your issue messages.

@opty77
Copy link
Author

opty77 commented Jan 23, 2025

I consider

If the sender sent no ms, we can not report them. Rather than to pretend "x.000000" they are there, we do not give them.

interesting regarding original dilemma in the very first comment (together with #96) and

Note that starting with the latest v5-devel version AND a recent Linux kernel, we can ask the system for more precise timestamps on messages that come in via the log socket.

which I tried to find in rsyslogd source code but failed and rather saw syslogd -T behavior.

@troglobit
Copy link
Owner

Great reply, thank you, so much clearer now! 😃

@opty77
Copy link
Author

opty77 commented Jan 31, 2025

Note that starting with the latest v5-devel version AND a recent Linux kernel, we can ask the system for more precise timestamps on messages that come in via the log socket.

which I tried to find in rsyslogd source code but failed and rather saw syslogd -T behavior.

Found and had seen wrong.

Basically set socket option SO_TIMESTAMP and get timestamp from control message.

Looks very promising, what do you think?

@troglobit
Copy link
Owner

I think that's a lot of work since it means refactoring all recv() and recvfrom() calls to use recvmsg(), which is the one supporting ancillary data such as control messages.

Also, I'm not sure I understand what you want us to do in the project with all this? RFC3164 messages do not have sub-second timestamps, but since the addition of RFC5424 support we can write and forward such messages with sub-second timestamp. So we have an option either just fall back to zero or use tv_usec at the time we parse the message. All this gives us is a discriminator if we look at messages unsorted, which may happen thanks to UDP messages when we forward to another server. For that, I consider the current implementation good enough.

@troglobit
Copy link
Owner

Decision:

  • the documentation for the -T option will be updated, removing any mention or limitation to "network" or "remote host"
  • the default behavior in the sysklogd project will remain the same, for backwards compatibility reasons, to trust timestamps in messages, this also aligns with FreeBSD & NetBSD syslogd behavior
  • messages that do not have a valid timestamp, i.e., old BSD pre-RFC3164, will always get the time of reception

@troglobit troglobit modified the milestones: v2.8.0, v2.7.1 Feb 2, 2025
@opty77
Copy link
Author

opty77 commented Feb 3, 2025

I think that's a lot of work since it means refactoring all recv() and recvfrom() calls to use recvmsg(), which is the one supporting ancillary data such as control messages.

One recv(2) and one recvfrom(2). :-)

I decided to try to implement the recv(2) case as it seems like my ultimate salvation.

Also, I'm not sure I understand what you want us to do in the project with all this? [...]

Consistency. I stopped liking timestamp built from two independent sources and I even wonder who requested that.

I could exploit RFC 5424 MSGID for message serial number or better inject [meta sequenceId="..."] to sort reliably but that doesn't look much elegant.

@opty77
Copy link
Author

opty77 commented Feb 6, 2025

FYI

my patch
diff -Naurx configure.ac a/sysklogd-2.7.0+fu/src/syslogd.c b/sysklogd-2.7.0+fu+st3/src/syslogd.c
--- a/sysklogd-2.7.0+fu/src/syslogd.c	2025-02-04 15:42:44.329740961 +0100
+++ b/sysklogd-2.7.0+fu+st3/src/syslogd.c	2025-02-06 16:05:27.322892451 +0100
@@ -148,6 +148,9 @@
 static int	  secure_opt;		  /* sink for others, log to remote, or only unix domain socks */
 static int	  secure_mode;		  /* same as above but from syslog.conf, only if cmdline unset */
 
+/* TODO: RemoteAddDate = 1 */
+static int	  SockTime = 0;		  /* Use UNIX socket timestamp for local RFC 3164 messages, disabled by default */
+
 static int	  RemoteAddDate;	  /* Always set the date on remote messages */
 static int	  RemoteHostname;	  /* Log remote hostname from the message */
 
@@ -194,7 +197,7 @@
 /* Function prototypes. */
 static int  allowaddr(char *s);
 void        untty(void);
-static void parsemsg(char *from, size_t from_len, char *msg);
+static void parsemsg(char *from, size_t from_len, char *msg, struct timeval *ts);
 static int  opensys(const char *file);
 static void printsys(char *msg);
 static void unix_cb(int sd, void *arg);
@@ -404,8 +407,8 @@
 int usage(int code)
 {
 	printf("Usage:\n"
-	       "  syslogd [-468AdFHKknsTtv?] [-a PEER] [-b ADDR] [-f FILE] [-m MINS] [-M SIZE]\n"
-	       "                             [-P PID_FILE] [-p SOCK_PATH] [-r SIZE[:NUM]]\n"
+	       "  syslogd [-468AdFHKknSsTtv?] [-a PEER] [-b ADDR] [-f FILE] [-m MINS] [-M SIZE]\n"
+	       "                              [-P PID_FILE] [-p SOCK_PATH] [-r SIZE[:NUM]]\n"
 	       "Options:\n"
 	       "  -4        Force IPv4 only\n"
 	       "  -6        Force IPv6 only\n"
@@ -454,6 +457,7 @@
 	       "  -r S[:R]  Enable log rotation. The size argument (S) takes k/M/G qualifiers,\n"
 	       "            e.g. 2M for 2 MiB.  The optional rotations argument default to 5.\n"
 	       "            Rotation can also be defined per log file in %s\n"
+	       "  -S        Use UNIX socket timestamp for local RFC 3164 messages\n"
 	       "  -s        Operate in secure mode, do not log messages from remote machines.\n"
 	       "            If specified twice, no socket at all will be opened, which also\n"
 	       "            disables support for logging to remote machines.\n"
@@ -478,7 +482,7 @@
 	int pflag = 0;
 	int ch;
 
-	while ((ch = getopt(argc, argv, "468Aa:b:C:cdHFf:Kklm:M:nP:p:r:sTtv?")) != EOF) {
+	while ((ch = getopt(argc, argv, "468Aa:b:C:cdHFf:Kklm:M:nP:p:r:SsTtv?")) != EOF) {
 		switch ((char)ch) {
 		case '4':
 			family = PF_INET;
@@ -580,6 +584,10 @@
 			rotate_opt++;
 			break;
 
+		case 'S':
+			SockTime = 1;
+			break;
+
 		case 's':
 			secure_opt++;
 			break;
@@ -813,8 +821,42 @@
 {
 	ssize_t msglen;
 	char msg[MAXLINE + 1] = { 0 };
+	struct timeval ts;
+	int ts_set = 0;
 
-	msglen = recv(sd, msg, sizeof(msg) - 1, 0);
+	if (SockTime) {
+		struct msghdr msgh;
+		struct iovec msgiov;
+		union {
+			char buf[CMSG_SPACE(sizeof(ts))];
+			struct cmsghdr align;
+		} u;
+
+		memset(&msgh, 0, sizeof(msgh));
+		memset(&msgiov, 0, sizeof(msgiov));
+		msgh.msg_control = u.buf;
+		msgh.msg_controllen = sizeof(u.buf);
+		msgiov.iov_base = msg;
+		msgiov.iov_len = MAXLINE;
+		msgh.msg_iov = &msgiov;
+		msgh.msg_iovlen = 1;
+		msglen = recvmsg(sd, &msgh, 0);
+		if (msglen > 0) {
+			struct cmsghdr *cm;
+
+			for (cm = CMSG_FIRSTHDR(&msgh); cm; cm = CMSG_NXTHDR(&msgh, cm)) {
+				if (cm->cmsg_level == SOL_SOCKET && cm->cmsg_type == SO_TIMESTAMP) {
+					memcpy(&ts, CMSG_DATA(cm), sizeof(ts));
+					ts_set = 1;
+					logit("Timestamp from UNIX socket #%d: %i.%i\n", sd, ts.tv_sec, ts.tv_usec);
+				}
+			}
+			if (!cm && !ts_set)
+				logit("Receive timestamp failed from UNIX socket #%d\n", sd);
+		}
+	} else {
+		msglen = recv(sd, msg, sizeof(msg) - 1, 0);
+	}
 	logit("Message from UNIX socket #%d: %s\n", sd, msg);
 	if (msglen <= 0) {
 		if (msglen < 0 && errno != EINTR)
@@ -823,7 +865,7 @@
 	}
 	msg[msglen] = 0;
 
-	parsemsg(LocalHostName, strlen(LocalHostName), msg);
+	parsemsg(LocalHostName, strlen(LocalHostName), msg, ts_set ? &ts : NULL);
 }
 
 static int create_unix_socket(struct peer *pe)
@@ -849,6 +891,15 @@
 
 	NOTE("Created UNIX socket %s", sun.sun_path);
 	pe->pe_sock[pe->pe_socknum++] = sd;
+
+	if (SockTime) {
+		int one = 1;
+		if(setsockopt(sd, SOL_SOCKET, SO_TIMESTAMP, &one, sizeof(one)) != 0)
+			ERR("Set SO_TIMESTAMP failed on UNIX socket %s", sun.sun_path);
+		else
+			NOTE("Set SO_TIMESTAMP succeeded on UNIX socket %s", sun.sun_path);
+	}
+
 	return 0;
 err:
 	ERR("cannot create %s", pe->pe_name);
@@ -905,7 +956,7 @@
 		return;
 	}
 
-	parsemsg(hname, hname_len, msg);
+	parsemsg(hname, hname_len, msg, NULL);
 }
 
 /*
@@ -1268,7 +1319,7 @@
  * result is passed to logmsg().
  */
 static void
-parsemsg_rfc3164(const char *from, int pri, char *msg)
+parsemsg_rfc3164(const char *from, int pri, char *msg, struct timeval *ts)
 {
 	struct logtime timestamp_remote = { 0 };
 	struct buf_msg buffer;
@@ -1291,7 +1342,7 @@
 
 		msg += RFC3164_DATELEN + 1;
 
-		if (!RemoteAddDate) {
+		if (!RemoteAddDate && !(SockTime && ts)) {
 			struct timeval tv;
 			time_t t_remote;
 			struct tm tm_now;
@@ -1332,6 +1383,17 @@
 		}
 	}
 
+	if (SockTime && ts) {
+		struct logtime now;
+
+		localtime_r(&ts->tv_sec, &now.tm);
+		now.usec = ts->tv_usec;
+		/* TODO: Needed? */
+		now.fake_usec = 0;
+		buffer.timestamp = now;
+		logit("Using timestamp from UNIX socket\n");
+	}
+
 	/*
 	 * A single space character MUST also follow the HOSTNAME field.
 	 */
@@ -1373,7 +1435,7 @@
  * standards and prints the message on the appropriate log files.
  */
 static void
-parsemsg(char *from, size_t from_len, char *msg)
+parsemsg(char *from, size_t from_len, char *msg, struct timeval *ts)
 {
 	char *q;
 	long n;
@@ -1432,7 +1494,7 @@
 
 		parsemsg_rfc5424(from, pri, msg + 2);
 	} else
-		parsemsg_rfc3164(from, pri, msg);
+		parsemsg_rfc3164(from, pri, msg, ts);
 }
 
 /*

seems to work.

Edit: Oops, this version actually uses UNIX socket timestamp for local BSD messages too.

Another edit: TODO: Use -x instead of -S to avoid possible collision with *BSD.

Hopefully last edit(s): TODO: Use __linux__?

@opty77
Copy link
Author

opty77 commented Feb 6, 2025

I could exploit RFC 5424 MSGID for message serial number or better inject [meta sequenceId="..."] to sort reliably but that doesn't look much elegant.

...and unfortunately still not guaranteed that even two RFC 5424 messages with precise timestamps arrive in chronological order and not swapped for some racy reason.

@opty77
Copy link
Author

opty77 commented Feb 6, 2025

I'm also thinking about using MSGID for denoting timestamp type/origin.

@opty77
Copy link
Author

opty77 commented Feb 6, 2025

Decision:

* the documentation for the `-T` option will be updated, removing any mention or limitation to "network" or "remote host"

I don't know the exact wording yet but couldn't this make one think that it also covers kernel messages which use their own timestamp logic?

@troglobit
Copy link
Owner

Decision:

* the documentation for the `-T` option will be updated, removing any mention or limitation to "network" or "remote host"

I don't know the exact wording yet but couldn't this make one think that it also covers kernel messages which use their own timestamp logic?

Good point, I'll keep that in mind 👍

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working documentation Documentation
Projects
None yet
Development

No branches or pull requests

2 participants