2010-12-21

Logging

If you are trying to figure out what a program is doing, chances are that you would like to look at the log files or the log output emitted on the console.  Depending on your luck this may give you the answers you seek ... or hair-related problems (discoloration, loss of etc).  Most programmers add logging code to their programs in some form -- from just printing messages on the console to adding and configuring logging libraries and logging messages that way.

Unfortunately, logging is by a lot of programmers, considered a sort of by-product of the development process.  Log messages are often added to aid the programmer while developing and then unceremoniously forgotten or ignored.  Decent logging often isn't an explicit requirement in many projects and thus programmers allow themselves to be sloppy about it.

Why is it important?

Being responsible for running software that was authored by other people you quickly learn how important log messages can be.  Especially if you do not have access to the source code.  The logs are the only real means by which a piece of software can communicate what it is trying to accomplish, and possibly, how it is failing (except for error messages and traces displayed as part of the UI).  Not knowing what a failing piece of software is doing leads to guesswork, and being forced to guess what is going on is rarely a good way to solve problems.  Knowing is preferable.


What to log?

The first rule of logging is to ask yourself if the information you are logging is needed.  Some programs that have some logging facility are inordinately chatty.  While logging too much is usually preferable to logging too little, the main problem with logging too much is that you drown the user in irrelevant information.

For every log message you add you should ask yourself if the log message is stricly needed.  Does it tell the user anything important about the state, or state transitions, of the program?   Is the program trying to access some external resource that it would be useful to know about?
 Most things that are part of the main program flow usually do not mandate logging.  If you are importing a file of records into a database, you do not need to log every record you are adding.  Though it might be a good idea to say which file you are reading and what database you are importing the records into.  Depending on how the log messages are consumed (appended to file, displayed on console etc) you may want to provide the user with some progress feedback for long-running tasks.  Possibly a summary after the task has completed with some pertinent information, such as the number of records added.

Of course, any exceptional conditions that occur need to be logged.

Debug output can be nice to have, but if you include messages that only make sense to the developer and which are largely superflous to normal operation, you should ensure that these messages are logged at a lower log level so they can be filtered out.


Completeness.

If you are taking the trouble of emitting a log message, you might as well do it properly.  Be sure to include all the critical information needed to understand what is going on.  If you get a parse error in a file, include the name of the file and possibly the line number or offset into the file.  If you are trying to access an external resource, like a web server, include the URL or the hostname etc.

If you need to track the lifecycle of some object, then try your best to be consistent and track at least creation and death of the objects you track so that it is possible to analyze the logs.  I once worked on a project where we needed to figure out why the system was losing a lot of data and nobody really knew where the problem was.  Since the system had incomplete logging just analyzing the logs didn't work.  Sometimes the developer logged when a resource it was handling was introduced and sometimes not.  The number of conditions where a resource could disappear was fairly huge, and few of them were logged in any meaningful way.   Unfortunately, the system didn't have just one problem, so we spent months trying to figure out what was going wrong.


Format.

Human readable log formats are mostly a good thing, but that doesn't mean that you should design log messages that only make sense for humans.  When designing a log format you are, in effect, designing a protocol and all the considerations you take when designing a protocol also apply to log messages.  You should take care to design log messages so that they lend themselves to easy-to-implement parsers.  If you have little experience with writing parsers then I suggest you sit down and write a parser for the log output of your program right now.

The most important part of a log format is to get the "framing" right -- that is:  it should be trivial to determine the boundaries between log messages.  Using linefeed to signal the end of a log message is a trivial way of framing log messages (if you have ensured that log messages will never contain an un-escaped linefeed).  Expecting the user to parse XML output is not.  XML parsers are fragile, slow, clumsy and not much fun to work with.  Especially not if you have terabytes of log messages to chew through.  Also ensure that the contents of log messages do not confuse the parser -- for instance that it doesn't get de-railed if you embed a log message within a log message.


Many log formatters burn CPU cycles on pointless formatting jobs.  A good example is formatting dates.  If you produce terabytes of log messages and most of the log lines are consumed by other programs rather than humans there is no point in formatting the date in a human readable format only to burn even more CPU parsing those dates.  Also, chances are you are not smart enough to pick a consistent time-zone for those dates and timestamps.

If you really need human-readable formats then provide a simple log filter program that you can pipe log messages through so that people can display log messages in whatever way they prefer.

If you use a line-oriented format you should also take care to choose the order of fields properly.  This can help immensely when working with log files using the UNIX command line tools.  In a company I used to work for the first field of any log message was the log level.  This meant that merging and sorting log files could not be done with trivial use of the sort program because it would jumble the log lines out of time sequence.  A thoughtless design decision that cost lots of time working around it -- quite possibly motivated by the original authors faulty understanding of how one might want to work with the log output (I suspect he formatted the log messages for screen use only).

A bad example.

A piece of software worth studying is the Maven build system.  This widely used piece of software pretty much breaks all the rules in the book and is a good example of horribly sloppy logging design.  It is overly chatty, which means that the information you really need is buried in heaps and heaps of unimportant information.  The formatting is very sloppy -- being designed only with a human reader in mind.  This means that writing a parser for the Maven output is a relatively daunting task -- most people wouldn't even bother trying.

It also illustrates what happens when you are not disciplined from the outset:  people take cues from those who went before them and emulate what they do.  So as new plugins are added to Maven, the new plugins tend to be just as bad.

2010-12-16

Information leakage

Recently there have been allegations that the ipsec implementation of OpenBSD has been tampered with.  I have no idea whether there is any truth to the allegations or not.  I am not a cryptanalyst nor am I an expert in applied cryptography or the branches of mathematics that you ought to know really well to truly understand the underlying theory -- and neither are you.

Now, there has been much speculation and much discussion in various forums around the web.  None of which seems to be burdened by any overwhelming level of insight.  Most people have a very naïve idea of what it takes to "compromise" a cryptosystem and think that we are talking about simple bugs.  Buffer overflows, important bits of information carelessly being exposed to unprivileged parts of the system in plaintext etc.

One concept that seems to be very hard to understand is the idea of a side-channel.  So I figured I'd have crack at (pardon the pun) giving an example of a side-channel leaking information in a security system.

Most of you have an idea of how a rotary combination lock works.   You twiddle a dial in alternate directions, stopping at a predetermined numbers, the rotors inside the lock line up, and eventually will allow the lock to be opened.  On the surface of things this could be a very time-consuming undertaking if you have no idea what sequence of numbers and turns you need to perform.

However, there may be shortcuts.  Depending on the quality of the lock it might have one or more side-channels that can be used to figure out the combination.  Two such side channels are feel and sound.  The feel of the dial, the lock handle and the sounds that the lock makes can impart information about its design and even provide usable information as to what the combination is.

Of course, most safes are fairly good these days so it would take a bit of experience to open them, but the one my parents used to have took less than an hour to crack when i was 12 years old.

I knew it had a 4 number combination and I knew that the sequence called for 3, 2 and then 1 turn between the first and the last number (again, by listening to it being opened by my dad, though not seeing any of the numbers).  The dial had numbers from 1 to 100, so in theory a great number of combinations that it would take a lot of time to go through.

After giving the problem some thought I had a mental model of what must be going on inside the safe -- how you mechanically align a number of rotors by rotating them in an alternating pattern (which I found out years later to be correct when I found a diagram of a similar lock).  Armed with that knowledge plus a theory of how the rotors must work, opening the thing was just a matter of learning how to feel what the rotors were doing and attacking the problem systematically.

And as I indicated earlier: it worked.  Mostly because the combination lock on that safe was poorly designed and leaked information.  Also, my dad opening the safe while I was in the next room was a process that leaked a lot of information.  In fact, the number of turns is what made me understand how the rotors must interact with each other.



Similar leakage of information can occur in cryptosystems due to poor design.  If you deliberately want to leak information about the internal state of the encryption process, or compromise the integrity of the system, it is more than likely that you would be able to sneak it past most people who only have a rough idea of cryptography, the underlying math or the practical reality of the implementations and operating environments. People tend to have very vocal debates over things they feel they understand. But you rarely see people saying "okay, I absolutely don't understand this -- explain it to me" when something more difficult needs to be done. If someone who we think know what he or she is doing does something we rarely question them for fear of coming off as stupid or uninformed. This is an exploitable (social) weakness.

So to those of you who think that we are talking buffer overflows and backdoors with magic passwords: your understanding of the alleged problem in OpenBSD being debated is orders of magnitude off and you could benefit from opining less and reading more.

2010-12-09

Feie for egen dør, Stoltenberg og Storberget.

I morgen, fredag 10 desember 2010, skal Regjeringen i statsråd angivelig legge frem Datalagringsdirektivet.  Samme dag deles Nobels fredspris ut til den kinesiske dissidenten Liu Xiaobo. Denne ironien er ikke tapt på Nettavisens Magnus Blaker som i dag publiserte artikkelen "Slik skal de unngå skandale".

Det er veldig trist å se vår statsminister og justisminister blamere seg selv ved å fremstå som hyklere på en slik dag.  På den ene siden fordømmer de andre regimers totalitære grep -- og på den annen side introduserer de lovgivning som legger en klam hånd over demokratiet og rettsstaten.

Det er sjelden man ser en slik skamløs prinsippløshet og mangel på ryggrad hos ledere som ønsker å bli ansett som Statsmenn.  De prinsippene som ligger til grunn for å bygge en rettsstat står høyest beklagelig ikke høyt i kurs hos politikere som ikke vet når det er deres plikt å være rake i ryggen og beskytte hardt tilkjempede prinsipper.

Jeg hadde helst sett at representanter for den sittende regjeringen hadde anstendigheten til å holde seg borte fra prisutdelingen og ikke skjende Nobelprisen ved sin tilstedeværelse.  Det passer seg dårlig.

Og mens jeg husker på det:

Forøvrig mener jeg fremdeles at Storberget bør fratre sin stilling som justisminister fordi han ved å mene at det ikke skal behøve å foreligge skjellig grunn til mistanke for å kunne overvåke privatpersoner er fundamentalt uegnet til å være justisminister i en liberal rettsstat.

Update: To my english-speaking readers:  I messed up.  This blog entry was meant for my other blog.  My apologies for the confusion.

Appropriate response

In the past few days there have been repeated instances of Denial of Service attacks against companies that have chosen not to provide their services to WikiLeaks.

There have also been accusations of government(s) being behind similar attacks on WikiLeaks.  In the absence of evidence of the latter I think one should be careful to make that accusation.  There is a much simpler explanation that is far more plausible:  there are people not representing any government that do not like WikiLeaks.

While those who wish to support WikiLeaks may derive some form of satisfaction from instigating, encouraging, or even taking part in these attacks I would wish that they would take the time to think more carefully about what they are doing.  I do not believe that Distributed Denial of Service attacks is an appropriate nor a productive way to resolve disagreements.

First of all, promoting your cause in ways that results in collateral damage on a large scale is fundamentally wrong.  If the majority of people affected by your actions have no part in the wrong you wish to right, you are, by all objective measures, a nuisance and you can legitimately be punished for your actions.  I can understand that it feels good to "stick it to the man", but there are other, better ways to do this than to force yourself upon those who have no part in this.

Second, by committing acts of vandalism that affect innocent bystanders you are providing your opposition with legal and moral ammo.  They can now label you as criminals, risk factors and possibly even apply more frightening labels such as "enemy combatant", which is essentially code for "those for which no laws apply".  This is not how you win.  This is how you get some temporary satisfaction in exchange for losing any and all moral high ground, jeopardizing your credibility, and ultimately: your chances to accomplish anything.

The only way you can win is by taking the moral high road.  If you want corporations to pay for underhanded dealings you do so by ensuring that they are asked hard questions, by digging out the facts and by making sure that those facts are brought to our attention.

This is hard work and most of you are not up for it.  You are up against well-funded PR machines, lobbyists, politicians who would rather not have constituents looking too closely at what they are doing, and an impotent press that is suffering from lack of resources, lack of competence and lack of political independence.  There is no shortage of tough challenges,  but that does not justify applying counterproductive tactics.

You respond by being responsible citizens.  Not by random acts of vandalism.

Thank you for reading.