Don't split up error messages in your source code

September 30, 2014

Every so often, developers come up with really clever ways to frustrate system administrators and other people who want to go look at their code to diagnose problems. The one that I ran into today looks like this:

if (rval != IDM_STATUS_SUCCESS) {
	cmn_err(CE_NOTE, "iscsi connection(%u) unable to "
	    "connect to target %s", icp->conn_oid,
	    icp->conn_sess->sess_name);
	idm_conn_rele(icp->conn_ic);
}

In the name of keeping the source lines under 80 characters wide, the developer here has split the error message into two parts, using modern C's constant string concatenation to have the compiler put them back together.

Perhaps it is not obvious why this is at least really annoying. Suppose that you start with the following error message in your logs:

iscsi connection(60) unable to connect to target <tgtname>

You (the bystander, who is not a developer) would like find the code that produces this error message, so that you can understand the surrounding context. If this error message was on one line in the code, it would be very easy to search for; even if you need to wild-card some stuff with grep, the core string 'unable to connect to target' ought to be both relatively unique and easy to find. But because the message has been split onto multiple source lines, it's not; your initial search will fail. In fact a lot of substrings will fail to find the correct source of this message (eg 'unable to connect'). You're left to search for various substrings of the message, hoping both that they are unique enough that you are not going to be drowned in hits and that you have correctly guessed how the developer decided to split things up or parameterize their message.

(I don't blame developers for parameterizing their messages, but it does make searching for them in the code much harder. Clearly some parts of this message are generated on the fly, but are 'connect' or 'target' among them instead of being constant part of the message? You don't know and have to guess. 'Unable to <X> to <Y> <Z>' is not necessarily an irrational message format string, or you equally might guess 'unable to <X> to target <Z>'.)

The developers doing this are not making life impossible for people, of course. But they are making it harder and I wish they wouldn't. It is worth long lines to be able to find things in source code with common tools.

(Messages aren't the only example of this, of course, just the one that got to me today.)


Comments on this page:

By dozzie at 2014-09-30 14:35:21:

Actually, it's not quite worth it to have such long lines. But there is a method, which results as side effects in both, short code lines and messages kept in a single line. It's logging with structure. In Perl or Python it would go like this:

$logger->error("CE_NOTE", {
  message => "iscsi connection unable to connect to target",
  connection => $icp->conn_oid,
  target => $icp->conn_sess->sess_name,
});

logger.error("CE_NOTE", {
  "message": "iscsi connection unable to connect to target",
  "connection": $icp->conn_oid,
  "target": $icp->conn_sess->sess_name,
})

My colleague did (after my few hints) something of similar usage in C++ (with `std::initializer_list`). I bet one could do such thing for C (probably with some printf-like formatting), but I don't write much C recently and I didn't have an opportunity to think about it for real uses.

hmm my sympaties. reminds me of a related situation: a long time ago i needed to search and analyze multi-line function declarations and calls [often with many longHungarianNotationNames :)]. I wrote a code matcher with a simplified C-like-language parser that understood the structure of comments, strings, function headers, blocks, and function calls, flatten them so I can pattern match across function declarations and function calls. don't remember offhand if I concatenated the strings - this is pre-C99 - though that would be an easy fix.

By cks at 2014-10-03 16:13:32:

dozzie: I think I was unclear in my entry. I'm okay with the form you used here because the actual textual message is all on one line, so it's easy to search for. In my example I'd have been happy if the two literal strings were one string, ie '"iscsi connection(%u) unable to connect to target %s"'.

(It actually requires slightly unnatural contortions to break them up; the first string has a trailing space before the closing " because C string concatenation doesn't create one for you.)

By Matrixik at 2014-12-20 06:24:39:

dozzie: you can do something similar in Go with https://github.com/inconshreveable/log15

log.Error("CE_NOTE", log.Ctx{
    "message": "iscsi connection unable to connect to target", 
    "connection": conn_oid, 
    "target": sess_name,
})
Written on 30 September 2014.
« Learning a lesson about spam-related logging (again)
NetworkManager and network device races »

Page tools: View Source, View Normal, Add Comment.
Search:
Login: Password:
Atom Syndication: Recent Comments.

Last modified: Tue Sep 30 00:33:12 2014
This dinky wiki is brought to you by the Insane Hackers Guild, Python sub-branch.