Introduction

Hello, and welcome to CS631 "Advanced Programming in the UNIX Environment". This is week 12, segment 1. In this week, we'll cover a bit of a hodgepodge of topics. We'll cover a few topics grouped together as "Advanced I/O", and we'll conclude this week's materials with a very high-level introduction to basic encryption in the Unix environment, but first, let's revisit "syslog". As you may remember from our video on daemon processes from week 10, we had identified a need for processes without a controlling terminal to communicate events to the system administrator or the users, and we had mentioned the use of "syslog" for this purpose. So why do we need a special daemon that logs messages for us? Wouldn't it be easier to simply have our process open a log file at program startup in append mode, then write data to it whenever it needs to, and then close it upon exit? Seems simple enough. Now the thing is, a daemon may want to send different messages to different places. Or perhaps it's not the daemon itself, but the administrator would prefer if, for example, debugging statements went to one file, while important messages about certain critical events went to another file. No problem, let's have the process open two files and write the messages there as needed. Problem solved. But sometimes the process wants to also write to a terminal, if it has one, anyway. And certain events may be so important that they are written to the serial console. Well, all doable. But now consider that this is a very common pattern. All daemons on the system will have this, or similar needs. And not only do they want to write to their own files, sometimes you want to collect errors or warnings from all your daemons in the same file, ...so you now need to coordinate access by multiple processes to shared resources. and so the mappings between processes and file increases and becomes more complex. But not only that -- you also have to consider that now every process has to have write access to the logfiles in question. And most daemons run with a dedicated user, so you need to grant granular write access, or allow the daemons to run with higher privileges to write to all the files and resources. So that gets messy quickly, as you can tell.

A central logging facility

Here, doesn't this image look nicer? If we had a central logging facility, then we can abstract all the messy work of handling files and all that away from the processes. You know - do one thing and do it well, then allow the daemon processes to simply make a few library calls. Now that central facility still requires write access, but all the individual processes do not any longer, which also nicely allows us to run them with very limited privileges. So in a way, we can think of this central logging facility of a daemon itself that juggles all the different messages submitted to it by the different applications. Here's a video of syslogd -- a daemon that requisitioned its groove back -- in action. Messages come in and are swiftly filed into the right files. Alright, let's see what this _actually_ looks like...

syslogd(8) example

Here, under /var/log, we see a number of files that are regularly and frequently updated. The names are reasonably self-explanatory: there's a maillog, an authlog, a log file for cron, and a file for generic messages. Different files have different permissions, depending on whether the messages received are considered to be possibly sensitive in nature or not. So let's take a look at the entries in the authlog. Here we see a number of messages from sshd, and some from sudo. The regular messages are not sensitive, so we can look at them as a normal user. We'll notice that the format across the files is consistent, with a field noting which process logged the message. Let's see which processes all have been logging information. We extract the fifth field from the file and count each instance. Ok, so a bunch of syslog, ntp, dhcpcd processes. Let's try to get rid of the process IDs. There, that's better. So we see we have around 10 processes that log messages, with most messages coming from the kernel, followed by dhcpcd, then ntpd. If we repeat this from all the log files, we see a few more daemons, hopefully showing the usefulness of having a central logging facility instead of having each one of these daemons implement all the same logic. How does syslogd know which messages should be sent to which of these files? Let's look at /etc/syslog.conf -- this file shows that there's a simple mapping of messages of certain types or priorities to log files.

syslogd(8)

We'll see in a few minutes how we can log messages ourselves, but let's note that there are several ways that messages can be delivered to this central logging facility: The kernel itself can submit messages via the log(9) function, allowing it to not have to implement actual logging logic. Any process on the system can make a call to the syslog(3) library function, which we'll see in more detail in a minute. But in addition to that - and that's actually quite cool - syslogd can also accept messages coming from the network, usually UDP port 514. This is really useful: imagine you have hundreds or thousands of hosts; you don't want to have to go to each host to investigate what happened on each. It'd be much easier to collect all the logs from all hosts in one central location and then look at those messages in one place. syslogd(3) allows for this to happen. So all together, syslog kind of looks like this. Each of the mechanisms by which messages are accepted allow syslog to process them in a uniform manner and then distribute them according to its configuration and write them to a file, send them to a user, or itself send them on to another host. With all that, you can build a large scale, complex message logging system for your infrastructure.

syslog(3)

But let's look at how you as a programmer would use syslog(3): We have two calls to look at, openlog(3) and syslog(3). openlog(3) allows you to influence the behavior of the subsequent calls to syslog(3): In order to differentiate your messages from those logged by other processes, you can prepend a string to each message. We've seen that in the example where each daemon processes uses its name for this prefix message. You can further specify a number of logging options, such as to log the messages to the console or stdout in addition to the files, to log the process ID etc. Next, you specify the so-called "facility", which is used by syslog to determine where to route your message. syslog(3) itself is then called whenever you want to log a message. It hands the message to the syslog daemon tagged with the given priority, allowing the daemon to separate important messages from those that are informational only or used for debugging purposes.

syslog(3) and logger(1)

Let's illustrate the use of these library functions with an example. Here's our 'main' function, where we call openlog(3), specifying the program name as the prefix, asking syslog to also print messages to the terminal, with the process ID included. We picked the 'user' facility to identify our process as a regular user process. Then we install a few signal handlers and, if we were to ever exit normally, close the logs as part of our usual cleanup. Our signal handler then calls syslog(3) for each signal it receives, using different priorities for each of the signals we're catching. Here we go. We hit Ctrl+\ to send SIGQUIT and it is printed to the terminal with the process ID. But let's see if it also found its way into the log files. Yep, there it is. Let's try to generate the same signal again, followed by SIGINFO, which we can generate by hitting Ctrl+t. Note, by the way, that on BSD systems sending SIGINFO to a process automatically triggers some information about the process to be printed. But our signal handler still logged its message. Now let's send it SIGUSR1 from a new shell. That, too, gets logged. Now let's try SIGUSR2. Hmmm, nothing happens. Let's try again. If we switch back to the program, we see that it received the signal and syslog triggered the logging to the terminal, but nothing showed up in our logs! Let's send it SIGQUIT again. There, that was logged to the file. But also note that syslog added this statement here -- "last message repeated 3 times". That is, syslog is smart enough to detect duplicate messages and rather than writing those to the file, it will wait until a different message comes in. So if we send SIGQUIT a few times, followed by SIGUSR2, we see them logged over here like this. Now let's take a look at the configuration of syslog: Let's separate our messages into a different file by specifying user.notice to go to /var/log/usermsgs First we need to create the file, then restart syslogd. We note that syslogd itself logs messages via syslog. When we now start our program again, and send it the SIGUSR1 signal, we see that it still logs to /var/log/messages, but the message is _also_ logged to the file we specified. That is, we see that syslog has the ability to allow logging to multiple files at the same time. Now recall that we log the messages for the different signals using different priorities, with anything matching "notice" or higher being logged to the new file. But if we send SIGINFO, this information is _not_ logged to the new file, even though of course the signal is received, and per our openlog(3) directive logged to the terminal. Sending SIGUSR1 again, we don't get another message in our file since the message was just repeated, even if sent from a different process, but syslogd reports in /var/log/messages that the message was repeated. If we send SIGINFO, that isn't logged because "info" is of a lower priority than "notice", and we only instructed syslogd to log "notice" or higher here. SIGQUIT, for example. Since this central logging facility is rather useful, we cant not only log things via the library functions, but also via the command-line. For that, we have the logger(1) utility, which provides a simple interface to these library functions. For example, we can log a message with a local0 facility and a level of "info", or we can log a message in the 'user' facility. As before, if it's below "notice" it won't make it into our separate file, but higher priority messages do get delivered. Finally, we can send a message of level "emergency", which will be delivered to all logged in users on their terminal, as shown here. These messages still are logged to the file /var/log/messages.

Recap

Ok, time to summarize. syslog has been around for a while. It's been the de-facto standard for system logging on Unix systems since the 80s. syslog has been standardized in RFC5424, which includes a definition of the network packet format; By default, syslog will use UDP on port 514 for network connections, although nowadays you may also see syslog traffic be transmitted over TCP, or wrapped in TLS. Some newer versions of syslog such as syslog-ng or rsyslog have added further enhancements, but amongst a number of large scale organizations it's popular these days to use a different message relay service, such as elasticsearch or solr, for example. However, it's worth noting that there is a whole lot of equipment out there that simply cannot use anything different from standard RFC5424 format UDP to port 514 packets to relay messages. Network equipment comes to mind. Either way, syslog is a very convenient service that exhibits many of the properties of the Unix philosophy and is, as we've seen in our code example, rather easy to use. Give it a try! Thanks for watching - cheers!