 Yeah, thank you very much. So a few words to myself. I work for Genua. We are a company building BSD based open BSD based firewalls And I'm a open BSD committer since 10 years now so I can combine my profession with my hobby So what we'll talk about first of all why do we need something else? It has been said already is this log is a very old program and just works and that's what we expect from it Where are we now starting position? What did I do to make? The local logging better on on the machine. What did I change with remote logging sending this log messages to other? Machines and I have a short summary of what I did Okay, why do we need logging and why do we need reliable logging? So we do system analysis We want to know what on the machine is going on if you debug a problem And if some log messages are missing and we don't see that then it makes our task harder Second thing is we have attackers in the internet And they try to avoid that we see their traces They try to avoid that we see log messages So if they can bring the system to state where it doesn't lock anymore They can make their tech and we don't see that it did something evil And then the third thing is we certify Yeah, we are on time And We do a certification for our product with common criteria and there someone wrote into the documents Yeah, we do a reliable syslogger and we don't lose log messages. So We had a bunch of dirty hacks in our product to make that and I thought Let's move all the intelligence into the system into the syslog The it's all that the community and community can have an advantage for it And we have cleaner code and don't require our hacks So what can go wrong? First of all syslog is doing if it does remote logging it with UDP forever and UDP is not known for being reliable It's basically unreliable. You can just lose it if you lose UDP packet. You don't see the log message Then we have UNIX datagram Sockets for local delivery they you need file descriptors then you have to need need access to the file You can be a run change routed then you don't see it anymore. So it's def lock That's the the classical thing and there are things that can go wrong So and then we have time stamps and time zones and you run change routed the classical syslog takes the time zone from The local file system and the client was logging it So when you have when you forget to to put your ETC local time in your change route environments you get syslog messages that are different time zones some of them are UTC some of them are local time and Timestamps is also a problem when you do remote logging when you have a global environment and every syslog is Logging in local time and then you have a common log file with all things and every machine has a different time Stems that's really hard to debug. Okay Where did we start from so that's how? syslog works when you you just go through So that's how a syslog works when you you are a C programmer So there's a libc function. That's called syslog. You can say okay. I have several Severities here. We have an error message You can do some printf style Formatting Then everything goes to libc there the priority is processed. So this is converted to a number You have timestamps added there the print is done and then it's sent to devlog that's a UNIX files UNIX domain socket and The syslog D is listening on that So then the syslog D is receiving the thing writes it to a log file or sends it via UDP So this this has been there for forever more or less So now we look into details how that works So we have some priorities facilities levels severities and options that we can pass There the first confusion starts the man page speaks of level the RFC calls it severity The header files calls it priority while the RFC Means the combined thing between severity and facility is the priority so what? So what do you do? We have an open log That's this Lipsy function that a program calls when it starts running and there it can say it's okay My name is FTP demon. So tag this name to all the log messages So the user knows where it comes from it can say, okay and I want that my pit file my pit number is locked in all messages and If logging goes wrong in the message so if cannot reach this log the messages should show up at the console then you can say log cons and there are some other options there and Then we have the facility facility means that every program that there are some classes of programs For example FTP programs then we have you use the news the syslog the mail So it's basically what a server in the beginning of the 80s could have and then we have local Facilities local zero to local eight. That's everything else What's local 16? I don't know So those are our numbers and the the facility and the Severity they are all together and then they're called priority and The Lipsy generates such a string So it this one is in a decimal notation those two are together And you have time stamp. That's the classical BSD timestamp Then the program name the pit and the message so what can we change here? So we we write that to dev log that means we need a file descriptor so when do we acquire the file descriptor? We can either do it with open log or we can do it when we do the syslog call and there We have a special switch. That's N delay when you say no delay to open log. It opens the file descriptor immediately So that's it has an advantage. So we have opened it at once so before you change route And also when you go into to a change route environment, then logging still works although you have no socket there But then you got to stick up to the syslog D that means he closes all The the the listening sockets and you have to reconnect Lipsy will do that unless you're in change route and unless you have specified to syslog D to To add an additional lock socket into the change route So and then the other art added to pledge to Open BSD where you can specify that only special classes of System calls are allowed, but you want to allow every Program to write its log messages because they are the errors. They are the traces for the attacker and that's common so all this concept makes it quite complicated because You need this file descriptor you can run out of file descriptors because you have to log and delay you have to reopen it during operation You have to allow somehow syslog Socket is somehow the eunuchs domain socket. So you have to pledge eunuchs everything So that's not good. And when you say lock cons And the lip sees makes a sent to sees. Oh syslog D is not running Now I have to open the console file descriptor dev console So you need another device in your change route. Don't forget that and you need a file descriptor so if you run out of file descriptor and want to lock that doesn't work and So that's that's the implementation nightmare, especially in in situations where something went wrong So what's the solution you have a new system called? So if you invented it, it's called sense syslog and there we move tasks from Lip see to the kernel So how does it work? It's has an integer return word value like most of our system calls then you also see some Some in some error if something didn't work for example a no buffs if you run out of m buffs and You put in the message. It's not null terminated or in most cases it is But basically you give a lot as a length of the message and you pass some flags So there's only one flag supported at the moment and that's lock cons where you have to open Want to log on the console if the send to the syslog fails And the advantages that you don't need a file descriptor Because the colonel has opened the console anyway, and it knows what to do So it's not to ask of the program anymore to grab the console the colonel does it So here's an example what I call I put in the the string the length and the flag No, no does not come Okay, the question was whether I need the pit here or not and I need it all the other Processing is still in lip see colonel is only responsible for sending it. So lip see will generate the The priority the timestamp the name that you gave with open lock Otherwise, you have to store all that in the colonel it adds the pit So the pit is not reliable. Everyone can send whatever pit he wants and all the print F dispatch Processing it's still done in lip see So how do we get the message out of the colonel again before it's just like the just opened and listen socket on the unix domain socket And here's just like the creates a socket pair The socket pair is a system call and you get it's something like a pipe It's a socket with two ends and you can write in one end and get it from the other way and the other way around and Then syslog details the colonel with an yachtle it opens the fklok and does this I octal with the file descriptor of one end of the socket pair and says oh, this is my logging file descriptor and Then the colonel Registered it and it knows one logging file descriptor and every time you call send syslog it uses this and Syslog D listens on the other end and colonel writes into this socket pair because it knows which one it is because of this I octal the colonel also knows when the sent to doesn't work then it writes to the console It has it open anyway You can ktrace everything that's going through there. We have added some ktrace Oops, just have to ktrace the program and you see what it's logging Normally you write a file descriptor here minus one is written because the program doesn't have a file descriptor for that and What it's new I can count the arrows the colonel can count the arrows. So what does reliable logging mean? So either when we see oh, we cannot lock anymore. We hold the system until it works but we don't want that and So my solution for reliable logging is counting the errors and lock the errors when it works again So you see there was a problem the system works and works and continues and then we say and be careful We lost five messages and Here the colonel can count the error We have one colonel one central place and every time the sending to the syslog d fails it increments the counter So we have it on this slide The problem is with error logging at error handling That the syslog function that is implemented in libc and more or less standard is void So the program never knows or never knows whether it failed And even if it would know it cannot do anything because it cannot lock So doing it in the program is the wrong place and we do it in the colonel we counted there and then when We continue logging and the syslog the colonel tries to write to syslog again and again and once it recognized Oh, it works again, then it writes out a message To tell the user it didn't work So it says send syslog drop two messages and it writes the air know of the first failed Senses lock So I think that's a new buff for not connected something like that. I think that's not connected So if you lock something before the syslog d is running you get a not connected So next thing the timestamps so as I said before we take the local time in In every change route because it's done by libc when the log messages generate generated That's bad and when you look at the format you have no year. We have no time zone We have no daylight daylight saving time indication. So One time in a year. You see for one time every log message There are double lot messages and then you have one hour gap half a year later We have only second precision no sub second precision and Colonel when the when the colonel is logging something like the the dmask buffer the boot up messages They don't have a timestamp anyway So syslog has to do something for colonel messages So what is always doing for colonel messages is adding the timestamps looks the messages. Oh, there's no timestamp let's add one and I extended that so that the timestamp is always optional Syslog tries to parse it and if there's no timestamps. Yeah, then add one that also corresponds to the way What is written in this syslog rfc? Yeah, we also have devices that won't write timestamps. So syslog has to be capable to add one If the device that we get the remote message from doesn't have a clock So and what what I changed is that lip see doesn't generate a timestamp anymore So we always take the syslog timestamp and we have one central instance that is responsible for generating timestamps New people coming to the talk You'll just go in find a place and be quick So syslog d generates the The timestamp it's one central instance. You don't have going timestamps going back It is a difference now before you locked when the message The you did the timestamp in the program when the message happened now you do it in syslog. So you have a delay there and depending on when syslog gets scheduled it may be Bigger or not bigger So We can use higher precision as a new So the solutions for all this is you can turn syslog d you can give it the option minus z and then It generates in the new easel format In utc that is the solution for we have no daylight saving time no time zone Whatever and there we have advantages. We can also use millisecond precision So this format is in you are syslog rfcs And you see here you have the year the month the date the hour minute Second and you have a precision and this z means it's zulu time. So it's more or less utc gmt Whatever you call it Here we are allow up to six tickets precision or fractions of seconds and you should What's Henning saying there? That's correct And what does our syslog d do? I I have to quickly repeat it. Sorry Also, so Henning says that utc is without leap seconds and gt gmt is with And we log in our systems without leap seconds Thank you So You have the precision here You are allowed to specify by rfc up to six tickets I only do three because I did a measurement how how long is the The delay between logging in the program and reading it in syslog d and I don't get a better precision And that's roughly correct and the rfc says by specifying the number of tickets. You can say how precise you are It's like physics so We have other advantages by using send syslog directly So there are one some situations where you don't want to call the libc functions for you as Um application programmers just use libc syslog does everything for you But we can do other things we can call send syslog from a system signal handler. It's signal handler safe Um, we do have it In our libc when we see that a mem copy does overlap. We have mem move That's when you have memory regions that do overlap and you have mem copy That is not allowed to use if the regions do overlap because then it could do bad overwritings And if a programmer does it wrong then open bsd libc will generate a log message But we don't want to call other libc functions from there. So we just did it for a raw census log Then we have the stack protector handler that sees that a stack cookie has been overwritten by buffer overflow and in that cases you don't want to call other libc functions to To make it worse. Yeah, and it calls printf and does some formatting. So we do call some functions We uh, we call some astral little cut to to to create the message but only that And and then we just call census log directly So we get the message without Doing more on this broken stack And we also have some log message from the dynamic linker It also cannot call libc because it's there to load libc there. We also use that But don't do it It's never necessary except for those cases So there are other places where we can lose log messages We have the the demask where the kernel prints the boot up messages and prints some debug messages if you enable device driver debugging And basically it's a it's a ring buffer. So kernel writes and syslog reads. There's a it doesn't read on def k log and it can overflow And if syslog is reading slower than your device debugging messages appear Then it will override and you lose some messages And it's very hard. I once I tried to debug the usb stack and I felt no, you have this message and have that message And uh, how can that happen and I read the code and and it couldn't happen. Yeah, I was just an override And those messages had nothing to do with each other There were a lot of other messages in between So the kernel is counting the bytes it is overwriting It can count the bytes and when um syslog doesn't read and I see the counter is not zero And I've lost some bytes and the first thing the kernel writes to the syslog is this message And then you see ah, there was a gap now. Um, I know what's going on when I'm debugging this device driver So what do we do when we log remotely? So syslog d can do a lot of things So we have a sender Some some log host that is sending us messages We can get messages from some processes who do logging the kernel generates its messages himself And then we can write it to a file We can spawn a process and pipe it into it We have a memory buffer where we can store um syslog messages Temporarily that's interesting for diskless machines. And then we have a special syslog c uh command that communicates with over eunuch's domain socket with syslog and then it reads out the messages Um, yeah, it has been added to open bsd It was there when I looked into it, but it's an open bsd feature Then you Really? No, no, no Yeah, but I think I saw it in other bsd so So Pipe is there and free bsd so whoever copied it from Okay, so Henning says so Henning says everybody copies from open bsd. There's no other direction But I'm doubt that that's right and I would also say it's not good if it's if it would be right because There are also good other things in other bsd that we should share So Henning so I'm I'm supposed to repeat everything that Henning says and now Henning did some jokes about himself Okay So we can send the the messages to other remote logging facilities We can write something to the console We can write something to every users terminal with write all we can write something to special users You can put users in your syslog files or root gets messages or Henning or whatever Um, and you can write to special tty's So let's look at the at the details. That's more or less what I already explained When you have the process it uses either the new Method send syslog or devlog we kept the old method to be backwards compatible not everyone is using libc There's a pro module Syslog where you can say I use unix domain socket then uses that perhaps you have some programs around that still use that And then you can add additional unix sockets. That's basically for putting your devlog in all your change root environments You can specify multiple of them on the command line same minus a minus a bar And then we have devk log. That's for the messages generated generated by the kernel himself So let's look at the remote logging We have ipv4 and ipv6 when I started looking at syslog. There was only ipv4 And we can do udp tcp tls on both sides when I started we only had udp So how does udp logging look like We have a single udp packet and that contains a log message and that's it Then we have some rfcs talking about the size we have old rfcs that say Ah, it should not more than thousand and then we have others who say yeah, perhaps we should process 2000 And then we have one rfc if you don't make it longer than 1180 the the payload Then you can assume that it doesn't get fragmented And if it doesn't get fragmented then the chances are higher that it will reach the destination um So what I did is I took this value from one of the rfcs And truncate every message that I sent to udp to this length So how does it look like We have the priority we've seen before We have the timestamp depending on how you set your syslog With minus z or not you get the the the bsd timestamp or the easel timestamp So then the rfc says here comes the uh the hostname Um the if Rfc is called bsd syslog format But our syslog doesn't have at the hostname. So I don't know which bsd syslog they refer to We have an option Marcus, I think I did it where we can say minus h to add this Hostname or ip address to to every message um So and then there that uh there comes that what we receive from libc it doesn't change Yes, um the question was whether I added ascending or receiving and the answer is we added when we send it so we So what what what what I do when we when we receive a message we start parsing it We are looking at the priority that we filter it with our config file Um, we we we look at the timestamp. We add one if there is none I've always so added the the minus z option if you find the old format I replace it with a new format because here you don't see anything if you have global logging and and then It also adds this when it does in udp sent But that's also an open bsd extension another question It's the question is what happens if the message is longer and the answer is it gets truncated. I just cut it off So how does it look in tcp? So there are a bunch of rfcs. We have the old syslog format doesn't know anything about tcp. Then we have newer rfcs um They have one rfc of about syslog in general the next one is about syslog over udp Next one is about syslog over tls and there's no tcp But then you have another rfc with a bigger larger number and there um Somebody has written down what he's found What syslog implementation who has found that use tcp? So it's a collection of things that are out there and usually it just works So what we do in the tcp stream? We just put a new line to split the messages And then there are other implementations that said oh, we want new lines in our syslog messages But that doesn't work if you write in the log file because then you can't because there of course the new line is the delimiter And I replace every new new line that I get somewhere with the underscore by the way um, so somebody also use null delimiter to split tcp messages and And then there are so I split when I read it. I think with new line and null And then there's an octet counting format That's the new sheets. That's already that's also in the in the tls rfc That says are you write the decimal number with a number of bytes and you make a space and then here are 60 bytes till here And then the next message starts So what I do when I send a message add a new line here, so I'm compatible with everything except when somebody explicit explicitly is expect No delimiter, but I don't think That that is the case. So everybody splits splits that new line. It's just written in that rfc And another advantage is when you put a new line here It's much easier to to parse those messages if you just print them out You get a new line every time um, you see a new message and Just the the the octet counting in front So tls format there we have an rfc and it says Octet counting is the only supported format Then you must support 2,000 bytes And you should support 8,100 And what I did is um I added a global constant That says syslog messages have that maximum size and everything else is truncated So it's truncated in libc. It's truncated in kernel and it's truncated in syslog It can even truncated multiple times because we are adding all those timestamps and changing things And so it can get longer and then gets truncated again So truncation is the the right thing what to do with syslog messages If they don't fit because most of the time people can get out figure out What's going on at the beginning and it's much better than dropping it. Don't drop them So what I did also is converting syslog to lib event before you had a poll loop And doing all this tcp with multiple senders and multiple listeners and doing tls Um, it's quite hard with poll. So thio Uh recommended to change to lib tls that the lib event that was the first thing I did And then I linked to lib tls to do the tls stuff and I wrote a little wrapper um that does encryption of lib event buffers by sending them through lib tls instead of doing a plain read and writes And this is one c file located in the syslog directory and it has already been copied to our ldup d Demon that also needs that feature And newer the things that in open bsd We have a rather old lip tls because we think the new one lip tls too because this is Lip event. Uh, sorry. Sorry. Sorry. Lip event. Uh, the lip event is is feature bloat. So we have a lip event one 14 Something yeah Yeah Yeah, we we are still api uh api Compatible so things that when you develop something with the open bsd lip event and Copy it to linux and take the old lip event there and it still works But I've done a lot of cleanup there and internally it looks quite different That's also the reason why I didn't add this feature to our lip event Because then we wouldn't be api compatible anymore anymore. I've looked in lip event two. They have something like that So if you write portable programs, just use lip event two and if you do open bsd programming Just add it here Locally So what you also have to do when you do tls you have to care about Identifying your communication partner and doing some Certificate checks and as usual certificates are complicated You have this public key infrastructure and nobody Can set it up and understands how it should work and what it really does So I've implemented everything what you what you may need And now I've put it on four slides for every use case So um what you always have to do if you want to accept encrypted messages You have to provide a server certificate. So our syslog d uses a server certificate here and You put it in etc ssl Together with the host name you have you can also put an ip address here So the idea is to enable receiving Tls it's not enabled by default you put a t here A minus capital t and you say the host where you That's an ip address where you want to listen on you can also say 000 to listen on on a star socket You put a port if you leave it out the tls port is 6,514 We also have a 514 for udp and there's no well known port for tcp Because the 514 tcp A number it has been used by some remote shell whatever old unix tool um So but people use it anyway just uses nobody it does remote shell And so what I did here is a real ad does the same so you can put certificates for your Your machine and keys and private keys you just put them there and then syslog d uses it You can also add the port here then you can use specific certificates for syslog and relady Um So why do we do that? Because when we have a certificate here a server certificate here the sender knows with whom it it's talking So the sender can identify The drain of all the messages and that means the attacker cannot redirect the messages to himself And he cannot see our messages So another thing Funny thing about tls is you can have client certificates so then The client provides a certificate and we want to figure out whether it's the correct one first We have to enable it enable using tcp at all tls at all and we specify a certificate authority file and um Every time a sender tries to connect to us We ask him to show me your client certificate and we Check whether it's signed with this ca and if it is we um We take the message otherwise. We don't take it that means the syslog d can identify the sender who wants to talk to us And the attacker cannot inject messages. So nobody else is allowed to send something to us So that's the other side when we want to send something out So first the first thing I had to do is Thinking about the format how to specify that I want to use tls You have to give it in the in the config file of syslog syslog.con And what was there classically is that you use an ad sign And then the ip or host name and then you send you the udp packet there And what I wanted to do was able to specify or take tcp take ipv4 take ipv6 so you can say Here tls tcp or udp And then you can also optionally add in 4 or in 6 and then it will you will be forced to that protocol to that ip version And yeah, I thought about how to specify it and then I took just Something that looks like in your uh the prefix of your url because i'm sure that that will not collide with the hostname And I can parse it reliably if somebody has a better idea And those things that doesn't look like I'm I'm open for suggestions so Then If we want to send something out the receiver syslog Host the receiver lock host has a server certificate as every tls server and we want to validate it So you can either specify a ca file if it's your private pk pk Or if you want to send something to well-known syslog these at the nsa or at google Or wherever you want to have your messages Then just take something that is provided by upstream. That's the default certificate store in open bc so syslog must know the ca and The the hostname must also be in the server certificate so that Nobody else that belongs to the same cryptographic infrastructure Like komodo can can spoof it and um, so the hostname you specify here must be in the common name of the certificate Or in the subject out name lip tls handles that handles that for us And so we we can identify to whom we are sending messages And so we the attacker cannot redirect it um And the the messages are confidential And if everything this pka and this thing is too complicated turned on by default you can just disable it So for test environments that might be useful or if you don't care who's reading your messages And just want to get it off get them off use minus me So that's the final certificate slide So here we um use client certificates ourselves you can specify them on the command line And then the receiver can check them. And so he's sure that he's getting the The Messages from us and the tucker does not inject anything. So how does the error handling work? um We wanted to say that we we log all incoming connections um So what I first implemented is that we Write a message every time we accept something and somebody closes the connection to us And then somebody complained. Oh, it fills up our all our lock files. So I converted that to debug messages So syslog is in a special facility So syslog can and you can identify all the messages that are generated by syslog itself It's a facility and I changed the priority to or the severity to debug And so it's not locked by default, but you can turn it on and see Who is connecting to me and when you set up your syslog environment? It's maybe useful and you can leave it on if you don't have too many messages, but if you have Thousand clients rebooting every hour, then of course you don't want to see all that We lock connection errors so when When something goes wrong with a connection to a client we log an error and you see oh something is wrong And I lost some messages or may lose some messages Um, we count the dropped messages. We why we have buffers buffers to Sending buffers for for the messages And if we get a sick up we throw them away if you cannot cannot write anymore They fill up and get a sick up. We throw them away. We get a sick term We throw them away then we count the messages that are in the buffer and lock that so you can see um How many messages were not sent to a tcp destination It's not completely reliable because the kernel also locks some messages and the kernel throws The buffers away if there's an error on the tcp connection And but when you see oh, we have a connection error Then you know or there may also some log messages be lost because the kernel has thrown away the kernel buffers And more than that are locked here that are the messages that are Dropped in user land in syslog to user land. So it looks like this syslog d because syslog generated the messages Dropped to messages and it also locks the name of the host where it wanted to send them and what are also implemented when you have multiple messages um then Syslog d writes message repeated. It doesn't write the same stuff all the time It's important for local logging because otherwise you can fill up your log files easily But it's bad for remote logging because when you have multiple syslogs then you're not sure to which message the The last message adopt belongs then you can turn it off either for remote logging or even globally with a minus r option So now let's go to the conclusion so i've um The new message flow i've here and i've made it italic everything that has changed so for the program nothing has changed the syslog call looks the same And here in libc we have no timestamp anymore And we do a syscall the special sense syslog syscall and not a send The kernel has the send syslog and it knows about logging errors and counts the errors And syslog d still receives it. It's no different whether we receive from a socket pair or from or from a unix socket It adds the timestamp. So we have one single instance responsible for timestamps Um, it writes it to a log file that didn't change and it can also send to tls or tcp So that's new So what also has to be done to be reliable logging to have a reliable log system on your machine First of all syslog may not die. Normally when you write programs, it's a good idea to die and fix the buck If anything goes wrong die, but if if syslog dies You're blind. You don't see anything what's going on. Perhaps the attacker wanted to kill syslog by some funky thing And you don't know what's going on. So syslog tries to run It logs all the errors it gets at startup or and whatever and maybe you lose some log systems You can't bind to the udp socket and you it doesn't work or tcp socket is wrong. It doesn't work Gets a log message, but still running other messages appear So we count the dropped messages internally We make tcp and tls support because they are more reliable and more confidential than udp We changed everything to lip event. That means we get safe signal handlers. We don't have to to Do all those dances with sick prog mask to to avoid some races here and there All the signal handlers are not real signal handlers. They run the main program flow lip event handles that for us We cope with file descriptor exhaustion When you write a server that accepts a lot of things like incoming tls syslog messages You we run against your process limit and then And then you Critical file descriptors you cannot open anymore. For example, we run with pref sap. That means we have file descriptor passing between a low privileged process that does all the The network handling because now we do tls. We have to be careful here And we have a privileged program that opens the log file We have to do it at every c cup for example and we have to open consoles and tty's and Read user databases to send messages to special users so And then we do file descriptor passing. So we have to we need a reserve of file descriptors And syslog handles that because incoming tcp and tls connections will always leave about 10 file descriptors Not allocated. They are for internal use Then already said we have pref sap What's important to to avoid blind rob attacks There's there's an attack when you have when you do fork you have the same address Random address layout in two processes And if you can probe the one you can gather information about the other And to fix that you have to make an exit call Normally we accept the child here We accept the parent because it was much easier to to implement in syslog d because syslog d does a lot of startup things with for and then it does the fork and So if I accept the child all the startup is is lost and the child needs the startup the startup In this initialization And the the parent only serves some some requests like doing do dns open some lock files And there it's better to lose all the states So I do the the exec and I have just a minimal program just doing the iMessage requests Easy things and we run pledge in both processes the child and the parent So I've already written some tests usually before I change programs. I I write some regression tests Um, and then I fix the bugs and then I add the new features That's the the the evil thing about writing tests. You always find bugs and then you have to fix them So don't do that um So the tests work in the way that they generate some some config start the syslog d Then they have a client in the server process the client process Generate some lock files, then it's stop everything and then I check And what can I check I can check the standard error output of syslog d syslog d runs in debug mode where every Debug message and all other lock messages are printed there. So I can see what's going on Um, the client writes a log, but it's sending to syslog. It can use native send syslog methods or udp or tls or tcp or whatever um The server also has a log what you've received from syslog d We have a log file. We can look into that. I spawn some pipes there and I look into that I make some console redirection to see that everything goes to the console that is specified there uh, I create some fake users and that I enter in the via user temp File and then syslog looks into that and writes it there on the console and redirected the console and look into the user's console Or the user's terminal. Sorry. It's the terminal redirection and I look into the terminal that from my fake user Um, syslog d creates a ktrace. I can grab in the ktrace if it does the the correct system calls And I can look in the fstat if it's has opened the right sockets Yes a question Oh, um, that's not a regression framework itself. It's the Other question repeating the question was how I test That something has been written to the console with our regression framework and the answer is um It's not the framework itself. It's something implemented in this syslog test. It's some pearl modules that do things And there's the thing that you have in x. You have the x console It's a program and it tells the kernel redirect everything that's written to the console into this window And I use that mechanism to lock everything that is written to the console into A process and the process writes into the file and at the end of the test I grab in the file So and of course software is never finished. I always say only that projects generate stable software um So what else can we do here? So the thing is when you prepare such a talk you look into to the code and think oh, that's all buggy that could be done better So the first thing I thought is um All those initialization errors that are written to standard error or the console when syslog goes up Cannot be written into a log file because they are not there And I could count the errors. I have a diff for that. It's on tech And that's meant as a hint for some co-developers to do the review Um then I went to the our Quality assurance guy at genua and said oh now we have reliable logging and we don't lose anything and he tested it and says Oh and the file system is full You stop logging. Yeah, and it's true if syslog gets twice an error when writes your file descriptor and file system exhausted Then it stops logging there even if the file system gets empty again So if a diff for that, but it is it's on top on the other diff So I will send it out when the first one has been reviewed and committed Also have a test for that. I fill a I create a file system with def vnd fill it up write a log file to that get the error and then Um check that and I empty it again and check that it's rocked again and Read all the debug messages that syslog de creates for that So then I have read the old rfc with the hostname and there's a new rfc how to Write remote syslog messages and they have version numbers there and other features and we are somewhere in between but not quite And perhaps we should get more rfc compliant That's also when when I was preparing the talk and then Yeah, you you go through this conferences talk to other developers. They say oh, I do a talk here Make some promotion that people come here and then MPI says oh, I still have a bug there And can you fix it before you do your talk? No, didn't fix it, but I promised him to put it on the slide And then yesterday at the social event I was talking with imbra from the dragonfly project and he said Oh, yeah, you know when you when you when you do this startup Um, then you get the dmesh things and when syslog reads the dmesh buffer, it's a timestamp there And wouldn't it be better when the kernel adds the timestamp? It could use the the uptime and syslog can create it to to regular timestamps Then we would know in watch order those messages come and so the problem is in our company. We have a central configuration thing and they put every log message in the database and then they sort by timestamp And all those messages coming from a kernel at the same timestamp because when they were read And then they log it showed randomly to the user That's a bad thing to do And the idea was um, if the kernel would log it we would see When when the the dmesh messages Appear we can see where were the delays. How long did it take? That's one thing and then I thought about it when we would do that also for the syslog call We would get the the the time When the program does the log and that when syslog you get scheduled and reads the log and we could get more precision So I'll think about that if I want to influence it Yeah, and that's it So turns out you have already talked about the my First of my notes about been uptime in the kernel and kernel timestamps, but I have another one Uh, you said you're opening a socket pair and you're marking a socket as Used by syslog by this special ioc tool, right? Yes so there is a race condition if you do that and the Then some program tries to represent itself as a syslog demon and then it waits before until the syslog d gets sick up When it closes everything and tries to reopen again um You do the ioc tool on the def klog file descriptor So you have to open def klog and depending on your fire permissions in slash def only root can do that Okay Yeah, so you have to check for root and you have to check to be not true that in this case, right? um Yeah, because there's no device. Yeah, otherwise Okay, so you need to have access to def klog to to be a syslog A reader for sensors lock. Yeah, and if you are root you are fucked up anyway. Yeah Very good more questions For your new syscall, why are you using avoid pointer? Is there a valid use case why it's not a character pointer actually? Oh, that's theos idea Okay, so I have to ask him the question because it's if it's only because it's like right and read that stupid There's no valid use case for So there's not to be a character you this is not system d after all Yeah, so so there are two possibilities either theo has a good reason for it Or it was just to stupid to copy it correctly from the main page. Okay I'm curious, uh, what's the motivation for uh using the additional socket pair instead of uh reading and writing directly from the klog for the Senses log messages. So in klog you have the real kernel messages. They have a different format They are different from from user messages. So you want to to have a different uh a difference the klog buffer is more or less The thing that is in dmask So so if you call the log function in the kernel, it gets added to the dmask And it can be read by syslog d from def klog. That's very that's very distinct from userland logging So we added the new syslog um the syscall send syslog and their new mechanism was Needed and theo did it with a socket pair and I think it's a good idea So but I don't know exactly why this approach was chosen Anymore questions Then let's thank Alexander for his great presentation Thank you