In a past life, before I worked for Laminar Research, I was a plugin developer.  So I’ll admit up-front that I might be the most guilty individual when it comes to this particular problem: log spam.

What do I mean by log spam?  By log spam I mean printing information to Log.txt that isn’t necessary.

Log.txt exists so that we (and third party developers) can look at a single machine-generated file and get a strong idea of what a user did with X-Plane for diagnostic purposes.  Therefore log.txt needs to contain three kinds of information:

  1. Basic configuration information.  We print your graphics card, your OS, etc.  (In 10.30 we’ll even get your CPU type right on OS X. 🙂  It’s more reliable to log this than to send a user into ten different control panels to gather information.
  2. Very basic event logging, e.g. what did the user do?  Where did he start his airplane, what scenery was loaded.
  3. All abnormal conditions, including error alerts that came up.

In particular, what we do not need to do is log the detailed blow-by-blow progress of loading in excruciating detail.

If I may use my own sins as an example, older versions of XSquawkBox shipped with debug code on that dumped the contents of its entire ICAO dictionary – thousands of lines of text.  This information isn’t configuration (it’s not unique to particular installs), it isn’t an event – it is part of the event of loading XSquawkBox, and its not an error condition. What a mess!  (Fortunately Wade has fixed this and turned such logging off in the newest XSB betas.)

Programmers write this kind of logging code to help trace program execution, but it’s important to turn it off – if we don’t, the log files get so verbose that everyone spends a ton of time just fishing through ten tons of junk.

Some more guidelines:

  • Log the presence of files or sub-modules that are user-configurable, but do so briefly.  It’s reasonable for SASL or Gizmo to list scripts that do not come with the base package, or for XSquawkBox or Pilots Edge to list CSLs found.  (This information lets a developer see what a user has done to modify the plugin.)
  • Don’t log the presence of required files unless an error condition occurs.  An empty log can simply mean “everything went okay.”  (The sim will already confirm successful plugin loading on a per-plugin basis.)
  • Log rare events, e.g. a flight starting, a network connection being opened.  Don’t log events that occur at high frequency, like receipt of a single network packet.

X-Plane is guilty of log-spam too; I’m slowly trying to cut down on this.  For example, spurious autogen-tree warnings are now gone from the log in 10.25r1.

Support Debugging

Sometimes you need all of that logging.  My suggestion is: if your add-on is complicated, make a specific interface to get verbose diagnostics that users can turn on as needed.  For example, X-Plane has an option in “operations and warnings” to dump verbose play-by-play network data to Log.txt.  When you enable this, you can get a ton of information about network operations, but the log will also be totally over-run.  The option is meant only for developers who are integrating with X-Plane’s UDP networking, and thus it has to be turned on by hand.

The OBJ engine actually also has such a trick – if you put the single word DEBUG (all caps) at the end of your .obj file, the entire OBJ contents will be output in detail to Log.txt.  Again, this is a ton of information, available when needed, but off by default.

You can support verbose logging in your add-on with a script variable, a dataref, a change to a preferences file.  Pick an easy mechanism, so that you can have users turn on verbose logging only when they need it.

Not Everyone Has Grep

Finally, a quick aside to my fellow professional programmers.  You might be rolling your eyes and going: “Ben you idiot, it’s easy to filter the log.  Everyone should just prefix their log entry and use grep.”

If we were all programmers, I would agree 100%.  But please understand that aircraft and scenery authors have to look through the log to get diagnostic information about art-asset problems, and this is an audience that is sometimes not comfortable with command-line tools, huge 25MB text files, massive amount of text, etc. So we are trying to keep the log.txt more human-readable than, for example, dmesg on Linux.

About Ben Supnik

Ben is a software engineer who works on X-Plane; he spends most of his days drinking coffee and swearing at the computer -- sometimes at the same time.

5 comments on “Let’s All Try to Fight Log Spam

  1. Roger that.

    Guilty as charged. Many are there because in the heat and euphoria of the debugging moment I forget to remove them. 😉 Others are very valuable.

    Blue side up,
    Bob

  2. I’d like the option to turn off scenery related logs when coding sasl. Even better if sasl had an option to write its own log file. User choice is always good.

    1. The SASL devs should create their own logging facility – that’s not up to the sim.

      No way to turn the log off but we ARE trying to switch to the Linux-style log, e.g.

      E/OBJ: bla bla bla

      The idea is that you can use ‘grep’ to rapidly filter the log for just what you want.

Comments are closed.